| 関連記事 |
|---|
| 【ISUCON11予選】ISUCON に入門してみる（①セットアップ） |
| 【ISUCON11予選】ISUCON に入門してみる（②計測ツールの導入） |
| 【ISUCON11予選】ISUCON に入門してみる（③1296→15434） |
| 【ISUCON11予選】ISUCON に入門してみる（④15434→???） |
これは何？
「ISUCONに入門してみる」シリーズでは、筆者が ISUCON11 を解く際にやったことを備忘録的に時系列順に書き並べていきます。本記事（②計測ツールの導入）では、ボトルネックを探す際に有用な計測ツールを導入していきます。以降では、以下の順で説明していきます。
- top
- alp
- slow-query-log
（今後必要そうなツールが出てきたら、随時追記していきます。ここにない便利なツールなどあったら、コメントいただけると助かります
）
top
これは何？
以下のように、稼働中のシステムをリアルタイムかつ簡潔に監視することができるLinuxコマンドです。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2691 mysql 20 0 1716536 233124 19004 S 62.1 6.1 3:46.90 mysqld
5075 isucon 20 0 1526428 23688 8364 S 46.8 0.6 0:45.19 isucondition
5123 isucon 20 0 1809380 227204 11716 S 43.2 6.0 0:28.03 bench
446 www-data 20 0 18948 16124 5276 S 15.3 0.4 1:07.64 nginx
445 www-data 20 0 13492 10732 5280 S 11.0 0.3 0:34.75 nginx
413 syslog 20 0 224500 5460 3800 S 7.3 0.1 0:30.87 rsyslogd
162 root 19 -1 406128 261232 260008 R 7.0 6.9 0:47.71 systemd-jo
使い方
top コマンドを打った状態で、ベンチマーカーを実行します。自分は、ベンチマーカーを実行し始めてから数秒経ってからの top コマンドの結果をコピペするようにしていますが、もう少し効率良くやれる方法がないかなぁと思っています。
alp
これは何?
以下のように、各URI毎のリクエスト数やレスポンスまでの時間の平均・総和などの情報を取得することができるツールです。URIの部分を見るとわかるように、正規表現にマッチするURIごとに集計することができます。また、指定したキーでソート可能で、SUMでソートして上の方のURIに対応する処理の中から遅い部分を探していく、などということができます。
+--------+--------+-----+--------+-----+-------+-----+------------------------------+-------+-------+----------+-------+-------+
| COUNT | METHOD | 1XX | 2XX | 3XX | 4XX | 5XX | URI | MIN | MAX | SUM | AVG | P99 |
+--------+--------+-----+--------+-----+-------+-----+------------------------------+-------+-------+----------+-------+-------+
| 520954 | POST | 0 | 500905 | 0 | 20049 | 0 | /api/condition/[-a-z0-9]+ | 0.020 | 0.272 | 6255.801 | 0.012 | 0.104 |
| 15938 | GET | 0 | 13786 | 0 | 2152 | 0 | /api/condition/[-a-z0-9]+ | 0.004 | 1.012 | 1464.524 | 0.092 | 0.400 |
| 18189 | GET | 0 | 17228 | 0 | 961 | 0 | /api/isu/.+/icon | 0.004 | 3.004 | 1005.944 | 0.055 | 0.420 |
| 3111 | GET | 0 | 2602 | 0 | 509 | 0 | /api/isu | 0.004 | 3.004 | 725.548 | 0.233 | 1.004 |
| 666 | GET | 0 | 81 | 0 | 585 | 0 | /api/trend | 0.008 | 1.032 | 600.348 | 0.901 | 1.016 |
| 4900 | GET | 0 | 3384 | 0 | 1516 | 0 | /api/isu/.+/graph | 0.004 | 1.804 | 365.848 | 0.075 | 0.276 |
| 3568 | GET | 0 | 2652 | 0 | 916 | 0 | /api/isu/[-a-z0-9]+ | 0.000 | 1.544 | 138.336 | 0.039 | 0.260 |
| 3899 | POST | 0 | 1438 | 0 | 2461 | 0 | /api/auth | 0.004 | 3.004 | 77.472 | 0.020 | 0.120 |
| 440 | POST | 0 | 408 | 0 | 32 | 0 | /api/isu | 0.004 | 0.212 | 34.716 | 0.079 | 0.156 |
| 1257 | GET | 0 | 518 | 0 | 739 | 0 | /api/user/me | 0.000 | 1.000 | 15.744 | 0.013 | 0.136 |
| 771 | POST | 0 | 449 | 0 | 322 | 0 | /api/signout | 0.000 | 0.232 | 10.516 | 0.014 | 0.092 |
| 1365 | GET | 0 | 690 | 675 | 0 | 0 | /assets/vendor.ee7444dd.js | 0.000 | 0.040 | 4.600 | 0.003 | 0.020 |
| 1367 | GET | 0 | 692 | 675 | 0 | 0 | /assets/favicon.d0f5f504.svg | 0.000 | 0.032 | 4.144 | 0.003 | 0.020 |
| 1365 | GET | 0 | 690 | 675 | 0 | 0 | /assets/index.23dac98b.js | 0.000 | 0.032 | 3.784 | 0.003 | 0.020 |
| 1365 | GET | 0 | 690 | 675 | 0 | 0 | /assets/logo_white.svg | 0.004 | 0.032 | 3.676 | 0.003 | 0.024 |
| 4 | - | 0 | 0 | 0 | 4 | 0 | - | 3.522 | 3.522 | 3.630 | 0.907 | 3.522 |
| 1365 | GET | 0 | 690 | 675 | 0 | 0 | /assets/index.144d8ca8.css | 0.000 | 0.032 | 3.128 | 0.002 | 0.020 |
| 1023 | GET | 0 | 688 | 334 | 1 | 0 | / | 0.000 | 0.040 | 2.808 | 0.003 | 0.020 |
| 688 | GET | 0 | 682 | 6 | 0 | 0 | /assets/logo_orange.svg | 0.000 | 0.036 | 2.756 | 0.004 | 0.024 |
| 11 | POST | 0 | 11 | 0 | 0 | 0 | /initialize | 0.212 | 0.272 | 2.608 | 0.237 | 0.272 |
| 527 | GET | 0 | 527 | 0 | 0 | 0 | /?jwt=.+ | 0.000 | 0.036 | 1.724 | 0.003 | 0.024 |
| 325 | GET | 0 | 198 | 127 | 0 | 0 | /isu/........-....-.+ | 0.000 | 0.004 | 0.096 | 0.000 | 0.004 |
| 24 | GET | 0 | 8 | 16 | 0 | 0 | /register | 0.000 | 0.004 | 0.020 | 0.001 | 0.004 |
| 1 | GET | 0 | 0 | 0 | 1 | 0 | /sitemap.xml | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 |
| 2 | GET | 0 | 0 | 0 | 2 | 0 | /robots.txt | 0.000 | 0.012 | 0.012 | 0.006 | 0.012 |
| 2 | GET | 0 | 0 | 0 | 2 | 0 | /Tpa7 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1 | GET | 0 | 0 | 0 | 1 | 0 | /.well-known/security.txt | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1 | GET | 0 | 0 | 0 | 1 | 0 | /favicon.ico | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1 | GET | 0 | 0 | 0 | 1 | 0 | /.git/config | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1 | GET | 0 | 0 | 0 | 1 | 0 | /manager/html | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+--------+--------+-----+--------+-----+-------+-----+------------------------------+-------+-------+----------+-------+-------+
使い方
/etc/nginx/nginx.confのhttp{}内に、以下のような記述を追記します。
user www-data;
worker_processes auto;
error_log /var/log/nginx/error.log warn;
pid /run/nginx.pid;
events {
worker_connections 1024;
}
http {
include /etc/nginx/mime.types;
default_type application/octet-stream;
log_format main '$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for"';
+ log_format ltsv "time:$time_local"
+ "\thost:$remote_addr"
+ "\tforwardedfor:$http_x_forwarded_for"
+ "\treq:$request"
+ "\tstatus:$status"
+ "\tmethod:$request_method"
+ "\turi:$request_uri"
+ "\tsize:$body_bytes_sent"
+ "\treferer:$http_referer"
+ "\tua:$http_user_agent"
+ "\treqtime:$request_time"
+ "\tcache:$upstream_http_x_cache"
+ "\truntime:$upstream_http_x_runtime"
+ "\tapptime:$upstream_response_time"
+ "\tvhost:$host";
- access_log /var/log/nginx/access.log main;
+ access_log /var/log/nginx/access.log ltsv;
sendfile on;
#tcp_nopush on;
keepalive_timeout 65;
#gzip on;
include /etc/nginx/conf.d/*.conf;
include /etc/nginx/sites-enabled/*.conf;
}
nginx の設定ファイルを編集したら、nginx の再起動をする必要があることに注意してください。
$ sudo systemctl restart nginx
次に、alp をインストールします。
$ wget https://github.com/tkuchiki/alp/releases/download/v1.0.12/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip
$ sudo install ./alp /usr/local/bin
以下のコマンド（の最後の行の部分）でアクセスログを表示できます。表示したい項目等に応じてカスタマイズ可能なので、alp の使い方の詳細は以下の README を読んでください。
$ ALPSORT=sum
$ ALPM="/api/isu/.+/icon,/api/isu/.+/graph,/api/isu/.+/condition,/api/isu/[-a-z0-9]+,/api/condition/[-a-z0-9]+,/api/catalog/.+,/api/condition\?,/isu/........-....-.+,/?jwt=.+"
$ OUTFORMAT=count,method,1xx,2xx,3xx,4xx,5xx,uri,min,max,sum,avg,p99
$ sudo alp ltsv --file=/var/log/nginx/access.log --nosave-pos --pos /tmp/alp.pos --sort $(ALPSORT) --reverse -o $(OUTFORMAT) -m $(ALPM) -q
slow-query-log
これは何?
遅いSQLクエリを以下のように確認できます。
Count: 6303 Time=0.14s (861s) Lock=0.00s (0s) Rows_sent=1.0 (6272), Rows_examined=32720.2 (206235238), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N
Count: 10171 Time=0.03s (327s) Lock=0.00s (0s) Rows_sent=415.6 (4227240), Rows_examined=6893.5 (70113715), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
Count: 28579 Time=0.01s (207s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
COMMIT
Count: 3289 Time=0.02s (51s) Lock=0.00s (0s) Rows_sent=519.3 (1707892), Rows_examined=1326.1 (4361634), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' AND `timestamp` < 'S' ORDER BY `timestamp` DESC
Count: 10429 Time=0.00s (51s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (10429), isucon[isucon]@localhost
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S')
Count: 12588 Time=0.00s (38s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
#
Count: 962 Time=0.02s (15s) Lock=0.00s (0s) Rows_sent=797.6 (767268), Rows_examined=1594.3 (1533701), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` ASC
使い方
まず最初にmysqlに接続します。
$ mysql -u isucon -p isucon isucondition
接続できたら、slow query のログの出力先や、何秒以上を slow query とするか、などの設定を行なっていきます。 例えば以下のコマンドでは、0.001秒以上かかるクエリのログを/tmp/slow-query.logに出力するように設定されます。
set global slow_query_log_file = '/tmp/slow-query.log';
set global long_query_time = 0.001;
set global slow_query_log = ON;
上記設定後、ベンチマークを回すと、/tmp/slow-query.logにログが出力され、以下のコマンドで内容を確認することができます。
$ sudo mysqldumpslow -s t /tmp/slow-query.log
本番ではログ出力は止めた方がスコアが上がると思うので、再びmysqlに接続後、以下のコマンドでログ出力をオフにしましょう。
set global slow_query_log = OFF;