【n+1問題】クエリを見直してチューニングしてみよう！【変なSQL見える化作戦】 #PHP

本記事は、サムザップ #2 AdventCalendar 2020の12/16の記事です。

この記事では、開発中のフェーズで、リリース直前のスマートフォン向けゲームを開発しているプロジェクトで実際に行ったMySQLのパフォーマンスチューニングのとある取り組み（作戦）について紹介したいと思います。

はじめに

例えば、このような雑なゲームで考えてみます。
以下のように、ユーザが3枚のカードをデッキに所持しているとします。

▼ user_card :ユーザが所持するカードテーブル（card_idはm_cardテーブルのidを指す）

id	user_id	card_id
123	1	1
124	1	2
125	1	3

▼ m_card :カードのマスタデータテーブル

id	name	hp
1	赤たぬき	60
2	青たぬき	42
3	黄たぬき	84

このとき、ユーザが所持しているカードの一覧を表示させようとすると、

user_cardテーブルから所持しているカードを取得
m_cardテーブルから所持しているカードのマスタデータを取得

となるかと思います。

1. user_cardテーブルから所持しているカードを取得

まずは、user_id=1のカードを取得します。

select * from user_card where user_id=1;

これで、このユーザが所持しているカードのcard_idが1,2,3ということがわかります。

2. cardテーブルから所持しているカードのマスタデータを取得

次に、card_idが1,2,3のマスタデータを取得します。

select * from m_card where id = 1;
select * from m_card where id = 2;
select * from m_card where id = 3;

これで、所持しているカードの情報も取得できます。

気になった

さて、ここで気になりました。

select * from m_card where id = 1;
select * from m_card where id = 2;
select * from m_card where id = 3;

これって、IN句を用いれば1クエリで書けるんじゃないかと。

select * from m_card where id in (1,2,3);

ちょっとした工夫だけで、この例だけでもクエリ数が2つ減りました。
1クエリを投げて返ってくるまでのレイテンシも意外と大きく、場合によってはms単位で時間がかかってしまいます。10msだとしても、10クエリを投げるだけで100msもかかります。もし、ユーザが100枚のカードを所持していたら1秒もかかってしまう計算です。

このように、例えばN+1問題のような、アプリ全体を重くする原因になりそうなクエリは良くない！ということで、こういうクエリを変なSQLと呼ぶこととします。

変なSQL見える化作戦

この変なSQLを撲滅させたいと思い、その取り組みを変なSQL見える化作戦としました。もちろん見える化がゴールではなく、撲滅がゴールです。今思えば作戦名も変なSQL撲滅作戦の方が良かったかもしれないですね。

具体的なソースコード等は省略します。また、この記事で紹介するプログラムやログ等の例は実際に出力されたものではなく、この記事用に書いているので、おかしなところがあるかもしれませんが、気にせず良い感じに汲み取ってください。

変なSQLの見える化

撲滅するためにも、まずはこの変なSQLを把握しないといけません。
まず、上記のユーザの所持しているカードの例だと、この所持カード一覧取得APIを叩いたときに流れるSQLをチェックすれば良いと考えました。つまり、そのゲームで用意されている各APIを叩いて、その時のSQLを解析して、変なSQLの有無を確認すれば良いということになります。

前提条件

言語はPHP、データベースにMySQLを利用しています。

APIの叩き方

まずは、APIを叩くところについてです。

今回利用したのはphpunitです。また、このチームでは、API定義を書いていて、その定義ファイルからAPIを叩いてレスポンスが問題ないことのテストコードを自動で生成して書くようにしています。そこに対して、前処理を追加したり、異常系のテストを追記したりしています。もちろん何も書かなくてもAPIを叩くだけのテストは出来上がっています。
（APIの定義は、swaggerでもオリジナルの定義ファイルでも構いません）
例えば、HTTPテスト 8.x Laravel - JSONとの完全一致を検証に書いてあるサンプルコードで例えると、
リクエストパラメータがname、レスポンスがcreatedとする/userのAPIの定義を書いておけば、そこに書いてある（以下のコード）テストをコマンド一つで生成されるようになっています。
※チーム内でのAPIのテストの生成はこれとは違った形で生成していますが、json()を用いているのは同じです。

