パフォーマンスが求められるWebアプリケーションは 極限までSQLを調整 するもの。
Laravelで実行されるSQLの把握するために、実行されるSQLをドバっとログファイルに出力するミドルウェアを書いてみました。

そうはいっても、とても簡単なコードですよ。

動作を確認した環境は以下です。

  • Laravel 5.3
  • PHP 7

ミドルウェアとは

Laravelのミドルウェアは、要するに「 すべてのURLに共通した処理を行うフィルター 」です。

ミドルウェアを利用するメリットは「アプリケーション全体のふるまいを1か所で定義することができる」ことですね。

今回の「ログを一括で出力する」ような場合に、ログを全ファイルに埋め込むとなると、機械的で無意味作業となってしまいます。
ミドルウェアならば1ファイル追加するだけです。

何にも疑問を持たずに全ファイル修正とか、、、エンジニアがやる仕事じゃないですよね。

ミドルウェアの実装

次のようにartisanコマンドを打ってミドルウェアのスケルトンを作成します。

1php artisan make:middleware MiddlewareName
2

生成されたPHPファイルを開くと、handle()メソッドが定義されています。

1public function handle($request, Closure $next)
2{
3    return $next($request);
4}
5

上記を分解すると、次のようになっています。

 1public function handle($request, Closure $next)
 2{
 3
 4    // A.コントローラーの処理を実行する前に
 5
 6    $response = $next($request);
 7
 8    // B.コントローラーの処理を実行後の
 9
10    return $response;
11}
12

$next($request)を呼び出す前が、Laravel4系でいうApp::before。
$next($request)呼出しの後は、App::afterに対応する感じですね。

ソースコード

 1<?php
 2namespace App\Http\Middleware;
 3
 4use Illuminate\Support\Facades\Log;
 5
 6use Closure;
 7
 8class QueryDebugMiddleware
 9{
10    /**
11     * Handle an incoming request.
12     *
13     * @param  \Illuminate\Http\Request  $request
14     * @param  \Closure  $next
15     * @return mixed
16     */
17    public function handle($request, Closure $next)
18    {
19        if (\Config::get('app.debug') === false) {
20            return $next($request);
21        }
22
23        $this->readyOutputSqlLog();
24
25        $response = $next($request);
26
27        $this->outputSqlLog();
28
29        return $response;
30    }
31    private function readyOutputSqlLog()
32    {
33        foreach (\Config::get('database.connections') as $db_name => $settings) {
34            $query_org = \DB::connection($db_name)->enableQueryLog();
35        }
36    }
37    private function outputSqlLog()
38    {
39        foreach (\Config::get('database.connections') as $db_name => $settings) {
40            $queries = \DB::connection($db_name)->getQueryLog();
41            if (empty($queries)) {
42                continue;
43            }
44            Log::debug('Query log, '. $db_name);
45            foreach ($queries as $query) {
46                Log::debug($query);
47            }
48        }
49    }
50}
51

ログ出力サンプル

 1[2016-11-17 11:17:17] vagrant.DEBUG: Query log, mysql
 2[2016-11-17 11:17:17] vagrant.DEBUG: array (
 3  'query' => 'select * from `users` where `users`.`deleted_at` is null',
 4  'bindings' =>
 5  array (
 6  ),
 7  'time' => 0.37,
 8)  
 9[2016-11-17 11:17:17] vagrant.DEBUG: array (
10  'query' => 'select * from `auth_tokens` where (`user_id` = ?) limit 1',
11  'bindings' =>
12  array (
13    0 => 1,
14  ),
15  'time' => 0.34000000000000002,
16)

うん、なかなか良いです。

導入手順

  • 上記ソースをApp/Http/Middleware/QueryDebugMiddleware.phpに保存する
  • app/Http/Kernel.phpにミドルウェアを追加する
1protected $middlewareGroups = [
2    'web' => [
3        :
4        \App\Http\Middleware\QueryDebugMiddleware::class,
5

ちょっと解説

複数DB対応

複数データベースに対応しており、データベースの定義をconfig/databaseより取得しています。

ログ出力設定

app.debug=trueの場合にSQLのログを出力しています。
Log::debug()を使っておりますので、ログレベルの調整でも出力可否を変更できます。

私はconfig/appにSQLログ出力切り替え用のパラメーターを追加しました。

1// config/app.php
2'debug'     => env('APP_DEBUG',     false),
3'debug_sql' => env('APP_DEBUG_SQL', false),
4

SQLのログ量は結構多いため、さらに出力するログファイルを分けるとベターだと思います。

おわりに

Laravelのミドルウェアはなんとなくとっつきにくさを感じていたのですが、使いだすと大変便利です。 ミドルウェアを活用して楽をしましょう。

なお、SQLのログ出力についてはlaravel-debugbarというのもあるようですね。
こちらも勉強してみます。

参考URL

teratail : DB::select等の実行SQLを取得する方法はありますか
https://teratail.com/questions/26487

Webエンジニアブログ : Laravelで実行されたSQLを確認する
http://dim5.net/laravel/debugging-sql-queries.html


PHPフレームワーク Laravel Webアプリケーション開発 バージョン5.5 LTS対応

竹澤 有貴,栗生 和明,新原 雅司,大村 創太郎
出版社:ソシム  発売日:2018-09-26

Amazonで詳細を見る

PHPフレームワーク Laravel入門

掌田津耶乃
出版社:秀和システム  発売日:2017-09-16

Amazonで詳細を見る

初めてのPHP

David Sklar
出版社:オライリージャパン  発売日:2017-03-18

Amazonで詳細を見る