🔑

Windowsデスクトップアプリの障害解析にOpenTelemetryはどこまで使えるか——ETW・ダンプとの境界を実測する

に公開

この記事が扱う課題は 3 行で書ける。顧客に配布した Windows デスクトップアプリの「客先でだけ遅い・たまに失敗する」調査が、ログを足して再リリースする往復になっている。OpenTelemetry(以下 OTel)をデスクトップアプリに入れたとき何が分かって何が分からないのか、その境界が曖昧なまま語られている。そして OTel が答えられない障害から先、ETW(Event Tracing for Windows)やダンプへどう調査をつなぐかについて、少なくとも筆者が調べた範囲では、実装と実測を伴う資料を見つけられなかった。

想定読者は、顧客配布の C#/.NET 製 Windows デスクトップアプリを保守していて、冒頭の往復に覚えのあるエンジニアだ。OTel の入門記事ではないし、サーバーサイドの分散トレーシングの話もしない。

先に結論

  • やったこと: 画像バッチ処理を模したサンプルアプリに OpenTelemetry を手動計装し、障害注入・UI フリーズ・導入コストの 3 つの実験で「どこまで使えるか」を実測した
  • 結果: OTel が答えるのは「どの端末・いつ・どの処理・どのフェーズ」までの絞り込み(実験 1: 障害の特定に 5 歩 / 1 分 40 秒)。「なぜ止まったか」は ETW・ダンプの領分だった。境界を越える引き継ぎは、単一試行だが trace_id の有無で所要が大きく変わった(実験 2: 1 分 13 秒 対 8 分 9 秒、後者は誤同定あり。絞れなかった要因は記録不足で切り分けられていない)
  • 導入コスト: SDK のみから OTLP(OpenTelemetry Protocol)常時送信へ切り替えると、プロセス経過時間の中央値は 2560→6056ms(+約 3.5 秒。うち約 3.0 秒は終了時の flush)、パイプライン処理時間の中央値は 1364→1721ms だった。送信先が落ちている間は終了が数秒遅れ、その回のテレメトリは失われ得る(実験 3)
  • 仕掛け: OTel と ETW・ダンプは、trace_id・時刻・PID を引き継ぎキーとして自前で接続設計して初めてつながる。この設計を、以後「引き継ぎ設計」と呼ぶ

境界を 1 枚にするとこうなる。

手順・設定・コードの全文はサンプルリポジトリ(urario/otel-windows-handoff)に置いた。実装の責務分割・実行時シーケンス・設計判断まで追いたい人向けには、アーキテクチャ設計書を別に用意してある。

https://github.com/urario/otel-windows-handoff/blob/main/docs/architecture.md

本文が受け持つのは、なぜ境界がそこにあるのか、何ができて何ができないのかだ。

なぜ「客先でだけ遅い」の調査は毎回つらいのか

「月次の取り込み処理が、うちだと 20 分かかるんですが」。手元の検証機なら 2 分で終わる処理に、こんな問い合わせが来たとする。ログを送ってもらって開いても、INFO の行が数千行並ぶだけで、どのファイルの処理に何秒かかったのかはどこにも書いていない。処理時間を出すログは、遅さが問題になって初めて欲しくなるからだ。

ここから往復が始まる。仮説を立てて計測ログを仕込み、ビルドし、リリース手続きを通し、客先で更新してもらい、再発を待つ。1 往復で早くて数日、リリースに検証や承認が挟まる現場なら数週間。しかも 1 回目の仮説が当たる保証はない。ログを仕込んだ場所が外れていれば得られる情報はゼロで、また一周だ。

このつらさの内訳は 3 つに分解できる。

再現できないこと。障害は客先の入力データ・環境・タイミングに依存していて、手元に同じ条件を作れない。観測する場所を客先に置くしかないのに、その観測手段がテキストログしかない。

ログは書いた場所しか語らないこと。テキストログは「仮説を立てた人が、立てた仮説の分だけ」情報を残す仕組みだ。仮説が外れれば沈黙する。本当に欲しいのは、仮説より前に「どの処理のどの段階までは正常で、どこからおかしいのか」を機械的に絞り込める構造なのに、ログの行はその構造を持っていない。

突き合わせが手作業になること。アプリのログ、Windows Event Log、顧客へのヒアリング。これらをつなぐキーは時刻しかない。客先マシンの時計のずれを気にしながら、複数のファイルを目視で行き来することになる。

サーバーサイドであれば、プロセスの常駐・安定した通信・集中管理という前提を置きやすく、APM や OTel の導入資料もその前提で書かれている。デスクトップアプリはそうはいかない。プロセスは客先で起動と終了を繰り返すし、ネットワークは常時つながっている保証がないし、テレメトリを外へ送ること自体に顧客との合意が要る。サーバー前提で書かれた OTel の解説がそのまま当てはまらない理由は、この生存条件の違いにある。

往復がつらい根本は、観測が仮説の後追いになっていることだ。仮説を立てる前に「どのジョブのどのフェーズが遅いか」が構造ごと手元に届けば、往復の回数そのものを減らせる。OTel に期待するのはこの役割で、それ以上ではない。では何が「それ以上」に当たるのか。言葉で線を引くのではなく、サンプルを組んで実測で確かめる。

何をどう測ったか:検証構成と計装設計

「どこまで使えるか」を実測で確かめるには、どんなサンプルなら足りるのか。条件を 3 つ置いた。障害が決定的に再現できること。OTel が答えられない障害を意図的に起こせること。導入コストを条件を変えて測れること。