ExampleTest.php

<?php

class ExampleTest extends TestCase
{
    /**
     * 基本的な機能テストの例
     *
     * @return void
     */
    public function testBasicExample()
    {
        $response = $this->json('POST', '/user', ['name' => 'Sally']);

        $response
            ->assertStatus(201)
            ->assertExactJson([
                'created' => true,
            ]);
    }
}

そのため、全てのAPIの定義ファイルが存在するので、基本的には全てのAPIを叩くテストはそれぞれ最低1つは書かれていることになります。（ここではそのテストによるカバレッジは無視している）

APIを叩いたときに発行されるSQLの取得方法

APIを叩いたときに流れるSQLだけを取得方法についてです。
SQLログは、言語に依存しないように、MySQLのgeneral_logを使用することにしました。

「APIを叩いたときに流れるSQLだけ」を取得するために、先程紹介したテストコードの$this->json()に注目しました。このメソッドを叩く処理は各APIを叩いていることとほぼ同じかなと思います。（全く同じではないけど、APIが叩かれたときの処理が実行されるという意味ではほぼ同じという表現）
すなわち、json()の処理の間に出力されるgeneral.logだけを見れば良いということになります。

ここでは、複雑なことは考えません。

json()が呼ばれる直前にgeneral.logの中身を削除する
json()の処理をさせる
json()が終わった後にgeneral.logの中身を取得する

以上のようにすれば、そのAPIが叩かれるときに発行されるクエリを取得することができます。

元のテストに対して、なるべく手を加えずに変なSQL見える化作戦を実施したかったので、以下のようなTestCaseを継承したクラスを作成しました。

TestCaseForSqlCheck

<?php

abstract class TestCaseForSqlCheck extends TestCase
{
    public function json($method, $uri, array $data = [], array $headers = [])
    {
        // 1. general.logの中身を削除する
        // ~~~general.logを削除する処理を書く~~~

        // 2. APIを叩く
        parent::json($method, $uri, $data, $headers);

        // 3. general.logの中身を取得する
        //~~~general.logを取得してゴニョゴニョする処理を書く~~~

    }
}

後は、変なSQL見える化作戦でSQLをチェックするときだけ、各APIのテストの継承元をこのクラスに変更するだけです。

$ git diff ExampleTest.php
- class ExampleTest extends TestCase
+ class ExampleTest extends TestCaseForSqlCheck

全APIのテストを一括で変更する必要があると思いますが、sedコマンド等を利用すれば、コマンド一つで一括置換ができるかと思います。

変なSQLの抽出

ここまでで、各APIを叩いたときに発行されるクエリログを取得することができるようになりました。（APIを叩いたときに出力されるgeneral.logが取得できた）

さて、ここで変なSQLの定義を改めて考えてみましょう。

同じようなクエリが2回以上発行されるもの（複数回投げられていたら疑っても良さそう）
update文は1クエリにまとめるとめんどくさいので、ここでは無視する（insertは楽でしょ）

同じようなクエリとはどういうことなのか？一番最初の例で見てみましょう。

select * from m_card where id = 1;
select * from m_card where id = 2;
select * from m_card where id = 3;

idが1か2か3の違いですね。ということは、PREPARE構文を利用すれば良さそうに見えます。
上記の例だと、以下のようにクエリログが吐かれるかと思います。
（わかりやすくPrepareだけにフィルタリングしています。grep Prepareみたいなイメージ。また、以下は実際に出力されたクエリログではなく、手で書いたログなので、general.logの出力フォーマットとは少し異なります）

Prepare   select * from m_card where id = ?
Prepare   select * from m_card where id = ?
Prepare   select * from m_card where id = ?

