開発者が運用を理解するための第一歩 -PHPのスローログを観測可能にしてみた- Cybozu Inside Out

こんにちは、サイボウズ Garoon開発 Tsukimiチーム所属の中田です。

本記事は、開発チームの人間がサービス運用の仕組みや可観測性に興味を持ち、実際に取り組んでみた内容をもとに執筆したものです。
PHPのスローログを上手く活用できてないな、という課題感をきっかけに、ログの構造化やメトリクス化を試みた内容を紹介します。
ログは見ているけどメトリクスってあんまり意識してないな、という同じような立場の方の参考になれば幸いです。

サービス運用にあたり、障害調査や性能分析をするためにログを収集・活用する場面は多々あり非常に有用です。
しかし、そのログが常に扱いやすい形で出力されるとは限りません。
特にアプリケーションやミドルウェアが固定の形式で出力するログは、手を入れにくく、検索や分析をしづらいことがあります。

PHPではリクエストの処理時間が一定時間を超えた場合にスローログが出力されますが、このスローログはまさにその典型例です。
スローログは性能劣化の調査に役立ちますが、そのままでは複数行かつ非構造的な形式で出力されます。

本記事では、このPHPのスローログを題材に、次の2点を中心に紹介します。

ログを構造化する方法（複数行ログのまとめ方、正規表現によるフィールド抽出など）
構造化したログからメトリクスを生成する方法

PHPのスローログに限らず、アプリケーションや周辺サービスではログの形式変更ができないままに、構造化されていないログが出力されるケースがあります。
以下は、PHPが出力するスローログの一例です。

[19-Oct-2025 03:22:25]  [pool www] pid 8
script_filename = /home/www/php/scripts/simulate_slow_response_2.php
[0x00007fb2e26131b0] sleep() /home/www/php/scripts/include/SlowHelper.php:10
[0x00007fb2e2613160] doSleep() /home/www/php/scripts/include/Worker.php:13
[0x00007fb2e26130f0] process() /home/www/php/scripts/include/SlowSimulator.php:13
[0x00007fb2e2613080] run() /home/www/php/scripts/simulate_slow_response_2.php:8

[19-Oct-2025 03:34:37]  [pool www] pid 7
script_filename = /home/www/php/scripts/simulate_slow_response_1.php
[0x00007a2bcb4141b0] sleep() /home/www/php/scripts/include/SlowHelper.php:10
[0x00007a2bcb414160] doSleep() /home/www/php/scripts/include/Worker.php:13
[0x00007a2bcb4140f0] process() /home/www/php/scripts/include/SlowSimulator.php:13
[0x00007a2bcb414080] run() /home/www/php/scripts/simulate_slow_response_2.php:8
...

このログには、発生時刻、プロセスID、スクリプトパス、スタックトレースなどが含まれていますが、
1つのスローログが複数行にわたっており各行の形式も異なっているため、活用するには以下のような課題を感じることがあります。

KibanaやGrafanaなどの可視化ツールで1行ずつ表示されてしまい、ログの全体像が把握しづらい
grepしようにも得たい情報が1行にまとまっておらず、部分的にしか検索結果が得られない
スローログの発生時刻やファイル名を使っての集計、傾向の把握が難しい

このような非構造的なログは、PHPのスローログに限った話ではありません。
PHPのエラーログ、MySQLのスロークエリログなども同様に、アプリケーション開発者が自由に形式を変えられないケースは存在します。

サービスを運用する上でこうしたログをそのまま活用すると、障害原因を効率的に調査できない場合や、障害発生/性能劣化の兆候を見逃すおそれがあります。
アプリケーションの規模が大きくなり、ログの量が増えれば増えるほど、人の手による調査は困難になり、機械的な分析やアラート設定が求められます。
本記事では、こうした課題に対処するために、ログを構造化し、メトリクスにする方法を紹介します。

ログを構造化すること自体は新しい考え方ではありませんが、「アプリケーション側で構造化して出力できないログを外部で整形する」という点が今回のポイントです。
次章以降では、実際にPHPのスローログをどのように構造化し、扱いやすい形に変換していくかを紹介します。
ログを構造化する意義や、実装の設計思想については以下の記事でも詳しく紹介されています。興味のある方はぜひ併せてご覧ください。

blog.cybozu.io

ブログ投稿にあたり、PHPのスローログを収集・構造化し、メトリクスにするための一例としてサンプルのリポジトリを用意しました。
本記事では、これを参考にログの収集から可視化までの流れを説明します。

