新: Laravel SQLの実行クエリログを出力する

:::note
2024/4/10 追記: こちらの記事をライブラリ化しました。

https://qiita.com/ucan-lab/items/dc33ab7df03ebf485898
:::

## 概要

今回アップデートしたLaravel [10.15.0](Laravelhttps://github.com/laravel/framework/releases/tag/v10.15.0) でSQL実行ログの出力処理が改善されました。

以前にも同様の記事を書いていましたが、こちらはこちらでしばらく使われるかなと思うので、古い記事は残しつづ新しく記事を書きました。

https://qiita.com/ucan-lab/items/753cb9d3e4ceeb245341

Laravelのアップデート内容についてはこちらに詳しく解説された記事がありますのでご紹介します。

https://qiita.com/fuwasegu/items/c6e668dae1546184ff15

## 環境

- PHP: 8.2.8
- Laravel: 10.15.0 以上
- MySQL: 8.0.32

## SQL実行ログを出力する

### サービスプロバイダーの作成

```shell-session
$ php artisan make:provider DatabaseQueryServiceProvider
```

```php:app/Providers/DatabaseQueryServiceProvider.php
<?php

declare(strict_types=1);

namespace App\Providers;

use Illuminate\Database\Events\QueryExecuted;
use Illuminate\Database\Events\TransactionBeginning;
use Illuminate\Database\Events\TransactionCommitted;
use Illuminate\Database\Events\TransactionRolledBack;
use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Event;
use Illuminate\Support\Facades\Log;
use Illuminate\Support\ServiceProvider;

final class DatabaseQueryServiceProvider extends ServiceProvider
{
    /**
     * Register services.
     */
    public function register(): void
    {
        if (config('logging.sql.enable') !== true) {
            return;
        }

        DB::listen(static function(QueryExecuted $event) {
            $sql = $event->connection
                ->getQueryGrammar()
                ->substituteBindingsIntoRawSql(
                    sql: $event->sql,
                    bindings: $event->connection->prepareBindings($event->bindings),
                );

            if ($event->time > config('logging.sql.slow_query_time')) {
                Log::warning(sprintf('%.2f ms, SQL: %s;', $event->time, $sql));
            } else {
                Log::debug(sprintf('%.2f ms, SQL: %s;', $event->time, $sql));
            }
        });

        Event::listen(static fn (TransactionBeginning $event) => Log::debug('START TRANSACTION'));
        Event::listen(static fn (TransactionCommitted $event) => Log::debug('COMMIT'));
        Event::listen(static fn (TransactionRolledBack $event) => Log::debug('ROLLBACK'));
    }
}
```

前のコードより圧倒的にシンプルになりましたにぇ！

### config/app.php

作ったサービスプロバイダーをLaravelに登録します。

```php:config/app.php
    'providers' => ServiceProvider::defaultProviders()->merge([
        // ...
        App\Providers\DatabaseQueryServiceProvider::class,
    ])->toArray(),
```

### config/logging.php

SQLのログのON/OFFを環境ごとに切り替えられるようにします。

```php:config/logging.php
    /*
    |--------------------------------------------------------------------------
    | SQL Log
    |--------------------------------------------------------------------------
    */

    'sql' => [
        'enable' => env('LOG_SQL_ENABLE', false),
        'slow_query_time' => env('LOG_SQL_SLOW_QUERY_TIME', 2000), // ms
    ],
```

### .env

```
LOG_SQL_ENABLE=true
LOG_SQL_SLOW_QUERY_TIME=1000
```

## 動作確認

```php:routes/web.php
<?php

declare(strict_types=1);

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

Route::get('/ok', static function () {
    $user = User::factory()->create();

    return 'ok: ' . $user->name;
});

Route::get('/ng', static function () {
    $user = User::factory()->create();

    try {
        DB::transaction(static function () use ($user) {
            $user->name = 'change name';
            $user->save();

            throw new RuntimeException('ng');
        });
    } catch (RuntimeException $exception) {
        // ...
    }

    $user->refresh();

    return 'ng: ' . $user->name;
});
```

- http://localhost/ok
- http://localhost/ng

```log:storage/logs/laravel.log
// ok のログ
[2023-07-14 09:35:43] local.DEBUG: 10.71 ms, SQL: insert into `users` (`name`, `email`, `email_verified_at`, `password`, `remember_token`, `updated_at`, `created_at`) values ('Prof. Crystel Kemmer', 'rmorissette@example.net', '2023-07-14 09:35:43', '$2y$10$92IXUNpkjO0rOQ5byMi.Ye4oKoEa3Ro9llC/.og/at2.uheWG/igi', 'sTXIOq3yoi', '2023-07-14 09:35:43', '2023-07-14 09:35:43');
```

INSERTのログを確認できればOK

```log:storage/logs/laravel.log
// ng のログ
[2023-07-14 09:35:45] local.DEBUG: 12.34 ms, SQL: insert into `users` (`name`, `email`, `email_verified_at`, `password`, `remember_token`, `updated_at`, `created_at`) values ('Thad Beier', 'agustin29@example.net', '2023-07-14 09:35:45', '$2y$10$92IXUNpkjO0rOQ5byMi.Ye4oKoEa3Ro9llC/.og/at2.uheWG/igi', 'kppSwzWWLs', '2023-07-14 09:35:45', '2023-07-14 09:35:45');  
[2023-07-14 09:35:45] local.DEBUG: START TRANSACTION  
[2023-07-14 09:35:45] local.DEBUG: 1.22 ms, SQL: update `users` set `name` = 'change name', `users`.`updated_at` = '2023-07-14 09:35:45' where `id` = 26;  
[2023-07-14 09:35:45] local.DEBUG: ROLLBACK  
[2023-07-14 09:35:45] local.DEBUG: 2.26 ms, SQL: select * from `users` where `id` = 26 limit 1;  
```

トランザクション張ってロールバックしたところのログが確認できればok

実行時間が1秒以上の場合はWARNINGで出力されます。
また、`SQL: ` から右を1行コピペすればすぐSQLを実行できます。