サンプルは、画像バッチ処理を模したジョブパイプラインにした。実体は画像のデコードやエンコードではなく、依存ライブラリのないバイト演算で CPU 負荷を作るバイナリ処理だ。1 ファイル = 1 ジョブ、各ジョブは load → transform → save の 3 フェーズを通る。障害注入は 2 種類で、特定ファイルの読込遅延と、保存時のアクセス拒否(リトライ付き)。どちらも同じ入力なら同じジョブが同じように遅くなり、同じように失敗する。乱数で障害をばらまく案は最初に捨てた。何度回しても同じ絵が出ないと、条件間の比較にならないからだ。

GUI(WinUI 3)のシェルも付けたが、理由はひとつしかない。UI スレッドのブロック、つまり OTel が原因に答えられない障害を再現するには、UI スレッドを持つアプリが要る。それだけのための存在なので、GUI フレームワークの選定やセットアップの話はしない。

全体の部品はこうなる。

計装は 3 本柱だ。ActivitySource でジョブ単位のルート Span とフェーズ単位の子 Span を張る。Meter で完了・失敗・リトライのカウンタと、ジョブ所要時間のヒストグラムを取る。ILogger のログは OTel の logs パイプラインを通し、trace_id が自動で相関する。動作モードは、SDK off・SDK のみ(Exporter なし)・OTLP 送信ありの 3 つを切り替えられるようにした。この 3 モードが、後述する導入コスト実験の測定条件そのものになる。

引き継ぎ側は 3 経路に分けた。どれも「trace_id を、その調査ツールが読める場所へ、フリーズが起きる前に置いておく」ための仕込みだ。

引き継ぎ先 trace_id を置く場所 読み出す道具
ETW(ETL) カスタム EventSource のペイロード WPR で収録 → WPA
ダンプ メモリ上の固定書式マーカー(静的フィールド) WinDbg / バイト検索
ログ ジョブ開始時の handoff 行(時刻・PID・trace_id) テキスト検索

ツールが変わっても、引き継ぎ設計の成立条件は次の 4 点だ。

  1. 相関 ID はアプリで一度だけ生成する
  2. 障害前に同じ値を各証跡へ複製する
  3. 収録・捕捉ツールを障害前から待機させる
  4. 各証跡から相関 ID を確実に読み出せるようにする

カスタム EventSource はジョブの開始・終了時に trace_id・span_id・job.id を発行する。WPR(Windows Performance Recorder)で収録して WPA(Windows Performance Analyzer)で開くと、ETL に「どの時刻・スレッドで、どの trace_id を処理していたか」の目印が並ぶ。UI フリーズの注入操作にも専用の Activity と EventSource イベントを張り、ブロック前に trace_id が OTel と ETW の両方へ届くようにした。

ダンプ向けのマーカーは、事前にハング検知を待機させた ProcDump が取得するフルダンプへ写り、WinDbg やバイト検索で trace_id を読める。handoff ログは、ほかの証跡が使えないときに時刻と PID から Trace へ遡る保険だ。

設計で棄却した対案を 3 つ書いておく。採用したものより、捨てたもののほうにこのサンプルの意図が出ている。

HTTP や DB 向けの計装ライブラリ(OpenTelemetry.Instrumentation.Http など)には頼らず、全部手で張った。HTTP や DB が主役のアプリなら計装ライブラリから始めるのが正しい。だがこの記事の主題は計装設計そのものだし、load → transform → save というドメイン固有のフェーズ構造は、既製の計装からは決して出てこない。

Span のタグ file.name にはファイル名だけを載せ、フルパスは載せない。パスにはユーザー名が含まれることがあり、テレメトリに個人情報が混ざる。フルパスはカーディナリティも際限なく膨らませ、バックエンド側の集計を壊す。もっとも、これはテレメトリの漏洩面の入口にすぎない。何がどこまで漏れ得るかは、本番導入の節でまとめて扱う。

パイプラインと計装はプラットフォーム中立のコアに置き、GUI は薄いシェルにした。おかげで計装ロジックを Linux の CI で機械的に検証でき、GUI が壊れてもコンソールから実験を回せる。密結合にすれば書く量は減ったはずだが、それでは実験の枠組みが GUI の生死と心中する。

測る前に踏んだ罠

本筋の実験に入る前の段階の罠を 2 つ。どちらもエラーが出ない種類の罠だ。

EventSource は、有効化前のイベントを黙って捨てる。 スパイク検証の最初の収録で、先頭ジョブの開始イベントだけが ETL に入っていなかった。エラーも警告もない。ただ無い。ETW のイベントは、セッションがプロバイダを有効化する前に発行すると捨てられる。対策は順序とウォームアップだ。収録開始 → アプリ起動の順序を守る。そのうえで、計測対象の処理より前に EventSource を初期化し、捨てられてもよいイベントを 1 発撃って短い猶予(このサンプルでは 250ms)を置く。ただしこの猶予はヒューリスティックで、有効化の保証ではない。確実にしたいなら WPR を先に開始する運用で担保する。

プロセス終了時、キューに残った Span は黙って消える。 OTel SDK の送信は非同期のバッチ処理で、Span は一度キューに積まれてから送られる。Provider を破棄しないままプロセスが落ちると、キューに残っていた Span はどこにも届かない。例外も出ない。本筋の対策は、Provider をアプリ寿命で保持し、終了時に確実に Dispose(graceful shutdown)を通すことだ。正しく Shutdown すれば通常は終了処理の中で送信される。このサンプルではそれに加えて ForceFlush → Shutdown を明示的に呼び、flush にかかった時間を 1 行出力する。送り切りの成否と所要時間そのものが導入コスト実験の測定対象だからだ。なお、プロセスのクラッシュや強制終了には ForceFlush も Shutdown も効かない。

ビルド手順・Collector の設定・実行方法は、リポジトリの README に委ねる。ここから先は実測の話だ。

