関連記事
【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;

参考

[1] https://isucon.net/archives/56082639.html