世界を動かす技術を、日本語で。

時間で記録する、カウントではなく

概要

ログ出力方法 はソフトウェアエンジニアリングにおいて重要な議題。 イベント処理時のログ は、件数ベースよりも時間ベースが有効。 時間ベースのログ はログ頻度を安定化し、システム負荷を抑制。 件数ベースのログ は環境ごとの差異が大きく運用が難しい。 一貫した可観測性 を維持するため、時間ベースのログを推奨。

ログ出力の最適化:時間ベース vs 件数ベース

  • ログ出力のタイミング には主に「件数ベース」と「時間ベース」の2種類のアプローチ
  • 件数ベース は「X件ごとにログ出力」する方式
    • 例:1,000件ごとに「Processed 1000 events.」を記録
  • 時間ベース は「X秒ごとにログ出力」する方式
    • 例:1秒ごとに「Processed N events.」を記録
  • 時間ベースのログ は、処理速度が異なる環境(本番・ローカル)でも一定のログ頻度を維持
  • 件数ベースのログ は、処理速度が速い本番環境ではログが多発し、遅いテスト環境ではログがほとんど出ない問題

時間ベースログのメリット

  • ログレートの安定化
    • 環境や負荷に関係なく、一定間隔でログを出力
  • システムパフォーマンスの維持
    • 高負荷時の無駄なログ出力を防止し、イベント処理速度を確保
  • 運用コスト削減
    • 不要なログ蓄積や検索コストの低減
  • 可観測性の向上
    • どの環境でも、アプリケーション稼働状況を安定的に把握

件数ベースログの課題

  • 適切な件数(X)の決定が困難
    • 処理速度によって最適値が大きく変動
  • 本番とテストで挙動が大きく異なる
    • 本番ではログが大量発生し、テストではほとんど出力されない
  • オーバーログ・アンダーログのリスク
    • ログ過多でパフォーマンス低下やコスト増加
    • ログ不足でアプリケーション稼働状況が把握困難

推奨事項

  • デフォルトは時間ベースのログ出力 を採用
    • 例:1秒ごとにイベント処理件数を出力
  • ログ頻度の一貫性 を重視し、可観測性とパフォーマンスのバランスを確保
  • 件数ベースログは特殊な要件時のみ 限定的に利用

結論

  • イベント処理のログ出力 は「X秒ごと」の時間ベース方式が最適
  • 一貫した運用・保守性システム健全性 の維持に寄与

Hackerたちの意見

この投稿はよくある罠にはまってるね。ログとメトリクスを混同してる。面白いことをログに残そう。「面白い」は「ハッピーパス」の実行とは違う文脈を指すんだ。システムメトリクス、例えば呼び出し回数や処理時間のヒストグラムなどを集めて、投稿で使われてるログステートメントと同じ情報を提供できるようにしよう。

返信してくれてありがとう!この手のシステム(大規模、イベント駆動)での作業はまだ始めたばかりで、HNには自分よりずっと上手い人がいるから、彼らの意見が気になって投稿したんだ。結局、ログとメトリクスの違いって何なの? どちらかが構造化されていて、もう一方が非構造化? 一方が巨大なテキストの塊で、もう一方が時系列データベースに保存されてる? 現在は、構造化ログをLokiに入れて「メトリクスをログしてる」感じかな。それで、後で解析してプロットできるんだ。君や他のコメント者たちのおかげで、この分野をもっと掘り下げるための語彙が得られたよ。ありがとう!

メトリクスは集約のおかげでクエリがずっと早いし、機能が変わっても安定してることが多い。任意の集約の下で真実であり続けるもののためにメトリクスを保存するのは良いことだよ。例えば、合計、カウント、最大値などは良いけど、パーセンタイルのように集約に耐えられないものは避けた方がいいね。

投稿がいい感じだと思った。前にスクリプトを書いたとき、カウントで印刷して圧倒されちゃったことがある。カウントの数字を変えるんじゃなくて、時間を使えばよかったな。