実験1:OTel はどこまで絞り込めるか

最初の実験は、主張の前半「どの処理のどのフェーズまでは絞り込める」を実測する。問いを 4 つに固定した。どのジョブが遅いか。遅いのはどのフェーズか。どのジョブが何回リトライして失敗したか。そのとき端末で何が起きていたか。同じ 4 つの問いに、計装済みの Trace+Log と、テキストログの grep だけ、の 2 通りで答えて、かかった時間と答えの出方を比べる。

障害は 2 種類とも決定的に注入する。入力は 1 MiB × 100 ファイルで、対象は job.id が 10 の倍数の 10 ジョブに固定。障害①は load に 3 秒の遅延を差し込み、障害②は save でアクセス拒否を送出して 3 回のリトライの末に失敗させる。何度回しても同じジョブが同じように壊れるから、ここに載せるスクリーンショットは読者の手元でも同じ絵になる。

障害①:「遅い」はフェーズ単位まで割れるか

想定していた手順は 2 歩だった。トレース UI でジョブ一覧を所要時間の降順に並べ、突出したジョブの Span を開く。実際には 5 歩・1 分 40 秒かかった。

内訳を隠さず書く。リソースで絞り、ルート Span の名前でフィルタするまでは想定どおり。3 歩目で所要時間の降順ソートを探して約 20 秒を失った。今回使ったトレース UI(Aspire Dashboard)は Trace 一覧のソートがタイムスタンプにしか対応しておらず、所要時間でのソートとフィルタは執筆時点で未実装だった(機能要望は挙がっている)。代わりに一覧の duration バーを目視でスキャンすると、約 3 秒の外れ値 10 件は 2 ページ分のスクロールで拾えた。job 10 の Trace を開くと、load だけが約 3.0 秒で、transform と save は正常域。「10 の倍数のジョブの load が遅い」まで、ここで言い切れる。

この 1 分 40 秒には教訓が 2 つ入っている。特定できたのは job.id とフェーズ構造がテレメトリに最初から入っていたからで、目視スキャンという泥臭い代替が成立したのもそのおかげだ。一方で、100 件だから目視で済んだのであって、客先の実データ規模では成立しない。所要時間ソートを持つ UI(たとえば Jaeger の Longest First)なら想定どおり 2 歩で着く。絞り込みの速さは計装だけでは決まらず、バックエンド UI の機能にも依存する。ここは設計時に見落としていた。

障害②:「たまに失敗する」にリトライ込みで答えられるか

こちらは 4 歩・1 分 2 秒。障害①より速かった。エラーになった Trace は一覧で赤く表示されるので、ソートを探す寄り道がそもそも発生しない。

エラーの Trace を開いて save Span を選ぶと、retry.count = 3、Status は Error、例外イベントに UnauthorizedAccessException が記録されている。ログ側には save の再試行が 100 → 200 → 400 ms の間隔で 3 行並び、その先に「ジョブ失敗 job.id=10」のエラー行。ログの各行には trace_id が付いていて、リンクをたどれば同じ Trace に戻れる。アプリの実行結果は成功 90・失敗 10・リトライ計 30 で、注入の設計値と一致した。

もうひとつ確認したのは、アプリ画面のジョブ詳細に表示した trace_id が、バックエンドのトレース一覧の該当行、そしてその Span 詳細の TraceId と同じ値で一致することだ。さきほどのログ行も含めれば、アプリ・ログ・Trace が一本の trace_id で貫かれている。当たり前に見えて、これが後の実験の土台になる。UI に見えているその値が、そのまま ETW・ダンプ側への引き継ぎキーになるからだ。

アプリ画面のジョブ詳細の trace_id、バックエンドのトレース一覧の該当行、その Span 詳細の TraceId が同じ値で一致している画面
同じ trace_id が、アプリ画面のジョブ詳細・バックエンドのトレース一覧・その Span 詳細の 3 か所で一致している。この値が ETW・ダンプへの引き継ぎキーになる。

証跡スクリーンショット(実験1の生画面)

実験1の証跡スクリーンショット
障害①のフェーズ別 span 時間と、障害②の error Trace・リトライログの生画面。

①と②を並べると、絞り込みの速さは障害の出方で非対称だと分かる。エラーになる障害には error という明確な入口があり、UI の機能差の影響を受けにくい。遅くなるだけの障害は duration が入口で、UI のソート機能に左右される。実務で厄介なのはたいてい後者だ。

比較:同じ問いに grep で答える

計装なしで出力したテキストログに、Select-String(PowerShell の grep 相当)だけで同じ 4 つの問いに答えた。結果はこうなる。

問い Trace + Log テキストログ grep
どのジョブが遅いか 特定できた(障害①: 5 歩・1 分 40 秒。フェーズ特定まで込み) 答えられた(load の行を抽出)
遅いのはどのフェーズか 同上(Span を開くだけ) 答えられた(同じ行にフェーズ名がある)
どのジョブが何回リトライして失敗したか 特定できた(障害②: 4 歩・1 分 2 秒) 答えられた(retryUnauthorized)
そのとき端末で何が起きていたか(メモリ・ディスク) 傾向は見えた(10 秒粒度のホストメトリクスを Trace の時刻窓と手作業で重ねられた) 答えられなかった(ログに存在しない)

時間だけ見れば grep 側は 4 問合計で 50 秒。Trace 側より速い。ただしこの 50 秒は、答えもログの形式も知っていて、検索コマンドまで事前に用意した状態の下限値だ。この実験の作り上、どちらの側も「答えを知っている実験者」が測っている。だから時間の優劣より、答えの出方の差を見てほしい。

