ISUCON Նظߨश 2017 ࣮ફฤ 2017.08.25 @fujiwara

@fujiwara @mackee_w (ISUCON2,3ຊબग़৔) ٕज़෦

͜Ε͔Βͷ࣮श ISUCON 6 ༧બ໰୊(Ұ෦վม൛) Λମݧ͍͖ͯͨͩ͠·͢ ࡢ೥ͷ༧બͱͷ૬ҧ఺ Ϛγϯ͕ 2ίΞ → 3ίΞ ϕϯν͕ϦϞʔτͰ͸ͳ͘ϩʔΧϧ Go ൛ΛҰ෦վม (είΞ͸༧બͱൺֱͰ͖ͳ͍ͷͰ஫ҙ)

ISUCON 7 ༧બʹ͍ͭͯ ͘͞ΒͷΫϥ΢υͰ։࠵ ӡӦ͕αʔόʔΛ༻ҙ͢Δ(ࣗ෼Ͱىಈ͠ͳ͍) աڈͷ༧બ͸શͯࣗ෼ͰΠϯελϯεΛىಈ͍ͯͨ͠ ͭ·Γࠓ೔ͱಉ͡งғؾͷ͸ͣ1 1 ͨͩ͠ϕϯνϚʔΫ͸͓ͦΒ͘ϦϞʔτͩͱࢥΘΕ·͢

ϨΪϡϨʔγϣϯΛख़ಡ͢Δ ϨΪϡϨʔγϣϯ͸ຖճҟͳΔ ࣄલࠂ஌͞ΕΔ಺༰ʴ౰೔ެ։͞ΕΔৄࡉ είΞͷܭࢉํ๏ɾSuccess/Fail ͷ൑ఆ৚݅ ڐՄ͞ΕΔ͜ͱɾ͞Εͳ͍͜ͱ աڈʹ͸ ʮϒϥ΢βͰදࣔͨ͠ࡍͷݟͨ໨Λมߋ͠ͳ͍ʯ ͱ͍͏߲໨΋

·ͣαʔόʹ ssh ϩάΠϯ ssh -l ubuntu [֤ࣗͷαʔόͷIPΞυϨε] ύεϫʔυͱެ։伴͸ࣗ༝ʹมߋ͍ͯͩ͘͠͞ ͦͷޙͷૢ࡞͸جຊతʹ isucon ϢʔβʔͰߦ͍·͢ $ sudo su - isucon

γεςϜΛ೺Ѳ͢Δ ϒϥ΢βͰ http://[֤ࣗͷαʔόͷIPΞυϨε]/ ʹΞΫηε ΞϓϦέʔγϣϯΛ೺Ѳ αʔόͰ pstree ΍ ps auxwf ౳Λ࣮ߦͯ͠ ಈ͍͍ͯΔϓϩηεΛ֬ೝ͢Δ Կͷ daemon ΍ϛυϧ΢ΣΞͰߏ੒͞ΕͯΔ͔Λ೺Ѳ

αʔόΛ͍͡Δલʹ ࣮֬ʹ໭ΕΔΑ͏ʹ͓ͯ͘͠ աڈͷ༧બͰ͸αʔόΛॳظঢ়ଶͰىಈ͠௚͕ͤͨ… ࠓճͷ༧બͱաڈͷຊબͰ͸αʔόΛյͨ͠Βͦ͜Ͱऴྃ ϨΪϡϨʔγϣϯΛख़ಡ͢Δ͜ͱ(େࣄͳ͜ͱͳͷͰೋճ) ISUCON 3 ຊબͰ͸αʔό্ͷը૾ϑΝΠϧΛࣦ͏ͱͦ͜Ͱશ ͕ͯऴΘΓ·ͨ͠

Git ౳Ͱ؅ཧ͠Α͏ ΞϓϦέʔγϣϯ͕഑ஔ͞Ε͍ͯΔ /home/isucon/webapp → ڞಉ࡞ۀͷ৔߹ɺGitHub ΍ BitBucket ͷϓϥΠϕʔτ repoʹpush͢Δͷ͕͓קΊ2 OSɺϛυϧ΢ΣΞͷઃఆϑΝΠϧ͕͋Δ /etc ΋(rootͰ) $ git init $ git add . $ git commit -m "first commit" 2 ࣮ࡍͷ༧બɺຊબͰ͸ڝٕதʹrepoΛެ։ͯ͠͠·͏ͱࣦ֨ʹͳΔͷͰ஫ҙ