全く同じクエリが発行されていることがわかりますね！これなら判別することができます。
MySQLで例えるなら、このログに対して、select sql,count(*) from general.log group by sqlみたいなことをすれば良さそうですね！

ということで、変なSQLの抽出についての処理をまとめると以下になるかと思います。

general.logのPrepareだけをフィルタリングする（grepするイメージ）
update文は除外する
同じクエリをグルーピングしてカウントする
カウントした結果が2回以上のものを変なSQL候補とする

また、全体のphpunitを実行して各APIに対しての変なSQLを集計した後処理として、ログを集計するために、phpunitのTestRunnerの拡張のexecuteAfterLastTest()を利用することで、集計を楽にすることができました。

アウトプットイメージ

上記のような手順を行い、各APIごとの変なSQLとその出現回数をログとして出力させます。

解析結果出力例

URL: post /user
2回: select * from user where id = ?

URL: get /user
2回: select * from user where id = ?
3回: select * from m_card where id = ?

URL: /card
2回: select * from user where id = ?
3回: select * from m_card where id = ?

項目数: 5個

変なSQLが見えましたね。これで見える化は完了です！
上記の解析結果出力例は変なSQLは2種類ですが、項目数を5個として数えています。
この項目数が、サービス全体に与える影響力に比例しそうだったので、この数値を追うことにしました。select * from user where id = ?このクエリがいろんなところに影響しているということですね。
この例に関しては、この2種類の変なSQLを撲滅させれば撲滅完了ということになります。

撲滅フェーズ

さて、ここまでの手順で見える化が完了しました。
撲滅のために、以下について紹介したいと思います。

自動実行させる
結果を見えるところに出力させる
撲滅順序の決定
チームメンバーを巻き込む
実行タイミング・周期

自動実行させる

定期的に上記の見える化の処理を実行し、解析するようにします。
そのためにも、人間が手動で実行していたら、例えばその人が一回忘れたらおそらく一生再実行されることはないと思ってます。また、その人が異動や退職したりすることでも、この作戦はそこで停止してしまう可能性があります。そのためにも、実行者は人間ではなくcron等を用いて自動実行をするようにしました。

そこで、今回はGithub Actionsを利用することにしました。サーバサイドだけで環境を用意でき、また、PHPソースをgit管理したときに、同じレポジトリでその実行フローも管理することができたりと、導入がとてもしやすい印象なので、Github Actionsを選択しました。

Github Actions上のフローをざっくりと説明すると、以下のような流れになるかと思います。

環境構築（composer install等。docker-composeを使ってローカル開発環境と同じにすることで、デバッグしやすくしている）
phpunitの設定（TestRunnerのエクステンションを利用するようにphpunit.xmlの編集をしたりする）
各TestCaseの継承先を上で紹介したTestCaseForSqlCheckに変更する（sedコマンドで一発）
phpunitを実行してAPIのテストを行う
最後に解析結果を出力する

そして、Github Actionsの実行結果は以下のようになります。（スクショは自動実行ではなく、手動実行の結果ですがほぼ表示は変わらないです。）

このようにして、Github Actions上で実行・確認ができるようになりました。

結果を見えるところに出力させる

解析結果を出力するのですが、それがGithub Actionsのコンソールやどこかのスプレッドシートやファイルに出力するだけではダメです。みんなが嫌でも目に入るところに出力する必要があります。
そこで、今回はSlackに投稿するようにしました。社内でのチャット・連絡手段はSlackを使用しているので、みんなが必ず毎日何度も目にします。見ないと仕事になりませんよね。
Slackでも、それ用のチャンネルを作成して出力するのも良くないと思います。ミュートにされたらおしまいです。そのため、例えばエンジニアが普段連絡をするようなチャンネルにあえて投稿してやります。
あとは投稿されたらできるだけ毎回違うリアクションを速攻でつけると、みんなはそのリアクションが気になって解析結果を見てしまうと思います。