この投稿はよくある罠にはまってるね;ログとメトリクスを混同してる。これは「混同」ってより、メトリクスをログにエクスポートするためのアドホックなメトリクスサブシステムを構築してるって感じ。x秒ごとにスクレイピングされるプロメテウスのエンドポイントを公開するのと、x秒ごとに同じデータをログに印刷するのに理論的な違いはないよ。

メトリクスやトレース、ログメッセージなどをログした後にフィルタリングと集約をしよう;前にやるんじゃなくて。データの保持やロールアップ、データストレージを制限するための他の戦略は、データを発信するシステムとは別に考えられるよ。少なくとも、適切なデータストアを使えばね。オープンサーチやエラスティックサーチのやり方が結構好きだな。エラスティックサーチではデータストリームがあって、時間やデータサイズに基づいてロールオーバーするように設定できる。ロールオーバーが終わると、インデックスは読み取り専用になって、新しいデータは現在のものに追加される。古いものに対して何をするかを決めるライフサイクルポリシーを定義できるし、例えばコールドストレージに移したり、ロールアップで変換したり、最終的には削除することもできる。アプリケーションのログでは、通常は異なるログレベルを割り当てるよね。トレースやデバッグは通常、本番環境では無効にされてる(そうあるべきだし)。インフォは結構うるさいことが多い。ワーニングは繰り返しがち(開発者が警告を無視して、修正しないことが多いから)。エラーは珍しいはず。エラーがログされると、すぐにメールが来るようにシステムを設定してる。エラーは何かが壊れてるってことだから、修正が必要だよ。エラーにはゼロトレランス。エラーが発生したとき、他のログ情報がコンテキストを提供してくれるから、その価値はある。ただし、せいぜい数日間だけ。週末やクリスマスを乗り越えるのに十分な長さ。だけど、その後はただのノイズになっちゃう。大体2週間で厳しく切ってる。カバー理由で長く保存する必要がある場所もあるけど、データ保持にはもちろんコストがかかる。巨大なデータ量をログして、エラーを無視する会社を見たことがある。1日30GB。ほんとにひどい。私:「あなたのデータベース層がずっとエラー出してるみたいだけど(制約違反とかそれ以上のこと)、何か対策した方がいいんじゃない?」彼ら:「ああ、これは普通だから、無視してるだけだよ」(PHPショップで、無能が普通だった)。私:「じゃあ、何か壊れたときどうやってわかるの?!」彼ら:「......?!」私の高給のコンサルティング仕事は、この運営に少しでも常識を叩き込むことだった。あるマネージャーが、こんな無駄に年間数十万も使ってることに気づいたから。私のフィーはその中では誤差みたいなもんだった。今までで一番簡単な仕事。でも、彼らが実際に何をやってるのか、なぜそうなってるのかを調べ始めると、ちょっと恥ずかしかった。ほとんどが、「ああ、誰かが一度設定しただけで、その後は見てなくて、彼は辞めちゃった。どうするつもり?!」みたいな感じだった。この会社にはそういうのがたくさんあった。リソースの無駄や、ログからの意味のあるフィードバックを気にする人が全くいなかった。もしそれがあなたのチームなら、何か手を打つ必要があるよ。それがあなたの仕事で、ちゃんとできてない。外部のコンサルタントに言われる必要があるなら、大きく変えることを考えた方がいいかもね。

ログを通じてメトリクスを収集するシステムを作ったんだけど、全く別のシステムを設定したくないときに、私のアプリにはうまく機能してるよ。

これに対する一つの例外は、インストーラーやrsync、curl、ddなどの明確な開始と終了があるバッチスクリプトやCLIツールだね。ここでメトリクスを設定するのは過剰すぎるし、ユーザーは進行状況に興味があるかもしれない。ログを通じて提供するのが一番簡単だよ。カースUIはいい中間地点かもしれないけど、やっぱり過剰になることが多い。

