Laravel 処理パフォーマンス計測

概要

本番運用しているシステムのCPU使用率が極端に高い処理に対して、SQLチューニングのため動作確認及び検証に使用

使用コード解説

実行開始時刻・CPU使用量の取得

$start = microtime(true);
$startUsage = getrusage();

$start：処理開始時点のUNIXタイムスタンプ（マイクロ秒単位）。

$startUsage：開始時点のCPUリソース使用状況（getrusage()で取得）。

SQLクエリログの有効化

DB::enableQueryLog();

LaravelのDBクエリログを有効化し、この後に発行される全SQLクエリを記録する。

実行終了時のCPU使用量取得

$endUsage = getrusage();

$endUsage：処理終了時点のCPUリソース使用状況。

CPU使用時間の計算

$cpuTime = ($endUsage["ru_utime.tv_sec"] - $startUsage["ru_utime.tv_sec"])
         + ($endUsage["ru_utime.tv_usec"] - $startUsage["ru_utime.tv_usec"]) / 1e6;

実行時間（経過時間）の計算

$duration = microtime(true) - $start;

**処理全体の経過時間（秒）**を計算。

CPU使用率の計算

$cpuUsagePercent = $duration > 0
    ? round(($cpuTime / $duration) * 100, 2)
    : 0;

CPU使用率（%）**を算出。
「CPUが実際に使われた時間 ÷ 全体の経過時間 × 100」で計算。
例えば、全体5秒のうちCPUが1秒使われたら20%。

ログ出力

Log::info("Execution time: {$duration} seconds");
Log::info("CPU Time: {$cpuTime} seconds");
Log::info("CPU Usage: {$cpuUsagePercent}%");
Log::info(DB::getQueryLog());

実行時間・CPU時間・CPU使用率・SQLクエリログをLaravelのログに出力。

出力例

local.INFO: Execution time: 0.47892212867737 seconds  
local.INFO: CPU Time: 0.103081 seconds  
local.INFO: CPU Usage: 21.52%  
  array (
    'query' => 'select * from `users` where `id` = ? limit 1',
    'bindings' => 
    array (
      0 => 'id',
    ),
    'time' => 18.48,
  ),

→SQLの処理については処理時間やquery結果を踏まえて修正方法を検討。
時間など前後するため、複数回実行して確認する。
下記記事など参考にしました。
クエリチューニングによる速度改善34項目

まとめ

動作検証などを実施する際に上記処理を記載することで、パフォーマンスを可視化。
SQLクエリもログとして出力され、複雑な処理を簡素化させることができるかなどに使用可能です。