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

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

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

  • Laravel 5.3
  • PHP 7

ミドルウェアとは

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

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

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

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

ミドルウェアの実装

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

php artisan make:middleware MiddlewareName

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

public function handle($request, Closure $next)
{
    return $next($request);
}

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

public function handle($request, Closure $next)
{

    // A.コントローラーの処理を実行する前に

    $response = $next($request);

    // B.コントローラーの処理を実行後の

    return $response;
}

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

ソースコード

<?php
namespace App\Http\Middleware;

use Illuminate\Support\Facades\Log;

use Closure;

class QueryDebugMiddleware
{
    /**
     * Handle an incoming request.
     *
     * @param  \Illuminate\Http\Request  $request
     * @param  \Closure  $next
     * @return mixed
     */
    public function handle($request, Closure $next)
    {
        if (\Config::get('app.debug') === false) {
            return $next($request);
        }

        $this->readyOutputSqlLog();

        $response = $next($request);

        $this->outputSqlLog();

        return $response;
    }
    private function readyOutputSqlLog()
    {
        foreach (\Config::get('database.connections') as $db_name => $settings) {
            $query_org = \DB::connection($db_name)->enableQueryLog();
        }
    }
    private function outputSqlLog()
    {
        foreach (\Config::get('database.connections') as $db_name => $settings) {
            $queries = \DB::connection($db_name)->getQueryLog();
            if (empty($queries)) {
                continue;
            }
            Log::debug('Query log, '. $db_name);
            foreach ($queries as $query) {
                Log::debug($query);
            }
        }
    }
}

Githubにも同じものをアップしましたー。
https://gist.github.com/atuweb/ff07d5330a1418dd317a894eae074b7c

ログ出力サンプル

[2016-11-17 11:17:17] vagrant.DEBUG: Query log, mysql
[2016-11-17 11:17:17] vagrant.DEBUG: array (
  'query' => 'select * from `users` where `users`.`deleted_at` is null',
  'bindings' =>
  array (
  ),
  'time' => 0.37,
)  
[2016-11-17 11:17:17] vagrant.DEBUG: array (
  'query' => 'select * from `auth_tokens` where (`user_id` = ?) limit 1',
  'bindings' =>
  array (
    0 => 1,
  ),
  'time' => 0.34000000000000002,
)

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

導入手順

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

ちょっと解説

複数DB対応

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

ログ出力設定

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

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

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

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

おわりに

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

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

この記事はtomita@atuwebがお届けしました。

参考URL

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

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


スポンサーリンク
ad_336
ad_336
  • このエントリーをはてなブックマークに追加
  • Evernoteに保存Evernoteに保存
スポンサーリンク
ad_336