grep が 3 問に答えられたのは、このサンプルのログがフェーズの開始・終了とリトライを出力していたからだ。冒頭に書いた「ログは書いた場所しか語らない」がそのまま出ている。書いてあった 3 問には答えられ、書いていない 4 問目には沈黙した。実務の「客先でだけ遅い」で最初に欲しくなるのは、まさにこの 4 問目のような、仮説を立てる前には仕込んでいない情報だ。

出方にも差がある。grep の答えは行の集合で、ジョブ → フェーズ → リトライという階層は読む側が頭の中で組み立て直す。Trace は最初からその構造で届く。100 件なら気合いで読める。数万行のログと数百ジョブになったとき、この差が調査時間の差になる。なお 4 問目の答え方にも限定がある。Performance Counter の収集間隔は 10 秒で、数秒のジョブとの対応は時刻窓の目視合わせだ。個々の Trace との因果関係までは示せない。

先に断っておくと、この実験で分かるのは「load に 3.0 秒かかっている」までだ。今回は自分で 3 秒と決めて注入したから答えを知っているが、実務ではここからが本番になる。ディスクが遅いのか、ウイルススキャンに捕まっているのか、ネットワークドライブなのか。Span は範囲を指すだけで、理由は語らない。理由が要る場面をどうするかが、次の実験だ。

実験2:OTel が答えを持たない障害を、どう引き継ぐか

2 つ目の実験は境界の向こう側、OTel が構造的に答えられない障害を扱う。サンプルアプリには UI スレッドを 30 秒ブロックするボタンを仕込んであり、ジョブが流れている最中に押せばウィンドウは「応答なし」になる。ユーザーから見ればすべてが止まっている。では OTel から見ればどうか。

OTel から見えるもの、見えないもの

先に正確に書いておくと、UI スレッドが止まっても OTel SDK 全体が止まるわけではない。Span の送信はバックグラウンドのバッチ処理で動いているから、並行して走っていたジョブの Span はフリーズ中も届き続ける。実測でもそこを確認する。それでも調査は進まない。フリーズを起こした操作の Span はそこで終わらないかぎり Export されず、UI スレッドがいまどのコールスタックで何を待って止まっているのかは、どの Span にも書かれていないからだ。「プロセスは観測できているのに、肝心の why が観測範囲の外にある」。ここが OTel の境界であり、この実験で ETW・ダンプへ切り替える地点になる。

フリーズ直前に UIFreezeRequested の完了済み Span が届き、フリーズ中も並行ジョブの Span は流れ続けるが、フリーズの why はどの Span にも無いことを示すトレース UI
フリーズ操作の直前に UIFreezeRequested の短い完了済み Span が届いている。フリーズ中も並行ジョブの Span は流れ続けるが、UI スレッドが何を待って止まっているか(why)はどの Span にも書かれていない。

trace_id を ETW・ダンプへ渡す仕込み

引き継ぎの要は、フリーズが始まる前に、アプリ計装が同じ相関値を境界の外の 3 経路へ自前で複製しておくことだ。障害発生時の時系列と、それがどの観測境界をまたぐかを 1 枚にすると、こうなる。

縦がフリーズ操作の時系列、3 つの box が観測境界だ。アプリ計装(UI ハンドラ)は UI スレッドをブロックする前に、同じ trace_id を ETL・ダンプ・ログの 3 経路へ順に残す。ブロックが始まった後は、送信・収録・ハング検知が並行して進み、応答なしの瞬間のフルダンプが残る。

こうして残った証跡は、原因側で道具を使い分けて読む。WinDbg でダンプの UI スレッドのコールスタックを開けばブロックしている呼び出しに届くし、カーネルイベント込みで収録した ETL なら WPA の Wait 解析で「何を待って止まっていたか」まで見える(カスタム EventSource だけの軽量収録では Wait 解析はできない。収録プロファイルはリポジトリで使い分けている)。

引き継ぎ先の証跡スクショ(WinDbg / WPA)

WinDbg で UI スレッドのコールスタックからブロック箇所に到達した画面
WinDbg でダンプの UI スレッドを開き、ブロックしている呼び出しまで辿った画面。

WinDbg でダンプ内のマーカー文字列から trace_id を読み出した画面
ダンプに写ったメモリ上のマーカー文字列。ダンプ単体から、このダンプがどの trace_id の操作かを読み出せる。

WPA の Wait 解析でブロック区間を特定した画面
カーネルイベント込みで収録した ETL を WPA の Wait 解析にかけ、UI スレッドが待っていた区間を特定した画面。

WPA の Generic Events に UIFreezeRequested の trace_id ペイロードが刻まれている画面
同じ ETL の Generic Events に、UIFreezeRequested イベントの trace_id ペイロードが並んでいる。ダンプ内マーカーの trace_id と突き合わせる相手はこれだ。

trace_id あり/なしで突合する

測りたいのはツールの操作手順ではなく、引き継ぎキーの価値だ。ブロック箇所そのものはどちらの条件でもダンプのスタックから読めるので、比較の課題はその手前の突合に置く。「いま Trace UI で調査対象にしているフリーズ操作に対応する ETL イベントとダンプは、どれか」。この特定を 2 つの条件で行う。

条件を成立させるために、収録は 1 回の WPR 記録の中で「アプリ起動 → 並行ジョブ実行中にフリーズ → ダンプ取得 → アプリ終了」を 3 回繰り返す。ETL には同名の UIFreezeRequested イベントが 3 つ、ダンプも 3 つ、互いに時刻が近く PID も再利用され得る状態で並ぶ。客先から届く調査材料は、たいていこういう「複数回分が混ざった束」だ。

