isuconへの備えとしてのツール紹介

この記事は、[Ateam Finergy Inc. × Ateam Wellness Inc. Advent Calendar 2023](https://qiita.com/advent-calendar/2023/ateam-finergy-wellness)の16日目の記事です。

# はじめに
isucon13本戦が終わり、毎年のことながら惨敗しました。毎年出場しているので、使用しているツールや当日までの準備についてまとめたいと思います。

# 使っているツール

## netdata

以下のようなコマンドを一つサーバ上のミドルウェエアがどれくらいリソースを使われているかを可視化してくれます。
> curl https://my-netdata.io/kickstart.sh > /tmp/netdata-kickstart.sh && sh /tmp/netdata-kickstart.sh

初手ではだいたいnetdataを見てどのミドルウェアが重そうかをみて分析対象を絞り込んでいます。
isuconは環境構築に時間をかけると施策ができず詰む事が多いので簡単に入り重宝しています。

https://github.com/netdata/netdata

## kataribe

Webサーバのログを分析し、パフォーマンスチューニングに最適な箇所を教えてくれます。
このツールを使うと、実行時間が長いURLを見つけ出し、問題の根源にアプローチが容易になります。類似のツールとしてalpもあるので両方試してみると良いと思います。

```
Top 20 Sort By Total
Count    Total     Mean   Stddev     Min   P50.0   P90.0   P95.0   P99.0     Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1859  189.976   0.1022   0.0928   0.000   0.079   0.238   0.301   0.393   0.451   1856    0    3    0    36362827          0      19560      78352  GET /api/livestream/<num>/livecomment
  417  163.116   0.3912   0.0715   0.031   0.391   0.483   0.505   0.549   0.568    414    0    3    0    25996941          0      62342      63962  GET /api/livestream/search?limit=<num> HTTP/1.1
 1894  148.732   0.0785   0.0722   0.000   0.059   0.185   0.229   0.296   0.367   1890    0    4    0    30888524          0      16308      73689  GET /api/livestream/<num>/reaction
    9  131.113  14.5681   6.6361   3.767  20.000  20.002  20.002  20.002  20.002      2    0    7    0         202          0         22        102  GET /api/livestream/<num>/statistics
 3056   55.011   0.0180   0.0037   0.001   0.017   0.023   0.025   0.031   0.063   3052    0    3    1     1435280          0        469        522  POST /api/register HTTP/1.1
  480   53.531   0.1115   0.0379   0.000   0.116   0.151   0.163   0.188   0.194    476    0    4    0      558700          0       1163       1463  POST /api/livestream/reservation HTTP/1.1
16959   41.771   0.0025   0.0020   0.000   0.002   0.005   0.006   0.008   0.085  16959    0    0    0  1053961091          0      62147     171855  GET /api/user/*/icon
 2418   27.442   0.0113   0.0053   0.001   0.010   0.018   0.022   0.031   0.049   2416    0    2    0     4671715         57       1932       2742  POST /api/livestream/<num>/livecomment
 3091   18.758   0.0061   0.0025   0.002   0.006   0.009   0.010   0.015   0.048   3070    0    0   21       54329         14         17        154  POST /api/icon HTTP/1.1
 1711   17.314   0.0101   0.0048   0.001   0.009   0.016   0.019   0.026   0.047   1710    0    1    0     3172042          0       1853       2206  POST /api/livestream/<num>/reaction
   29   16.957   0.5847   0.3369   0.083   0.729   0.909   0.970   1.036   1.036     29    0    0    0     3425241      97565     118111     148172  GET /api/livestream/search?tag=<tag>
 3060   11.453   0.0037   0.0034   0.001   0.003   0.006   0.007   0.010   0.122   3058    0    2    0         128          0          0         64  POST /api/login HTTP/1.1
 1012    4.780   0.0047   0.0045   0.000   0.003   0.010   0.013   0.022   0.039   1012    0    0    0      591147          3        584      22512  GET /api/livestream HTTP/1.1
   22    3.291   0.1496   0.0816   0.020   0.119   0.247   0.309   0.318   0.318     22    0    0    0        3038        133        138        154  GET /api/user/*/statistics
  528    1.996   0.0038   0.0057   0.001   0.003   0.007   0.009   0.026   0.097    526    0    0    2      120063          3        227      19229  GET /api/livestream/<num>/report
    1    1.781   1.7810   0.0000   1.781   1.781   1.781   1.781   1.781   1.781      1    0    0    0          27         27         27         27  POST /api/initialize HTTP/1.1
  474    1.475   0.0031   0.0021   0.000   0.003   0.005   0.007   0.010   0.020    474    0    0    0     2888154       6089       6093       6095  GET /api/tag HTTP/1.1
  393    1.099   0.0028   0.0017   0.000   0.002   0.005   0.006   0.008   0.011    393    0    0    0       22420          5         57        521  GET /api/livestream/<num>/ngwords
  261    0.938   0.0036   0.0023   0.001   0.003   0.007   0.008   0.011   0.016    261    0    0    0        6003         23         23         23  POST /api/livestream/<num>/moderate
  163    0.455   0.0028   0.0019   0.000   0.002   0.005   0.006   0.011   0.013    163    0    0    0           0          0          0          0  POST /api/livestream/<num>/enter
```

https://github.com/matsuu/kataribe

## fgprof

弊チームはGo言語でisuconに出場しています。
fgprofはフレームグラフで関数レベルの詳細を提供してくれます。
修正してみて効果があるかないかを特定することができます。

https://github.com/felixge/fgprof

## pt-query-digest

MySQLのslow query logを分析するこのツールは、データベースのボトルネックの分析に利用できます。
実行回数が多いクエリはN+1問題、実行時間が長いクエリはインデックス最適化とどんな施策をするかを明確に教えてくれます。

以下の例だと`SELECT tags`が実行回数が多くN+1が起きていそうなことが分かります。

```
# A software update is available:

# 29.4s user time, 220ms system time, 31.95M rss, 390.66G vsz
# Current date: Sun Dec 10 16:14:14 2023
# Hostname: mac2023.local
# Files: mysql-slow.log
# Overall: 781.46k total, 80 unique, 8.40k QPS, 2.17x concurrency ________
# Time range: 2023-12-10T07:07:32 to 2023-12-10T07:09:05
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           202s     1us   343ms   258us   626us     2ms    84us
# Lock time             1s       0    13ms     1us     1us    39us     1us
# Rows sent          1.11M       0   7.71k    1.49    4.96   28.85    0.99
# Rows examine      54.24M       0  12.94k   72.78    4.96  430.91    0.99
# Query size        36.91M       6   1.94M   49.53  118.34   2.34k   34.95

# Profile
# Rank Query ID                            Response time Calls  R/Call V/M
# ==== =================================== ============= ====== ====== ===
#    1 0xC499D81D570D361DB61FC43A94BB888A  56.4213 27.9%  30286 0.0019  0.00 SELECT livestreams reactions
#    2 0xFBC5564AE716EAE82F20BFB45F6C37E7  37.5346 18.6% 298079 0.0001  0.00 SELECT tags
#    3 0xA3401CA3ABCC04C3AB221DB8AD5CBF26  19.2948  9.5%    477 0.0405  0.01 UPDATE reservation_slots
#    4 0x38BC86A45F31C6B1EE324671506C898A  18.2439  9.0% 103380 0.0002  0.00 SELECT themes
#    5 0xF7144185D9A142A426A36DC55C1D2623  12.8711  6.4%  62610 0.0002  0.00 SELECT livestream_tags
#    6 0x7F9C0C0BA9473953B723EE16C08655F1  12.4450  6.2%    478 0.0260  0.01 SELECT reservation_slots
#    7 0xEA1E6309EEEFF9A6831AD2FB940FC23C  11.8314  5.9%  84679 0.0001  0.00 SELECT users
#    8 0xFD38427AE3D09E3883A680F7BAF95D3A   9.6100  4.8%  30282 0.0003  0.00 SELECT livestreams livecomments
#    9 0xD6032FE08E1FE706A928B8B7CBA06B85   3.8080  1.9%  28182 0.0001  0.00 SELECT livestreams
#   10 0x3F155F5E71EFF856F0CF7B8430DE8C23   2.8247  1.4%  20062 0.0001  0.01 SELECT users
#   11 0xAD0C28443E1E5CFAFF1569DBB4F7E63A   2.5225  1.2%   1733 0.0015  0.00 SELECT reactions
#   12 0x59F1B6DD8D9FEC059E55B3BFD624E8C3   1.7257  0.9%   4717 0.0004  0.00 SELECT reservation_slots
#   13 0x25A8CED3CE7A62689A139EB1D769F15E   1.2449  0.6%     22 0.0566  0.03 SELECT users livestreams reactions
#   14 0xD7DB5E8885E63F863372470C17D5DAC2   1.1666  0.6%     22 0.0530  0.02 SELECT users livestreams livecomments
#   15 0x9E2DA589A20EC24C34E11DDE0FBF5564   1.0004  0.5%  38063 0.0000  0.00 START
# MISC 0xMISC                               9.6072  4.8%  78385 0.0001   0.0 <65 ITEMS>

# Query 1: 409.27 QPS, 0.76x concurrency, ID 0xC499D81D570D361DB61FC43A94BB888A at byte 173565268
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-12-10T07:07:51 to 2023-12-10T07:09:05
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          3   30286
# Exec time     27     56s   230us    36ms     2ms     8ms     3ms   541us
# Lock time      5    66ms       0    10ms     2us     1us    67us     1us
# Rows sent      2  29.58k       1       1       1       1       0       1
# Rows examine  76  41.25M    1001   2.36k   1.39k   2.27k  467.19   1.46k
# Query size     7   2.91M      98     101  100.67   97.36       0   97.36
# String:
# Databases    isupipe
# Hosts        192.168.0.12
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms  ##############################
#  10ms  ###
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'livestreams'\G
#    SHOW CREATE TABLE `isupipe`.`livestreams`\G
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'reactions'\G
#    SHOW CREATE TABLE `isupipe`.`reactions`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) FROM livestreams l INNER JOIN reactions r ON l.id = r.livestream_id WHERE l.id = 1997\G

# Query 2: 4.52k QPS, 0.57x concurrency, ID 0xFBC5564AE716EAE82F20BFB45F6C37E7 at byte 186334071
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-12-10T07:07:59 to 2023-12-10T07:09:05
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         38  298079
# Exec time     18     38s    41us    16ms   125us   348us   284us    69us
# Lock time     37   441ms       0     5ms     1us     1us    28us     1us
# Rows sent     25 291.09k       1       1       1       1       0       1
# Rows examine   0 291.09k       1       1       1       1       0       1
# Query size    24   9.08M      31      33   31.93   31.70    0.45   31.70
# String:
# Databases    isupipe
# Hosts        192.168.0.12
# Users        isucon
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us  #########
#   1ms  #
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'tags'\G
#    SHOW CREATE TABLE `isupipe`.`tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM tags WHERE id = 62\G


```

https://docs.percona.com/percona-toolkit/pt-query-digest.html


# まとめ

紹介したツールは大体開始30分くらいですべて使えるようにしています。
導入が早ければ早いほど施策の実施時間が増えるので、自動化や練習によって手になじませると良いです。
最近このあたりをもう少し見直したいと考えているので、更におすすめがあればぜひ教えてほしいです。