
[@money166](https://twitter.com/money166)  
[@tatsuo48](https://github.com/tatsuo48)  
と一緒に今年も YO!HEYHEYHEY! として [ISUCON11](https://isucon.net/archives/55706291.html)に参加してきました。

今年も非常に楽しく参加できました。  
運営の皆さま、ありがとうございました！

## 結果
予選の結果は参考スコアで 47258 で全参加チーム598チーム中80位でした。  
[ISUCON11 オンライン予選 全てのチームのスコア（参考値） : ISUCON公式Blog](https://isucon.net/archives/56021246.html)

17:00以降の固定ダッシュボードで25位まで上昇していたので、これは！？と思ったのですが、壁は厚かったです。

<img src="/images/posts/isucon11/dashboard-last-score.jpg" alt="ダッシュボードでの最終スコア" width="1798" height="330" />

5年間毎年参加して、ずっと初期実装のスコアから大きく点数を上げられなかったので、6年目の今年は非常に大きな進歩があって嬉しかったです！

## テーマ
今年のアプリケーションのテーマは自分が持っている椅子の状態を監視するWebサービスでした。  
登録している椅子が定期的にサーバーに自身の状態を送信して、ユーザーはその状態をWebサービスで確認することで椅子の状態を管理できます。

いわゆる IoT です。

サービスの説明からも予想できる通り、今年は常に大量のデーターがサーバーに送信されDBに書き込まれ続けるので、DBのCPU負荷が常に高い状態でした。（ベンチ回したら最初からCPU負荷が150%とか出ていました）  
このDB負荷をどう処理するかが問題のキーとなっている印象でした。

## 振り返り
### 良かった点
- 今年はZoomで繋いでオンラインで作業をしており、画面共有などでチームでの作業がやりやすかった
- ベンチ回して効果が無い場合は前の状態に戻す徹底できたので、アプリケーションが動かなくなる問題が発生しなかった
- 基本は2人以上のペアプロを意識して進めたので、それによって気付ける事が多かった
	- ボトルネックの原因とか
- しっかりマニュアルを読み込んでスコア計算の仕様を意識して対応方針が決められた
- Miroでタスク管理して誰が何をやっているか把握しながら進められた

### 反省点
- Go言語をあまり勉強しておらずアプリケーションの修正に時間がかかった
- 勉強不足で New Relic での DB の監視を導入できなかった
- 全体的にスコア上がってから次の一手が思いつかず頭打ちになった

## チームでやったこと
- インフラ環境の初期構築をしてサーバーを立ち上げ
- 当日マニュアルやアプリケーションマニュアルを熟読
- アプリケーションを実際に動かして機能一覧を把握
- 競技用サーバーへのデプロイ環境の整備
- アプリケーションに New Relic のエージェントを追加
- DBのスキーマ情報を整理
- New Relic のダッシュボードでHTTPリクエストを確認してボトルネックを調査して対応方針を検討
- **==== ↓ ここからボトルネック対応 ====**
- サーバー構成を サーバー1:DB, サーバー2: アプリケーション に変更: 1000 => 8000
- isu テーブルで画像カラムをクエリしない修正を追加: スコア変わらず
- 椅子の状態のデータ送信をサーバー3台に分散: スコア変わらず
- 椅子の状態のDBへの書き込みをバルクインサートに変更: 上手く実装できず
- サーバー構成を サーバー1: DB, サーバー2: アプリケーション, サーバー3: 椅子状態のデータ受信 に変更: スコア変わらず
- 対応方針を再検討
- isu_condition の jia_isu_uuid にインデックスを追加: 8000 => 25000
- isu_condition の timestamp にインデックスを追加: 25000 => 28000
- データを捨てる割合を 90% => 75% に変更: 28000 => 33000
- 画像をクライアントにキャッシュさせる: 対応が上手くできなかった
- Nginx や アプリケーション のデバッグログを停止: 33000 => 35000 （影響あった気がする）
- /api/trend のリクエストもサーバー3に流すように変更: 35000 => 47000

### アプリケーションを実際に動かして機能一覧を把握
今回は例年と比べてアプリケーション規模が小さい？印象だったので、全体の把握がスムーズにできた。  
オープニングでの事前のサービス紹介で概要が掴めたのも大きかった。

### New Relic の Go エージェントの追加
次のドキュメントを参考に echo のミドルウェアとしてエージェントを追加した
- [Go向けNew Relicのインストール \| New Relic Documentation](https://docs.newrelic.com/jp/docs/agents/go-agent/installation/install-new-relic-go/)
- [Goエージェントの互換性と要件 \| New Relic Documentation](https://docs.newrelic.com/jp/docs/agents/go-agent/get-started/go-agent-compatibility-requirements/)

### HTTPリクエストを確認してボトルネックを調査して対応方針を検討
リクエストの大半は `POST /api/condition/:jia_isu_uuid` が占めていた。  
これは椅子の状態を受け取ってDBに書き込むAPIエンドポイントなので、当初の想定通り。

`GET /api/trend` が最大で60sec、平均しても20secのレスポンス時間となっていた。

上記2つのAPIエンドポイントに絞って、実装の詳細を確認しながらボトルネックの調査と対応方針を決めた。

### サーバー構成を サーバー1:DB, サーバー2: アプリケーション に変更: 1000 => 8000
DBのCPU負荷が150~180%とかなり高かったので、サーバー1をDB専用にして、リクエストをサーバー２で捌くように変更した。

7000点ほどスコアが上昇

### isu テーブルで画像カラムをクエリしない
isu_conditions テーブルには画像がバイナリで含まれていた。  
/api/trend では `SELECT * FROM isu` と未使用にも関わらず画像カラムも取得していたので、これで読み込みに時間がかかってレスポンス時間に影響していると予測して、必要なカラムだけをクエリするようにしたが、大きな変化は無かった。

```go
- "SELECT * FROM `isu` WHERE `character` = ?",
+ "SELECT `id`, `jia_isu_uuid` FROM `isu` WHERE `character` = ?",
```

### 椅子の状態のデータ送信をサーバー3台に分散
椅子状態のデータ送信が大量にリクエストされているので、これにより他のリクエストが待機状態で捌かれていないのでは？と思い3台にリクエストを分散してみた。  
あまり効果は無かった。

```go
- postIsuConditionTargetBaseURL string // JIAへのactivate時に登録する，ISUがconditionを送る先のURL
+ postIsuConditionTargetBaseURLs []string // JIAへのactivate時に登録する，ISUがconditionを送る先のURL

=======

- postIsuConditionTargetBaseURL = os.Getenv("POST_ISUCONDITION_TARGET_BASE_URL")
- if postIsuConditionTargetBaseURL == "" {
-	e.Logger.Fatalf("missing: POST_ISUCONDITION_TARGET_BASE_URL")
	return
}

+ postIsuConditionTargetBaseURLs = strings.Split(os.Getenv("POST_ISUCONDITION_TARGET_BASE_URLS"), ",")
+ if postIsuConditionTargetBaseURLs == nil {
+	e.Logger.Fatalf("missing: POST_ISUCONDITION_TARGET_BASE_URLS")
		return
}
```

### サーバー構成を変更
引き続き椅子状態のHTTPリクエストにより /api/trend などの他のリクエストが待ち状態になっていると推測して、POST /api/condition/:jia_isu_uuid へのリクエストだけを全て別サーバーで処理するように変更した。

スコアへの影響は無かったが、CPU負荷は分散された。

- サーバー1: DB
- サーバー2: アプリケーション
- サーバー3: 椅子状態のデータ受信とDBへの書き込み

### 対応方針を再検討
最初に目星をつけた対応を色々と試したが結果が出なかったので、改めて対応方針を検討した。

ベンチマークをログを見ていると「タイムアウトが多く発生しているため、サービスの評判が下がりこれ以上ユーザーは増えません」という怪しげなログを発見。  
ベンチマーク実行後の `user` テーブルを見てみると、ユーザー数が13人しか登録されていなかった。

改めて当日マニュアルのスコア計算の仕様を読み直すと  
> スコアはユーザーがISUのコンディションやスコアを確認すると加点されます。

との事なので、

新規ユーザーは最初にTOPページにアクセスする  
=> TOPページのトレンド情報がリクエストされる  
=> リクエストがタイムアウトしてユーザーが離脱  
=> ユーザー登録されずにユーザーが増えない  
=> スコアが伸びない  

タイムアウトが大量に発生  
=> ユーザーが加点となるリクエストができない  
=> スコアが増えない  

という2つのシナリオを仮定して、スコアを伸ばすためにはユーザーを増やす必要がありそうと判断

そのためには、ログにも出ているタイムアウトを改善する必要があり、タイムアウトとなっているリクエストは明らかに `/api/trend` だったので、このエンドポイントを改善する方針でボトルネック調査を継続

### isu_condition の jia_isu_uuid にインデックスを追加: スコア改善: 8000 => 25000
改めて `/api/trend` のボトルネックを考えていたら `isu_condition` への書き込みが常に発生しているので、テーブルロックが発生して `isu_condition` の読み込みが待ち状態になっている影響で時間がかかっているのでは？と推測

実際に調べてみたら
> InnoDBは行ロックだが、ユニーク制約 or インデックスが張られていないカラムで検索した場合はテーブルロックになってしまう。  

[InnoDBで行ロック/テーブルロックになる条件を調べた \#mysqlcasual Advent Calendar 2013 \- あおうさ＠日記](https://bluerabbit.hatenablog.com/entry/2013/12/07/075759)

という情報を発見  

`/api/trend` は以下のクエリでデータを読み込んでおり、テーブルロックによるりデータの読み込みが待ち状態になっている可能性がありそうだったので、検索カラムにインデックスを追加した。

```sql
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC
```

```sql
+ CREATE INDEX jia_isucon_uuid_index ON isu_condition(jia_isu_uuid);
```

この修正 `/api/trend` のレスポンス時間が改善されて、スコアが大幅に上昇した。

### isu_condition の timestamp にインデックスを追加: 25000 => 28000
同様の理由で `isu_condition` の `timestamp` にもインデックを追加して、スコアが上昇

```sql
+ CREATE INDEX jia_isucon_uuid_timestamp_index ON isu_condition(jia_isu_uuid, timestamp);
```

### データを捨てる割合を 90% => 75% に変更: 28000 => 33000
初期実装では受信した椅子の状態の90%を捨てる実装になっていた。

```go
// TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき
dropProbability := 0.9
if rand.Float64() <= dropProbability {
	c.Logger().Warnf("drop post isu condition request")
	return c.NoContent(http.StatusAccepted)
}
```

> ISU のコンディション確認（GET /api/condition/:jia_isu_uuid）で、ユーザが前回確認したコンディションより新しいコンディションを確認した際に加点

スコア計算では、ユーザーが新しい状態を確認した時に加点の対象となるため、椅子の状態を捨てていると加点の機会を大きく損なってしまうので、ここの割合を75%に減少させる調整を実施して、スコアが上昇した。

```go
- dropProbability := 0.9
+ dropProbability := 0.75
```

### 画像をクライアントにキャッシュさせる
ここまでの改善で新たに椅子の画像を取得する `GET /api/isu/:jia_isu_uuid/icon` が新たなボトルネックのエンドポイントとして浮上してきた。

ここは明らかにDBにバイナリで画像を保存している事による影響だと考えて、クライアント側に画像をキャッシュさせる対応を試みたが、上手く対応できなかった。

### ログの停止: 33000 => 35000
競技も終盤になっていたので、Nignx や アプリケーションのデバッグログ出力を停止した。  
ちゃんと覚えてないが、スコアが僅かに改善した気がする。

### トレンドのリクエストもサーバー3に流すように変更: 35000 => 47000
全体のCPU負荷を見ていて、サーバー2: アプリケーション のCPU負荷が高く、 サーバー3: 椅子の状態受信 のCPU負荷が低かったので、負荷を分散するために思い切って `/api/trend` のリクエストをサーバー3へリダイレクトする対応を追加

これが見事に成功してCPU負荷が分散されて、スコアが大幅に上昇した。

### 競技終了
17:00で更新が停止された状態でのダッシュボード上での最終スコア  

<img src="/images/posts/isucon11/dashboard-last-score.jpg" alt="ダッシュボードでの最終スコア" width="1798" height="330" />


ISUCON11予選に参加して自己ベストを更新しました


ISUCON10に向けた復習として [ISUCON 夏季講習 2017](http://isucon.net/archives/50648750.html) をやりました。ボトルネック発見のための基本的なデータ収集の部分だけまとめています。

## 環境構築
仮想マシンとしてVirtualBoxを用いて、問題は [isucon7の予選問題](https://github.com/matsuu/vagrant-isucon/tree/master/isucon7-qualifier) を利用します。

```shell
# プライベートネットワークのIPアドレスを指定
$ vi Vagrantfile
   # Create a private network, which allows host-only access to the machine
   # using a specific IP.
-  config.vm.network "private_network", ip: "192.168.33.10"
+  config.vm.network "private_network", ip: "192.168.33.10"

# 仮想環境を構築
$ g clone https://github.com/matsuu/vagrant-isucon.git
$ cd vagrant-isucon/icuon7-qualifier
$ vagrant up
$ vagrant halt # 初回起動だとimageの仮想マシンでアプリケーションが起動しなかった
$ vagrant up 
```

## ベンチマークを実行

最初にアプリケーションサーバーの仮想マシンに割り当てられたIPアドレスを確認する。

```shell
$ vagrant ssh image
$ ifconfig 
...
enp0s9    Link encap:Ethernet  HWaddr 08:00:27:4a:09:63
          inet addr:172.28.128.8  Bcast:172.28.128.255  Mask:255.255.255.0
          inet6 addr: fe80::a00:27ff:fe4a:963/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:11 errors:0 dropped:0 overruns:0 frame:0
          TX packets:10 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:4968 (4.9 KB)  TX bytes:1332 (1.3 KB)
...          
```

確認したIPアドレスに対してベンチを実行する。

```shell
$ vagrant ssh bench
$ cd /home/isucon/isubata/bench
$ bin/bench -remotes 172.28.128.8 # imageマシンのIPアドレスを指定
[isu7q-bench] 2020/07/26 09:33:46.171614 dataset.go:37: datapath ./data
[isu7q-bench] 2020/07/26 09:33:47.656776 bench.go:472: Remotes [172.28.128.8]
[isu7q-bench] 2020/07/26 09:33:47.656810 bench.go:346: State.Init()
[isu7q-bench] 2020/07/26 09:33:47.663825 bench.go:348: State.Init() Done
[isu7q-bench] 2020/07/26 09:33:47.663853 bench.go:350: requestInitialize()
[isu7q-bench] 2020/07/26 09:33:47.756337 bench.go:358: requestInitialize() Done
[isu7q-bench] 2020/07/26 09:33:47.756358 bench.go:363: preTest()
[isu7q-bench] 2020/07/26 09:33:58.556061 bench.go:371: preTest() Done
[isu7q-bench] 2020/07/26 09:33:58.556186 bench.go:380: validationMain()
[isu7q-bench] 2020/07/26 09:33:59.560581 bench.go:267: Increase Load Level.
[isu7q-bench] 2020/07/26 09:34:00.557278 bench.go:263: Cannot increase Load Level. Reason: SlowPath /message Before 11.790899ms
[isu7q-bench] 2020/07/26 09:34:01.557413 bench.go:263: Cannot increase Load Level. Reason: SlowPath /profile/yamaoka_shinsuke Before 415.740187ms
[isu7q-bench] 2020/07/26 09:34:02.557313 bench.go:260: Cannot increase Load Level. Reason: RecentErr 2020-07-26 09:34:02.336753948 +0000 UTC m=+16.304791155 リクエストがタイムアウトしました (POST /message ) Before 220.553901ms
```

## アプリケーションの動作確認

ブラウザで [http://192.168.33.10](http://192.168.33.10) にアクセスすれば動作確認ができます。ベンチマーク実行前の場合はデータが無く動作確認がやり辛いので、ベンチマークを先に実行しておく事をオススメします。アカウントは適当に新規登録してログインしてください。

## 仮想環境のMySQLに接続する

sshの設定を確認する。MySQLの接続情報は [ansibleの設定ファイル](https://github.com/matsuu/ansible-isucon/blob/master/isucon7-qualifier/roles/mysql/tasks/main.yml) を参照しました。

```shell
$ vagrant ssh-config image
Host image
  HostName 127.0.0.1
  User vagrant
  Port 2222
  UserKnownHostsFile /dev/null
  StrictHostKeyChecking no
  PasswordAuthentication no
  IdentityFile /Users/tomohiro/workspace/isucon/vagrant-isucon/isucon7-qualifier/.vagrant/machines/image/virtualbox/private_key
  IdentitiesOnly yes
  LogLevel FATAL
```

MySQLクライアントで次の設定でMySQLに接続します。

```
MySQLホスト: 127.0.0.1
ユーザー名: isucon
パスワード: isucon
データベース: isubata
SSHホスト: 192.168.33.10
SSHユーザー: vagrant
秘密鍵: ~/isucon7-qualifier/.vagrant/machines/image/virtualbox/private_key
```

## 実装言語を変更する
ISUCONでは複数の言語から自分たちが好きな言語を利用できます。ここでは、JavaScript(Node.js)に実装言語を変更します。参考実装の切り替えは、[ISUCON7 予選マニュアル](https://gist.github.com/941/8c64842b71995a2d448315e2594f62c2)を参照しました。

```shell
# アプリケーションサーバーで作業
$ vagrant ssh image

# サービスの一覧を確認
$ ls -l /etc/systemd/system/ | grep isubata
-rw-r--r-- 1 root root  331 Jul 26 09:01 isubata.golang.service
-rw-r--r-- 1 root root  363 Jul 26 09:01 isubata.nodejs.service
-rw-r--r-- 1 root root  367 Jul 26 09:01 isubata.perl.service
-rw-r--r-- 1 root root  386 Jul 26 09:01 isubata.php.service
-rw-r--r-- 1 root root  386 Jul 26 09:01 isubata.python.service
-rw-r--r-- 1 root root  382 Jul 26 09:01 isubata.ruby.service

# 実行中の参考実装を確認
vagrant@ubuntu-xenial:~$ systemctl list-unit-files --type=service | grep isubata
isubata.golang.service                     disabled
isubata.nodejs.service                     disabled
isubata.perl.service                       disabled
isubata.php.service                        disabled
isubata.python.service                     enabled
isubata.ruby.service                       disabled

# 参考実装の言語を変更
$ sudo systemctl stop isubata.python.service
$ sudo systemctl disable isubata.python.service
$ sudo systemctl start isubata.nodejs.service
$ sudo systemctl enable isubata.nodejs.service
```

起動を確認する。

```shell
$ service isubata.nodejs status
● isubata.nodejs.service - isucon7 qualifier main application in nodejs
   Loaded: loaded (/etc/systemd/system/isubata.nodejs.service; enabled; vendor preset: enabled)
   Active: active (running) since Sun 2020-07-26 12:24:52 UTC; 2min 59s ago
 Main PID: 5901 (node)
   CGroup: /system.slice/isubata.nodejs.service
           └─5901 /home/isucon/local/node/bin/node /home/isucon/isubata/webapp/nodejs
```

## ボトルネック計測

### 監視ツールのインストール
以下のツールから好きなのを選んでインストールします。

* htop
* dstat
* glances
* netdata

```shell
$ sudo apt install htop
$ sudo apt isntall dstat
$ sudo apt install glances
$ bash <(curl -Ss https://my-netdata.io/kickstart-static64.sh)
```

### 監視ツール実行の様子

ベンチマーク実行中のCPUやメモリなどのリソース状況を可視化できます。

#### glances

```shell
$ glances
ubuntu-xenial (Ubuntu 16.04 64bit / Linux 4.4.0-184-generic)                                                     Uptime: 3:06:11

CPU      99.7%  nice:     0.2%             LOAD    2-core             MEM     53.6%  active:    1.51G             SWAP      0.0%
user:    74.7%  irq:      0.0%             1 min:    7.61             total:  1.95G  inactive:   262M             total:       0
system:  23.1%  iowait:   0.2%             5 min:    6.71             used:   1.05G  buffers:   54.1M             used:        0
idle:     0.3%  steal:    0.0%             15 min:   3.86             free:    928M  cached:     779M             free:        0

NETWORK     Rx/s   Tx/s   TASKS 123 (228 thr), 1 run, 122 slp, 0 oth sorted automatically by cpu_percent, flat view
enp0s3       6Kb    6Kb
enp0s8        0b     0b     CPU%  MEM%  VIRT   RES   PID USER        NI S    TIME+ IOR/s IOW/s Command
enp0s9     133Kb 40.1Mb    179.3  20.1 1.52G  402M  1225 mysql        0 S 20:15.77     0     0 /usr/sbin/mysqld
lo         550Mb  550Mb     12.8  22.8 1.53G  456M  5901 isucon       0 S  1:12.94     0     0 /home/isucon/local/node/bin/node
                             2.9   1.4 89.8M 27.6M  6345 vagrant      0 R  0:00.83     0     0 /usr/bin/python3 /usr/bin/glances
DISK I/O     R/s    W/s
sda1           0   359K
sdb            0      0   Warning or critical alerts (lasts 4 entries)
                          2020-07-26 12:38:07 (ongoing) - CPU_SYSTEM (99.7)
FILE SYS    Used  Total   2020-07-26 12:37:55 (ongoing) - CPU_USER (74.8)
/ (sda1)   3.68G  9.63G   2020-07-26 12:37:51 (0:00:04) - WARNING on CPU_SYSTEM (81.2)
2020-07-26 12:38:07       2020-07-26 12:37:36 (ongoing) - LOAD (1.9)
```

#### netdata
ブラウザで http://<imageマシンのIPアドレス>:19999 にアクセスします。今回の場合は、http://172.28.128.8:19999/ にアクセスすれば確認ができます。

<img src="/images/posts/isucon-summer-course-2017/netdata.png" alt="netdata" width="1427" height="765" />

## alpでアクセスログを解析

### alpをインストール

```shell
$ wget https://github.com/tkuchiki/alp/releases/download/v1.0.3/alp_linux_amd64.zip
$ sudo apt install unzip
$ unzip alp_linux_amd64.zip
$ sudo install ./alp /usr/local/bin
```

### nginxにalp用の出力を追加

```shell
$ sudo vi /etc/nginx/nginx.conf
http {
        ...

        ##
        # Logging Settings
        ##

        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 ltsv;
        error_log /var/log/nginx/error.log;

$ sudo rm /var/log/nginx/access.log && sudo systemctl reload nginx
```

### alpでアクセスログを解析
ベンチマークを実行後にalpでアクセスログを集計して計測結果を見てみます。処理時間の合計で降順ソートした結果を見てみると、 `/message` と `/fetch` へのアクセスに時間を要しています。また、 `/icons` 配下の画像のレスポンスも気になりますね。  
ここで修正した気持ちをグッと抑えて次はMySQLのクエリ解析を実施していきます。

```shell
$ alp ltsv -r --sort sum --file /var/log/nginx/access.log
+-------+-----+-----+-----+-----+-----+--------+------------------------------------------------------+-------+--------+---------+--------+--------+--------+--------+--------+------------+------------+--------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD |                         URI                          |  MIN  |  MAX   |   SUM   |  AVG   |   P1   |  P50   |  P99   | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+-----+-----+-----+-----+--------+------------------------------------------------------+-------+--------+---------+--------+--------+--------+--------+--------+------------+------------+--------------+------------+
|    90 |   0 |  60 |   0 |  30 |   0 | GET    | /message                                             | 0.002 | 10.216 | 397.354 |  4.415 |  0.003 |  3.236 | 10.084 |  4.455 |      5.000 |  52648.000 |  1261915.000 |  14021.278 |
|    44 |   0 |   7 |   0 |  37 |   0 | GET    | /fetch                                               | 0.002 | 10.085 | 350.770 |  7.972 |  0.002 | 10.001 |  0.002 |  3.769 |      0.000 |   3098.000 |    21687.000 |    492.886 |
|    18 |   0 |   5 |   0 |  13 |   0 | GET    | /icons/7598595abd317f5ae637300a27f95e3c700376a7.png  | 0.820 | 10.028 | 143.519 |  7.973 |  0.820 | 10.002 |  7.973 |  2.878 |      0.000 | 437319.000 |  2186261.000 | 121458.944 |
|    17 |   0 |   6 |   0 |  11 |   0 | GET    | /icons/c434098fec37fd0d2c1e646d104220f6ffabbea7.png  | 0.132 | 10.009 | 137.344 |  8.079 |  0.132 | 10.005 |  7.973 |  2.903 |      0.000 | 103218.000 |   619208.000 |  36424.000 |
|    17 |   0 |   5 |   0 |  12 |   0 | GET    | /icons/61463cd868570a29cc1b74232000e84d3276e315.png  | 0.228 | 10.130 | 136.311 |  8.018 |  0.228 | 10.015 | 10.000 |  3.084 |      0.000 | 381286.000 |  1905666.000 | 112098.000 |
|    18 |   0 |   6 |   0 |  12 |   0 | GET    | /icons/5e981ef46ec0f47bdc2f188673325b85078f5235.png  | 0.144 | 10.043 | 135.467 |  7.526 |  0.144 | 10.000 |  9.019 |  2.927 |      0.000 | 769314.000 |  4613375.000 | 256298.611 |
|    17 |   0 |   7 |   0 |  10 |   0 | GET    | /icons/158fa9df919970ac8bc3bc2724ed5b02fe30968d.png  | 0.140 | 10.047 | 125.555 |  7.386 |  0.140 | 10.047 |  9.999 |  3.542 |      0.000 | 115188.000 |   806284.000 |  47428.471 |
|    14 |   0 |   3 |   0 |  11 |   0 | GET    | /icons/0614f0cea1b70fb71b4c3b88545a42327157a41e.jpg  | 4.715 | 10.138 | 125.212 |  8.944 |  4.958 | 10.021 | 10.047 |  2.104 |      0.000 | 559681.000 |  1678461.000 | 119890.071 |
|    14 |   0 |   5 |   0 |   9 |   0 | GET    | /icons/ba2d2384f825a83862f3b61302468b2e07f0a0f7.png  | 3.736 | 10.026 | 119.459 |  8.533 |  3.736 | 10.026 | 10.025 |  2.271 |      0.000 | 294773.000 |  1473311.000 | 105236.500 |
|    14 |   0 |   4 |   0 |  10 |   0 | GET    | /icons/65ea5a70b1fcf8f5f816b01b87f2aca2251315b0.png  | 2.330 | 10.039 | 117.397 |  8.386 |  2.330 | 10.039 |  9.191 |  2.362 |      0.000 | 299543.000 |  1197726.000 |  85551.857 |
```

## MySQLのクエリ解析

スロークエリログの出力設定を追加して、改めてベンチマークを実行してログを出力します。設定が正常に完了していれば、 `/var/log/mysql/mysql-slow.log` が出力されます。

```shell
$ sudo vi /etc/mysql/mysql.conf.d/mysqld.cnf
[mysqld]
slow_query_log = 1
log_slow_queries = /var/log/mysql/mysql-slow.log
long_query_time = 0

$ sudo systemctl restart mysql
$ sudo sytemtctl restart isubata.nodejs.service
```

### pt-query-digestのインストール
[pt-query-digest](https://www.percona.com/doc/percona-toolkit/LATEST/pt-query-digest.html) はMySQLのクエリログを集計するサポートツールです。

apt 経由でインストールするとパッケージのバージョンが古くバグが存在するので注意してください。  
[mariadb \- Pipeline process 5 $iteration$ caused an error: Redundant argument in sprintf at /usr/bin/pt\-query\-digest line 2556 \- Stack Overflow](https://stackoverflow.com/questions/38245395/pipeline-process-5-iteration-caused-an-error-redundant-argument-in-sprintf-at)

```shell
$ wget percona.com/get/percona-toolkit.tar.gz
$ tar xf percona-toolkit.tar.gz
$ cd percona-toolkit-3.2.0
$ perl Makefile.PL && make && sudo make install
$ sudo pt-query-digest --help
```

### スロークエリのログを見る

`pt-query-digest` でスロークエリログを見ていきます。

`SELECT * FROM image WHERE name = 'c434098fec37fd0d2c1e646d104220f6ffabbea7.png'\G` の実行が非常に時間が掛かってるっぽいですね。

```shell
$ sudo pt-query-digest --limit 10 /var/log/mysql/mysql-slow.log
# Profile
# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0x086EF2D69E0CA10C16A13978... 989.3391 93.5%   751 1.3174  0.09 SELECT image
#    2 0xB36405B8C0D2F0C74866C96B...  47.8231  4.5%  4012 0.0119  0.02 SELECT message
#    3 0x23E986FD32D530D2691DE3FA...   5.1509  0.5%  5077 0.0010  0.02 SELECT user
#    4 0xDF664753A9FC79D32CF41F09...   3.3720  0.3%  4000 0.0008  0.01 SELECT haveread
#    5 0xE8390778DC20D4CC04FE01C5...   2.6107  0.2% 11863 0.0002  0.01 ADMIN PING
#    6 0xEC97B582BC15F46A85799218...   2.4980  0.2%    89 0.0281  0.04 SELECT message
#    7 0x6CB85ADF7C155CAA91283C30...   2.0849  0.2%    49 0.0425  0.03 SELECT message
#    8 0xE1F097E42A11604ECA5E8124...   0.9187  0.1%    17 0.0540  0.02 INSERT image
#    9 0x34E80BA8226FB17741883793...   0.8466  0.1%   268 0.0032  0.07 SELECT user
#   10 0x98584C6216E0B67546AAE7D3...   0.7411  0.1%    89 0.0083  0.02 INSERT UPDATE haveread
# MISC 0xMISC                          2.2539  0.2%   838 0.0027   0.0 <16 ITEMS>

# Query 1: 11.92 QPS, 15.70x concurrency, ID 0x086EF2D69E0CA10C16A13978F3B7FCFA at byte 13991086
# Scores: V/M = 0.09
# Time range: 2020-08-02T06:11:47 to 2020-08-02T06:12:50
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          2     751
# Exec time     93    989s   121ms      3s      1s      2s   338ms      1s
# Lock time      6   154ms    23us    35ms   205us   287us     1ms    76us
# Rows sent     25  11.77k       1      25   16.04   22.53    3.89   15.25
# Rows examine   1 745.91k    1001    1018 1017.06 1012.63    8.50 1012.63
# Query size     0  57.81k      46      80   78.83   76.28    2.31   76.28
# String:
# Databases    isubata
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  #######
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isubata` LIKE 'image'\G
#    SHOW CREATE TABLE `isubata`.`image`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM image WHERE name = 'c434098fec37fd0d2c1e646d104220f6ffabbea7.png'\G

...
```

ISUCON 夏季講習 2017をやり、ボトルネック発見までの基本的なデータ収集の部分だけをまとめました。

ISUCONの夏季講習2017をやった

神奈川の田舎で働いてるフロントエンドエンジニアのブログ