条件 A は trace_id を使う。Trace UI で選んだ操作の trace_id を、ETL の EventSource ペイロードと、ダンプ内のマーカー文字列に対して完全一致で突き合わせる。条件 B は trace_id を封印し、発生時刻と PID(ダンプのファイル名・メタデータと ETL のイベント時刻)だけで同じ特定をやり直す。測るのは所要時間だけではない。候補に残った数(一意に決まったか)と誤同定の有無も記録する。

調査対象は 2 回目のフリーズ操作に固定した。結果はこうなる。

条件A: trace_id で突合 条件B: 時刻と PID のみ
対応する ETL イベント+ダンプの特定までの所要時間 1 分 13 秒 8 分 9 秒
候補に残った数 1 件(完全一致で一意) 3 件
誤同定の有無 なし あり(別のダンプを開いて手戻り)

これは単一オペレータ・各条件 1 回・調査対象を 2 回目のフリーズに固定した、単一試行の観測値だ。効いているのは時間そのものより「一意に決まるかどうか」で、条件 A は 3 回分が混ざった束から完全一致で 1 件が即座に残ったのに対し、条件 B は候補 3 件を絞る決め手を欠き、別のフリーズのダンプを開く誤同定と手戻りが出た。

ここには再現条件の限定が付く。PID は本来、近い値で照合するものではなく完全一致で使う識別子で、3 回の PID が互いに異なり両側で正しく読めていれば、時刻に頼らず絞れたはずでもある。今回の一次データには 3 回分の PID・時刻・ダンプ名の対応表を残しておらず、絞れなかった要因(PID 再利用・突合先での PID 取得可否・時刻粒度のどれか)は切り分けられない。加えて、A/B をどちらの順で実施したか、所要時間の計時を何から何まで(トレース UI を開いた時点か、対象を選んだ時点か)で取ったかも記録がない。だからこの 1 分 13 秒対 8 分 9 秒は定量的な効果量ではなく、時刻ベースの目視突合が誤同定の入口になった 1 回の参考値として読んでほしい(対応表・実施順・計時境界の記録は今後の課題)。

それでも、条件 B の作業が冒頭の「時計のずれを気にしながら複数のファイルを目視で行き来する」往復と同じ形をしていることは変わらない。引き継ぎ設計とは、この目視の突き合わせを、フリーズが起きるより前に trace_id を仕込んで消す設計だ。この仕込みは、障害が起きる前にしかできない。

実験3:導入コストはいくらか

4 条件と測定方法

最後は、そもそも入れて大丈夫なのかという話だ。絞り込みが効くと言われても、処理が目に見えて遅くなったり、送信先が落ちただけでアプリが道連れになったりするなら、顧客配布のアプリには入れられない。条件は 4 つ用意した。

条件 モード 意味
① OTel SDK off off Provider を構築しない。ただし計装なしではない。ActivitySource・Meter の API 呼び出し、EventSource、通常ログは残る。②以降との差は「既存の計装呼び出しに SDK リスナーを接続した増分」を意味する
② SDK のみ sdk Span は生成されるが Exporter がなく破棄される
③ OTLP 送信 otlp + Collector 稼働 localhost の Collector へ送る通常運用
④ 送信先が死んでいる otlp + Collector 停止 送信先が落ちたまま動き続ける

④を外さなかったのは、デスクトップアプリではこれが異常系ではなく日常だからだ。客先の Collector やネットワークが常に生きている保証はない。送信先が消えたときに本体の処理が遅くなるのか、終了時に何秒待たされるのか、テレメトリは何件消えるのか。ここを知らずに配布はできない。

測定は 100 ジョブのバッチを条件ごとにウォームアップ 1 回 + 6 回実行する。順序効果(ファイルキャッシュ・JIT 等)を薄めるため、①〜③は実行回ごとに条件順をローテーションし、④だけは Collector 停止を伴うため最後にまとめて実行する(この 1 条件だけ実行順が後方に固定される点は後述の限界にあたる)。OS のファイルキャッシュやウイルススキャンは制御していない。サンプリングは常時 100% で、サンプリングによる欠落はこの実験には含まれない。以下の表は各条件の中央値で示し、実行ごとのばらつきが効く項目は本文で断る。

今回の測定は WinUI アプリの自動実行(--auto-run --exit-after)で回した。数値は各条件 6 回(先頭のウォームアップ 1 回を除いた実行分)の中央値だ。モバイルでの横スクロールを避けるため、条件を行に置き、時間系とメモリ・送信系の 2 枚に分けた。

時間系(中央値、単位 ms):

条件 パイプライン プロセス経過 flush
① off 1418 2588 2
② sdk 1364 2560 8
③ otlp 1721 6056 3056
④ otlp(停止) 1426 7729 5066(失敗)

メモリ・送信系(中央値):

条件 Private Bytes ピーク Collector 出力増分 欠落ルート Span
① off 131MB - -
② sdk 132MB - -
③ otlp 137MB 約564KB/実行 0 件
④ otlp(停止) 138MB N/A(受信側で確認不能) 100 件(推定)

表の名前は測っているものに正直に付けた。「パイプライン処理時間」はジョブ処理だけの時間、「プロセス経過時間」は SDK 初期化や flush や WinUI の起動終了まで含む時間で、別物だ。「出力増分」は Collector が file exporter で JSON へ展開した後のファイルサイズの増分で、ネットワークを流れた OTLP のバイト数ではない。「観測できなかった数」は ProcessJob ルート Span の件数差で、子 Span・ログ・メトリクスは数えていない。④ の 2 項目に付けた「N/A」「推定」は、Collector が止まっている以上、受信側で数える実測が成立しないためで、根拠は結果の項で述べる。