github.com

本構成では、以下のコンポーネントを使用してPHPのスローログを収集・構造化し、メトリクスにします。

Fluent Bit: 軽量なログ収集・処理エージェント。複数行ログの結合や構造化を担当
OpenTelemetry Collector:ログやメトリクスの収集・変換・エクスポートを行うコンポーネント。ログをメトリクスに変換する
Loki: 構造化ログの保存とクエリを行うログストレージ
Prometheus: メトリクスの保存とクエリを行うメトリクスストレージ
Grafana: LokiやPrometheusからデータを取得し、可視化するダッシュボードツール

ログの構造化やメトリクスにする方法は様々あります。
OpenTelemetry Collector内でログのパースや構造化、メトリクスの生成を行うことも可能ですし、
Grafana Alloyではログの収集からメトリクスにするまでを1つのコンポーネントで完結することもできます。
実際に試したり運用する場合は、環境や要件に応じて柔軟にアレンジしてください。

ログの収集から可視化までの全体の流れは以下の通りです。

flowchart

PHP-FPMがスローログを出力し、Fluent Bitが収集する
Fluent Bitが複数行ログを1つにまとめ、正規表現でパースして構造化する
構造化したログをOpenTelemetry Collectorに送信する
OpenTelemetry Collectorがログからメトリクスを生成する
LokiとPrometheusにそれぞれログとメトリクスを保存する

保存したログとメトリクスはGrafanaで可視化され、ダッシュボード上で分析や監視が可能になります。

まず、Fluent Bitを使ってPHPのスローログを構造化する方法を紹介します。
大きく分けて2つのステップがあります。
1つ目は、複数行にわたるスローログを1つのログエントリ単位にまとめること。
2つ目は、ログエントリから各属性を抽出し、JSON形式に変換することです。
始めにスローログを1つの出来事として扱えるようにすることで、後続の処理（属性抽出やメトリクス化）を行いやすくなります。

Fluent Bitの設定ファイルについて興味のある方は、サンプルリポジトリのfluent-bitディレクトリをご参照ください。

複数行のログをログエントリ単位にまとめる

前述の通りPHPのスローログは1つのログエントリに対して複数行出力されます。
したがって、まずは「どこからどこまでが1つのログエントリか」を判別し、まとめる必要があります。
例として以下のようなスローログが出力されているとします。

[19-Oct-2025 03:22:25]  [pool www] pid 8
script_filename = /home/www/php/scripts/simulate_slow_response_2.php
[0x00007fb2e26131b0] sleep() /home/www/php/scripts/include/SlowHelper.php:10
[0x00007fb2e2613160] doSleep() /home/www/php/scripts/include/Worker.php:13
[0x00007fb2e26130f0] process() /home/www/php/scripts/include/SlowSimulator.php:13
[0x00007fb2e2613080] run() /home/www/php/scripts/simulate_slow_response_2.php:8

[19-Oct-2025 03:34:37]  [pool www] pid 7
...

PHPのスローログは[timestamp] [pool www] pid xxxの形式で始まります。この行を1行目として、「次のスローログが始まるまでの行」を1つのログエントリとして扱うことができます。以下はFluent Bitでmultiline.parserを利用して、スローログを1つのログエントリにまとめる例です。

pipeline:
 
  inputs:
   
    - name: tail
      path: /var/log/php-fpm/slow.log
      tag: php.slow
     
      multiline.parser: php_slow


multiline_parsers:
  - name: php_slow
    type: regex
    rules:
      - state: start_state
        regex: '^\[\d{2}-[A-Za-z]{3}-\d{4} \d{2}:\d{2}:\d{2}\]  \[pool www\] pid \d+'
        next_state: script_filename
      - state: script_filename
        regex: '^script_filename="
        next_state: backtrace
      - state: backtrace
        regex: "^\[0x[0-9a-f]+\]'
        next_state: backtrace

ログの属性を抽出してJSON形式に変換する

複数行のログを1つのログエントリとして扱えるようになったので、次はログを構成している属性を抽出しJSON形式に変換します。
例として、以下のような形に変換することを目指します。

