【初心者向け】ウェブパフォーマンスチューニングで役立つツールのご紹介

こんにちは。アプリケーションサービス部の渡辺です。

2024/12/8 に ISUCON14 に参加しました。
ISUCON への参加は初めてです。
事前勉強をしたのですが、初めて使うツールが色々ありましたのでご紹介させていただきます。

CPU の使用率を確認したい

top コマンド を使うことでCPU の使用率を確認できます。

top コマンドの出力例

メモリの使用率を確認したい

free コマンドを使うことでメモリの使用率を確認できます。

free コマンドの出力例

アクセスログを解析したい

alp を使うことで URL, HTTP メソッドごとにレスポンス回数、レスポンスタイム (最小、最大、平均、合計) などのいろいろな基準でアクセスログを分析することができます。

alp は Access Log Profiler の頭文字で読み方は [éɪélpíː] または [ælp] だそうです。
APT. ではありません *1

github.com

アクセスログを以下のように分析することができます。
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 の意)

docs.percona.com

# 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 に参加してみていろいろな手法があるんだなぁと非常に学びになりました。

なお、本ブログでご紹介させていただいたツールは以下の書籍をベースとしております。
非常に勉強になる書籍ですので、ご興味ある方はお手に取ってみてください。

gihyo.jp

*1:本ブログを執筆している時期にバズっている ROSÉ & Bruno Mars の曲

渡辺 隼人 (記事一覧)

アプリケーションサービス部 ディベロップメントサービス1課

音楽と猫ちゃんが好き