LaravelでのSQLログ出力を実装しよう

こんにちは。PHPer田中(雅)です。
Laravelを使う中で、パフォーマンス調査を行うため、画面ごとの操作に実行されているSQLとその実行時間を確認する必要がありました。
今回の記事では、その手間を解消するために、LaravelでSQLログの機能を実装いたしましたのでご紹介します。

使用環境

今回使用している環境です。
Laravel : 6.6.1
php : 7.4
barryvdh/laravel-debugbar : 3.2
MySQL : 14.14

実装するもの

すぐに実行可能なSQLを出力できる
.envを参照し、環境に応じて出力の有無を切り替えられる
SQLログは別のファイルにする

という部分をゴールとし、実装を行っていきます。

すぐに実行可能なSQLを出力する

barryvdh/laravel-debugbarで使われているライブラリを利用して、実装を行っていきます。
すべてのSQL実行時にログ出力を行いたいので、サービスの初期処理として登録するための実装を

app/Providers/AppServiceProvider.php

に行います。
※ 最後に全文を載せてあります。

$queryCollector = new QueryCollector();
$queryCollector->setDataFormatter(new QueryFormatter());
// bindを当て込むための設定
$queryCollector->setRenderSqlWithParams(true);

こちらではフォーマッターとして何を使用するかと、bind変数を実際の値に当て込むための設定を行っています。

$db::listen(
    function ($query, $bindings = null, $time = null, $connectionName = null) use ($logOutPut, $db, $queryCollector) {
        if ($query instanceof \Illuminate\Database\Events\QueryExecuted) {
            $bindings = $query->bindings;
            $time = $query->time;
            $connection = $query->connection;

            $query = $query->sql;
        } else {
            $connection = $db->connection($connectionName);
        }

        $queryCollector->addQuery($query, $bindings, $time, $connection);

        // SQLの実行情報を取得
        $sqlExecCollect = $queryCollector->collect();
        foreach ($sqlExecCollect['statements'] as $sqlStatement) {
            // ログに出力するデータを作成
            $logOutPut['sql'] = $sqlStatement['sql'];
            $logOutPut['duration_str'] = $sqlStatement['duration_str'];
        }
        // ログを加工しやすいようにtabで出力
        Log::channel('sqllog')->debug(json_encode($logOutPut, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE));
    }
);

こちらでは実行されているSQL,bind変数などをコレクタに渡しています。
また、addQuery内では、bind変数を型に合わせて変換、collect() については、整形された情報を取得しています。

.envを参照し、環境に応じて出力の有無を切り替えられる

環境ごとに設定値を変更できるようにする「.env」を見ることでデバッグ設定がある場合は、不要なログを出さないようにします。

.envでSQLのログ出力が有効になる設定はこちらです。

APP_DEBUG=true

以下の内容を

app/Providers/AppServiceProvider.php

に記述します。

// .envを見てログ出力を行うかどうかを判別
if (env('APP_DEBUG') !== true) {
    return;
}

SQLログは別のファイルにする

以下の内容を

config/logging.php

に記述します。

'stack' => [
    'driver' => 'stack',
    'channels' => ['daily', 'sqllog'], // sqllogを追加
    'ignore_exceptions' => false,
],

追加設定

'sqllog' => [
    'driver' => 'daily',
    'path' => storage_path('logs/sql.log'),
    'level' => 'debug',
],

app/Providers/AppServiceProvider.php

上述の通りですが、channelを指定することでlogging.phpで設定したものを適用できます。

Log::channel('sqllog')->debug(...);

できたもの

今回実装したコードの出力結果は以下のとおりです。