測定環境は Intel Core i7-6700(3.40GHz)/ RAM 16GB / Windows 11(build 22621)/ .NET SDK 10.0.302。Collector は windowsperfcounters を外した E3 専用構成(collector/otelcol-e3.yaml)で起動した。OS のファイルキャッシュとウイルススキャンは制御していないので、絶対値ではなく条件間の差として読んでほしい。

バージョンは、サンプルアプリが測定時コミット 4f27237、OpenTelemetry の各パッケージが 1.17.0(Directory.Packages.props で固定。ロックファイルは置いていない)、Collector は README の取得コマンドで指定した otelcol-contrib 0.153.0 だ。

中央値だけでは各条件のばらつきが見えないので、ウォームアップを除く 6 回分の生値を畳んで置いておく。

6 回分の生データ(ウォームアップ除く。単位 ms)
条件 run パイプライン プロセス経過 flush
off 1 931 2030 3
off 2 1347 2475 3
off 3 1929 3098 3
off 4 1315 2447 2
off 5 1489 2700 2
off 6 1575 2764 2
sdk 1 1296 2415 8
sdk 2 1424 2597 8
sdk 3 1844 3079 8
sdk 4 1183 2345 8
sdk 5 1730 2913 7
sdk 6 1303 2523 8
otlp 1 1567 5826 3073
otlp 2 1824 6165 3057
otlp 3 1712 6038 3035
otlp 4 1680 5937 3054
otlp 5 1730 6074 3052
otlp 6 1741 6085 3058
otlp(停止) 1 1290 7703 5056
otlp(停止) 2 1488 7878 5081
otlp(停止) 3 1211 7508 5063
otlp(停止) 4 1448 7750 5069
otlp(停止) 5 1579 7879 5074
otlp(停止) 6 1403 7708 5058

結果から言えること

数字を 3 つに分けて読む。

まず ①→② の増分、つまり ActivitySource や Meter の API を呼ぶだけの状態から SDK のリスナーを接続して Span を生成・破棄する状態への差。パイプライン処理時間の中央値は ① 1418ms → ② 1364ms で、差(−54ms)は実行ごとのばらつき(① 931〜1929ms、② 1183〜1844ms)に完全に埋もれている。プロセス経過時間も同様だ。言えるのは「このワークロードとこの測定条件(単一マシン・各 6 回)では、SDK 接続による明確な増加は検出できなかった」までで、ゼロの証明ではない。

次に ②→③、送信を足したときの増分がこの実験のいちばん重要な数字だ。プロセス経過時間は 2560ms から 6056ms へ、約 3.5 秒跳ねる。内訳を分けると、100 ジョブの処理そのもの(パイプライン処理時間)が中央値 1364→1721ms(+357ms、約 +26%)、残りの約 3.0 秒が終了時の flush(中央値 3056ms)だ。ただしパイプライン側の増分は ②(1183〜1844ms)と ③(1567〜1824ms)のばらつきが重なる幅にあり、n=6 では確度の高い増分とまでは言えない。確実に言えるのは、送り切りのコストがプロセスを閉じる瞬間にまとまって出るという構造で、これは flush の中央値 3.0 秒にそのまま出ている。Collector が受けたテレメトリは file exporter 展開後で約 564KB/実行だった。

そして ④、送信先が落ちている条件。ここが配布アプリで効いてくる。実測できたのは、flush が成功せず約 5 秒でタイムアウトすること(success=false、終了が約 5 秒遅れる)までだ。表の「ルート Span 100 件欠落」は受信側で数えた実測値ではない。Collector が止まっている間は受信側での確認がそもそもできない。flush が失敗し、SDK に永続キューは無く、プロセス終了でメモリ上のキューごと消える、という構成から導いた推定で、測定スクリプトもこの 2 項目は観測せずに固定値を記録している。Collector 復帰後に回収されないことまでは観測していない。検証構成の節で「プロセス終了時、キューに残った Span は黙って消える」と書いた終了パスについて、実測で裏づけられたのは flush の失敗とその所要時間であり、欠落件数は構成からの帰結だ。

判断としてはこうだ。SDK を接続して Span を生成する段階は、少なくともこのワークロードでは処理性能への明確な影響を検出できなかった。ここをためらう理由は今回の数字からは出てこない。送信を有効にするなら、終了時に数秒の flush コストが乗ること(このワークロードでは処理時間の中央値にも +26% 程度の増分が見えた)と、送信先が落ちている間はテレメトリが失われ得ること・終了が遅れることを、終了パスの設計(flush のタイムアウト値と、落ちている送信先をどう扱うか)込みで織り込む必要がある。ここを設計せずに常時送信をそのまま配ると、客先の Collector が落ちた日に「アプリの終了が遅い」という別の問い合わせを生む。

実験から導いた診断手段マップ

3 つの実験で境界線の位置を測った。ここで、Windows デスクトップアプリの診断でよく使う 5 つの手段を、実測から見えた役割で地図にする。実験前に立てていた仮説の表を、実測で確かめた結論として置き直したものだ。

まず「答える問い」と「相関キー」。それぞれの手段の代表的な使い方で書いている。

手段 主に答える問い(代表的な使い方) 相関キー
テキストログ(log4net / NLog 等) その時点で何が記録されたか なし(自前で埋めれば trace_id も持てる)
Windows Event Log 管理者向けの重大事象(代表例) EventID・時刻(ActivityID 等を足すことも可能)
OpenTelemetry どの端末・いつ・どの処理・どのフェーズか(絞り込み) trace_id
ETW/WPR その時 OS・スレッドで何が起きていたか 時刻・PID
ダンプ その瞬間のプロセス内部状態 PID・時刻