そのようなちょっとした工夫を積み重ねてチームにちょっとずつ浸透させていきました。

撲滅順序の決定

時間には制限があります。もしかしたら全ての変なSQLを撲滅することができないかもしれないです。
そこで、それぞれの変なSQLに対して、優先度をつけます。

優先度は以下のように分けました。

優先度レベル	内容	対応方針
S	状況・条件によっては3回以上のクエリが投げられる or 固定だけど多い（n+1問題みたいなもの）	リリースまでに直す
A	3〜5回だけど、どんな状況・条件でも必ず固定の回数だけ投げられる or 不要なクエリが投げられている	リリースまでに直したい
B	必ず2回だけ	いつかは直したい
D	仕様上仕方がない or 作り上仕方がない	放置する。変なSQLではない！

優先度レベルがSには、マスタデータの状態、データベース、ユーザデータによってものすごく増える可能性があるものを設定しています。
一番最初の例のように、ユーザのカードの所持枚数が100枚とかになると100クエリ投げられてしまう、のように無限ほどではないけど、どんどん増えてしまうものを最優先で撲滅しました。

select * from m_card where id = 1;
select * from m_card where id = 2;
select * from m_card where id = 3;

また、例えばフレンドになるという処理を考えたときに、フレンド上限の判定をする場合、自分のフレンド数と相手のフレンド数をチェックする必要があると思います。その時のフレンド数を取得するクエリが2回になったとしたら、それは必ず2回以内しか投げられません。3人以上のフレンド数を取得する必要はありません。でも、きっと一回で取得することも可能だと思います。そういった場合は優先度レベルをBとしています。

実際にやってみて、優先度レベルがAになるのは、処理をざっくりみただけじゃわからないけど、でもヤバそう、みたいなざっくりとした感覚で設定していました。

また、優先度をBにしたけど、直そうと思ったら「システムを作り直す」「機能自体を作り変えなきゃいけない」みたいなことが発生した場合は優先度レベルはDに下がります。
この作戦に対しての工数はそこまでかけ過ぎないことが大事だと思っています。

チームメンバーを巻き込む

変なSQLの撲滅運動は、1人でやらず、みんなでやりましょう。
みんなで実施することで、チームメンバー全員が変なSQLに対する感度が上がり、これを通してよりパフォーマンスを意識したプログラムを書けるようになると思います。
また、1人だとなかなか終わらないので、みんなで協力しましょう。

実行タイミング・周期

さて、優先度が決まったからと言って、片っ端からどんどん片付けていくのはよくありません。最初から全速力で走ると、すぐに疲れてしまいます。
そこで、今回は「1週間に1種類の変なSQLだけ撲滅させる」としました。

「1週間に1つだけなら、なんとなくできそうな感じがしませんか？」

また、毎週木曜日にチーム内のサーバ定例MTGを実施しているので、そこでその週の振り返りをするようにしていました。
そのMTGの変なSQL見える化作戦で話すこととしては、以下になります。

現状の変なSQL一覧の確認
この一週間で増えた/減った項目の確認
次の一週間でどれを撲滅させるかの決定

現状の変なSQL一覧の確認

変なSQLを一覧で可視化します。今回はこれをスプレッドシート等にまとめて管理します。実際に使用したスプレッドシートを紹介したいと思います。
（ここだけ貼り付けがアナログですね。）

スプレッドシートにした大きな理由は特にありません。とりあえず変なSQLの一覧が見えてフィルタとか色つけたりできればいいなって思ったくらいなので、今回はスプレッドシートを使用しました。
こうやってみると、このチームのシステムは変なSQLがたくさんありますが、このスクショはこれでも一部なんです。

この一週間で増えた/減った項目の確認

この一週間でどれだけ減ったかを増えたかを確認します。もちろん開発をしていれば増える可能性もあります。また、直したと思ったらいつの間にか別の変なSQLが出現している場合もあります。そういったのを確認して、認識をあわせます。