[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `users` order by `users`.`id` asc limit 10 offset 0","duration_str":"32.77ms"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 17 limit 1","duration_str":"1.7ms"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 6 limit 1","duration_str":"590μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 11 limit 1","duration_str":"700μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 11 limit 1","duration_str":"570μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 14 limit 1","duration_str":"560μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 9 limit 1","duration_str":"660μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 16 limit 1","duration_str":"560μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 14 limit 1","duration_str":"900μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 17 limit 1","duration_str":"630μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `prefectures` where `prefectures`.`id` = 14 limit 1","duration_str":"650μs"}
[2019-12-09 14:26:08] local.DEBUG: {"execType":"web","method":"GET","URL":"http://example.com/user/show","sql":"select *
from `users` order by `users`.`id` asc limit 10 offset 10","duration_str":"620μs"}

上記のようなログ出力となり
「execType」は実行方法で「web」か「console(コマンドやcron実行)」
「duration_str」はSQLの実行時間
他についてはリクエスト時の情報と実行されたSQL文です。

app/Providers/AppServiceProvider.php の全文

こちらが今回実装した全文です。

<?php

namespace App\Providers;

use Illuminate\Support\ServiceProvider;
use Log;
use DB;
use Illuminate\Support\Facades\App;
use Barryvdh\Debugbar\DataCollector\QueryCollector;
use Barryvdh\Debugbar\DataFormatter\QueryFormatter;

class AppServiceProvider extends ServiceProvider
{
    /**
     * Register any application services.
     *
     * @return void
     */
    public function register()
    {
        // .envを見てログ出力を行うかどうかを判別
        if (env('APP_DEBUG') !== true) {
            return;
        }

        $queryCollector = new QueryCollector();
        $queryCollector->setDataFormatter(new QueryFormatter());
        // bindを当て込むための設定
        $queryCollector->setRenderSqlWithParams(true);

        $db = new DB();
        $logOutPut = [];

        // コンソール実行かどうか
        if (App::runningInConsole()) {
            $logOutPut['execType'] = 'console';
            $logOutPut['execCommand'] = implode(' ', $_SERVER['argv']);
        } else {
            $logOutPut['execType'] = 'web';
            $logOutPut['method'] = $_SERVER['REQUEST_METHOD'];
            $logOutPut['URL'] = url()->full();
        }
        $db::listen(
            function ($query, $bindings = null, $time = null, $connectionName = null) use ($logOutPut, $db, $queryCollector) {
                if ($query instanceof \Illuminate\Database\Events\QueryExecuted) {
                    $bindings = $query->bindings;
                    $time = $query->time;
                    $connection = $query->connection;

                    $query = $query->sql;
                } else {
                    $connection = $db->connection($connectionName);
                }

                $queryCollector->addQuery((string) $query, $bindings, $time, $connection);

                // SQLの実行情報を取得
                $sqlExecCollect = $queryCollector->collect();
                foreach ($sqlExecCollect['statements'] as $sqlStatement) {
                    // ログに出力するデータを作成
                    $logOutPut['sql'] = $sqlStatement['sql'];
                    $logOutPut['duration_str'] = $sqlStatement['duration_str'];
                }
                // ログを加工しやすいようにJSONで出力
                Log::channel('sqllog')->debug(json_encode($logOutPut, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE));
            }
        );
    }

    /**
     * Bootstrap any application services.
     *
     * @return void
     */
    public function boot()
    {
        //
    }
}

barryvdh/laravel-debugbarのソースコードを見た場所

barryvdh/laravel-debugbarのgithub内の下記の辺りを参照しました。

引用元:https://github.com/barryvdh/laravel-debugbar/blob/master/src/LaravelDebugbar.php#L297

$queryCollector = new QueryCollector($timeCollector);
$queryCollector->setDataFormatter(new QueryFormatter());
if ($this->app['config']->get('debugbar.options.db.with_params')) {
    $queryCollector->setRenderSqlWithParams(true);
}
if ($this->app['config']->get('debugbar.options.db.backtrace')) {
    $middleware = ! $this->is_lumen ? $this->app['router']->getMiddleware() : [];
    $queryCollector->setFindSource(true, $middleware);
}
if ($this->app['config']->get('debugbar.options.db.explain.enabled')) {
    $types = $this->app['config']->get('debugbar.options.db.explain.types');
    $queryCollector->setExplainSource(true, $types);
}
if ($this->app['config']->get('debugbar.options.db.hints', true)) {
    $queryCollector->setShowHints(true);
}
$this->addCollector($queryCollector);
try {
    $db->listen(
        function ($query, $bindings = null, $time = null, $connectionName = null) use ($db, $queryCollector) {
            if (!$this->shouldCollect('db', true)) {
                return; // Issue 776 : We've turned off collecting after the listener was attached
            }
            // Laravel 5.2 changed the way some core events worked. We must account for
            // the first argument being an "event object", where arguments are passed
            // via object properties, instead of individual arguments.
            if ( $query instanceof \Illuminate\Database\Events\QueryExecuted ) {
                $bindings = $query->bindings;
                $time = $query->time;
                $connection = $query->connection;
                $query = $query->sql;
            } else {
                $connection = $db->connection($connectionName);
            }
            $queryCollector->addQuery((string) $query, $bindings, $time, $connection);
        }
    );
・・・

最後に

最後までお読みいただきありがとうございます。
Laravelにはこういった便利なパッケージがまだまだあります。
パッケージを利用することで高品質なものを手早く実装していけるようになります。

CSVIT事業部　LS（リーディングサービス）部田中(雅)

PHPをメインとしていますが、AWS LambdaやGoなどにも興味があります！

使用環境

実装するもの

すぐに実行可能なSQLを出力する

app/Providers/AppServiceProvider.php

.envを参照し、環境に応じて出力の有無を切り替えられる

app/Providers/AppServiceProvider.php

SQLログは別のファイルにする

config/logging.php

app/Providers/AppServiceProvider.php

できたもの

app/Providers/AppServiceProvider.php の全文

barryvdh/laravel-debugbarのソースコードを見た場所

最後に

人気の記事

カテゴリー