データベースの渋滞を見つけよう ​

最初に使う懐中電灯は、**slow query log（スロークエリログ）**です。

Webアプリは、データベースへ「この椅子の最新状態を教えて」のような問い合わせを送ります。この問い合わせをSQL（エスキューエル）、SQLを実行した1回分をquery（クエリ）と呼びます。スロークエリログには、それぞれのSQLにかかった時間や、調べた行数が記録されます。

名前には「slow」とありますが、基準時間を0秒にすれば速いSQLも含めて記録できます。1回は一瞬でも、何万回も呼ばれるSQLを見つけられるのがうれしいところです。

人間が見る数字は、まず3つ ​

• Time: その形のSQLに使った時間。1回の時間と合計時間を区別する
• Count: 何回実行されたか
• Rows_examined: 答えを作るために、データベースが何行調べたか

「1回が遅い」「回数が多すぎる」「答えは1行なのに何万行も探している」は、それぞれ別の問題です。出力全部を理解しようとしなくて大丈夫。まずはこの3つから、一番もったいなさそうなSQLを探します。

Agentへのプロンプト ​

環境によってMySQLとMariaDBの設定場所も、入っている集計ツールも違います。導入コマンドを人間が写経する代わりに、Agentへ実機を調べてもらいます。

次はslow query logだけを手がかりに改善してください。

- DBの種類、バージョン、読み込まれている設定ファイルを実機で調べる
- 全SQLを記録できるようにし、再起動後に設定値が反映されたことを確認する
- 解析ツールは、まずサーバーに入っているものを探す。なければ公式の配布元を確認して導入する
- ベンチ前にログを空にし、変更前のベンチマークを1回実行する
- SQLごとの合計時間、回数、調べた行数、返した行数を比べる
- 遅い理由をコードとEXPLAINで確かめ、観測とつながる変更だけを行う
- 関連する変更は一度にまとめてよい。ただし、変更後は必ず再計測する
- 初期化後にもindexや追加テーブルが残るよう、初期化SQLも更新する
- スコア、観測、仮説、変更、再計測結果を表へ追記する

専門用語を使うときは、その場で短く意味を説明してください。

次はslow query logだけを手がかりに改善してください。

- DBの種類、バージョン、読み込まれている設定ファイルを実機で調べる
- 全SQLを記録できるようにし、再起動後に設定値が反映されたことを確認する
- 解析ツールは、まずサーバーに入っているものを探す。なければ公式の配布元を確認して導入する
- ベンチ前にログを空にし、変更前のベンチマークを1回実行する
- SQLごとの合計時間、回数、調べた行数、返した行数を比べる
- 遅い理由をコードとEXPLAINで確かめ、観測とつながる変更だけを行う
- 関連する変更は一度にまとめてよい。ただし、変更後は必ず再計測する
- 初期化後にもindexや追加テーブルが残るよう、初期化SQLも更新する
- スコア、観測、仮説、変更、再計測結果を表へ追記する

専門用語を使うときは、その場で短く意味を説明してください。

実際に見えた、最初の大渋滞 ​

今回の環境では、MariaDB付属のmysqldumpslowで集計しました。ログを有効にした状態のスコアは1,431でした。計測前の1,284より少し高いですが、この程度の揺れで「ログを入れたら速くなった」とは判断しません。

目立った数字は次のとおりでした。

最新の1件だけ欲しいのに、平均約4万行を調べています。ここで「データベースが遅い」とぼんやり言うのではなく、ISUの識別子と時刻を組み合わせた検索が苦手、という具体的な仮説が立ちます。

1回目の改善 ​

Agentは、同じ原因につながる変更をまとめて入れました。

• (jia_isu_uuid, timestamp)のindexを追加し、「このISUの最新」を後ろからすぐ探せるようにした
• グラフ用SQLを全期間から、画面に必要な24時間へ絞った
• 10件届く状態を1件ずつ保存せず、1回のSQLでまとめて保存した
• 読み取りだけの処理から不要なtransactionを外した
• trendの「ISUを1台読むたび、さらに状態を全部読む」繰り返しを、まとめたSQLに変えた

indexは、本の巻末にある索引のようなものです。すべてのページをめくらず、目的の場所へ飛べます。transactionは複数の変更をひとまとまりとして扱う仕組みですが、読むだけの場所で細かく開始・確定していたため、その費用を減らしました。

再計測のスコアは7,125。約5倍になりました。そして同じログをもう一度見ると、最新1件のSQLは平均1行を調べるだけになっています。仮説は当たっていそうです。

速くなると、次の渋滞が見える ​

ここで終わらず、7,125のベンチで取ったログを読み直します。すると順位が入れ替わりました。

• trend用にまとめたSQL: 3,119回、合計68秒
• 状態一覧のSQL: 1,194回で、約50万行をアプリへ返している

1回目の変更でtrendの無駄な繰り返しは減りましたが、「毎回、全ISUの最新状態を計算する」仕事そのものは残っています。また状態一覧は画面へ最大20件しか返さないのに、絞り込みをGoで行うため、DBから大量に受け取っていました。

そこで2回目は、少し構造を変えました。

• 各ISUの最新状態だけを置く小さなcache tableを作る
• 状態が届くたびに、履歴の保存と一緒にcacheも更新する
• trendは履歴全体を集計せず、そのcacheを読む
• 状態レベルの絞り込みとLIMIT 20をSQL側へ移す

cache（キャッシュ）は、何度も計算する答えをすぐ読める場所へ置いておく仕組みです。データを二重に持つぶん、更新忘れには注意が必要です。そのため、初期化時の再構築と、元データの最新時刻との一致も検証しました。

結果は18,572、timeoutは2件でした。状態一覧が調べて返す行数は平均約20行になり、上位SQLの実行時間は今回の集計精度では0.00秒に丸まるところまで下がりました。

大事なのは、最初からcache tableを思いつくことではありません。計測するたびに一番上が入れ替わり、その数字に合わせて次の変更を選んだことです。