TT Lab
はじめる
学ぶ 学習パス コース

失敗したのに終了コードは 0 だった

ログ 5 千行を表計算なしで読む

TT Labで続きを見る

一言でいうと

ログ数千行とCSV百行あまりから、「何件・何パーセント・上位5件・p95・最悪の1分」を取り出すのに、pandasは必要ありません。csv・collections.Counter・statistics・datetimeだけでできて、そうして作ったツールは、依存関係なしに、どのサーバーでも動きます。

なぜ必要なのか

障害の会議で「5xxは何時何分に集中したのか」と尋ねると、誰かがログをノートPCにコピーして、Excelに貼り付けました。5千行だったのでできましたが、翌月には50万行になっていました。本番サーバーには、pandasがなく、インターネットもありません。ところが、必要な計算は、数える・まとめる・分位数・時間の区間に分けるだけです。標準ライブラリは、この4つをすべて持っていて、それで作ったツールは、デプロイするものがファイル1つです。

どう動くのか

読み取り。ログの1行は、正規表現で分割します。nginxのcombined形式は、[10/Sep/2026:03:14:07 +0900]のような時刻、"GET /api/orders HTTP/1.1"のリクエスト、ステータスコード、最後に処理時間が付きます。ファイルは1行ずつ読みます(for line in f)。全体をメモリに載せないので、50万行でも同じコードでできます。パースに失敗した行は、数えておきますが、止まりません。ログには、いつも壊れた行があります。

CSVは、csvモジュールのDictReaderで読みます。最初の行を列名として、行ごとに辞書を返します。カンマが入った値や引用符の処理を、手でsplit(",")すると、必ず間違います。そのため、モジュールがあるのです。値はすべて文字列なので、int()・float()への変換は、自分で行います。

数える。collectionsのCounterは、ハッシュ可能な値を数える辞書です。Counter(status // 100 for ...)なら、2・4・5でまとめたステータスクラスが出てきて、most_common(5)が上位5件を返します。defaultdict(list)は、サービスごとに値を集めるときに使います。

分位数。statisticsのquantiles(data, n=100)は、データを確率が等しい100の区間に分ける、99個の分割点を返します。そのため、p50は[49]、p95は[94]、p99は[98]です。分割点は、最も近い2つのデータの間を線形補間した値で、既定の方法はexclusiveです。同じデータでも、方法が違うと値が少し違うので、ツールは、どの方法を使ったかを書き残しておかないと、他の人が再現できません。median()は、中央値だけが必要なときに使います。

時間。datetimeのstrptime(s, "%d/%b/%Y:%H:%M:%S %z")が、nginxの時刻をタイムゾーン付き(aware)のオブジェクトにします。%zが+0900を読みます。タイムゾーンのない(naive)オブジェクトとawareオブジェクトは比較できないので、--sinceのような入力も、fromisoformat("2026-09-10T03:00:00+09:00")のように、タイムゾーンを入れて受け取ります。「1分の区間」は、dt.replace(second=0, microsecond=0)をキーにして数えれば済みます。

import re, statistics
from collections import Counter
from datetime import datetime

LINE = re.compile(r'\[(?P<ts>[^\]]+)\] "(?P<method>\S+) (?P<path>\S+) [^"]*" (?P<status>\d{3}) \d+ "[^"]*" "[^"]*" (?P<rt>[\d.]+)$')

def parse(line):
    m = LINE.search(line)
    if not m:
        return None
    return {"ts": datetime.strptime(m["ts"], "%d/%b/%Y:%H:%M:%S %z"),
            "path": m["path"], "status": int(m["status"]), "rt": float(m["rt"])}

by_class = Counter(); times = []
for line in open("/opt/fixtures/pyops/access.log"):
    r = parse(line)
    if r:
        by_class[f"{r['status'] // 100}xx"] += 1
        times.append(r["rt"])
q = statistics.quantiles(times, n=100)
print(by_class["5xx"], round(q[94], 3))   # 5xx 건수, p95

エクスポート。結果は、人が読む1行と、機械が読むJSON(json)の2とおりで出力します。datetimeは、JSONにそのまま出力できないので、isoformat()の文字列に変換します。浮動小数点は、round(x, 3)で桁数を決めておかないと、2回実行した結果が同じに見えません。

現場での姿

最もよく見る失敗は、平均です。応答時間の平均が0.08秒という報告のあとで、p99が4秒ということはよくあります。遅い1%が、平均に埋もれます。分位数を出す習慣が、そのために必要です。2つ目は、タイムゾーンです。ログは+0900なのに、--sinceをUTCで入れたり、naiveで入れたりして、1時間ずれたまま、「その時間には問題がなかった」という結論が出ます。3つ目は、パースの失敗を黙って捨てることです。形式が少し変わった日から、ツールが0件を報告しますが、parsed=0 skipped=52000のように、スキップした数も一緒に出力すれば、その日のうちにわかります。

次のラボですること

/opt/fixtures/pyops/access.log(約5千行、03:12から03:17に障害の区間があります)とdeploys.csvを、標準ライブラリで分析するlogstat.pyとdeploys.pyを作ります。行数とパースに成功した数、ステータスクラスごとの件数、上位のパス、p50/p95/p99、5xxが最も多かった1分、サービスごとのデプロイの失敗率と中央値、--since/--untilのフィルター、そして、すべてを含むJSONレポートまで出力します。