ISUCON本で初めてのパフォーマンスチューニングに挑戦してみた

## はじめに
**自己紹介**
未経験からWEB系エンジニアへの転職を目指している者です。現在はRuby on Railsを学習中です。

**この記事を書いたきっかけ**
　現在、プログラミング学習コミュニティでISUCONの勉強会に参加しており、[『達人が教えるWebパフォーマンスチューニング〜ISUCONから学ぶ高速化の実践』](https://gihyo.jp/book/2022/978-4-297-12846-3)を読みながら学習を進めています。
ISUCON本を読み進めると3章のハンズオンを取り組むことになるのですが、AWSを初めて使う自分のような初学者には少し難しい内容だったので、備忘録を兼ねて用語と手順をまとめてみました。

## 動作環境
- mac OS Sonoma 14.2.1

## ハンズオンの概要
3章では、iscogramという画像投稿サイトをAWSのEC2で起動させて、パフォーマンスチューニングの流れをハンズオンで実践的に学習していきます。

[1.private-isuをAWSのEC2で起動させる](#private-isuをawsのec2で起動させる)
[2.負荷試験環境を準備する](#負荷試験環境を準備する)
[3.ベンチマーカーで負荷試験を実行できるようにする](#ベンチマーカーで負荷試験を実行できるようにする)
[4.ボトルネックを発見する](#ボトルネックを発見する)
[5.パフォーマンスチューニング](#パフォーマンスチューニング)

## private-isuをAWSのEC2で起動させる
　ISUCONの学習用として一般に公開されている[リポジトリ](https://github.com/catatsuy/private-isu)に記載されているAMI IDを使用してインスタンスを起動させます。

<details><summary>AWSとは</summary>

- Amazon Web Servicesの略称
- Amazonが提供するクラウドサービスで仮想サーバー、DB、ストレージなどのさまざまなサービスがある
</details>

<details><summary>EC2とは</summary>

- Amazon Elastic Compute Cloudの略称
- AWS上に構築できる仮想サーバーのサービス
- [:page_facing_up:EC2の公式ドキュメント](https://docs.aws.amazon.com/ja_jp/AWSEC2/latest/UserGuide/concepts.html)
</details>

<details><summary>AMIとは</summary>

- Amazon Machine Imageの略称
- EC2インスタンスを起動するための必要情報がまとめられたテンプレートみたいなやつ
- インスタンスはEC2で構築したサーバーの単位のこと
- [:page_facing_up:インスタンスとAMIの公式ドキュメント](https://docs.aws.amazon.com/ja_jp/AWSEC2/latest/UserGuide/ec2-instances-and-amis.html)
</details>

### 起動手順

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/63e8e584-b5b5-c1ab-ff51-8a637bc38407.png" width="80%">

- AWSのEC2サービスのページに移動する
- ページ左のナビゲーションバーから"AMI"をクリック
- "パブリックイメージ"を選択して、検索バーにリポジトリで公開されているprivate-isuのAMI ID`ami-0d92a4724cae6f07b`を入力して検索
- 検索結果に出てきたイメージのAMI IDをクリック

---

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/477a2371-ba1f-d4aa-d340-b88e34276bd2.png" width="80%">

- "AMIからインスタンス起動"をクリックして、イメージの概要ページに移動する

---

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/d959c921-2c3c-3301-5fe9-736210bc0217.png" width="80%">

- インスタンスに適当な名前を付ける

---

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/a39076ac-5d14-568b-3c0e-cd68a0cb2c6e.png" width="80%">

- インスタンスタイプを選択する
- 今回はISUCON本推奨の`C5.large`を使用
- 1時間で約0.1ドルくらいかかるので、長時間起動したままにしないように注意!

<details><summary>インスタンスタイプとは</summary>

- 用途によって選択できるCPUやメモリなどの組み合わせのこと
- 当たり前のことではあるが、スペックが高いと料金も高くなる
- [:page_facing_up:インスタンスタイプの公式ドキュメント](https://docs.aws.amazon.com/ja_jp/AWSEC2/latest/UserGuide/instance-types.html)
</details>

---
<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/a35c5189-dd2d-f842-11d0-a2fe8dcc9c1b.png" width="80%">

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/a8e492da-ce34-b987-397d-16ab1718f9d8.png" width="80%">

- "新しいキーぺエアの作成"をクリック
- キーペアに適当な名前を付ける
- キーペアのタイプとプライベートキーファイル形式の設定はそのまま
- "キーペアを作成"をクリック

<details><summary>キーペアとは</summary>

- 公開鍵暗号方式に使われる公開鍵と秘密鍵の組み合わせのこと
- EC2インスタンスへ接続する際のセキュリティ認証に使う
- EC2インスタンスに誰でも接続できないようにするため必要
- [:page_facing_up:キーペアの公式ドキュメント](https://docs.aws.amazon.com/ja_jp/AWSEC2/latest/UserGuide/ec2-key-pairs.html)
- [:page_facing_up:公開鍵暗号方式の解説](https://eset-info.canon-its.jp/malware_info/term/detail/00198.html)
</details>

---

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/2476a00d-02de-5d8d-3d07-b4f273ccbd60.png" width="80%">

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/ca23591e-78bb-e862-d639-b5558c011931.png" width="80%">

- "セキュリティグループを作成"にチェック
- "SSHからのトラフィックを許可"にチェック
- "インターネットからのHTTPトラフィックを許可"にチェック
- 右上の"編集"ボタンをクリック
- SSHとHTTPのソースタイプを"自分のIP"に変更する

<details><summary>SSHとは</summary>

- Secure Shellの略称
- 通信を暗号化することで安全にリモートログインできる
- [:page_facing_up:SSHの解説](https://zenn.dev/airiswim/articles/fc1c35680bbc8a)
</details>

---

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/1d8b798d-2f1e-bd3b-128c-eb881955b78a.png" width="80%">

- ストレージの設定は本で特に指定されていなかったのでデフォルトのまま
- "インスタンスを起動"をクリック
- ロード画面に遷移後、成功と表示されればOK!
---

### 動作確認
<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/de0f10a3-e4fb-56ae-e9a5-e937adc4c9a5.png" width="80%">

- 作成したEC2インスタンスの概要ページでパブリックIPアドレスを確認する
- パブリックIPアドレスが`18.177.141.172`だった場合、ブラウザで`http://18.177.141.172/`にアクセスする

---

<img src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/159fb0f6-8af9-2ff8-e796-f065f68adb83.png" width="80%">

- iscogramのページが表示されればOK!
- ユーザー登録や画像投稿などの操作をして動作を確認する

## 負荷試験環境を準備する
### nginxにssh接続する

![スクリーンショット 2024-03-04 15.30.04.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/3625095/635ab092-e0d9-503e-4977-c63ded495763.png)

<details><summary>nginxとは</summary>

- Webサーバーのソフト
- [nginxの公式サイト](https://www.nginx.co.jp/resources/glossary/nginx/)
</details>

インスタンスのパブリックDNSをインスタンスの概要ページからコピーして、ターミナルでsshコマンドを実行する
[:page_facing_up:sshコマンドの解説記事](https://qiita.com/chihiro/items/c24fcbd82d1d8833e497)

```bash
$ ssh -i <キーペアのパス> <インスタンスのユーザー名>@<インスタンスのパブリックDNS>

# 具体的には以下のようなコマンドとなります
$ ssh -i Downloads/private-isu-keys.pem ubuntu@ec2-18-177-141-172.ap-northeast-1.compute.amazonaws.com
```
SSHでの接続が拒否された場合は、chmodコマンドでファイルの読み取り権限を付与してから再接続する
[:page_facing_up:chmodコマンドの解説](https://qiita.com/ntkgcj/items/6450e25c5564ccaa1b95)
```bash
$ chmod 400 <キーペアのパス>
```

接続に成功すると、以下のように表示される

```
Welcome to Ubuntu 22.04.3 LTS (GNU/Linux 6.2.0-1011-aws x86_64)

 * Documentation:  https://help.ubuntu.com
 * Management:     https://landscape.canonical.com
 * Support:        https://ubuntu.com/advantage

  System information as of Tue Mar  5 15:17:06 JST 2024

  System load:  0.0                Processes:             108
  Usage of /:   50.7% of 15.32GB   Users logged in:       0
  Memory usage: 19%                IPv4 address for ens5: 172.31.34.76
  Swap usage:   0%


Expanded Security Maintenance for Applications is not enabled.

0 updates can be applied immediately.

Enable ESM Apps to receive additional future security updates.
See https://ubuntu.com/esm or run: sudo pro status


The list of available updates is more than a week old.
To check for new updates run: sudo apt update

Last login: Sun Sep 17 14:52:00 2023 from 153.240.10.3
ubuntu@ip-172-31-34-76:~$ 

```

### nginxのアクセスログをJSON形式で出力する

vimコマンドで`nginx.cnf`を開き、httpコンテキストに以下の設定を追加する
[:page_facing_up:vimコマンドの解説](https://zenn.dev/mo_ri_regen/articles/vim-four-modes5)
[:page_facing_up:nginx.confの解説](https://heartbeats.jp/hbblog/2012/02/nginx03.html)
```
$ sudo vim /etc/nginx/nginx.conf
```
`nginx.cnf`に追加する設定
```
http {
        ##
        # Logging Settings
        ##

        # 変数の解説はISUCON本のp59,60に掲載されています
        # --- ここから ---
        log_format json escape=json '{ "time":"$time_iso8601",'
                                    '"host":"$remote_addr",'
                                    '"port":"$remote_port",'
                                    '"method":"$request_method",'
                                    '"uri":"$request_uri",'
                                    '"status":"$status",'
                                    '"body_bytes":"$body_bytes_sent",'
                                    '"referer":"$http_referer",'
                                    '"ua":"$http_user_agent",'
                                    '"request_time":"$request_time",'
                                    '"response_time":"$upstream_response_time"}';

        access_log /var/log/nginx/access.log json;
       # --- ここまで ---
       
        error_log /var/log/nginx/error.log;
}
```

nginxコマンドで設定ファイルの検証を実行する
[:page_facing_up:nginxコマンドの解説](https://qiita.com/katzueno/items/44e02db2f1bfa0de5860)

```
$ sudo nginx -t
```

JSON形式となっていない古いログを削除する
<details><summary>JSONとは</summary>

- JavaScript Object Notationの略称
- データフォーマットの一種
- [:page_facing_up:JSONの解説](https://datamix.co.jp/media/datascience/introduction-to-json/)
</details>

```
$ sudo rm /var/log/nginx/access.log
```
nginxをリロードし、設定を再読み込みする

```
$ sudo systemctl reload nginx
```
## ベンチマーカーで負荷試験を実行できるようにする
### EC2上のubuntuにalpをインストールする

以下のコマンドを実行してalpをインストールする

<details><summary>alpとは</summary>

- Access Log Profilerの略称
- Webサーバーのアクセスログ集計ツール
- [:page_facing_up:alpのリポジトリ](https://github.com/tkuchiki/alp)
- [:page_facing_up:alpの解説](https://atsum.in/linux/alp/)
</details>

```
# 記事作成時にlatestであったv1.0.21をダウンロード
$ wget https://github.com/tkuchiki/alp/releases/download/v1.0.21/alp_linux_amd64.tar.gz
$ tar xvzf alp_linux_amd64.tar.gz

#　インストール
$ sudo install ./alp /usr/local/bin
```

動作確認のため、標準入力からJSONのログを与えてalpコマンドでログを解析してみる
```
$ cat /var/log/nginx/access.log | alp json
```
以下のようなログ出力結果が出ればOK!
```
+-------+-----+-----+-----+-----+-----+--------+------------------+-------+-------+--------+-------+-------+-------+-------+--------+-------------+-------------+-------------+-------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD |       URI        |  MIN  |  MAX  |  SUM   |  AVG  |  P90  |  P95  |  P99  | STDDEV |  MIN(BODY)  |  MAX(BODY)  |  SUM(BODY)  |  AVG(BODY)  |
+-------+-----+-----+-----+-----+-----+--------+------------------+-------+-------+--------+-------+-------+-------+-------+--------+-------------+-------------+-------------+-------------+
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /posts/10000     | 0.068 | 0.068 | 0.068  | 0.068 | 0.068 | 0.068 | 0.068 | 0.000  | 1306.000    | 1306.000    | 1306.000    | 1306.000    |
| 1     | 0   | 1   | 0   | 0   | 0   | GET    | /image/10000.png | 0.000 | 0.000 | 0.000  | 0.000 | 0.000 | 0.000 | 0.000 | 0.000  | 1056749.000 | 1056749.000 | 1056749.000 | 1056749.000 |
| 20    | 0   | 20  | 0   | 0   | 0   | GET    | /                | 1.472 | 1.492 | 29.600 | 1.480 | 1.484 | 1.488 | 1.492 | 0.005  | 35644.000   | 35644.000   | 712880.000  | 35644.000   |
+-------+-----+-----+-----+-----+-----+--------+------------------+-------+-------+--------+-------+-------+-------+-------+--------+-------------+-------------+-------------+-------------+
```

### MacでApacheBenchを使えるようにする

以下のコマンドを実行し、httpdをインストールする
<details><summary>ApacheBenchとは</summary>

- Apache HTTP Serverに同梱されている性能テストツール
- abコマンドで単一かつ同一のURLに対するリクエストを、指定した分だけ生成することができる
- [:page_facing_up:ApacheBenchの解説](https://dev.classmethod.jp/articles/ab-tutorial/)
</details>

```
$ brew install httpd
```

動作確認のため、abコマンドでiscogramに1並列で10回のリクエストを送信してみる
```
$ ab -c 1 -n 10 http://EC2のパブリックIP/
```
以下のようなログ出力結果が出ればOK!
```
This is ApacheBench, Version 2.3 <$Revision: 1903618 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 54.249.70.244 (be patient).....done


Server Software:        nginx/1.18.0
Server Hostname:        54.249.70.244
Server Port:            80

Document Path:          /
Document Length:        35644 bytes

Concurrency Level:      1
Time taken for tests:   16.201 seconds
Complete requests:      10
Failed requests:        0
Total transferred:      360160 bytes
HTML transferred:       356440 bytes
Requests per second:    0.62 [#/sec] (mean)
Time per request:       1620.087 [ms] (mean)
Time per request:       1620.087 [ms] (mean, across all concurrent requests)
Transfer rate:          21.71 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       22   24   1.8     23      29
Processing:  1522 1596  38.0   1614    1625
Waiting:     1499 1572  37.8   1588    1601
Total:       1545 1620  38.4   1636    1654

Percentage of the requests served within a certain time (ms)
  50%   1636
  66%   1639
  75%   1643
  80%   1644
  90%   1654
  95%   1654
  98%   1654
  99%   1654
 100%   1654 (longest request)
```

### abコマンドの結果とalpによる解析結果を比較する

**＜abコマンドの結果＞**
abコマンドの動作確認のためiscogramへ10回リクエストした結果から、レスポンスタイムの平均値は1620[ms]
```
Time per request:       1620.087 [ms] (mean)
```
**＜alpによる解析＞**
nginxのアクセスログの末尾10件をalpコマンドで解析するとレスポンスタイムの平均値は1475[ms]
```
$ tail -n 10 /var/log/nginx/access.log | alp json -o count,method,uri,min,avg,max
# 解析結果
+-------+--------+-----+-------+-------+-------+
| COUNT | METHOD | URI |  MIN  |  AVG  |  MAX  |
+-------+--------+-----+-------+-------+-------+
| 10    | GET    | /   | 1.468 | 1.475 | 1.484 |
+-------+--------+-----+-------+-------+-------+
```
レスポンスタイムの計測値を比較すると145[ms]の差があるが、これはEC2サーバーで処理を終えた結果がクライアントに届くまでに時間がかかるためだと考えられる

### アクセスログのローテーション方法
**＜ログのローテート＞**
複数回の試験結果を1つのログファイルに記録してしまうとalpでの解析が面倒になるため、負荷試験ごとにログファイルを変更する必要がある
**＜ローテートの手順＞**
nginxのログファイルをリネームする
```
$ sudo mv /var/log/nginx/access.log //var/log/nginx/access.log.old
```
nginxをリロードし、新しいファイルにログが出力されるようにする
```
$ sudo systemctl reload nginx
```

## ボトルネックを発見する
### 最初の状態で負荷試験を実行する
Macでabコマンドを実行し、1並列で30[s]間リクエストを送る
```
$ ab -c 1 -t 30 http://EC2のパブリックIP/

# 実行結果
This is ApacheBench, Version 2.3 <$Revision: 1903618 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 35.77.89.45 (be patient)
Finished 19 requests


Server Software:        nginx/1.18.0
Server Hostname:        35.77.89.45
Server Port:            80

Document Path:          /
Document Length:        35644 bytes

Concurrency Level:      1
Time taken for tests:   30.458 seconds
Complete requests:      19
Failed requests:        0
Total transferred:      684304 bytes
HTML transferred:       677236 bytes
Requests per second:    0.62 [#/sec] (mean)
Time per request:       1603.031 [ms] (mean)
Time per request:       1603.031 [ms] (mean, across all concurrent requests)
Transfer rate:          21.94 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       22   23   1.3     23      27
Processing:  1532 1580  41.7   1593    1648
Waiting:     1508 1554  40.1   1568    1624
Total:       1555 1603  42.0   1616    1675

Percentage of the requests served within a certain time (ms)
  50%   1615
  66%   1638
  75%   1638
  80%   1639
  90%   1659
  95%   1675
  98%   1675
  99%   1675
 100%   1675 (longest request)
```

ベンチマーク実行中にEC2でtopコマンドを実行して、システム全体の負荷を確認する
[:page_facing_up:topコマンドの解説](https://qiita.com/k0kubun/items/7368c323d90f24a00c2f)

```
$ top

# 実行結果
top - 14:05:32 up  1:07,  2 users,  load average: 0.40, 0.15, 0.05
Tasks: 108 total,   1 running, 107 sleeping,   0 stopped,   0 zombie
%Cpu(s): 45.2 us,  0.3 sy,  0.0 ni, 54.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3695.7 total,   1582.2 free,    688.2 used,   1425.3 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   2769.2 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                        
    818 mysql     20   0 1786676 450964  36352 S  87.3  11.9   1:38.44 mysqld                                         
    844 isucon    20   0  222216  72920   9984 S   3.3   1.9   0:03.35 ruby                                           
    422 _chrony   20   0   18892   3612   2944 S   0.3   0.1   0:00.08 chronyd   
```
実行結果から読み取れること
- 3行目:  `%Cpu(s): 45.2 us`はホストで使えるすべてのCPUコア(c5.largeは2コア)を合計したものを100とした場合の使用率を示しており、約45[%]のリソースが使われている 
- 7行目： `%CPU:`の項目からMySQLのプロセスは約87[%]ものリソースを使っている(CPU1コア換算)
- 8行目： `%CPU:`の項目からWebアプリケーションのプロセスは約3[%]しかリソースを使っていない(CPU1コア換算)

これらの結果から、MySQLの処理がボトルネックになっていることと、ホスト全体で2コアのCPUが使えるにもかかわらず、1コア分は遊んでいることがわかる

### MySQLのボトルネック原因を調査する
MySQLで発行されているクエリを解析して、ボトルネックとなっている原因の詳細を調査する

**＜スロークエリログ＞**
MySQLでは、処理に時間がかかったクエリをスロークエリログに出力することができる
[:page_facing_up:スロークエリログの解説](https://dev.mysql.com/doc/refman/8.0/ja/slow-query-log.html)

記録される情報は下記の通り
- 処理したSQL文
- Query_time:クエリの処理にかかった時間
- Lock_time:ロックを取得する時間
- Rows_sent:クエリの実行結果とクライアントに送信した行数
- Rows_examined:クエリを読み取るためにSQL内部で読み取った行数

**＜スロークエリログの出力設定＞**
vimコマンドで`mysqld.cnf`を開き、以下の設定を追加する
```
$ sudo vim /etc/mysql/mysql.conf.d/mysqld.cnf
```
`mysqld.cnf`に追加する設定
```
# Here you can see queries with especially long duration
slow_query_log          = 1
slow_query_log_file     = /var/log/mysql/mysql-slow.log
long_query_time         = 0
```
mysqlを再起動させる
```
$ sudo systemctl restart mysql
```

**＜スロークエリログの解析＞**
ベンチマークを再度実行する
```
$ ab -c 1 -t 30 http://EC2のパブリックIP/
```
mysqldumpslowコマンドを実行して、スロークエリログのサマリーを出力する
[:page_facing_up:mysqldumpslowコマンドの解説](https://dev.mysql.com/doc/refman/8.0/ja/mysqldumpslow.html)
```
$ sudo mysqldumpslow /var/log/mysql/mysql-slow.log

# 実行結果
Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 418  Time=0.05s (19s)  Lock=0.00s (0s)  Rows=3.0 (1254), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

Count: 19  Time=0.02s (0s)  Lock=0.00s (0s)  Rows=10000.0 (190000), isuconp[isuconp]@localhost
  SELECT `id`, `user_id`, `body`, `created_at`, `mime` FROM `posts` ORDER BY `created_at` DESC

Count: 418  Time=0.02s (6s)  Lock=0.00s (0s)  Rows=1.0 (418), isuconp[isuconp]@localhost
  SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  SET NAMES utf8mb4

Count: 1672  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1672), isuconp[isuconp]@localhost
  SELECT * FROM `users` WHERE `id` = N

Count: 4763  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=4583.3 (21830024), isuconp[isuconp]@localhost
  #

Count: 2255  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Close stmt

Count: 2508  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare
```

一番の多くの時間を消費しているクエリがサマリーの一番上に出力される
以下のログより、SELECT文が30秒間に418回呼ばれて、計19秒も消費していることがわかる
```
Count: 418  Time=0.05s (19s)  Lock=0.00s (0s)  Rows=3.0 (1254), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
```

lessコマンドで`mysqld.cnf`を開き、一番の多くの時間を消費しているクエリの詳細を確認する
[:page_facing_up:lessコマンドの解説](https://www.ritolab.com/posts/205)
```
sudo less /var/log/mysql/mysql-slow.log
```
発行されているクエリの詳細を見てみる
```
# Query_time: 0.046435  Lock_time: 0.000001 Rows_sent: 3  Rows_examined: 100003
SET timestamp=1709704605;
SELECT * FROM `comments` WHERE `post_id` = 9999 ORDER BY `created_at` DESC LIMIT 3;
```
`Rows_sent: 3  Rows_examined: 100003`より、クエリを処理する際に内部で読み取ったテーブルの行数は100003行に対し、クライアントに返した行数は3行であることがわかる

なぜ、こんな非効率な処理となっているか原因を探るため、commentsテーブルの詳細を確認する
MySQLサーバーにログイン
```
$ sudo mysql -u root
```
`isuconp`のDBを選択
```
$ USE isuconp;
```
`comments`テーブルのスキーマを表示すると、プライマリキー以外のインデックスがないことがわかる
```
$ SHOW CREATE TABLE comments;

# 出力結果
+----------+----------------------------------------------------------------------------+
| Table    | Create Table                                                               |
+----------+----------------------------------------------------------------------------+
| comments | CREATE TABLE `comments` (
  `id` int NOT NULL AUTO_INCREMENT,
  `post_id` int NOT NULL,
  `user_id` int NOT NULL,
  `comment` text NOT NULL,
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100001 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci|
+----------+----------------------------------------------------------------------------+
1 row in set (0.00 sec)
```

EXPLAIN文でクエリの実行計画を確認してみる
[:page_facing_up:EXPLAIN文の解説](https://dev.mysql.com/doc/refman/8.0/ja/explain-output.html)
```
$ EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 9999 ORDER BY `created_at` DESC LIMIT 3;

+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table    | partitions | type | possible_keys | key  | key_len | ref  | rows  | filtered | Extra                       |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
|  1 | SIMPLE      | comments | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 96610 |    10.00 | Using where; Using filesort |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)
```
`key`の値がNULLになっているのでインデックスは使用されず、commentsテーブルほぼすべてのレコードを読み取ろうとしていることがわかり、インデックスを作成すれば改善が見込めそうだという推測ができる
[:page_facing_up:インデックスと実行計画の解説](https://zenn.dev/yuulab/articles/f415920220acf9)

## パフォーマンスチューニング
### パフォーマンスチューニングを実施する

`post_id`カラムにインデックスを貼る
[:page_facing_up:インデックスを追加するSQLの解説](https://qiita.com/pugiemonn/items/8a6b322654aa65e2966b)
```
$ ALTER TABLE comments ADD INDEX index_post_id (post_id);
```
もう一度EXPLAIN文を実行する
```
$ EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 9999 ORDER BY `created_at` DESC LIMIT 3;

+----+-------------+----------+------------+------+---------------+---------------+---------+-------+------+----------+----------------+
| id | select_type | table    | partitions | type | possible_keys | key           | key_len | ref   | rows | filtered | Extra          |
+----+-------------+----------+------------+------+---------------+---------------+---------+-------+------+----------+----------------+
|  1 | SIMPLE      | comments | NULL       | ref  | index_post_id | index_post_id | 4       | const |   11 |   100.00 | Using filesort |
+----+-------------+----------+------------+------+---------------+---------------+---------+-------+------+----------+----------------+
1 row in set, 1 warning (0.00 sec)
```
`key`の値から`index_post_id`というインデックスが使用されることがわかり、`rows`の値から11行程度の読み取りで処理できる見込みであることがわかる

再度、クエリを実行する
```
$ SELECT * FROM `comments` WHERE `post_id` = 9999 ORDER BY `created_at` DESC LIMIT 3;
```
スロークエリログを確認すると、14行の読み取りで処理できるようになっていることがわかる
```
$ sudo less /var/log/mysql/mysql-slow.log

# Query_time: 0.000340  Lock_time: 0.000003 Rows_sent: 3  Rows_examined: 14
SET timestamp=1709708074;
SELECT * FROM `comments` WHERE `post_id` = 9999 ORDER BY `created_at` DESC LIMIT 3;
```

### パフォーマンスチューニングの成果を確認する
スロークエリログを削除し、nginxを再起動する
```
$ sudo rm /var/log/nginx/access.log
$ sudo systemctl restart nginx
```

abコマンド実行する
```
$ ab -c 1 -t 30 http://EC2のパブリックIP/

# 実行結果
This is ApacheBench, Version 2.3 <$Revision: 1903618 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 35.77.89.45 (be patient)
Finished 199 requests


Server Software:        nginx/1.18.0
Server Hostname:        35.77.89.45
Server Port:            80

Document Path:          /
Document Length:        35644 bytes

Concurrency Level:      1
Time taken for tests:   30.036 seconds
Complete requests:      199
Failed requests:        0
Total transferred:      7167184 bytes
HTML transferred:       7093156 bytes
Requests per second:    6.63 [#/sec] (mean)
Time per request:       150.934 [ms] (mean)
Time per request:       150.934 [ms] (mean, across all concurrent requests)
Transfer rate:          233.03 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       21   23   0.9     23      29
Processing:   122  128   7.7    127     212
Waiting:       98  103   7.3    102     189
Total:        144  151   8.2    150     242

Percentage of the requests served within a certain time (ms)
  50%    150
  66%    151
  75%    152
  80%    152
  90%    154
  95%    157
  98%    171
  99%    195
 100%    242 (longest request)

```

abコマンド実行中にtopコマンドを実行する
```
$ top

# 実行結果
top - 16:21:41 up 0 min,  1 user,  load average: 0.61, 0.20, 0.07
Tasks: 113 total,   1 running, 112 sleeping,   0 stopped,   0 zombie
%Cpu(s): 25.6 us,  4.4 sy,  0.0 ni, 69.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.2 st
MiB Mem :   3695.7 total,   2633.4 free,    637.6 used,    424.6 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   2827.2 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                        
    661 isucon    20   0  217928  68952   9984 S  33.9   1.8   0:09.59 ruby                                           
    523 mysql     20   0 1784704 420432  36096 S  25.6  11.1   0:08.29 mysqld                                         
    888 ubuntu    20   0   10936   3840   3200 R   0.7   0.1   0:00.04 top
```

インデックスを貼る前と貼った後のデータを比較してみる

| 項目| インデックスなし| インデックスあり |
|:---|------------:|-----------:|
| 全体のCPU使用率 | 45.2[%] | 25.6[%] |
| MySQLのCPU使用率(1コア換算) | 87.3[%] | 25.6[%] |
| WebアプリのCPU使用率(1コア換算) | 3.3[%] | 33.9[%] |
| レイテンシ | 1603[ms] | 151[ms]|
| スループット | 0.62[request/sec] | 6.63[request/sec]|

私の環境ではインデックスを貼ることで約10倍のリクエストを処理できるようになり、MySQLのCPU使用率も約60[%]下がったので、はじめてのパフォーマンスチューニング成功です!
しかし、ISUCON本では約50倍のリクエストを処理できるようになっていたので、それと比較すると劣った結果でした。

abコマンドの結果がサーバーとクライアントの通信経路で発生しているレイテンシも含んでおり、私の環境ではこれが影響しているのではないかと考えましたが、`ping`コマンドを実行してもレイテンシは平均25[ms]くらいで直接的な原因ではなさそうでした。
沼りそうなので、今回はこれ以上の深掘りはやめておきますw
[:page_facing_up:pingコマンドの解説](https://zenn.dev/yuulab/articles/f415920220acf9)
[:page_facing_up:EC2にpingを送る方法の解説](https://qiita.com/hayate_h/items/de517d3efc82d4e308b4)

## まとめ
初めて使うツールやコマンドだらけでかなり苦労しましたが、なんとかパフォーマンスチューニングすることができました。

自分が詰まったところには、公式ドキュメントや記事のリンクを貼っているので初学者の参考になれば幸いです。

~~ISUCON本の3章では、並列処理についてパフォーマンスチューニングのハンズオンも行っているで今後はそちらの記事も作成できればと考えています。~~
=>続編作成しました！
　[:page_facing_up:ISUCON本で初めてのパフォーマンスチューニングに挑戦してみた ~続編~](https://qiita.com/kaito_399/items/3a4186cc8b3dbfa85a3b)

最後までお読みいただきありがとうございます！