ϕϯνΛֻ͚ͯΈΑ͏ ॳظ࣮૷͸ Perl $ cd /home/isucon/isucon6q $ sudo ./isucon6q-bench 2017/08/24 17:58:01 start pre-checking 2017/08/24 17:58:19 pre-check finished and start main benchmarking 2017/08/24 17:59:01 benchmarking finished {"pass":true,"score":0,"success":386,"fail":39,"messages":[ "ϦΫΤετ͕λΠϜΞ΢τ͠·ͨ͠ (GET /)", "ϦΫΤετ͕λΠϜΞ΢τ͠·ͨ͠ (POST /keyword)", "ϦΫΤετ͕λΠϜΞ΢τ͠·ͨ͠ (POST /login)", "ϦΫΤετ͕λΠϜΞ΢τ͠·ͨ͠ (POST /stars)"]}

ࣗ෼ͷ࢖͏ݴޠͷ࣮૷ʹ੾Γସ͑ͯϕϯνͯ͠ΈΑ͏ $ sudo -s # systemctl stop isuda.perl # systemctl stop isutar.perl # systemctl start isuda.XXX # systemctl start isutar.XXX # journalctl -f XXX ͸ go js perl php python ruby scala ͷ͍ͣΕ͔

ϕϯνΛֻ͚ͳ͕Βαʔόͷ༷ࢠΛݟΑ͏ top htop dstat -t -a glances

netdata - https://my-netdata.io # bash <(curl -Ss https://my-netdata.io/kickstart-static64.sh) ϒϥ΢βͰ http://αʔόͷΞυϨε:19999/ ʹΞΫηε

ϘτϧωοΫΛݟ͚ͭΔ

ʮਪଌ͢ΔͳܭଌͤΑʯ Ͳ͕͜ϘτϧωοΫͳͷ͔Λ͸͖ͬΓͤ͞Δ·Ͱ͸ɺਪଌΛߦ ͬͨΓɺεϐʔυϋοΫΛͯ͠͸ͳΒͳ͍ɻ ܭଌ͢΂͠ɻܭଌ͢Δ·Ͱ͸଎౓ͷͨΊͷௐ੔Λͯ͠͸ͳΒͳ ͍ɻ3 Robert C. Pike 3 https://ja.wikipedia.org/wiki/UNIX%E5%93%B2%E5%AD%A6

alpͰΞΫηεϩάΛղੳͯ͠ΈΑ͏ github.com/tkuchiki/alp Access Log Profiler releases ͔Β alp_linux_amd64.zip Λμ΢ϯϩʔυͯ͠ల։ wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip unzip alp_linux_amd64.zip sudo install ./alp /usr/local/bin

