kavo’s diary

備忘録

ISUCON8予選問題のアクセスログ解析

ISUCON

概要

ISUCON8予選問題の環境で、H2Oサーバのアクセスログをalpに噛ませ、URI単位で重い処理を特定するまでの手順。

計測環境

改善の第一歩は現状把握ということで、色々なものの計測環境を整えていきたい。

  • Webサーバ
  • アプリ
    • プロファイラ（関数単位、行単位）
  • サーバ・NWリソース
    • CPU、メモリ、ディスクIO、NW帯域、ポート...

Webサーバ

特に重要な情報源となるWebサーバのアクセスログ解析のやり方を整理する。今回WebサーバはH2O。 ログ解析ツールにalpを使う。

設定ファイルの特定

サービス一覧を確認、サービス名を特定。

$ systemctl list-units --type=service
~
  h2o.service  loaded active running H2O - the optimized HTTP/1, HTTP/2 server
~

h2o.serviceの状態を確認、設定ファイルのパスを特定。今は/etc/h2o/h2o.confらしい。

$ systemctl status h2o.service
~
           ├─4359 /usr/sbin/h2o -c /etc/h2o/h2o.conf
~

ログ設定の編集

/etc/h2o/h2o.confを編集、アクセスログフォーマットをalp仕様に変更する。

access-log:
  path: /var/log/h2o/access.log
  format: "time:%t\thost:%h\tua:\"%{User-agent}i\"\tstatus:%s\treq:%r\turi:%U\treqtime:%{duration}x\tsize:%b\tmethod:%m\t"

文法チェック。

$ h2o -m test -c /etc/h2o/h2o.conf
configuration OK

h2oをリスタートさせ、ブラウザとかcurlとかでアクセスしてみる。ログが編集した通りのフォーマットになって出てくればOK。

$ sudo systemctl restart h2o.service
$ sudo tail -f /var/log/h2o/access.log

alp実行

資材をダウンロード、展開、実行。表がカラじゃなきゃOK。

$ wget https://github.com/tkuchiki/alp/releases/download/v0.4.0/alp_linux_386.zip
$ unzip alp_linux_386.zip 
$ sudo ./alp -f /var/log/h2o/access.log --sum

ベンチ後にalp実行、ボトルネック処理を特定

ログをカラにしてベンチ実行、alpで解析。このときScoreは800だった。

下図のalp結果はURIごとの累計応答時間を降順に並べている。 全合計が314秒くらいなので、/api/users/*と/だけで2/3近く占めていることが分かった。

$ sudo truncate /var/log/h2o/access.log --size 0
$ bash /home/isucon/torb/bench/tools/do_bench.sh
$ sudo ./alp -f /var/log/h2o/access.log --sum -r --aggregates "/api/users/*"
+-------+--------+-----------------------------------------+---------+
| COUNT | METHOD |                   URI                   |   SUM   |
+-------+--------+-----------------------------------------+---------+
|    12 | GET    | /api/users/*                            | 133.308 |
|    24 | GET    | /                                       |  64.064 |
|     5 | GET    | /admin/                                 |  26.668 |
|    24 | POST   | /api/events/11/actions/reserve          |  22.741 |
|    16 | GET    | /api/events/10                          |  16.836 |
~

これで、とりあえず/api/users/*や/あたりから見ていくのが良さそうなことが分かった。

余談

VSCodeの拡張機能のRemote SSHが便利だった。 図のようにサーバのディレクトリをローカルのようにいじれる感覚が素晴らしい。 f:id:kavohtn:20190630033712p:plain