次に「いつ観測できなくなるか」。手段ごとの生存条件だ。

  • テキストログ: プロセスが生きて書けること
  • Event Log: OS が生きていること
  • OTel: プロセスが生きて送信できること。加えて、対象の操作に Span が張られていて、それが完了して Export されていること(実験 2 で見た境界)
  • ETW: カーネルが生きていること。ただし該当プロバイダやカーネルイベントを事前に収録有効化していた場合に限る(実験 2 の Wait 解析には専用の収録が要った)
  • ダンプ: その瞬間を捕まえること。突合には PID だけでなくプロセス開始時刻も見る。PID は再利用されるからだ

「答える問い」の列に同じ行はひとつもない。どれも他の上位互換ではないから、「置き換え」は成立せず、あるのは使い分けだけだ。そして相関キーの列を見ると、標準状態で trace_id を主相関キーとして持つのは OTel だけだ。ETW は時刻と PID、ダンプは PID を軸にしていて、trace_id は手段をまたいで自然には共有されない。このサンプルが EventSource のカスタムペイロードとメモリ上のマーカーに trace_id を載せているのは、この共有を自前で作るためだ。誰かがキーを埋め込まない限り、調査は「時計のずれを気にしながら目視で時刻を合わせる」あの作業に戻る。実験 2 の条件 B がまさにそれで、引き継ぎ設計とは、このキーを事前に流し込んでおく設計のことだ。

ひとつ紛らわしい点を補足する。EventSource/ETW には Activity ID という仕組みが元からあるが、これは System.Diagnostics.Activity の trace_id とは別物だ(EventSource の Activity ID の解説)。ETW の Activity ID は ETW イベント同士の関連付けのための GUID で、W3C Trace Context の trace_id とは互換がない。このサンプルが EventSource のカスタムペイロードに trace_id の文字列を載せているのは、この非互換を跨ぐためだ。

症状から引く

境界の地図を、症状から引ける形に畳み直す。

特定の処理が遅い。 まず Trace の span 時間でどのフェーズが遅いかを見る(実験 1 の障害①: 5 歩・1 分 40 秒。UI のソート非対応を目視で迂回した分を含む)。多くはここで足りる。理由まで要るなら WPA でリソースを確認する。キーは trace_id。

たまに失敗する。 error の Trace と trace_id 相関ログを見る(実験 1 の障害②: 4 歩・1 分 2 秒)。多くはここで足りる。あとは失敗ジョブの入力・再現条件の確認になる。キーは trace_id。

UI が固まる(応答なし)。 OTel には why が写らない。ここが境界だ(実験 2)。ProcDump → WinDbg、WPA の Wait 解析へ引き継ぐ。キーは trace_id・時刻・PID。単一試行の実測では、3 回分が混在した収録から対象を特定するのに、trace_id 突合は 1 分 13 秒で一意に決まり、時刻+PID だけだと 8 分 9 秒かかって誤同定も起きた(後者が絞れなかった要因は記録不足で切り分けられていない。実験 2)。

メモリ・ディスクが重い。 Meter と Performance Counter で傾向はつかめる(実験 1 で確認したのは、10 秒粒度のホストメトリクスを Trace の時刻窓と手作業で重ねられるところまで)。深掘りは WPA のリソース解析になるが、今回の検証範囲には含めていない。キーは時刻。

本番導入の条件と限界

実験は「入れれば絞り込める」ことを示したが、顧客配布のアプリに入れる判断には、実験の外にある条件が付く。

テレメトリはどこまで漏れ得るか

このサンプルで意識的に絞ったのは file.name(フルパスを載せない)だが、漏洩面はそれだけではない。

  • host.name は実質的な端末識別子だ。このサンプルもリソース属性にマシン名を載せており、これは実験用の割り切りにあたる。配布アプリならハッシュ化するか、初回起動時に生成する匿名のインスタンス ID に置き換える
  • ファイル名自体にも顧客名や案件名が入り得る
  • 例外メッセージとスタックトレースにはフルパスが入る。ログの引数には入力値が入る。送信前にフィルタする設計が要る
  • ダンプはテレメトリ以上に機密の塊で、ETL にもファイル名・プロセス・ユーザー環境が入り得る。引き継ぎ先のデータは「送る」のではなく、暗号化と受け渡し手順を決めた上で個別に回収する

最低限の実装判断としては、テレメトリの opt-in(または無効化手段)、送信先・保持期間・アクセス権の明文化、端末識別子の匿名化、例外・ログのフィルタ、ダンプ・ETL の回収手順、の 5 点は計装と同時に決めておきたい。

送れないとき・送らないとき、テレメトリは欠ける

実運用で OTel のデータが欠ける条件は、プロセス停止と通信断だけではない。

  • サンプリングで対象の Trace ごと落ちる。head sampling で率を下げている場合、「エラーの Trace を後から探す」戦略とは相性が悪い。エラーが出た Trace が、そもそも送られていないかもしれないからだ
  • Batch Export のキューが満杯になれば、新しい Span は捨てられる
  • 送信先が落ちている間に再試行の期限を超えれば消える。プロセスが終了すればメモリ上のキューごと消える
  • バックエンド側のレート制限や属性制限で拒否されることもある

この実験は常時 100% サンプリング・ローカル Collector という、欠けにくい側に倒した条件で測っている。読者の環境でサンプリングを入れるなら、この節の欠落条件は実験結果の外側にあると考えてほしい。

検証しなかったこと

