⛳

Laravel 9.18 累積で遅いSQLクエリを確認できる機能を試す

2022/06/23に公開

Laravel

tech

前書き

この機能を一言で何と呼べば良いのか分かりませんが、「累積でのクエリ時間が一定時間を経過した際にその SQL クエリを確認できる」機能が、Ver. 9.18.0 で加わりましたので、試してみました。

なお、あくまで「累積」です。各クエリごとの時間ではなく、1リクエストなどにおける累積でのクエリです。0.5秒のクエリが3本走れば、合計1.5秒になりますが、その時間でのチェックになります。（各クエリでの確認については、一番下で）

参考リンク
GitHub: Allow handling cumulative query duration limit per DB connection #42744
本家ドキュメント（あまり詳しく書かれていない）

本題

今回は、その基準（許容）時間を1秒（1000ms）とすることにします。この時間以上掛かるようなら、SQL のログを取るという事にします。
少し雑ですいませんが、まず web.php に以下のように書きます。

web.php

<?php

use App\Models\User;
use Illuminate\Support\Facades\Route;

Route::get('log', function () {
    User::select(['id', 'name'])->get();
    \DB::select('select sleep(0.5);');
    \DB::select('select sleep(0.4);');
    \DB::select('select sleep(0.3);'); // ここで1秒を超える
    \DB::select('select sleep(0.2);');

    return 'hello';
});

この時、何（どこ）をログりたいか、という話はあると思います。

一番時間の掛かった 0.5 秒のクエリをログりたいか、
1秒を超えた時点の0.3秒のクエリをログりたいか、
又は、1秒を超えるまでのクエリ全部をログりたいか、
はたまた、クエリではなく、リクエストされたURLをログりたいとか

まずは、2番について見て行き、その後、3番について見て行きます。

その前に、SQLのログを取りたいと言えば、@ucan-lab さんの下記の記事が大変参考になりますね。いつも助けられています。
Laravel SQLの実行クエリログを出力する

ということで、肝心の記述を AppServiceProvider に書く事にします。今回は、logger() ヘルパ関数を使って、debug レベルでログを取ります。

AppServiceProvider.php

    public function boot()
    {
        \DB::whenQueryingForLongerThan(1000, function ($connection, $event) {
            logger($event->sql);
        });
    }

リクエストを送信すると、以下のようにログられます。

[2022-06-22 22:41:02] local.DEBUG: select sleep(0.3);

ほう。という感じです。ただ、あまりにもシンプル過ぎます。SQL の実行時間やバインディングされた値なども知りたいですね。
試しに、先の SQL 文を下記のように変えて試してみます。（やや無理矢理ですが😅）

# Before
\DB::select('select sleep(0.3);'); // ここで1秒を超える

# After
\DB::select('select sleep(0.3) where 1 = ?;', [1]); // ここで1秒を超える

そして、ログの取得は、下記のように変えます。

# Before
logger($event->sql);

# After
logger($event->sql, [
    'time' => $event->time,
    'bindings' => $event->bindings,
]);

そうすると、今度はこうなります。

[2022-06-22 22:45:06] local.DEBUG: select sleep(0.3) where 1 = ?; {"time":301.66,"bindings":[1]}

取りあえず目的は達成できました。

では今度は、1秒を超えるまでのクエリ全部をログることにします。
こんな感じにすれば、大丈夫そうです。

AppServiceProvider.php

    public function boot()
    {
        \DB::enableQueryLog(); // こちら忘れずに

        \DB::whenQueryingForLongerThan(1000, function ($connection, $event) {
            logger($connection->getQueryLog()); // ここ

            logger($event->sql, [
                'time' => $event->time,
                'bindings' => $event->bindings,
            ]);

            logger('合計時間：'.$connection->totalQueryDuration().' ms'); // ついで
        });
    }

logger($connection->getQueryLog()); って箇所がポイントです。ここは、先程の1秒を超えた時点のクエリは含まれていません。（ですので、クエリは重複しません）

以下の感じでログられます。

[2022-06-22 22:48:07] local.DEBUG: array (
  0 =>
  array (
    'query' => 'select `id`, `name` from `users`',
    'bindings' =>
    array (
    ),
    'time' => 1.67,
  ),
  1 =>
  array (
    'query' => 'select sleep(0.5);',
    'bindings' =>
    array (
    ),
    'time' => 500.51,
  ),
  2 =>
  array (
    'query' => 'select sleep(0.4);',
    'bindings' =>
    array (
    ),
    'time' => 400.52,
  ),
)
[2022-06-22 22:48:07] local.DEBUG: select sleep(0.3) where 1 = ?; {"time":300.53,"bindings":[1]}
[2022-06-22 22:48:07] local.DEBUG: 合計時間：1203.23 ms

これでひとまず OK でしょうか。（合計時間は、あくまで1秒を超えた時点までのクエリ合計時間ですね）

各クエリでの時間の掛かるクエリをログりたい時。

以下の感じでいけます。（プルリク参考）

AppServiceProvider.php

    public function boot()
    {
        \DB::listen(function ($event) {
            if ($event->time > 350) {
                logger($event->sql, [
                    'time' => $event->time,
                    'bindings' => $event->bindings,
                ]);
            }
        });
    }

これでリクエストを送ると、350ミリ秒を超えるクエリがログられる為、以下のようになります。

[2022-06-22 22:52:25] local.DEBUG: select sleep(0.5); {"time":501.2,"bindings":[]}
[2022-06-22 22:52:25] local.DEBUG: select sleep(0.4); {"time":400.82,"bindings":[]}

いい感じですね。

雑感

こちらも @timacdonald さんのプルリクです。ホットですね❤️‍🔥

間違い等ありましたら、コメント下さい。

前書き

本題

各クエリでの時間の掛かるクエリをログりたい時。

雑感

Discussion