【ISUCON11予選】ISUCON に入門してみる（②計測ツールの導入）

|関連記事|
|:---|
|[【ISUCON11予選】ISUCON に入門してみる（①セットアップ）](https://qiita.com/zisui-sukitarou/items/81ccde650e5515787a60)|
|[【ISUCON11予選】ISUCON に入門してみる（②計測ツールの導入）](https://qiita.com/zisui-sukitarou/items/4514e0b6e7a3b481f9e5)|
|[【ISUCON11予選】ISUCON に入門してみる（③1296→15434）](https://qiita.com/zisui-sukitarou/items/22c78ec83366f388ab5f)|
|【ISUCON11予選】ISUCON に入門してみる（④15434→???）|

# これは何？
「ISUCONに入門してみる」シリーズでは、筆者が [ISUCON11](https://github.com/isucon/isucon11-qualify/blob/main/docs/manual.md) を解く際にやったことを備忘録的に時系列順に書き並べていきます。本記事（②計測ツールの導入）では、ボトルネックを探す際に有用な計測ツールを導入していきます。以降では、以下の順で説明していきます。
* top
* alp
* slow-query-log

（今後必要そうなツールが出てきたら、随時追記していきます。ここにない便利なツールなどあったら、コメントいただけると助かります:bow:）

https://github.com/zisui-sukitarou/isucon11-qualify/tree/main

# top
### これは何？
以下のように、稼働中のシステムをリアルタイムかつ簡潔に監視することができるLinuxコマンドです。

```bash
    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に対応する処理の中から遅い部分を探していく、などということができます。
```bash
+--------+--------+-----+--------+-----+-------+-----+------------------------------+-------+-------+----------+-------+-------+
| 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{}`内に、以下のような記述を追記します。
```diff_conf
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 の再起動をする必要があることに注意してください。
```bash
$ sudo systemctl restart nginx
```
次に、alp をインストールします。
```bash
$ 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 を読んでください。
```bash
$ 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
```
https://github.com/tkuchiki/alp

# slow-query-log
### これは何?
遅いSQLクエリを以下のように確認できます。
```bash
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に接続します。
```bash
$ mysql -u isucon -p isucon isucondition
```
接続できたら、slow query のログの出力先や、何秒以上を slow query とするか、などの設定を行なっていきます。 例えば以下のコマンドでは、0.001秒以上かかるクエリのログを`/tmp/slow-query.log`に出力するように設定されます。
```bash
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`にログが出力され、以下のコマンドで内容を確認することができます。
```bash
$ sudo mysqldumpslow -s t /tmp/slow-query.log
```
本番ではログ出力は止めた方がスコアが上がると思うので、再びmysqlに接続後、以下のコマンドでログ出力をオフにしましょう。
```bash
set global slow_query_log = OFF;
```

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