nginx.conf ʹ alp ༻ͷग़ྗΛઃఆ http { ͷͱ͜Ζʹ௥هͯ͠ log_format ltsv "time:$time_local" "\thost:$remote_addr" "\tforwardedfor:$http_x_forwarded_for" "\treq:$request" "\tstatus:$status" "\tmethod:$request_method" "\turi:$request_uri" "\tsize:$body_bytes_sent" "\treferer:$http_referer" "\tua:$http_user_agent" "\treqtime:$request_time" "\tcache:$upstream_http_x_cache" "\truntime:$upstream_http_x_runtime" "\tapptime:$upstream_response_time" "\tvhost:$host"; access_log /var/log/nginx/access.log ltsv; # rm /var/log/nginx/access.log && systemctl reload nginx

ϕϯνΛ·Θͨ͋͠ͱʹ alp Ͱղੳ $ alp --sum -r -f /var/log/nginx/access.log --aggregates='/keyword/.*' +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+ | 31 | 1.113 | 15.001 | 323.588 | 10.438 | 1.113 | 11.023 | 15.001 | 3.934 | 0.000 | 87485.000 | 972130.000 | 31359.032 | GET | / | | 84 | 0.001 | 10.408 | 182.531 | 2.173 | 0.001 | 1.241 | 10.406 | 2.825 | 106015.000 | 106015.000 | 8905260.000 | 106015.000 | GET | /css/bootstrap.min.css | | 53 | 0.012 | 3.009 | 109.075 | 2.058 | 0.012 | 2.999 | 3.009 | 1.270 | 0.000 | 335.000 | 775.000 | 14.623 | POST | /login | | 26 | 1.036 | 10.929 | 98.640 | 3.794 | 1.036 | 3.674 | 9.501 | 2.392 | 2247.000 | 49197.000 | 172511.000 | 6635.038 | GET | /keyword/.* | | 42 | 0.001 | 10.399 | 91.376 | 2.176 | 0.001 | 1.250 | 10.188 | 2.823 | 86351.000 | 86351.000 | 3626742.000 | 86351.000 | GET | /js/jquery.min.js | | 42 | 0.000 | 10.400 | 91.264 | 2.173 | 0.000 | 1.248 | 10.189 | 2.823 | 16849.000 | 16849.000 | 707658.000 | 16849.000 | GET | /css/bootstrap-responsive.min.css | | 42 | 0.001 | 10.409 | 91.132 | 2.170 | 0.001 | 1.223 | 10.210 | 2.828 | 1092.000 | 1092.000 | 45864.000 | 1092.000 | GET | /favicon.ico | | 42 | 0.001 | 10.399 | 90.840 | 2.163 | 0.001 | 1.137 | 10.184 | 2.825 | 28631.000 | 28631.000 | 1202502.000 | 28631.000 | GET | /js/bootstrap.min.js | | 42 | 0.001 | 10.398 | 90.706 | 2.160 | 0.001 | 1.132 | 10.180 | 2.826 | 93.000 | 93.000 | 3906.000 | 93.000 | GET | /img/star.gif | | 14 | 0.176 | 3.001 | 24.694 | 1.764 | 0.176 | 1.545 | 3.001 | 1.061 | 0.000 | 331.000 | 1023.000 | 73.071 | POST | /keyword | | 13 | 0.004 | 3.001 | 12.114 | 0.932 | 0.004 | 0.461 | 3.001 | 1.017 | 0.000 | 335.000 | 585.000 | 45.000 | POST | /stars | | 2 | 0.004 | 6.611 | 6.615 | 3.307 | 0.004 | 0.004 | 0.004 | 3.304 | 5.000 | 5.000 | 10.000 | 5.000 | GET | /logout | | 2 | 0.027 | 0.044 | 0.071 | 0.035 | 0.027 | 0.027 | 0.027 | 0.008 | 25.000 | 25.000 | 50.000 | 25.000 | GET | /initialize | +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+

੩తϑΝΠϧ͕ॏͦ͏ͳͷͰ nginx Ͱ഑ͬͯΈΔ? location / { ͷલʹԼهΛ͍Εͯ location ~ ^/(img|css|js|favicon.ico) { root /home/isucon/webapp/public; } # rm /var/log/nginx/access.log && systemctl reload nginx 4 ΋͏Ұճϕϯνͯ͠ alp Ͱղੳ 4 ϩάΛফͨ͘͠ͳ͚Ε͹ mv Ͱอଘ

Ͳ͏ͳΓ·͔ͨ͠?

੩తϑΝΠϧ͸଎͘ͳ͚ͬͨͲ… +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+ | 29 | 1.632 | 15.001 | 310.129 | 10.694 | 1.632 | 11.513 | 15.000 | 4.038 | 0.000 | 54728.000 | 939499.000 | 32396.517 | GET | / | | 36 | 0.586 | 12.471 | 197.041 | 5.473 | 0.586 | 3.888 | 12.417 | 4.025 | 2130.000 | 83098.000 | 315071.000 | 8751.972 | GET | /keyword/.* | | 63 | 0.002 | 3.000 | 132.119 | 2.097 | 0.002 | 2.418 | 3.000 | 1.157 | 5.000 | 335.000 | 1160.000 | 18.413 | POST | /login | | 22 | 0.216 | 3.001 | 48.918 | 2.224 | 0.216 | 2.629 | 3.001 | 0.951 | 0.000 | 331.000 | 1038.000 | 47.182 | POST | /keyword | | 21 | 0.004 | 3.001 | 24.217 | 1.153 | 0.004 | 0.582 | 3.001 | 1.020 | 0.000 | 335.000 | 735.000 | 35.000 | POST | /stars | | 3 | 0.001 | 1.962 | 1.970 | 0.657 | 0.001 | 0.001 | 0.007 | 0.923 | 5.000 | 5.000 | 15.000 | 5.000 | GET | /logout | | 1 | 0.130 | 0.130 | 0.130 | 0.130 | 0.130 | 0.130 | 0.130 | 0.000 | 25.000 | 25.000 | 25.000 | 25.000 | GET | /initialize | | 43 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 28631.000 | 28631.000 | 1231133.000 | 28631.000 | GET | /js/bootstrap.min.js | | 43 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 16849.000 | 16849.000 | 724507.000 | 16849.000 | GET | /css/bootstrap-responsive.min.css | | 43 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 86351.000 | 86351.000 | 3713093.000 | 86351.000 | GET | /js/jquery.min.js | | 43 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1092.000 | 1092.000 | 46956.000 | 1092.000 | GET | /favicon.ico | | 43 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 93.000 | 93.000 | 3999.000 | 93.000 | GET | /img/star.gif | | 86 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 106015.000 | 106015.000 | 9117290.000 | 106015.000 | GET | /css/bootstrap.min.css | +-------+-------+--------+---------+--------+-------+--------+--------+--------+------------+------------+-------------+------------+--------+-----------------------------------+ είΞ͸େࠩͳ͍͸ͣ ͭ·Γ੩తϑΝΠϧ͸ϘτϧωοΫͰ͸ͳ͔ͬͨ(ݱ࣌఺Ͱ͸)

MySQLͷΫΤϦΛղੳ͠Α͏ /etc/mysql/my.cnf [mysqld] slow_query_log = 1 slow_query_log_file = /var/log/mysql/slow.log long_query_time = 0 # શͯͷΫΤϦΛग़ྗ # systemctl restart mysql # systemctl restart isuda.XXX # systemctl restart isutar.XXX ΞϓϦ΋࠶ىಈ͠ͳ͍ͱDB઀ଓ͕੾ΕͯΤϥʔͷݪҼʹ

ͦΖͦΖ࠶ىಈ͕໘౗ʹͳ͖ͬͯ·ͨ͠Ͷ ҰൃͰͰ͖Δ shell script ΍ Makefile Λ༻ҙ͠·͠ΐ͏ #!/bin/sh set -e now=`date +%Y%m%d-%H%M%S` mv /var/log/nginx/access.log /var/log/nginx/access.log.$now # nginxͷϩάΛϩʔςʔτ systemctl reload nginx mv /var/log/mysql/slow.log /var/log/mysql/slow.log.$now # mysqlͷslowlogΛϩʔςʔτ mysqladmin -uisucon -pisucon flush-logs # ΞϓϦέʔγϣϯͷ࠶ىಈ systemctl restart isuda.XXX systemctl restart isutar.XXX # Τϥʔ͕ग़ͯͳ͍͔ϩάΛݟΔ journalctl -f

MySQL ͷ slow log # Time: 2017-08-24T10:18:22.683713Z # User@Host: isucon[isucon] @ localhost [] Id: 4 # Query_time: 0.160908 Lock_time: 0.000241 Rows_sent: 7110 Rows_examined: 14220 SET timestamp=1503569902; /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line 235 */ SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC; Query_time: ΫΤϦ࣮ߦʹֻ͔ͬͨ࣌ؒ Rows_sent: ΫϥΠΞϯτ(ΞϓϦ)ʹૹ৴ͨ͠ߦ਺ Rows_examined: ࣮ߦ͢ΔͨΊʹ಺෦ͰಡΈऔͬͨߦ਺

MySQL ͷ slow log Λղੳ # mysqldumpslow /var/log/mysql/slow.log Reading mysql slow query log from /var/log/mysql/slow.log Count: 11 Time=0.12s (1s) Lock=0.00s (0s) Rows=7110.0 (78210), isucon[isucon]@localhost /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line N */ SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC Count: 2 Time=0.02s (0s) Lock=0.00s (0s) Rows=10.0 (20), isucon[isucon]@localhost /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line N */ SELECT * FROM entry ORDER BY updated_at DESC LIMIT N OFFSET N Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), isucon[isucon]@localhost /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line N */ SELECT COUNT(*) FROM entry

pt-query-digest Ͱղੳ Percona Toolkit www.percona.com/software/database-tools/percona-toolkit # wget https://www.percona.com/downloads/percona-toolkit/3.0.4/binary/debian/xenial/x86_64/percona-toolkit_3.0.4-1.xenial_amd64.deb # apt install libdbd-mysql-perl libdbi-perl libio-socket-ssl-perl libnet-ssleay-perl # dpkg -i percona-toolkit_3.0.4-1.xenial_amd64.deb pt-query-digest --limit 10 /var/log/mysql/slow.log

ѹ౗తʹ࣌ؒΛ৯͍ͬͯΔΫΤϦ # Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== ============= ===== ====== ===== =============== # 1 0x6C987DBB94BEC091 36.1491 96.3% 202 0.1790 0.04 SELECT entry # 2 0x28FC5B5D583E2DA6 0.3160 0.8% 186 0.0017 0.00 SHOW GLOBAL STATUS # 3 0x0C85264D3C24C18B 0.3030 0.8% 19 0.0159 0.00 SELECT entry # 4 0x6FF06CCB4B4E1FAC 0.2020 0.5% 10 0.0202 0.01 INSERT UPDATE entry # 5 0x813031B8BBC3B329 0.1380 0.4% 372 0.0004 0.00 COMMIT (ུ) # Query 1: 2.27 QPS, 0.41x concurrency, ID 0x6C987DBB94BEC091 at byte 54680 SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC

໰୊ͷΫΤϦ͕Ͳ͔͜Βൃߦ͞ΕͯΔ͔ ιʔείʔυͰ֬ೝ͠·͠ΐ͏ ͪͳΈʹ Perl ͩͱΫΤϦίϝϯτ͕ຒ·͍ͬͯΔͷͰҰܸ /* /home/isucon/webapp/perl/lib/Isuda/Web.pm line 235 */ SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC; DBIx::Sunny by kazeburo

htmlify() ΤϯτϦ಺༰Λը໘ʹදࣔ͢ΔͨΊͷHTMLΛੜ੒͢Δؔ਺ ͜ͷதͰྫͷΫΤϦ͕ݺ͹Ε͍ͯΔ ͞ΒʹτοϓϖʔδͰ͸ϧʔϓ಺Ͱݺ͹Ε͍ͯΔʂ ॲཧΛಡΉͱɺ࣮͸͜ͷΫΤϦ͸ SELECT * Ͱ͸ͳ͘ SELECT keyword Ͱे෼

ແବͳΧϥϜΛSELECT͢Δͱ஗͍ ໿20ഒ # Query_time: 0.018891 Lock_time: 0.000156 Rows_sent: 7108 Rows_examined: 14216 SELECT keyword FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC; # Query_time: 0.373342 Lock_time: 0.000047 Rows_sent: 7108 Rows_examined: 14216 SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC;

EXPLAIN ͯ͠ΈΔ mysql> EXPLAIN SELECT keyword FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC; +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-----------------------------+ | id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra | +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-----------------------------+ | 1 | SIMPLE | entry | NULL | index | NULL | keyword | 767 | NULL | 5022 | 100.00 | Using index; Using filesort | +----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-----------------------------+ 1 row in set, 1 warning (0.00 sec) mysql> EXPLAIN SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC; +----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+ | id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra | +----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+ | 1 | SIMPLE | entry | NULL | ALL | NULL | NULL | NULL | NULL | 5022 | 100.00 | Using filesort | +----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+----------------+ 1 row in set, 1 warning (0.00 sec) SELECT keyword ͸ Using Index ͭ·Γ Index Λݕࡧ͢Δ͚ͩͰΫΤϦ͕׬ྃ͢ΔͷͰ଎͍

ΫΤϦΛม͑ͯϕϯνͯ͠ΈΑ͏ SELECT * Λ SELECT keyword ʹมߋ͢Δ͚ͩ 5 ΞϓϦͷ࠶ىಈΛ๨Εͣʹ 5 Go, Scala ͷਓ͸ίʔυ΋গ͠ௐ੔͕ඞཁͰ͢

Ͳ͏ͳΓ·͔ͨ͠ʁ ...score 0 ͷਓ͸ score Ͱ͸ͳ͘ success ͷ஋Λൺֱͯ͘͠ ͍ͩ͞

΍͍͖ͬͯ·͠ΐ͏ !

(͓·͚) ISUCON ͷ܏޲ͱରࡦ ISUCON ͸աڈͱಉ͡ύλʔϯͷ໰୊͸ग़ͮ͠Β͍ (ग़୊ऀͷ৺ཧ) ݱࡏͷٕज़τϨϯυΛऔΓࠐΉ܏޲͕͋Δ ISUCON 5 ༧બ: systemd ISUCON 5 ຊબ: Microservices, https ISUCON 6 ༧બ: Microservices ISUCON 6 ຊબ: React SSR, Docker, https ISUCON 7 ???