Open47

isucon本

kakkkykakkky

流石にログを残しながらやった方が良さげと思ったので残しながら。
探偵ごっこみたいで面白い。

kakkkykakkky

3. 基礎的な負荷試験

まず、30秒リクエスト負荷を与え続けると、

ab -c 1 -t 30 http://localhost/

docker statsで各コンテナのCPU使用率を見たところ、、

CONTAINER ID   NAME                      CPU %     MEM USAGE / LIMIT     MEM %     NET I/O           BLOCK I/O         PIDS 
a7aba7142c98   private-isu-nginx-1       0.09%     7.559MiB / 7.654GiB   0.10%     629kB / 631kB     0B / 4.1kB        9 
88267faceb9b   private-isu-app-1         4.09%     22.17MiB / 1GiB       2.16%     21.1MB / 1.29MB   0B / 0B           10 
7dd9c0346cab   private-isu-mysql-1       96.68%    455.5MiB / 1GiB       44.48%    676kB / 21.1MB    44.4MB / 16.7MB   36 
e4fa51d6d1fc   private-isu-memcached-1   0.01%     2.152MiB / 7.654GiB   0.03%     1.63kB / 126B     0B / 0B           10

ダントツでmysqlコンテナがすごいことに。

なので、mysqlあたりを調査すると。
その際に、スロークエリを吐かせるようにした。

[mysqld]
slow_query_log=1
slow_query_log_file=/var/log/mysql/mysql-slow.log
long_query_time=0

このcnfファイルやログファイルをコンテナにマウントするようにして、再度実行。

すると、以下のようなログが大量に