{
  "timestamp": "2025-10-19T03:22:25.000Z",
  "pid": "8",
  "script_filename": "/home/www/php/scripts/simulate_slow_response_2.php",
  "backtrace": {
    "#0": "sleep() /home/www/php/scripts/include/SlowHelper.php:10",
    "#1": "doSleep() /home/www/php/scripts/include/Worker.php:13",
    "#2": "process() /home/www/php/scripts/include/SlowSimulator.php:13",
    "#3": "run() /home/www/php/scripts/simulate_slow_response_2.php:8"
  },
}

正規表現で属性を抽出する

Fluent BitやOpenTelemetry Collectorのparser設定で、pidやscript_filenameなどを抽出できます。
今回はFluent Bitにて構造化を行う例を示します。

pipeline:
  inputs:
    - name: tail
      ...
      multiline.parser: php_slow

     
      processors:
        logs:
         
          - name: parser
            parser: php_slow_fields
            key_name: log

         
          - name: lua
            script: filters.lua
            call: append_backtrace


parsers:
  - name: php_slow_fields
    format: regex
    regex: '^\[(?\d{2}-[A-Za-z]{3}-\d{4} \d{2}:\d{2}:\d{2})\]  \[pool www\] pid (?\d+)\nscript_filename = (?[^\s]+)'
    time_key: timestamp
    time_format: '%d-%b-%Y %H:%M:%S'

Luaフィルタでスタックトレース部分を抽出する

スタックトレース部分は要素の数がログによって異なり正規表現での抽出が難しいです。なので今回はLuaフィルタを使ってパース後にスタックトレース部分だけ追加するようにしました。尚、今回はサンプルということで実験的な要素と見栄えの良さを優先してLuaフィルタを使ってパースまで行いましたが、実際に運用する場合は保守性の観点から別の対応を検討した方が良いかもしれません。

function append_backtrace(tag, timestamp, record)
    local msg = record["log"]
    if not msg then
        return 0, timestamp, record
    end

    local stack_obj = {}
    local i = 0
    for line in msg:gmatch("%[0x[^\n]+\n") do
        local frame = line:match("%]%s*(.-)%s*$")
        if frame then
        local key = "#" .. tostring(i)
        stack_obj[key] = frame
        i = i + 1
        end
    end
    record["backtrace"] = stack_obj

    return 2, timestamp, record
end

これらの処理を経て、PHPのスローログを各属性を抽出したJSON形式のログエントリとして扱えるようになりました。

構造化ログを活用してダッシュボードを作成する

構造化したログをLokiに保存した後、GrafanaのLogQLを使ってクエリを実行できます。例えば、特定の時間帯におけるスローログの発生件数を調べたり、属性でフィルタリング/グルーピングすることができます。実際にクエリを書く際は、スローログ自体の属性以外にも各種メタデータやラベルを活用できます。クエリ中で利用しているservice_nameやtopicについてはfluent-bit.yamlにて付与しているので、抽出した属性以外の情報を付与したい場合はそちらも参考にしてください。

# 時間帯別のスローログ件数
count_over_time({service_name="php-fpm"} | topic=`php-fpm.slow` [$__auto])

# 指定した時間帯におけるスローログの合計件数
sum(count_over_time({service_name="php-fpm"} | topic=`php-fpm.slow` [$__auto]))

# script_filenameごとのスローログ件数
sum by(script_filename) (count_over_time({service_name="php-fpm"} | topic=`php-fpm.slow` [$__auto]))

LogQLを駆使することで以下のようなダッシュボードも作成できます。本環境はサンプルではありますが、実際の運用においてもこのようなダッシュボードは障害調査や性能分析に役立つでしょう。構造化ログを活用することで、ログの可観測性を大きく向上できます。 dashboard

さて、前章まででスローログを構造化し運用で活用できるような一例を紹介しました。本章では、さらに一歩進んで構造化ログからメトリクスを生成する方法を紹介します。 …紹介するのですが、一度立ち止まって考えてみましょう。構造化されていないログに比べて可観測性が大きく向上した今、果たしてメトリクスに変換する必要はあるのでしょうか？構造化ログだけでも観測性は大きく向上しますが、メトリクスにすることで「アラートの仕組みとの結合が容易になる」「大規模なデータを対象に高速に集計できる」という利点が得られます。実際に運用する際に常にダッシュボードを眺めているなんてことは稀で、多くの場合はアラートを受け取って初めて異常に気づくことが多いでしょう。またログは詳細な情報を残せる一方で、大規模なサービスや長期間分のログから集計をする場合など膨大な量のデータを処理しようとするとパフォーマンス上の問題が発生しやすくなります。正直なところ、メトリクスにしても今回のサンプルでは例えばダッシュボードの内容はほぼ変わりません。しかし、ログからメトリクスを生成する仕組みを持っておくことで、将来的により柔軟な監視や分析が可能になります。