測っていないこと 記事の数字・主張への影響
単一マシン・HDD 上の 1 台でしか測っていない 実験 3 の処理時間・メモリの絶対値は環境依存。SSD の新しいノートから 10 年もののデスクトップまで幅がある
送り先はローカルの Collector とトレース UI まで 商用 APM・大規模 SaaS バックエンドの遅延・コスト・レート制限は範囲外
Span 属性を file.name 程度に絞った 実アプリで属性を増やしたときのカーディナリティ圧迫は測っていない
障害は 2 種・決定的な注入のみ 「たまにしか出ない」非決定的な障害を客先で捕まえられるかは別の検証が要る
実験 2 は単一試行・実施順や計時境界・要因の記録なし 1 分 13 秒対 8 分 9 秒は参考値。誤同定の原因(PID 再利用・突合先での PID 取得可否・時刻粒度)と、A/B の実施順・計時境界は記録がなく切り分け不能
実験 2 の trace_id 突合は事前の仕込みに依存 仕込みが無ければ条件 B(時刻+PID)と同じ土俵に戻る。ダンプ取得も ProcDump のハング検知待機が前提
otlp_down の欠落 100 件は受信側で未計測 実測は flush 失敗(約 5 秒)まで。欠落は永続キューなしの構成からの推定で、Collector 復帰後の回収は未観測
otlp_down だけ最後にまとめて実行 実行順の後方ドリフトと交絡している
送信量は file exporter 展開後のバイト数 ネットワークを流れた OTLP のワイヤバイト数ではない

既存アプリへの最小導入は 4 点

ここまで OTel を手動計装したサンプルで境界を測ってきたが、いま保守しているアプリに明日から OTel を全面導入しろという話ではない。境界の手前、絞り込みが効く側だけなら、入口は小さい。すでに log4net や NLog でテキストログを吐いているなら、既存のログ出力コードを書き換えずに、各行へ trace_id を乗せるところから始められる。

必要なのは次の 4 点だ。

  1. ジョブ境界で Activity を開始する。 ActivitySource.StartActivity() はリスナーがなければ null を返す(API 仕様)。つまり OTel SDK(または ActivityListener)を入れて初めて Activity.Current に値が入る。SDK 導入前に試すだけなら、低レベル API で new Activity(...).Start() する手もある(サンプルリポジトリの legacy-log-correlation がこの形だ)
  2. trace_id をログライブラリのコンテキストへ渡す
  3. レイアウトに trace_id の項目を足す
  4. ジョブの出口でコンテキストを戻す(log4net は finally で削除、NLog はスコープの Dispose)

log4net なら、4 点をまとめるとこうなる。async をまたぐので ThreadContext ではなく LogicalThreadContext を使う。

JobRunner.log4net.cs
// (1) ジョブ境界で Activity を開始する。
//     OTel SDK 導入済みなら ActivitySource.StartActivity() を使う。
//     SDK 未導入で試すだけなら、低レベル API で直接 Start できる。
using var activity = new Activity("ProcessJob")
    .SetIdFormat(ActivityIdFormat.W3C)
    .Start();

// (2) trace_id をログコンテキストへ渡す
log4net.LogicalThreadContext.Properties["trace_id"] =
    Activity.Current?.TraceId.ToString() ?? "-";   // Activity が無い経路では "-" になる
try
{
    // 既存のジョブ処理(中のログ出力コードは書き換えない)
}
finally
{
    // (4) ジョブの出口でコンテキストを戻す
    log4net.LogicalThreadContext.Properties.Remove("trace_id");
}

(3) はレイアウト側で、PatternLayout%property{trace_id} を足す。

NLog 5 以降なら ScopeContext が await を越えて流れる(4.x なら MappedDiagnosticsLogicalContext。サンプルは NLog 6.1.4 で固定)。Activity の開始(1)は log4net の例と同じだ。

JobRunner.nlog.cs
// (2)(4) ジョブ処理の入口。using を抜けるときにスコープごと戻る
using var _ = NLog.ScopeContext.PushProperty("trace_id",
    Activity.Current?.TraceId.ToString() ?? "-");

// 既存のジョブ処理

(3) はレイアウトに ${scopeproperty:trace_id}(4.x なら ${mdlc:item=trace_id})を足す。

4 点入れば、これまで書きためたログの各行に trace_id が乗る。ここでいう「その後でいい」のは、Trace をバックエンドへ Export して可視化する側の導入だ。Activity 自体は上の (1) のとおり最初から要る。ログと Trace が同じキーでつながってさえいれば、「客先でだけ遅い」の調査は、少なくとも時刻を目で合わせる作業からは抜けられる。実験 1 で見た trace_id の三点一致は、この 4 点があれば既存のログにも届く。

結論

実験前は、OTel の価値を「調査時間の短縮」で測ろうとしていた。だが実験 1 では、既知の問いには、整備されたテキストログと grep のほうが速かった(4 問 50 秒)。速さでは OTel が常に勝つとは言えない。

ログと Trace を共通の trace_id と階層構造で結び、メトリクスを同じ時間軸で重ねれば、仮説を立てる前には仕込んでいなかった問いにも探索の余地が残る。「客先でだけ遅い」の往復を減らすのは、検索速度ではなく、この探索可能性だと考え直した。

そして OTel が答えを持たない障害には、境界の外へ調査を継ぐ設計を先に仕込んでおく。trace_id・時刻・PID を EventSource、ダンプから読めるメモリ上のマーカー、ログの 1 行へ流し、WPR の収録と ProcDump のハング検知を事前に待機させておけば、「応答なし」の瞬間から WinDbg・WPA へ、目視の時刻合わせなしで渡れる。実測でも、単一試行ながら、仕込みがある側(trace_id 突合)は 1 分 13 秒で一意に到達し、無い側(時刻+PID)は 8 分 9 秒で誤同定も出た(この 1 回の観測値で、一般的な効果量ではない)。

サンプルの全文とビルド手順はリポジトリに置いた。clone すれば、この記事で測った障害①②が手元で同じように再現する。まず動かして、自分のアプリのどのジョブに 4 点を入れるかを決めるところからだ。

Discussion