前回でベンチマークの実行方法を知ることができました。 今回はアプリケーションの状態を計測する手順をまとめてみます。
ログを調べる
思いついたのは以下2点
slow query に関しては一つ一つの query 自体は時間がかからなくても、たくさん呼ばれている場合があったりするのでそこまで参考にならないかも。一応設定しておきます。
[mysqld] general_log=1 general_log_file=/var/log/mysql/query.log
吐き出した query を数えてみました
# wc -l query.log 37278 query.log
アクセスログからリクエスト状況を調べてみましょう。ログはこちらにあります /var/log/nginx/access.log
sfujiwara 氏のブログによると https://github.com/tkuchiki/alp を使ったとあるので試してみます。
インストール手順は下記の通り
$ cd /tmp $ curl -sLO https://github.com/tkuchiki/alp/releases/download/v0.2.4/alp_linux_amd64.zip $ unzip alp_linux_amd64.zip $ sudo mv alp /usr/local/bin/ $ alp --version 0.2.4
nginx のアクセスログを tlsv に修正してから再度 bench を実行します
cd ${HOME}/isucon5-qualify/bench
jq '.[0]' < ../webapp/script/testsets/testsets.json | gradle run -Pargs="net.isucon.isucon5q.bench.scenario.Isucon5Qualification 127.0.0.1"
access log を収集したら以下を実行すればOK
sudo alp -f /var/log/nginx/access.log
そうすると以下のように処理に時間がかかっている場所がわかります。
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+------------+------------+--------+------------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+------------+------------+--------+------------------------------------+ | 49 | 0.065 | 7.641 | 132.533 | 2.705 | 0.000 | 2.070 | 6.832 | 2.040 | 16390.000 | 16728.000 | 610174.000 | 12452.531 | GET | / | | 14 | 0.493 | 6.455 | 42.497 | 3.035 | 0.493 | 2.795 | 5.378 | 1.831 | 12001.000 | 14829.000 | 191765.000 | 13697.500 | GET | /friends | | 22 | 0.001 | 5.653 | 19.803 | 0.900 | 0.001 | 0.022 | 4.508 | 1.529 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login
ちなみに nginx のアクセスログの行数は少ないです。
wc -l access.log 206 access.log
なんとなく MySQL のクエリが多すぎるのでなんとかしたほうがいいような気がしてきました。
OS の状態を調査
bench tool を実行しながら top コマンドを実行すると mysql がプロセスを使っていることがわかります。
このあたりの解説は下記ブログを参考にするといいと思います。 http://blog.yuuk.io/entry/linux-server-operations
iostat に関してはそもそも入ってなかったので install します。
$ iostat -dx 5 The program 'iostat' is currently not installed. To run 'iostat' please ask your administrator to install the package 'sysstat' isucon@isucon5q:~$ sudo apt install sysstat
まとめると私がつかいそうなコマンドは以下のとおり。状況に応じて y_uuki 氏のブログを参考にするとします。
% free -h % top -c % vmstat 2 % iostat -dx 5
とりあえず上記コマンドなどから以下が読めるようになっていればとりあえず良い気もします。
- 負荷が大きいプロセスはどれか
- swap が発生している
以下も分かるとより素敵
- I/O よりも CPU に負荷が多い状態かどうか
- CPU よりも I/O に負荷が多い状態かどうか
今の所アクセスログと OS の状態から Web への request は少ない(206)が MySQL の query は多い(37278), CPU は webapp のプロセスよりも MySQL のプロセスが頑張っているようで、swap は特に発生していない。メモリは 2.3G 程余っている。
ちなみにインスタンスを CPU2個, Memory 3.5GB で生成して、かつベンチツールを同一インスタンス上で実行しているので予めご了承ください。
データ構造を調べる
データ構造の概要を調べてみます。free コマンド見た限り2.3GBほど容量が余っているみたいなのでそれを踏まえて見てみましょう。
mysql> select table_schema, sum(data_length+index_length) /1024 /1024 /1024 as GB from information_schema.tables where table_schema = 'isucon5q'; +--------------+----------------+ | table_schema | GB | +--------------+----------------+ | isucon5q | 1.793060302734 | +--------------+----------------+ 1 row in set (0.00 sec) mysql> select table_name, engine, table_rows as tbl_rows, avg_row_length as rlen, floor((data_length+index_length)/1024/1024) as allMB, floor((data_length)/1024/1024) as dMB, floor((index_length)/1024/1024) as iMB from information_schema.tables where table_schema='isucon5q'; +------------+--------+----------+------+-------+------+------+ | table_name | engine | tbl_rows | rlen | allMB | dMB | iMB | +------------+--------+----------+------+-------+------+------+ | comments | InnoDB | 1501945 | 233 | 386 | 334 | 52 | | entries | InnoDB | 393817 | 3645 | 1393 | 1369 | 24 | | footprints | InnoDB | 499400 | 38 | 18 | 18 | 0 | | profiles | InnoDB | 5166 | 79 | 0 | 0 | 0 | | relations | InnoDB | 494120 | 39 | 35 | 18 | 16 | | salts | InnoDB | 5000 | 39 | 0 | 0 | 0 | | users | InnoDB | 4862 | 326 | 1 | 1 | 0 | +------------+--------+----------+------+-------+------+------+ 7 rows in set (0.00 sec)
あくまで概要なので実際のデータとは違いますのでその辺りだけご注意ください。users は実際は 5000行。
とりあえず上記テーブルで競技中に変更される事のない table があるならばキャッシュする事が可能かもしれない、という予感がします。この状態でソースコードを読み始める事ができるかどうかが勝負の分かれ目になるような気がしなくもないです。
まとめ
とりあえずソースコードを読まない状態でわかった事は以下のとおり
- access.log から
/へのリクエストが累計で132秒ほど時間を取られているのでここをなんとかできればいいのではないか？という予感がします。 - access.log と query.log の総数の違いからなんとなく query が多すぎる疑問がわきます。
- OS の状態から memory が2.3GB空いているのでこれを活用する事を検討します。
- MySQL の状態から一部の table を memory に移動できればよしなにできる予感がします。
こういった情報があったほうがソースコード読みやすくなるのでその辺りの役割分担を上手くできると有利になるんじゃないかなあ。
