こんにちは。アプリケーションサービス部の渡辺です。
2024/12/8 に ISUCON14 に参加しました。
ISUCON への参加は初めてです。
事前勉強をしたのですが、初めて使うツールが色々ありましたのでご紹介させていただきます。
CPU の使用率を確認したい
top
コマンド を使うことでCPU の使用率を確認できます。
メモリの使用率を確認したい
free
コマンドを使うことでメモリの使用率を確認できます。
アクセスログを解析したい
alp を使うことで URL, HTTP メソッドごとにレスポンス回数、レスポンスタイム (最小、最大、平均、合計) などのいろいろな基準でアクセスログを分析することができます。
alp は Access Log Profiler の頭文字で読み方は [éɪélpíː] または [ælp] だそうです。
APT. ではありません *1
アクセスログを以下のように分析することができます。
ISUCON 当日も非常にお世話になりました。
$ cat example/logs/ltsv_access.log time:2015-09-06T05:58:05+09:00 method:POST uri:/foo/bar?token=xxx&uuid=1234 status:200 size:12 apptime:0.057 time:2015-09-06T05:58:41+09:00 method:POST uri:/foo/bar?token=yyy status:200 size:34 apptime:0.100 time:2015-09-06T06:00:42+09:00 method:GET uri:/foo/bar?token=zzz status:200 size:56 apptime:0.123 time:2015-09-06T06:00:43+09:00 method:GET uri:/foo/bar status:400 size:15 apptime:- time:2015-09-06T05:58:44+09:00 method:POST uri:/foo/bar?token=yyy status:200 size:34 apptime:0.234 time:2015-09-06T05:58:44+09:00 method:POST uri:/hoge/piyo?id=yyy status:200 size:34 apptime:0.234 time:2015-09-06T05:58:05+09:00 method:POST uri:/foo/bar?token=xxx&uuid=1234 status:200 size:12 apptime:0.057 time:2015-09-06T05:58:41+09:00 method:POST uri:/foo/bar?token=yyy status:200 size:34 apptime:0.100 time:2015-09-06T06:00:42+09:00 method:GET uri:/foo/bar?token=zzz status:200 size:56 apptime:0.123 time:2015-09-06T06:00:43+09:00 method:GET uri:/foo/bar status:400 size:15 apptime:- time:2015-09-06T06:00:43+09:00 method:GET uri:/diary/entry/1234 status:200 size:15 apptime:0.135 time:2015-09-06T06:00:43+09:00 method:GET uri:/diary/entry/5678 status:200 size:30 apptime:0.432 time:2015-09-06T06:00:43+09:00 method:GET uri:/foo/bar/5xx status:504 size:15 apptime:60.000 time:2015-09-06T06:00:43+09:00 method:GET uri:/req status:200 size:15 apptime:- reqtime:0.321 $ cat example/logs/ltsv_access.log | alp ltsv +-------+-----+-----+-----+-----+-----+--------+-------------------+--------+--------+--------+--------+--------+--------+--------+--------+-----------+-----------+-----------+-----------+ | COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | +-------+-----+-----+-----+-----+-----+--------+-------------------+--------+--------+--------+--------+--------+--------+--------+--------+-----------+-----------+-----------+-----------+ | 1 | 0 | 1 | 0 | 0 | 0 | GET | /req | 0.321 | 0.321 | 0.321 | 0.321 | 0.321 | 0.321 | 0.321 | 0.000 | 15.000 | 15.000 | 15.000 | 15.000 | | 1 | 0 | 1 | 0 | 0 | 0 | POST | /hoge/piyo | 0.234 | 0.234 | 0.234 | 0.234 | 0.234 | 0.234 | 0.234 | 0.000 | 34.000 | 34.000 | 34.000 | 34.000 | | 1 | 0 | 1 | 0 | 0 | 0 | GET | /diary/entry/1234 | 0.135 | 0.135 | 0.135 | 0.135 | 0.135 | 0.135 | 0.135 | 0.000 | 15.000 | 15.000 | 15.000 | 15.000 | | 1 | 0 | 1 | 0 | 0 | 0 | GET | /diary/entry/5678 | 0.432 | 0.432 | 0.432 | 0.432 | 0.432 | 0.432 | 0.432 | 0.000 | 30.000 | 30.000 | 30.000 | 30.000 | | 1 | 0 | 0 | 0 | 0 | 1 | GET | /foo/bar/5xx | 60.000 | 60.000 | 60.000 | 60.000 | 60.000 | 60.000 | 60.000 | 0.000 | 15.000 | 15.000 | 15.000 | 15.000 | | 2 | 0 | 2 | 0 | 0 | 0 | GET | /foo/bar | 0.123 | 0.123 | 0.246 | 0.123 | 0.123 | 0.123 | 0.123 | 0.000 | 56.000 | 56.000 | 112.000 | 56.000 | | 5 | 0 | 5 | 0 | 0 | 0 | POST | /foo/bar | 0.057 | 0.234 | 0.548 | 0.110 | 0.234 | 0.234 | 0.234 | 0.065 | 12.000 | 34.000 | 126.000 | 25.200 | +-------+-----+-----+-----+-----+-----+--------+-------------------+--------+--------+--------+--------+--------+--------+--------+--------+-----------+-----------+-----------+-----------+
クエリを分析したい
MySQL には スロークエリログ というものがあります。
スロークエリログは設定した所要時間を超過したクエリの詳細が、クエリの実行順に記録されます。
pt-query-digest を使うことでスロークエリログを以下のような見やすい形式で表示することなどができます。
(pt は Percona Toolkit の意)
# Rank Query ID Response time Calls R/Call V/M Ite # ==== ============================ ============== ====== ====== ===== === # 1 0x25D034CF58223D3C0432925... 238.8947 29.9% 75 3.1853 0.07 SELECT chairs chair_locations # 2 0xDCA6B16A0FC65C799EB401C... 186.0540 23.3% 6542 0.0284 0.00 SELECT ride_statuses # 3 0x780A355BC10F6DC5B57B4BB... 98.5442 12.3% 2648 0.0372 0.00 SELECT ride_statuses # 4 0x5CAA8168B7B8D221E74FB97... 65.9032 8.2% 1832 0.0360 0.00 SELECT ride_statuses # 5 0xD6AD8A431BE7CA447BE67E7... 57.0073 7.1% 339 0.1682 0.01 SELECT chair_locations # 6 0x9C1BE9A08595D62A2089634... 54.1629 6.8% 1502 0.0361 0.00 SELECT ride_statuses # 7 0xD8DAD8AC6EDE2238F17AC39... 29.5091 3.7% 10806 0.0027 0.00 SELECT rides # 8 0xFFFCA4D67EA0A788813031B... 22.8184 2.9% 6637 0.0034 0.01 COMMIT # 9 0x49D4717E21912CD8B13961B... 16.9419 2.1% 10856 0.0016 0.00 SELECT chairs # MISC 0xMISC 30.3115 3.8% 142869 0.0002 0.0 <116 ITEMS>
まとめ
ウェブパフォーマンスチューニングはあまりやったことがありませんでした。
今回 ISUCON に参加してみていろいろな手法があるんだなぁと非常に学びになりました。
なお、本ブログでご紹介させていただいたツールは以下の書籍をベースとしております。
非常に勉強になる書籍ですので、ご興味ある方はお手に取ってみてください。
*1:本ブログを執筆している時期にバズっている ROSÉ & Bruno Mars の曲