この記事は、Ateam Finergy Inc. × Ateam Wellness Inc. Advent Calendar 2023の16日目の記事です。
はじめに
isucon13本戦が終わり、毎年のことながら惨敗しました。毎年出場しているので、使用しているツールや当日までの準備についてまとめたいと思います。
使っているツール
netdata
以下のようなコマンドを一つサーバ上のミドルウェエアがどれくらいリソースを使われているかを可視化してくれます。
curl https://my-netdata.io/kickstart.sh > /tmp/netdata-kickstart.sh && sh /tmp/netdata-kickstart.sh
初手ではだいたいnetdataを見てどのミドルウェアが重そうかをみて分析対象を絞り込んでいます。
isuconは環境構築に時間をかけると施策ができず詰む事が多いので簡単に入り重宝しています。
kataribe
Webサーバのログを分析し、パフォーマンスチューニングに最適な箇所を教えてくれます。
このツールを使うと、実行時間が長いURLを見つけ出し、問題の根源にアプローチが容易になります。類似のツールとしてalpもあるので両方試してみると良いと思います。
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
1859 189.976 0.1022 0.0928 0.000 0.079 0.238 0.301 0.393 0.451 1856 0 3 0 36362827 0 19560 78352 GET /api/livestream/<num>/livecomment
417 163.116 0.3912 0.0715 0.031 0.391 0.483 0.505 0.549 0.568 414 0 3 0 25996941 0 62342 63962 GET /api/livestream/search?limit=<num> HTTP/1.1
1894 148.732 0.0785 0.0722 0.000 0.059 0.185 0.229 0.296 0.367 1890 0 4 0 30888524 0 16308 73689 GET /api/livestream/<num>/reaction
9 131.113 14.5681 6.6361 3.767 20.000 20.002 20.002 20.002 20.002 2 0 7 0 202 0 22 102 GET /api/livestream/<num>/statistics
3056 55.011 0.0180 0.0037 0.001 0.017 0.023 0.025 0.031 0.063 3052 0 3 1 1435280 0 469 522 POST /api/register HTTP/1.1
480 53.531 0.1115 0.0379 0.000 0.116 0.151 0.163 0.188 0.194 476 0 4 0 558700 0 1163 1463 POST /api/livestream/reservation HTTP/1.1
16959 41.771 0.0025 0.0020 0.000 0.002 0.005 0.006 0.008 0.085 16959 0 0 0 1053961091 0 62147 171855 GET /api/user/*/icon
2418 27.442 0.0113 0.0053 0.001 0.010 0.018 0.022 0.031 0.049 2416 0 2 0 4671715 57 1932 2742 POST /api/livestream/<num>/livecomment
3091 18.758 0.0061 0.0025 0.002 0.006 0.009 0.010 0.015 0.048 3070 0 0 21 54329 14 17 154 POST /api/icon HTTP/1.1
1711 17.314 0.0101 0.0048 0.001 0.009 0.016 0.019 0.026 0.047 1710 0 1 0 3172042 0 1853 2206 POST /api/livestream/<num>/reaction
29 16.957 0.5847 0.3369 0.083 0.729 0.909 0.970 1.036 1.036 29 0 0 0 3425241 97565 118111 148172 GET /api/livestream/search?tag=<tag>
3060 11.453 0.0037 0.0034 0.001 0.003 0.006 0.007 0.010 0.122 3058 0 2 0 128 0 0 64 POST /api/login HTTP/1.1
1012 4.780 0.0047 0.0045 0.000 0.003 0.010 0.013 0.022 0.039 1012 0 0 0 591147 3 584 22512 GET /api/livestream HTTP/1.1
22 3.291 0.1496 0.0816 0.020 0.119 0.247 0.309 0.318 0.318 22 0 0 0 3038 133 138 154 GET /api/user/*/statistics
528 1.996 0.0038 0.0057 0.001 0.003 0.007 0.009 0.026 0.097 526 0 0 2 120063 3 227 19229 GET /api/livestream/<num>/report
1 1.781 1.7810 0.0000 1.781 1.781 1.781 1.781 1.781 1.781 1 0 0 0 27 27 27 27 POST /api/initialize HTTP/1.1
474 1.475 0.0031 0.0021 0.000 0.003 0.005 0.007 0.010 0.020 474 0 0 0 2888154 6089 6093 6095 GET /api/tag HTTP/1.1
393 1.099 0.0028 0.0017 0.000 0.002 0.005 0.006 0.008 0.011 393 0 0 0 22420 5 57 521 GET /api/livestream/<num>/ngwords
261 0.938 0.0036 0.0023 0.001 0.003 0.007 0.008 0.011 0.016 261 0 0 0 6003 23 23 23 POST /api/livestream/<num>/moderate
163 0.455 0.0028 0.0019 0.000 0.002 0.005 0.006 0.011 0.013 163 0 0 0 0 0 0 0 POST /api/livestream/<num>/enter
fgprof
弊チームはGo言語でisuconに出場しています。
fgprofはフレームグラフで関数レベルの詳細を提供してくれます。
修正してみて効果があるかないかを特定することができます。
pt-query-digest
MySQLのslow query logを分析するこのツールは、データベースのボトルネックの分析に利用できます。
実行回数が多いクエリはN+1問題、実行時間が長いクエリはインデックス最適化とどんな施策をするかを明確に教えてくれます。
以下の例だとSELECT tagsが実行回数が多くN+1が起きていそうなことが分かります。
# A software update is available:
# 29.4s user time, 220ms system time, 31.95M rss, 390.66G vsz
# Current date: Sun Dec 10 16:14:14 2023
# Hostname: mac2023.local
# Files: mysql-slow.log
# Overall: 781.46k total, 80 unique, 8.40k QPS, 2.17x concurrency ________
# Time range: 2023-12-10T07:07:32 to 2023-12-10T07:09:05
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 202s 1us 343ms 258us 626us 2ms 84us
# Lock time 1s 0 13ms 1us 1us 39us 1us
# Rows sent 1.11M 0 7.71k 1.49 4.96 28.85 0.99
# Rows examine 54.24M 0 12.94k 72.78 4.96 430.91 0.99
# Query size 36.91M 6 1.94M 49.53 118.34 2.34k 34.95
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== =================================== ============= ====== ====== ===
# 1 0xC499D81D570D361DB61FC43A94BB888A 56.4213 27.9% 30286 0.0019 0.00 SELECT livestreams reactions
# 2 0xFBC5564AE716EAE82F20BFB45F6C37E7 37.5346 18.6% 298079 0.0001 0.00 SELECT tags
# 3 0xA3401CA3ABCC04C3AB221DB8AD5CBF26 19.2948 9.5% 477 0.0405 0.01 UPDATE reservation_slots
# 4 0x38BC86A45F31C6B1EE324671506C898A 18.2439 9.0% 103380 0.0002 0.00 SELECT themes
# 5 0xF7144185D9A142A426A36DC55C1D2623 12.8711 6.4% 62610 0.0002 0.00 SELECT livestream_tags
# 6 0x7F9C0C0BA9473953B723EE16C08655F1 12.4450 6.2% 478 0.0260 0.01 SELECT reservation_slots
# 7 0xEA1E6309EEEFF9A6831AD2FB940FC23C 11.8314 5.9% 84679 0.0001 0.00 SELECT users
# 8 0xFD38427AE3D09E3883A680F7BAF95D3A 9.6100 4.8% 30282 0.0003 0.00 SELECT livestreams livecomments
# 9 0xD6032FE08E1FE706A928B8B7CBA06B85 3.8080 1.9% 28182 0.0001 0.00 SELECT livestreams
# 10 0x3F155F5E71EFF856F0CF7B8430DE8C23 2.8247 1.4% 20062 0.0001 0.01 SELECT users
# 11 0xAD0C28443E1E5CFAFF1569DBB4F7E63A 2.5225 1.2% 1733 0.0015 0.00 SELECT reactions
# 12 0x59F1B6DD8D9FEC059E55B3BFD624E8C3 1.7257 0.9% 4717 0.0004 0.00 SELECT reservation_slots
# 13 0x25A8CED3CE7A62689A139EB1D769F15E 1.2449 0.6% 22 0.0566 0.03 SELECT users livestreams reactions
# 14 0xD7DB5E8885E63F863372470C17D5DAC2 1.1666 0.6% 22 0.0530 0.02 SELECT users livestreams livecomments
# 15 0x9E2DA589A20EC24C34E11DDE0FBF5564 1.0004 0.5% 38063 0.0000 0.00 START
# MISC 0xMISC 9.6072 4.8% 78385 0.0001 0.0 <65 ITEMS>
# Query 1: 409.27 QPS, 0.76x concurrency, ID 0xC499D81D570D361DB61FC43A94BB888A at byte 173565268
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-12-10T07:07:51 to 2023-12-10T07:09:05
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 30286
# Exec time 27 56s 230us 36ms 2ms 8ms 3ms 541us
# Lock time 5 66ms 0 10ms 2us 1us 67us 1us
# Rows sent 2 29.58k 1 1 1 1 0 1
# Rows examine 76 41.25M 1001 2.36k 1.39k 2.27k 467.19 1.46k
# Query size 7 2.91M 98 101 100.67 97.36 0 97.36
# String:
# Databases isupipe
# Hosts 192.168.0.12
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us ################################################################
# 1ms ##############################
# 10ms ###
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isupipe` LIKE 'livestreams'\G
# SHOW CREATE TABLE `isupipe`.`livestreams`\G
# SHOW TABLE STATUS FROM `isupipe` LIKE 'reactions'\G
# SHOW CREATE TABLE `isupipe`.`reactions`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) FROM livestreams l INNER JOIN reactions r ON l.id = r.livestream_id WHERE l.id = 1997\G
# Query 2: 4.52k QPS, 0.57x concurrency, ID 0xFBC5564AE716EAE82F20BFB45F6C37E7 at byte 186334071
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-12-10T07:07:59 to 2023-12-10T07:09:05
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 38 298079
# Exec time 18 38s 41us 16ms 125us 348us 284us 69us
# Lock time 37 441ms 0 5ms 1us 1us 28us 1us
# Rows sent 25 291.09k 1 1 1 1 0 1
# Rows examine 0 291.09k 1 1 1 1 0 1
# Query size 24 9.08M 31 33 31.93 31.70 0.45 31.70
# String:
# Databases isupipe
# Hosts 192.168.0.12
# Users isucon
# Query_time distribution
# 1us
# 10us ################################################################
# 100us #########
# 1ms #
# 10ms #
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isupipe` LIKE 'tags'\G
# SHOW CREATE TABLE `isupipe`.`tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM tags WHERE id = 62\G
まとめ
紹介したツールは大体開始30分くらいですべて使えるようにしています。
導入が早ければ早いほど施策の実施時間が増えるので、自動化や練習によって手になじませると良いです。
最近このあたりをもう少し見直したいと考えているので、更におすすめがあればぜひ教えてほしいです。