構造化ログからメトリクスを生成する

Fluent Bitで構造化したログをOpenTelemetry Collectorに送信し、Connectorを使ってログからメトリクスを生成します。今回はConnectorの中でもSignal to metrics connectorを使って、1つのスローログにつき1つのメトリクスを作成しました。また、絞り込み用にscript_filename属性をラベルとして付与しています。



connectors:
 
  signaltometrics/php_fpm_slow_log:
    logs:
     
      - name: php_fpm_slow_log_count
        description: PHP-FPM slow logs count.
        conditions:
          - log.attributes["topic"] == "php-fpm.slow"
        attributes:
          - key: script_filename
        sum:
          value: "1"

processors:
 
  transform/php_fpm_slow_log:
    error_mode: ignore
    log_statements:
      - conditions:
          - log.attributes["topic"] == "php-fpm.slow"
      - statements:
         
         
         
          - set(log.attributes["script_filename"], log.body["script_filename"])

OpenTelemetry Collectorの設定ファイル全体については、サンプルリポジトリのotelcol-config.yamlをご参照ください。作成したメトリクスはPrometheusにエクスポートし、Grafanaで可視化します。

作成したメトリクスと構造化ログを併用してダッシュボードを作成する

作成したメトリクスをPrometheusに保存し、GrafanaからPromQLでクエリを実行できます。構造化ログのときと同様に、メトリクスでもラベルを活用してフィルタリングやグルーピングが可能で、ダッシュボード上で分析や監視ができます。

# 時間帯別のスローログ件数
count_over_time(php_fpm_slow_log_count_total[1m])

# 指定した時間帯におけるスローログの合計件数
sum(count_over_time(php_fpm_slow_log_count_total[1m]))

# script_filenameごとのスローログ件数
sum by(script_filename) (count_over_time(php_fpm_slow_log_count_total[1m]))

前述した通り、メトリクスに変換したからといってダッシュボードの内容はほぼ変わりません。実際にサンプルリポジトリのダッシュボードも2種類用意しており、1つは構造化ログのみ使ったもの、もう1つはメトリクスも活用したもので、違いはほとんどありません。しかし、メトリクスを作成・活用することでアラート設定や長期間分の集計が容易になり、ログとメトリクスを組み合わせることでより柔軟な運用が可能になります。今回の取り組みでは、PHPのスローログを構造化し、メトリクスとして扱うことで可観測性の向上を試みました。題材はPHPのスローログでしたが、同じ考え方はPHPのエラーログやMySQLのスロークエリログなど、他のログにも応用できます。「ログを構造化する」「メトリクスに変換する」という流れ自体は、多くのシステムに共通する観測のアプローチであり、ツールやフォーマットが違っても本質は変わらないと考えています。本記事で紹介した構成や設定はあくまで一例ですが、重要なのは「運用を自分ごととして捉え、観測の仕組みを理解する」ことだと思います。ログの構造化やメトリクス化はその第一歩にすぎません。本記事がサービスの可観測性向上に取り組む一助となれば幸いです。

元の記事を確認する

「GPT-5が未解決の数学問題を解決した」とOpenAIの研究者が投稿も実際は既に解決済みの問題だったことが明らかになりGoogle DeepMindのデミス・ハサビスCEOら... 前の記事 AWSで障害　米国東部リージョンで20サービスが停止・遅延　Zoomや任天堂のサービスなどに影響か次の記事

複数行のログをログエントリ単位にまとめる

ログの属性を抽出してJSON形式に変換する

正規表現で属性を抽出する

Luaフィルタでスタックトレース部分を抽出する

構造化ログを活用してダッシュボードを作成する

構造化ログからメトリクスを生成する

作成したメトリクスと構造化ログを併用してダッシュボードを作成する

関連記事

Instant Replay for Unity v1.0.0 正式版をリリースしました

人生の主要5教科─「人生」という長期戦を走りきるために｜義務教育で紐解く仕事術 | SHIFT Group 技術ブログ

Amazon Bedrock AgentCore Observabilityを支えるADOTの実装に迫る

使い捨てできるGPUクラウド Runpodを使おう！ | NTT DATA TECHのフィード