確認するために、前回の解析結果と今回の解析結果を単純にdiffを取るだけです。Slackをちょっと遡れば前回の結果が投稿されているので、ファイルは作成する必要はありますが、コマンド一発で簡単に差分の確認ができます。

$ diff 今回.txt 前回.txt

また、減っていくと気持ちが良いですよね。「今週は○項目減って、S,A,Bレベルが残り○○項目です！」っていうのが意外と楽しいんですよね。これを発表するとメンバーから拍手が聞こえたりするのでちょっと盛り上がります。
しかも1種類だけの変なSQLを撲滅させたとしても、それが複数のAPIで発行されている可能性があるので、複数項目を撲滅させることができるのです。
なので、例えば変なSQLが項目数が50項目あったとしても、50回撲滅させる必要はなく、もしかしたら実際には20種類の変なSQLしかない可能性もあるのです。

次の一週間でどれを撲滅させるかの決定

そして、MTGの最後にはこの一週間で撲滅させる変なSQLをみんなに決めてもらいます。ここがポイントです。「自分はこれをやります」って言ってしまったら、翌週のMTGまでに片付けないといけなくなりますよね。
また、周りの人がちゃんと撲滅させているのに、1人だけ撲滅してなかったら焦りますよね。そういう意味でも、ちゃんと毎週1人1種類ずつではありますが、撲滅させていきます。

決定したら、あとはその一週間のうちで気が向いたときに対応してもらっています。もちろん、開発が遅れてはいけないので、そちらを優先しつつも、なるべく撲滅してもらうようにしていました。

バッチの実行タイミング

ということで、毎週実施のサーバ定例MTGまでには、解析してその実行結果をスプレッドシートにまとめておく必要があります。
そこで、木曜日の朝に、バッチの実行設定をしておきます。
出社した頃には解析結果が出てて、それを集計してサーバ定例に挑む。そのような感じで毎週実施してました。

そのため、Github Actionsのスケジュールで朝7時に設定していました。

code_check.yml

name: 変なSQL見える化

on:
  schedule:
    #毎週木曜日の7(-2+9)時(=水曜日22時)実行するように設定
    - cron:  '0 22 * * 3'

Github Actionsを実行していると、7時にcron実行の設定をしても7時ちょうどには実行されなく、遅いときは8時直前になることもあったりするのです。
そのため、ものすごい余裕をもって早めに実行するように設定しています。

そして、撲滅へ

このようにして、毎週撲滅していきます。
実際にやってみて、今回はおよそ2ヶ月半くらいでS,A,Bレベルの変なSQLの撲滅に成功しました。

もちろん最初の方に書きましたが、phpunitのAPIテストでカバーしている処理に限りますが、これで把握している変なSQLはなくなったはずです。

最後に

この作戦は、サービス全体のパフォーマンス・チューニングの役立つ情報の1つになると思います。
これにより、1リクエストあたりのクエリが減ることで、DBの負荷も下がり、最終的にコスト削減にも繋がり、結果利益の向上にも貢献できます。

また、この作戦を実施する目的はそれだけではなく、実はチームメンバーにもパフォーマンスを気にする癖をつけてもらいたいと思って実施しました。SQLを意識することで、よりパフォーマンスの高いコードを書けるようになったらいいなと思っていました。（これはまだチームメンバーに伝えておりませんwこの記事を通して伝えることになりそうです。。）

おまけ

ここからはおまけです。上で紹介しなかった工夫をここで軽く触れておこうと思います。

どのテストによる変なSQLかの出力

各API毎に変なSQLとその回数を出力させるだけではなく、どのテストを実行したときに発行されたSQLなのかも一緒に出力するようにしました。
これをやることで、どのテストで発行されたかを調査する時間がなくなり、業務効率がちょっぴり上がります。