アマゾンでのメトリクスシステムは楽しかったし、オクタでも似たようなAPIで書いたんだ。オープンソース用にもう一つ書くのもいいかも。メトリクスシステムで欠けてるのは、ビジネスオペレーションの文脈で細かいメトリクスを保持して、トレンドのために遅延集計を使うことだと思う。前に見たとき、ほとんどのメトリクスシステムは個々のイベントをログに記録して、集計するには処理が必要だったり、早すぎる段階で集計してしまって、個別のオペレーションやリクエストへの影響がわからなかったりした。リクエストごとのカウントや統計、タイミングを取得しつつ、ホストやデータセンター、地域、粒度で集計して高レベルのトレンドを得るというバランスが必要なんだけど、ほとんどのメトリクスAPIはこの考え方と合わないんだよね。

時間とカウントでの集約は普通のバッチ処理技術で、俺も多くのシステムの複数部分をスケールアウトするために使ってきた。この具体例については、他の人たちに同意するよ:これはメトリクスのケースだね。「エラーをログに、成功をメトリクスに[0]。」0: 成功イベント(通常のログよりちょっと多いかも)は重要かもしれない、特に何かに対して料金を取る場合はね。

ログに関して俺がもらった最高のアドバイス:コード内の主要な論理分岐(if/for)をすべてログに残すこと。もし「リクエスト」がクラウドインフラ内の複数のマシンにまたがるなら、リクエストIDをすべてに含めて、可能ならログをグループ化できるようにしよう。ログレベルは動的に制御できるようにして、必要な時にデバッグできるように(問題が多いから!)。可能なら、ユーザーごとにログレベルを設定して、特定のユーザーの問題をデバッグできるように - https://grugbrain.dev/ 俺が追加するのは、もしログが通常コンソールやテキストファイルではなく、SplunkやGrafanaのようなログ集約ツールで読まれるなら、テキストの行ではなくJSONオブジェクトとしてログを残すこと。検索が楽になるからね。

テキストの行ではなくJSONオブジェクトとしてログを残す または、人間にとって読みやすく、オーバーヘッドが低く、構造化されていて、少なくともGrafana/Lokiで解析やクエリに対応しているlogfmtもいいね。

同僚たちはできるだけログを少なくしようとするし、俺が見てきたプロジェクトのほとんどは、ログをイベントストリームではなくファイルとして扱ってる。検索やフィルタリング、分類、自動アラートができるのにね。ちょっと残念だな。例えば、コード内の分岐をログに残すことに反対する声があったりするけど、トレースログ(他の人が追加しないもの)だけは問題が起きた時にオフになってることが多い。個人プロジェクトではかなり助かるけど、限られたトラフィックのおかげで、十分なログが引き起こすかもしれない問題が最小限に抑えられてる。少なくとも、GlitchTipやSkywalkingのようなAPMを追加する方向に進むことはできるね。

可能なら、ユーザーごとにログレベルを設定して、特定のユーザーの問題をデバッグできるように それは賢いアイデアだね。今後絶対に使わせてもらうよ。

このアドバイスに従って、ログを生成することが主な機能と言えるサービスを見たことがある。実際にユーザーへの応答は生成されるトラフィックのほんの一部に過ぎなかった。私たちが本当に必要なのはスマートなログだよ:エラーが検出されたときだけフルスパンをログする、それ以外は必要ない。だけど、あまりサポートされてないケースなんだよね。

時間でスロットリングすることには追加の利点があって、マルチスレッド環境で効率的にやるのがずっと簡単なんだ。カウントでログを取ると、そのイベントのためにグローバルカウンターが必要になる(スレッドローカルにすることもできるけど、そうするとログのボリュームはスレッドの数に依存することになる)。コードパスがホットな場合(ログをスロットリングしたいならそうなるかも)、複数のスレッドがインクリメントで競合することになって、これは非常にコストがかかる。時間でログを取る場合は、ロードとクロック読み取りだけで済む(Linuxでは、CLOCK_MONOTONIC_COARSEは数ナノ秒で、目的には十分な解像度がある)、タイマーが切れたときだけ同期(比較とスワップ)が必要だから、スレッド同士が干渉することはほとんどないんだ。

それでも、各スレッドは毎秒(またはその期間)ごとに別々のログ呼び出しをすることになるから、全スレッドが一つのログ呼び出しに集約するわけじゃないんだ。

