💭

Laravel 8でログフォーマットを設定する - クラス名と行番号を添えて - 時間計測

10 min read

はじめに

経緯

Laravel 8の動作検証を行っている折、ログファイルの出力内容に行番号がついていないことに徐々にストレスを感じてきた。
過去のLaravel 6ではログフォーマットをカスタマイズして、クラス名や行番号を出力していたので、この違いがストレスとなって表れたのだった。

そこでLaravel 8でもログフォーマットの変更がそのまま適用できるかを確認しようと、例のごとくLaravel 公式ドキュメントのLaravel 8.x ログをざっと確認し、Laravel 6との違いはあまり無さそうと理解し設定を試みる。

ふむ、すっかり、IntrospectionProcessorの存在を忘れている。
クラス名も行番号も、このクラスにお世話になっていたのだった。

これは改めてまとめておかねばならない。

この記事は

Laravelのログフォーマットのカスタマイズで、クラス名や行番号を出力する設定の記録です。

ついでに、ログフォーマットをカスタマイズした場合としていない場合とで、どれくらい処理時間が変わるのか気になり、実際に計測してみました。

ちなみに、Laravel 6で使用していたのは、dailyチャンネルドライバを使用する方法です。

また、こちらの方の記事monologでの設定方法がタイムリーに紹介されていたので、こちらも参考にさせていただき(感謝)、monologチャンネルドライバを使用した方法も計測してみます。

環境

環境は、以前の記事で作成したものを利用。(かつ、SanctumのAPI認証も適用済みの環境)

設定

設定方法の解説は、公式ドキュメントLaravel 8.x ログにあるため、リソースだけ羅列します。

dailyチャンネルドライバ向けカスタマイズクラス

app/Logging/CustomizeFormatter.php
<?php

namespace App\Logging;

use Monolog\Logger;
use Monolog\Formatter\LineFormatter;
use Monolog\Processor\IntrospectionProcessor;

class CustomizeFormatter
{
    public function __invoke($logger)
    {
        $format = "%datetime% [%channel%.%level_name%] - %extra.class%(L.%extra.line%) - %message%" . PHP_EOL;
        $dateFormat = "Y-m-d H:i:s";
        $lineFormatter = new LineFormatter($format, $dateFormat, true, true);

        $introspectionProcessor = new IntrospectionProcessor(Logger::DEBUG, ['Illuminate\\']);

        foreach ($logger->getHandlers() as $handler) {
            $handler->pushProcessor($introspectionProcessor);
            $handler->setFormatter($lineFormatter);
        }
    }
}

monologチャンネルドライバ向けカスタマイズクラス

app/Logging/CustomizeRotatingFileHandler.php
<?php

namespace App\Logging;

use Monolog\Handler\RotatingFileHandler;
use Monolog\Logger;
use Monolog\Processor\IntrospectionProcessor;

class CustomizeRotatingFileHandler extends RotatingFileHandler
{
    public function __construct(
        string $filename,
        int $maxFiles = 0,
        $level = Logger::DEBUG,
        bool $bubble = true,
        ?int $filePermission = null,
        bool $useLocking = false
    ) {
        $introspectionProcessor = new IntrospectionProcessor($level, ['Illuminate\\']);
        $this->pushProcessor($introspectionProcessor);
        parent::__construct($filename, $maxFiles, $level, $bubble, $filePermission, $useLocking);
    }
}

ログ設定

確認用に、3つのチャンネルドライバを設定、logging.phpchannelsにそれぞれ追記。

1. dailyチャンネルドライバでログフォーマット変更なし

config/logging.php
        'test0' => [
            'driver' => 'daily',
            'path' => storage_path('logs/laravel_test0.log'),
            'level' => env('LOG_LEVEL', 'debug'),
            'days' => 14,
        ],

2. dailyチャンネルドライバでログフォーマット変更

config/logging.php
        'test1' => [
            'driver' => 'daily',
            'tap' => [App\Logging\CustomizeFormatter::class],
            'path' => storage_path('logs/laravel_test1.log'),
            'level' => env('LOG_LEVEL', 'debug'),
            'days' => 14,
        ],

3. monologチャンネルドライバでログフォーマット変更

config/logging.php
        'test2' => [
            'driver' => 'monolog',
            'level' => env('LOG_LEVEL', 'debug'),
            'handler' => App\Logging\CustomizeRotatingFileHandler::class,
            'handler_with' => [
                'filename' => storage_path('logs/laravel_test2.log'),
                'maxFiles' => 14,
            ],
            'formatter' => Monolog\Formatter\LineFormatter::class,
            'formatter_with' => [
                'format' => '%datetime% [%channel%.%level_name%] - %extra.class%(L.%extra.line%) - %message%' . PHP_EOL,
                'dateFormat' => 'Y-m-d H:i:s'
            ],
        ],

確認用のコントローラークラス

3つのチャンネルドライバで、それぞれ10,000回のログ出力を行い、時間を計測。

app/Http/Controllers/Api/AnyController.php
<?php

namespace App\Http\Controllers\Api;

use App\Http\Controllers\Controller;
use Illuminate\Http\Request;
use Illuminate\Support\Facades\Log;

class AnyController extends Controller
{
    public function logCheck(Request $request)
    {
        $report = [];
        foreach (['test0', 'test1', 'test2'] as $channel) {
            $start = microtime(true);
            foreach (range(1, 10000) as $no) {
                Log::channel($channel)->debug($no);
            }
            $time = microtime(true) - $start;
            $report[] = [$channel => $time];
        }

        return response()->json($report, 200);
    }
}

