💭

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

2021/09/30に公開

はじめに

経緯

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.phpのchannelsにそれぞれ追記。

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：考察

test1とtest2の差がほぼなくなった。

なるほど、むしろ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チャンネルドライバの記述方法の優秀さが興味深い結果であったな、と。

こんなところで。

はじめに

経緯

この記事は

環境

設定

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

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

ログ設定

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

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

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

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

確認用ルート設定

参考：SanctumのAPI認証回避

実行

実行方法

実行結果1

実行結果1：考察

実行結果2

実行結果2：考察

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

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

最後に

Discussion

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

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

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

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

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