SREやDevOps、オペレーションなんかやってると、叫びたくなるよ。メトリクスは別のストリームで出すべきで、ログから出すのは例外的なケースだけにすべきだよ。ログはシステムが問題を抱えている理由を特定するために使うべきで、システムが問題を抱えているかどうかを示すものではない。ログアラートは最初は良いアイデアに見えるけど、すぐに砂場にハマって将来の人たちを狂わせるし、大規模になるとシステムを圧倒することになる。ログアラートが悪い理由は、すべてのログが対処しなきゃいけないメトリクスポイントになるから。だから、ロギングシステムは常に稼働してエラーがない状態を保たなきゃいけない。でも、他の問題のせいで、このシステムはすぐに自分自身の獣になっちゃう。ログは一般的にKVよりもずっと大きいから、ロギングシステムでは大量のフィルタリングが行われて、負荷が増えるんだ。ロギングシステムはレートを理解してないから、「これは最初の未処理の例外か?」とか「10分で50回目か?」みたいな厄介なクエリを書く羽目になる。Prometheusのクエリはずっとシンプルだし、各言語のロギングライブラリはそれぞれ違う方法で処理するから、組織はA) すべての言語でログフォーマットを統一するか、B) ロギングシステムに各ログをアラートシステムが扱えるフォーマットに変換する方法を教える必要がある。もちろんAは開発者にとって大きな摩擦を生むし、Bは運用にとって大きな摩擦を生む。最後に、ロギングをやってる人は例外処理をうまく扱わないことが多いと思う。なぜなら、ロギングシステムが特定の問題をアラートしてくれるから、手動で対処する必要がないから。だから、将来あなたのコードを扱う運用担当者にお願いがある。prometheus_clientをインポートしてくれ。

なんか、開発者が実際のメトリクスの代わりにログを使うのが好きな理由に気づいたよ。うちはDatadogを使っていて、何度も開発者がアプリケーションに追加のロギングを加えて、そのログイベントをカウントするモニターを作るのを見た。これは抵抗が少ない道を選んでるって感じだね。ログを出すのはすごく簡単だし、カウントするのも簡単。実際のメトリクスを報告するのも難しくはないけど、システムに慣れてないと、どうやってやるかを見つけるのがログラインを出すよりも手間がかかるから、そうなるんだよね。

なんか見落としてる気がする。自分はソフトウェアエンジニアじゃないけど、ログを見てるときにイベントの数にはあまり興味がなくて、むしろそのイベントが何なのかを知りたいんだ。もし数が必要なら、それは自分のSEIMやBIがカウントすればいいことだと思う。

サンプルコードにバグがあると思う。「一貫したログレートがある」と主張しているけど、例では「read_event_from_queue()」はブロッキングであるべきだよ。指定された時間内にキューからアイテムが読み取られないと、ロギング部分がトリガーされないから、時間ベースのロギングは一貫したログレートを持たないことになる。それに加えて(潜在的な)バグがあるけど、メトリクスを出すことが選択肢でないなら、クールなアイデアだと思う。

ログレートは一貫しているべきだ アプリケーションが動いているか知りたいなら、ヘルスチェックを実装しなよ。この記事で提案されているパターンを本番システムで扱うことにならないことを願ってる。

ロギングを長くやってると、これが常識になると思う。ロギングバックエンドのパフォーマンスやサブスクリプションがバーストに襲われるときのことを考えてみて。例えば、あり得ないコードパスが繰り返しヒットしてエラーをログに記録したり、最悪の場合は例外トレースが出たりすることがある。X回ごとにロギングすると、全体の量は減るけど、全体のレートをコントロールすることはできない。X秒ごとにロギングすると、レートをうまく管理できるから、ロギングバックエンドのパフォーマンスやサブスクリプションによっては便利なんだ。

多くのロギングバックエンドには、これを処理するためのサンプリングレートがあることが多いよ。コードのあちこちでこれをやろうとするより、ロギングレイヤーでバッファを設定してそこで処理する方が確実に良いと思う。