確認用ルート設定

routes/api.php
use App\Http\Controllers\Api\AnyController;Route::get('/log-check', [AnyController::class, 'logCheck']);

参考:SanctumのAPI認証回避

こちらの記事まで適用している環境の場合に必要な設定

'api/log-check'をチェックから除外

app/Http/Middleware/VerifyExpiredApiToken.php
protected $except = [
        'api/authenticate',
        'api/log-check',
    ];

実行

実行方法

RESTクライアント Insomniaで、以下にGETでアクセス
http://localhost/app01/api/log-check

ログファイルが存在しない状態から、3回実行。

実行結果1

1回目 2回目 3回目
test0:daily、ログフォーマット変更なし 3.26s 3.24s 3.27s
test1:daily、ログフォーマット変更あり 3.39s 3.42s 3.41s
test2:monolog、ログフォーマット変更あり 3.33s 3.37s 3.33s
参考:APIレスポンスまま
  • 実行結果1回目
    [
        {
            "test0": 3.2608041763305664
        },
        {
            "test1": 3.391969919204712
        },
        {
            "test2": 3.333343029022217
        }
    ]
    
  • 実行結果2回目
    [
        {
            "test0": 3.244265079498291
        },
        {
            "test1": 3.426361083984375
        },
        {
            "test2": 3.372567892074585
        }
    ]
    
  • 実行結果3回目
    [
        {
            "test0": 3.2748639583587646
        },
        {
            "test1": 3.4101250171661377
        },
        {
            "test2": 3.33351993560791
        }
    ]
    

実行結果1:考察

特段、大きな差異はなかった。あまり面白くn
ほぼ誤差範囲であるものの、monologチャンネルドライバの方が処理時間が短い傾向が安定して表れている。
(ログ出力自体はいずれもmonologライブラリで処理されるため、あくまで設定記述方法の優劣に過ぎない。)
ただ、そこまで顕著な違いがあるわけではないので、好みで選べば良いかな、と。
monologチャンネルドライバの方が設定でコントロールし易いのでこちらが良いか。

実行結果2

ふと、configキャッシュした場合はどうなるのか気になる。

example-app01$ php artisan config:cache
Configuration cache cleared!
Configuration cached successfully!

この状態で再度、実行した。

1回目 2回目 3回目
test0:daily、ログフォーマット変更なし 3.24s 3.24s 3.29s
test1:daily、ログフォーマット変更あり 3.36s 3.32s 3.34s
test2:monolog、ログフォーマット変更あり 3.35s 3.37s 3.36s
参考:APIレスポンスまま
  • 実行結果1回目

    [
        {
            "test0": 3.2462210655212402
        },
        {
            "test1": 3.360684871673584
        },
        {
            "test2": 3.3511080741882324
        }
    ]
    
  • 実行結果2回目

    [
        {
            "test0": 3.245542049407959
        },
        {
            "test1": 3.3296830654144287
        },
        {
            "test2": 3.3794469833374023
        }
    ]
    
  • 実行結果3回目

    [
        {
            "test0": 3.294916868209839
        },
        {
            "test1": 3.3416640758514404
        },
        {
            "test2": 3.362916946411133
        }
    ]
    

実行結果2:考察

test1test2の差がほぼなくなった。

なるほど、むしろmonologチャンネルドライバの設定方法が優秀じゃないか、と。

configキャッシュをクリアすると、元の傾向に戻るので、誤差ではない模様。

example-app01$ php artisan config:clear
Configuration cache cleared!

参考:Laravel 6で実行した結果

せっかくなので、Laravel 6で実行してみる。

1回目 2回目 3回目
test0:daily、ログフォーマット変更なし 3.26s 3.24s 3.27s
test1:daily、ログフォーマット変更あり 3.39s 3.42s 3.41s
test2:monolog、ログフォーマット変更あり 3.33s 3.37s 3.33s
参考:APIレスポンスまま
  • 実行結果1回目
    [
    {
        "test0": 3.2403881549835205
    },
    {
        "test1": 3.345961093902588
    },
    {
        "test2": 3.2547988891601562
    }
    ]
    
  • 実行結果2回目
    [
    {
        "test0": 3.166055917739868
    },
    {
        "test1": 3.3231911659240723
    },
    {
        "test2": 3.3166069984436035
    }
    ]
    
  • 実行結果3回目
    [
    {
        "test0": 3.2421278953552246
    },
    {
        "test1": 3.289182186126709
    },
    {
        "test2": 3.306328058242798
    }
    ]
    

同じ傾向。

ちなみに、Laravel 6、Laravel 8で、まったく同じ設定内容で想定どおりの挙動になる。
ログ回りは気にしなくて良さそうである。

参考:フォーマット済みログ出力イメージ

  • フォーマット

    "%datetime% [%channel%.%level_name%] - %extra.class%(L.%extra.line%) - %message%" . PHP_EOL
    
  • 出力イメージ

    2021-09-29 10:00:00 [local.DEBUG] - App\Http\Controllers\Api\AnyController(L.17) - 10000
    

最後に

もう少し、興味深い傾向が出ることを期待していた気もしましたが、ログ回りはもう枯れに枯れていて、パフォーマンス向上の余地などないのでしょうね。
それより、monologチャンネルドライバの記述方法の優秀さが興味深い結果であったな、と。

こんなところで。

Discussion

ログインするとコメントできます