雑実装ですが、以下のようにどこテストから呼ばれているかをjson()内から知ることができます。

json()内の処理

$backTrace = debug_backtrace();
$functionName = $backTrace[2]['function'];
$className = $backTrace[2]['class'];

json()の中身で実際にAPIを叩いちゃう

元のjson()は擬似的にリクエストを作成してPHPの処理をさせているだけですが、実際にcurlしてしまおうという考えです。
処理するプロセスを分けることで、例えばPHP側で保持しているクエリキャッシュやstatic変数に保存している値を利用しないようにして、よりリアルな変なSQLを知ることができるようになります。

雑ではありますが、だいたいこんな感じの処理でjsonメソッドを置き換えることができました。
※nginxのコンテナを利用しているので、リクエスト先がnginxになっています。

    public function json($method, $uri, array $data = [], array $headers = [])
    {
        $content = json_encode($data, JSON_UNESCAPED_UNICODE);
        $url = 'http://nginx' . $uri;
        $header = [
            "Accept': 'application/json",
            "Content-Type: Content-Type: application/json",
            "Content-Length: " . strlen($content),
            'RealTime: ' . $realTime,
        ];
        $options = ['http' => [
            'header' => implode("\r\n", $header),
            'method' => $method,
            'content' => $content,
            'ignore_errors' => true,
        ]];
        $response = file_get_contents($url, false, stream_context_create($options));
        preg_match('/HTTP\/1\.[0|1|x] ([0-9]{3})/', $http_response_header[0], $matches);
        $statusCode = $matches[1];
        $this->response = new JsonResponse();
        $this->response->setData(json_decode($response, true));
        $this->response->setStatusCode($statusCode);
    }

カバレッジが気になる

APIのテストを実施したときのテストのカバレッジを計測して可視化することで、どの処理が網羅できてそうかがわかります。

去年のアドベントカレンダーで書いた「テストコードのカバレッジの見える化をして、テストを書く文化を作ろう。」でも紹介しましたが、phpunitで簡単にカバレッジを可視化することができます。
また、APIのテスト(tests/Controller)とロジックのテスト(tests/Logic)のディレクトリを分けておくことで、APIだけのテストを実施することも可能となります。

$ phpunit tests/Controller/

手軽に実行できるようにしておく

GithubのレポジトリのActionsのタブから、簡単に解析をするようにしています。

これは、workflowのトリガーのところに、workflow_dispatchイベントを設定することで簡単に実現することができます。
参考：ワークフローの手動実行 - GitHub Docs

code_check.yml

name: 変なSQL見える化

on:
  schedule:
    #毎週木曜日の7(-2+9)時(=水曜日22時)実行するように設定
    - cron:  '0 22 * * 3'
  workflow_dispatch:
    inputs:
      post_slack:
        description: 'post slack'
        required: false
        default: 'false'

これで、Jenkinsのジョブを実行する感覚で、ブランチを指定して解析処理を開始できるようになりました。

また、定期実行時はslackに投稿されるようになっているので、手動実行時はSlack投稿されないように、入力パラメータを設けてdefault値をfalseで設定しています。

ワークフロー内では、例えば以下のような条件式を書くことで簡単にSlack投稿の処理をさせないようにすることも可能です。

ymlcode_check.yml

        if [ "${{ github.event.inputs.post_slack }}" != "false" ]; then
          # slack投稿処理
        fi

これで、変なSQLの撲滅作業時に、ちゃんと撲滅できたかな？というチェックをすることができるようになりますね。

おまけは増え続ける

おまけでいくつか紹介しましたが、この作戦を続けていくと、どんどん工夫は増えていくと思います。
実際に、毎週開催のサーバ定例MTGのときにもチームの皆さんからフィードバックをもらって、例えば「どのテストによる変なSQLかが知りたい！」ってことで、おまけに書いてある機能を追加したりしています。
もしかしたら、この記事を投稿した翌日にも新しい機能が追加されているかもしれません。