/usr/sbin/mysqld, Version: 8.4.6 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 2025-09-13T10:23:26.418087Z
# User@Host: root[root] @ private-isu-app-1.private-isu_my_network [172.20.0.4]  Id:     8
# Query_time: 0.000233  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
use isuconp;
SET timestamp=1757759006;
SET NAMES utf8mb4;
# Time: 2025-09-13T10:23:26.471272Z
# User@Host: root[root] @ private-isu-app-1.private-isu_my_network [172.20.0.4]  Id:     8
# Query_time: 0.052447  Lock_time: 0.000014 Rows_sent: 10001  Rows_examined: 20002
SET timestamp=1757759006;
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC;
# Time: 2025-09-13T10:23:26.487160Z
# User@Host: root[root] @ private-isu-app-1.private-isu_my_network [172.20.0.4]  Id:     8
# Query_time: 0.001284  Lock_time: 0.000006 Rows_sent: 0  Rows_examined: 0
SET timestamp=1757759006;
# administrator command: Prepare;
# Time: 2025-09-13T10:23:26.508029Z
# User@Host: root[root] @ private-isu-app-1.private-isu_my_network [172.20.0.4]  Id:     8
# Query_time: 0.020730  Lock_time: 0.000001 Rows_sent: 1  Rows_examined: 100002
SET timestamp=1757759006;
SELECT COUNT(*) AS `count` FROM `comments` WHERE `pos

で、これだと辛いので、ホストマシンからmysqldumpslowを実行し、実行時間が長いクエリを並べてもらう。

# マウントされたホストマシンのログに対して実行
mysqldumpslow webapp/logs/mysql/mysql-slow.log

Reading mysql slow query log from webapp/logs/mysql/mysql-slow.log
Can't open webapp/logs/mysql/mysql-slow.log: No such file or directory at /opt/homebrew/bin/mysqldumpslow line 93.
yutakakiki@kakinokiyuunoMacBook-Air webapp % mysqldumpslow /logs/mysql/mysql-slow.log 

Reading mysql slow query log from /logs/mysql/mysql-slow.log
Can't open /logs/mysql/mysql-slow.log: No such file or directory at /opt/homebrew/bin/mysqldumpslow line 93.
yutakakiki@kakinokiyuunoMacBook-Air webapp % mysqldumpslow logs/mysql/mysql-slow.log 

Reading mysql slow query log from logs/mysql/mysql-slow.log
Count: 836  Time=0.02s (20s)  Lock=0.00s (0s)  Rows=3.0 (2470), root[root]@private-isu-app-1.private-isu_my_network
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

Count: 38  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=10001.0 (380038), root[root]@private-isu-app-1.private-isu_my_network
  SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC

Count: 836  Time=0.01s (7s)  Lock=0.00s (0s)  Rows=1.0 (836), root[root]@private-isu-app-1.private-isu_my_network
  SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@private-isu-app-1.private-isu_my_network
  SET NAMES utf8mb4
kakkkykakkky

生のスロークエリを見ると、そのクエリはこうなっていた。
100005行探索して、返しているのが3行。これは苦しい。

# administrator command: Prepare;
# Time: 2025-09-13T10:23:26.569123Z
# User@Host: root[root] @ private-isu-app-1.private-isu_my_network [172.20.0.4]  Id:     8
# Query_time: 0.024489  Lock_time: 0.000001 Rows_sent: 3  Rows_examined: 100005 # ここ
SET timestamp=1757759006;
SELECT * FROM `comments` WHERE `post_id` = 10000 ORDER BY `created_at` DESC LIMIT 3;
kakkkykakkky

テーブルのスキーマを見る。
docker exec -it private-isu-mysql-1 bashでターミナルに入り、
mysql -u root -pでmysqlに入る。

descで見たスキーマ

mysql> desc comments
    -> ;
+------------+-----------+------+-----+-------------------+-------------------+
| Field      | Type      | Null | Key | Default           | Extra             |
+------------+-----------+------+-----+-------------------+-------------------+
| id         | int       | NO   | PRI | NULL              | auto_increment    |
| post_id    | int       | NO   |     | NULL              |                   |
| user_id    | int       | NO   |     | NULL              |                   |
| comment    | text      | NO   |     | NULL              |                   |
| created_at | timestamp | NO   |     | CURRENT_TIMESTAMP | DEFAULT_GENERATED |
+------------+-----------+------+-----+-------------------+-------------------+
5 rows in set (0.00 sec)
kakkkykakkky

PRIMARY KEYにはINDEXが貼られる。
しかし、今回whereで検索かけてるpost_idにはindexingされていない。
これだと、全レコード調べる必要が出てきてしまうy

kakkkykakkky

EXPLAINでクエリ実行計画を確認。
key == null、これはindexingされていない

mysql> explain select *  from comments where post_id = 9995 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 | 98217 |    10.00 | Using where; Using filesort |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
kakkkykakkky

indexを貼ると、

mysql> explain select *  from comments where post_id = 9995 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  | post_id_idx   | post_id_idx | 4       | const |    6 |   100.00 | Using filesort |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+----------------+
kakkkykakkky

実行結果は、

# Time: 2025-09-14T01:34:44.892650Z
# User@Host: root[root] @ localhost []  Id:    12
# Query_time: 0.001142  Lock_time: 0.000008 Rows_sent: 3  Rows_examined: 9
SET timestamp=1757813684;
select *  from comments where post_id = 9995 order by created_at desc limit 3;

explainはあくまで実行計画なので、実際と若干ズレる。

kakkkykakkky

indexを改善したところで、再度負荷をかけると
docker statsでは、

CONTAINER ID   NAME                      CPU %     MEM USAGE / LIMIT     MEM %     NET I/O           BLOCK I/O         PIDS 
a7aba7142c98   private-isu-nginx-1       0.81%     7.629MiB / 7.654GiB   0.10%     10.9MB / 10.9MB   0B / 4.1kB        9 
88267faceb9b   private-isu-app-1         41.72%    21.94MiB / 1GiB       2.14%     349MB / 22.5MB    36.9kB / 0B       10 
7dd9c0346cab   private-isu-mysql-1       49.74%    489.9MiB / 1GiB       47.84%    11.9MB / 348MB    45.4MB / 26.7MB   37 
e4fa51d6d1fc   private-isu-memcached-1   0.01%     2.152MiB / 7.654GiB   0.03%     1.71kB / 126B     0B / 0B           10

mysqlの割合は減っている。
ただ、appが結構占めているのがわかる。

また、abコマンドの結果

Requests per second:    18.75 [#/sec] (mean)
Time per request:       53.335 [ms] (mean)

あちゃ、当初のrpsとレイテンシを記録し忘れている。たぶん良くなっただろう。

kakkkykakkky

appが結構占めているのがわかるようになったのは、mysqlのボトルネックが1つ解消され、rpsが増えたことで、よりwebappの稼働が増えたから

kakkkykakkky

mysqldumpslowは以下

Count: 563  Time=0.01s (4s)  Lock=0.00s (0s)  Rows=10001.0 (5630563), root[root]@private-isu-app-1.private-isu_my_network
  SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC

Count: 12386  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=3.0 (36595), root[root]@private-isu-app-1.private-isu_my_network
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

Count: 12386  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (12386), root[root]@private-isu-app-1.private-isu_my_network
  SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N

Count: 48981  Time=0.00s (1s)  Lock=0.00s (0s)  Rows=1.0 (48981), root[root]@private-isu-app-1.private-isu_my_network
  SELECT * FROM `users` WHERE `id` = N

Count: 147498  Time=0.00s (2s)  Lock=0.00s (0s)  Rows=0.7 (97952), root[root]@2hosts
  #

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

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

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Quit
kakkkykakkky

上のmysqldumpslowを見ると、commentsテーブルではなく、postsテーブルに対するクエリが上に来ている。

Count: 563  Time=0.01s (4s)  Lock=0.00s (0s)  Rows=10001.0 (5630563), root[root]@private-isu-app-1.private-isu_my_network
  SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC

しかし依然として前のクエリが大量発行されているのも気になる、

Count: 12386  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=3.0 (36595), root[root]@private-isu-app-1.private-isu_my_network
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

30sに12386ということは、1sに412回叩かれている。
abコマンドによれば 18.75rpsだから、412/18で、1リクエストあたり22回クエリを叩いていることになる。
これはN+1の予感？

kakkkykakkky

並列度を上げて負荷をかける。

2並列でabコマンドすると以下の通り、rpsは上がり、レイテンシが増えた。
レイテンシが20msくらい増えている。

Requests per second:    27.25 [#/sec] (mean)
Time per request:       73.403 [ms] (mean)

４並列にしてみると、rpsは変わらんがレイテンシがかなり上がっている。

Requests per second:    29.30 [#/sec] (mean)
Time per request:       136.537 [ms] (mean)

サーバーの処理能力が飽和している（捌けるreq数が限度きた）から、並列度が上がる分レイテンシーが上がっているということ。

kakkkykakkky

ちゃんとリソース（CPU）は使い切ってそれなのか？

kakkkykakkky

でdocker statsで見ると、40パーは使ってないのがわかる。

88267faceb9b   private-isu-app-1         64.29%    48.68MiB / 1GiB       4.75%     2.96GB / 192MB    36.9kB / 0B       11

これは多分、mysqlとかI/O通信でCPUの遊びが一部あることが原因かと思われれる。

kakkkykakkky

rubyではCPU数より多くworkerプロセスを立てれば、IO待ちで遊んでる時にCPUが暇しないみたいなことが書いてあった。Goはこれをgoroutineで解決する感じ？

copilot >

はい、その理解で正しいです。

Ruby（特にPumaやUnicornなどのWebサーバー）は、CPUコア数より多くのワーカープロセスを立てることで、I/O待ちの間も他のプロセスがCPUを使えるようにしています。
これはRubyのスレッドやプロセスがI/O待ちでブロックされやすい（GILやVMの制約）ためです。

一方、Goはgoroutineという軽量スレッドを大量に使い、I/O待ちの間も他のgoroutineが同じプロセス内でどんどんCPUを使えるようになっています。
Goランタイムが自動的にI/O待ちのgoroutineをスケジューリングし、CPUを無駄なく使う設計です。

まとめ：

Ruby：プロセスやスレッドを多重化してI/O待ちをカバー
Go：goroutineとランタイムのスケジューリングでI/O待ちをカバー（プロセスを増やさなくてもOK）
Goは「1プロセス＋大量goroutine」でI/OバウンドもCPUバウンドも効率よく処理できるのが強みです。
kakkkykakkky

3. シナリオを使った負荷試験

k6でe2e的にシナリオをjsで書いて負荷をかけれる。

kakkkykakkky
yutakakiki@kakinokiyuunoMacBook-Air private-isu % cat webapp/logs/nginx/access.log | alp json --sort=sum -r -m "/posts/[0-9]+,/@\w" 
+-------+-----+-----+-----+-----+-----+--------+---------------+-------+-------+--------+-------+-------+-------+-------+--------+-----------+-----------+--------------+-----------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD |      URI      |  MIN  |  MAX  |  SUM   |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY) |  SUM(BODY)   | AVG(BODY) |
+-------+-----+-----+-----+-----+-----+--------+---------------+-------+-------+--------+-------+-------+-------+-------+--------+-----------+-----------+--------------+-----------+
| 414   | 0   | 414 | 0   | 0   | 0   | GET    | /posts/[0-9]+ | 0.007 | 0.644 | 66.525 | 0.161 | 0.358 | 0.397 | 0.461 | 0.148  | 1661.000  | 78814.000 | 11979591.000 | 28936.210 |
| 414   | 0   | 414 | 0   | 0   | 0   | GET    | /             | 0.063 | 0.325 | 52.663 | 0.127 | 0.180 | 0.211 | 0.251 | 0.042  | 21836.000 | 21864.000 | 9047220.000  | 21853.188 |
| 183   | 0   | 183 | 0   | 0   | 0   | GET    | /@\w          | 0.085 | 0.273 | 26.113 | 0.143 | 0.196 | 0.219 | 0.250 | 0.038  | 33838.000 | 33847.000 | 6193254.000  | 33842.918 |
| 414   | 0   | 0   | 414 | 0   | 0   | POST   | /login        | 0.010 | 0.186 | 18.175 | 0.044 | 0.094 | 0.109 | 0.130 | 0.031  | 0.000     | 0.000     | 0.000        | 0.000     |
| 231   | 0   | 0   | 231 | 0   | 0   | POST   | /             | 0.006 | 0.171 | 9.831  | 0.043 | 0.084 | 0.094 | 0.134 | 0.031  | 0.000     | 0.000     | 0.000        | 0.000     |
| 183   | 0   | 0   | 183 | 0   | 0   | POST   | /comment      | 0.005 | 0.139 | 5.547  | 0.030 | 0.077 | 0.091 | 0.123 | 0.027  | 0.000     | 0.000     | 0.000        | 0.000     |
+-------+-----+-----+-----+-----+-----+--------+---------------+-------+-------+--------+-------+-------+-------+-------+--------+-----------+-----------+--------------+-----------+
kakkkykakkky

そういえばalpのカラムまとめ

カラム名 意味
count 集計対象となったリクエストの件数
1xx, 2xx, 3xx, 4xx, 5xx HTTPステータスコードごとの件数（例: 2xx = 成功、4xx = クライアントエラー）
method HTTPメソッド（GET, POST, PUT, DELETE など）
uri リクエスト先の URI（パス）。alp ではクエリパラメータ部分を正規化可能
min 該当リクエストの処理時間の最小値
max 該当リクエストの処理時間の最大値
sum 該当リクエストの処理時間の合計
avg 該当リクエストの処理時間の平均
p99 / p95 / p90 処理時間のパーセンタイル値（遅い方のボトルネック把握に使う）
stddev 処理時間の標準偏差（処理時間のばらつき具合）
kakkkykakkky

5. データベースのチューニング

先のintegration.jsをk6でrunし、docker statsで見てみる。

appも結構だけど、第一にボトルネックはDBぽい

CONTAINER ID   NAME                      CPU %     MEM USAGE / LIMIT     MEM %     NET I/O           BLOCK I/O         PIDS 
df2096f936fc   private-isu-nginx-1       2.98%     7.668MiB / 7.654GiB   0.10%     36.5MB / 36.1MB   0B / 4.1kB        9 
eca7327833b8   private-isu-app-1         81.30%    56.91MiB / 1GiB       5.56%     639MB / 59.9MB    0B / 0B           13 
8eb147bd6c99   private-isu-mysql-1       102.04%   505.1MiB / 1GiB       49.33%    37.6MB / 624MB    64.7MB / 96.7MB   42 
ccef14907104   private-isu-memcached-1   0.58%     3.75MiB / 7.654GiB    0.05%     417kB / 651kB     0B / 0B           10
kakkkykakkky

mysqlのプロセスlistをみる

mysql> show full processlist;
+-----+-----------------+------------------------------------------------+---------+---------+------+------------------------+-------------------------------------------------------------------------------------+
| Id  | User            | Host                                           | db      | Command | Time | State                  | Info                                                                                |
+-----+-----------------+------------------------------------------------+---------+---------+------+------------------------+-------------------------------------------------------------------------------------+
|   5 | event_scheduler | localhost                                      | NULL    | Daemon  |  665 | Waiting on empty queue | NULL                                                                                |
| 471 | root            | localhost                                      | NULL    | Query   |    0 | init                   | show full processlist                                                               |
| 756 | root            | private-isu-app-1.private-isu_my_network:60496 | isuconp | Execute |    0 | logging slow query     | SELECT * FROM `comments` WHERE `post_id` = 11785 ORDER BY `created_at` DESC LIMIT 3 |
| 759 | root            | private-isu-app-1.private-isu_my_network:60530 | isuconp | Prepare |    0 | logging slow query     | NULL                                                                                |
| 764 | root            | private-isu-app-1.private-isu_my_network:60570 | isuconp | Execute |    0 | logging slow query     | SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = 11769                  |
| 765 | root            | private-isu-app-1.private-isu_my_network:60586 | isuconp | Prepare |    0 | logging slow query     | NULL                                                                                |
| 766 | root            | private-isu-app-1.private-isu_my_network:60598 | isuconp | Execute |    0 | logging slow query     | SELECT * FROM `users` WHERE `id` = 999                                              |
| 768 | root            | private-isu-app-1.private-isu_my_network:60622 | isuconp | Execute |    0 | logging slow query     | SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = 11795                  |
+-----+-----------------+------------------------------------------------+---------+---------+------+------------------------+-------------------------------------------------------------------------------------+
8 rows in set, 1 warning (0.00 sec)

8スレッドで実行されていた。

kakkkykakkky

Stateで、Sending Dataとなっている部分は、大量のデータを読み取り中のクエリの可能性があり注意が必要らしい。この瞬間にはなかった

kakkkykakkky

で、スロークエリの分析には、ここまでsqlslowquerydumpを使ってきたが、より詳細に分析できるやつがあるらしい。

pt-query-digestっていうやつ。

以下でinstall。

brew install percona-toolkit
kakkkykakkky

クエリランキングが。
今のとこだと、SELECT posts　のクエリが最も時間が長い。

# Profile
# Rank Query ID                            Response time Calls R/Call V/M 
# ==== =================================== ============= ===== ====== ====
#    1 0x4858CF4D8CAA743E839C127C71B69E75  11.9731 42.0%   665 0.0180  0.02 SELECT posts
#    2 0xCDEB1AFF2AE2BE51B2ED5CF03D4E749F   4.3609 15.3%   334 0.0131  0.01 SELECT comments
#    3 0xDA556F9115773A1A99AA0165670CE848   2.9153 10.2% 78579 0.0000  0.00 ADMIN PREPARE
#    4 0x396201721CD58410E070DA9421CA8C8D   1.7570  6.2% 33625 0.0001  0.01 SELECT users
#    5 0xE83DA93257C7B787C67B1B05D2469241   1.4883  5.2%   334 0.0045  0.00 SELECT posts
#    6 0x009A61E5EFBD5A5E4097914B4DBD1C07   1.4503  5.1%   331 0.0044  0.00 INSERT posts
#    7 0x624863D30DAC59FA16849282195BE09F   1.2097  4.2% 19980 0.0001  0.00 SELECT comments
#    8 0x422390B42D4DD86C7539A5F45EB76A80   1.1721  4.1% 20645 0.0001  0.00 SELECT comments
#    9 0x9F2038550F51B0A3AB05CA526E3FEDDC   0.7333  2.6%   334 0.0022  0.01 INSERT comments
#   10 0xC9383ACA6FF14C29E819735F00B6DBDF   0.6099  2.1%   334 0.0018  0.01 SELECT posts
# MISC 0xMISC
kakkkykakkky

先ほどpost_idに関してindexを貼ったが、ソートもなかなか負荷のかかる処理らしい。
ExtraカラムのUsing filesortがそれ。

mysql> explain select * from comments where post_id = 100 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  | post_id_idx   | post_id_idx | 4       | const |    5 |   100.00 | Using filesort |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+----------------+

ソートにも対応できるように、post_id , created_atの複合indexを作り直そう。

すると、EXPLAINも変わった。「indexを逆向きに読んだ」とある。これは、標準がascでindexが作成されてしまうからか。

mysql> explain select * from comments where post_id = 100 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  | post_id_idx   | post_id_idx | 4       | const |    5 |   100.00 | Backward index scan |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+---------------------+

なら、そもそもdescで複合indexを作ろう。

ALTER TABLE `comments` DROP INDEX post_id_idx, ADD INDEX post_id_idx(`post_id`,`created_at` DESC);

するとExtraが消えた

mysql> explain select * from comments where post_id = 100 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  | post_id_idx   | post_id_idx | 4       | const |    5 |   100.00 | NULL  |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+-------+
1 row in set, 1 warning (0.00 sec)
kakkkykakkky

クラスターインデックスについてちょっとまとめ。

MySQLはクラスターインデックスという構造をとる。
PRIMARY INDEX :
主キーにつけられる。複合でも、それがuniqueであるならつけれる。テーブルにつき1つまで作成可能

SECONDARY INDEX:
PRIMARY INDEX以外のindexはこれ。ノードには、プライマリインデックスのキー値が含まれている。
だから、たとえばCountとかは、わざわざプライマリーインデックスを参照しなくても良かったりする。

SELECT COUNT(*) FROM comments WHERE user_id = 123;のクエリがあったとして、user_udにセカンダリインデックスがはられていれば、プライマリーキーであるidの数はセカンダリーインデックスのツリー上で判別できる。
こういうセカンダリインデックスだけで済むのを Covering Indexというらしい。

わかりやすい図があった


引用：https://www.google.com/url?sa=i&url=https%3A%2F%2Fblog.bytebytego.com%2Fp%2Fdatabase-indexing-strategies-part&psig=AOvVaw1xUbT1248tyVqa6bsY22FD&ust=1757936462132000&source=images&cd=vfe&opi=89978449&ved=0CAMQjB1qFwoTCPjxieaV2I8DFQAAAAAdAAAAABAL

これを実行

ALTER TABLE `comments` ADD INDEX `idx_user_id` (`user_id`);
kakkkykakkky

インデックスの張りすぎにも注意。

  • １クエリに対して使用されるインデックスは1つである
  • データの追加があったとき、インデックスは更新されるので、そこがオーバーヘッドである

必要なところだけ見極めて使う

kakkkykakkky

mysqlのようなBツリーindexだと、全文検索的なのが弱い。
LIKE句だと、hoge%のような前方一致しかインデックスが効かない。

なので文字の形態要素解析などが施された全文検索エンジンを利用したりする。ElasticSearchとか。

一応、mysqlも全文検索indexは対応している。

kakkkykakkky

空間インデックスというものもあるらしい。が、難しいなよくわからん。
緯度経度を使うやつらしいが、、、

わかりやすくまとめると、geminiによれば

空間インデックスは、

1. 地理的な空間を、四角形（タイル）などの単位で階層的に分割・管理します。
2. 各データは、自分がどの「タイル」に属するかという情報を持つようになります。
3. 検索時には、まず該当する「タイル」を特定し、そのタイル内のデータだけを効率的に調べます。

これにより、地図上での「近い」「範囲内にある」といった検索が、飛躍的に高速になります。
kakkkykakkky

出たーN+1について。

digestによるランキングだと、以下は、レスポンスタイムとして短いのに実行数が多くて、ランキング上位に上がっている。

4 0x396201721CD58410E070DA9421CA8C8D   1.7570  6.2% 33625 0.0001  0.01 SELECT users

クエリ自体はPRIMARY INDEXだから高速なのか。

# Query 4: 1.12k QPS, 0.06x concurrency, ID 0x396201721CD58410E070DA9421CA8C8D at byte 14103398
# Scores: V/M = 0.01
# Time range: 2025-09-14T10:16:17 to 2025-09-14T10:16:47
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         14   33625
# Exec time      6      2s    20us    65ms    52us    76us   533us    38us
# Lock time     42    27ms       0   623us       0     1us     3us     1us
# Rows sent      0  32.84k       1       1       1       1       0       1
# Rows examine   0  32.84k       1       1       1       1       0       1
# Query size     4   1.22M      38      38      38      38       0      38
# String:
# Hosts        private-isu-app-1.private-isu_my_network
# Users        root
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us  ##
#   1ms  #
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'users'\G
#    SHOW CREATE TABLE `users`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `users` WHERE `id` = 999\G

1回のクエリで得た結果の件数（これをN件とする）に対して、関連する情報を集めるため、N回以上のクエリを実行してしまうことでアプリケーションのレスポンス速度の低下やデータベースの負荷の原因になることをN+1問題と言います。

このN+1を特定するためには、スロークエリから実行数のおおい箇所を特定するのがいい。らしい。
それで、アプリケーションコードの中でloop処理の中でクエリを発行している箇所を洗い出す必要がある。こればっかりはアプリケーションからのクエリ発行の仕方の問題だから、そっちをみるしかない。

で、特定できた後も、それがアプリケーションにとって本当にボトルネックなのかを調べる。

N+1の対処には以下のような方法がある。

  • JOINで一気にとる
  • キャッシュを使う
    • middlewareを追加する必要
  • 別クエリでpreloadする
    • 複雑なSQL不要
kakkkykakkky

キャッシュを使って解消する方法。

postを30件取ったとして、そこにあるuser_idからまたUser情報を引き直す、典型的なN+1があったとする。
これには、
1. １回目はN+1を許容する

  • postsレコードとる
  • その件数分users引き直す
  • usersをKVSにキャッシュ

2. 2回目からは、usersに関してはキャッシュからひく

しかし、DBのN+1は起きづらくなったにせよ、キャッシュのN+1は残ってる。（結局Users数分引いてるんで）

DBとしてのボトルネックは減らせるが、キャッシュサーバーとアプリケーションサーバーがそれはそれで通信が発生するのでうんまあ。
この通信に関しては、KVSはMulti keysでバルク参照が可能なので、N件分の参照の通信は減らすということは可能。

kakkkykakkky

「別クエリによる」preloadを使う方法。

IN句を使うと、２回のクエリに抑えられる。

  1. postsを取得
  2. user_idsをIN句に配列で指定して一気にusersを取得

preloadについて簡潔にまとめると

preload（プリロード）は、アプリケーションが必要なデータを事前にまとめて読み込んでおくこと。

これにより、後でデータを個別に何度もデータベースに問い合わせる（N+1問題）のを防ぎ、処理を効率化できる。

IN句などを使って、関連データを一括で取得するのが典型的な例。

まとめて情報を取得する、preloadはJOINを使うやり方もあるが、INはクエリがシンプルという利点はある。

「事前に」という文脈がなんか強く聞こえるが、geminiによれば

preloadとは、アプリケーションが必要になる前に、関連データをまとめてデータベースから取得しておくことです。

アプリケーションとして必要になる「前」に、効率よく取得するってことね。

kakkkykakkky

N+１はDBに限ったことではなく、先に見たキャッシュや、APIコールにも言える。

必要な情報をバルク取得できるAPIもケースバイケースでいるよね。

kakkkykakkky

JOINした時に、オプティマイザが思い通りにindexを使ってくれないパターンがある。
（統計情報とか見て判断してるから）
そういう時は、FORCE INDEXを使ってあげれば使ってくれる。

こうしないと、意図せずオプティマイザが、indexを使わずにフルスキャンしてくれちゃう（？）可能性もありうる。

kakkkykakkky

また、INNER JOINを使ってる場合は、STRAIGHT_JOIN も使える。

これは、クエリの順番通りにクエリを実行してくれるというもの。

kakkkykakkky

不要な select * from ...の*には気を付ける。

kakkkykakkky

アプリケーションサーバーとデータベースサーバーは基本TCP通信。

だけど、このTCP通信はコストが高い。
3way handshake.....確かにそれは高くなりそうだな。

さらにTLS暗号化のパケットのやり取りも入ってくるとなると、接続時の通信はボトルネックとなりうる。

そこで、接続を永続化したい。・

goのmysqlドライバーだと

db.SetMaxOpenConns(8) # 同時接続数MAX
db.SetMaxIdleConns(8)  # 同時使ってない接続MAX

永続化の文脈だと、SetMaxIdleConnsaが大きい。
デフォルトは2なので、使ってないと２を超えると毎回接続し直す。

kakkkykakkky

storage量が多かったり、read/writeのI/O負荷が高い場合は、io-waitもボトルネックとなる。

読み取りの高速化対策として、

  • OSはディスクキャッシュとして、一回読んだデータはメモリにキャッシュとして格納して次回からはそっから高速に読み出す機構がある
  • それとは別に、MySQLにもInnoDB Buffer Poolという同様なキャッシュ機構がある

この二つのキャッシュが二重で起こると無駄なので、mysqlのcnfファイルとかに以下を記しておくといい。

innodb_flush_method=O_DIRECT
kakkkykakkky

そして、更新（write）に関して、以下は初しり。

  • データベースの更新クエリ（INSERT、UPDATE、DELETEなど）は、まずディスクキャッシュ（バッファプール） に書き込まれる。

ディスクキャッシュに書き込まれた後、fsyncという機能で、ストレージに同期される。これはOSの命令。
しかし、これにはmsくらいかかったりしてまあまあ時間がかかったりしてるっぽい。

そのため、同期的なfsyncをやめて、非同期のflushに任せる手法もある。
しかし、flushは時間間隔が長い（s~10s）ため、リスキーでもある。

mysqlの設定としてinnodb_flush_log_at_trx_commitという設定値がある。説明は以下。

1: コミットごとにディスクへ同期書き込み。最も安全だが遅い。fsyncと同義

0: 約1秒ごとにディスクへまとめて書き込み。最も速いが、直近1秒のデータが失われる可能性がある。

2: コミットごとにOSキャッシュへ書き込み、約1秒ごとにディスクへ物理書き込み。速さと安全さの中間。
kakkkykakkky

また、MySQL8.0では更新ログがデフォルトで記録される。

これは、リードレプリカなどに非同期で同期するために必要不可欠。レプリケーションには必須。

だけど、ISUCONとかで冗長構成を取らないなら、

disable-log-bin = 1

として無効化してもいいかもしれない。

kakkkykakkky

このレプリカDBへのログのflushも制御可能。

sync_binlog = 1: 最も安全。トランザクションコミットごとにバイナリログをディスクにfsyncします。デフォルト。

sync_binlog = 0: 最も高速。バイナリログはOSのキャッシュに書き込まれ、約1秒ごとにディスクにflushされます。

sync_binlog = N (N>1): トランザクションコミットごとにN回バッファリングされ、N回目にfsync が実行されます。1より高速で、0より安全な中間的な設定です。つまり、N回分のログへの書き込みごとにflushされる
kakkkykakkky

6. リバースプロキシの利用

  • マルチプロセス・シングルスレッド
    • 1リクエスト1 プロセス
    • プロセスを増やせば捌けるリクエストは増えるが、リソースに限界がある
    • プロセスが多すぎるとスケジューラが無駄に切り替えを行い、そのたびにコンテキストスイッチが発生してキャッシュもリセットされ、性能が下がる(C10K問題
    • でもまあシンプル
  • シングルプロセス・マルチスレッド
    • 同じプロセス上のメモリ空間をスレッド間で共有できるため、メモリ節約
    • しかしスレッドの切り替えにはコンテキストスイッチが。
      • これ解決するのは、goroutineかも。
        • 要は、マシンスレッドを意識せずにアプリケーションランタイムの中の軽量スレッドを扱えるから。
    • 順序が保証されない（スケジューラが決めること）、スレッド間のメモリ共有/競合とか、考えるところは多くなる
kakkkykakkky

静的ファイル等は、nginx等のproxyから配信するようにして、アプリケーションサーバーへの負荷を減らすのがいい。

kakkkykakkky

C10K問題とは。

ハードウェアに問題はなくても、クライアントの同時接続数が多すぎると性能が落ちる問題。
マルチプロセスだと、クライアント接続が増えるほどスレッドが増え、メモリを食いまくるし、コンテキストスイッチのオーバーヘッドも辛い。

nginxはこの問題を解決しているらしい。
https://yohei-a.hatenablog.jp/entry/20120504/1336157667

kakkkykakkky

nginxは、マルチプロセス / シングルスレッドらしい。基本的には。
でもそれぞれのプロセスは並行処理を行う。

nginxの worker procesはネットワークI/Oがnon-blockingなんだって。golangと一緒やな。

プロセスは以下の感じだから、workerをうまくスケジューリングしてそう。
master:worker = 1:n

そして多重I/0もサポートしていると。
これは一気にI/Oを行って、readyなものだけ教えてくれたりする効率的なやつっぽい。

とりまnginx、効率的そうだよと言うはなし。