Ichizokuは日本唯一のSentry公認販売業者です。
日本語のドキュメント、動画、サポート窓口で日本のお客様のSentry活用を支援します。

【Sentry Logs】ダイナミックサンプリング問題をデバッグ

Article by: Simon Hellmayr

 

 
この四半期、Sentry のチームの一部は不具合の修正に注力し、正確には 800 件を超える問題を解決しました。その中には、社内の Sentry プロジェクトでトランザクションのスパイク(急増)を引き起こしていた複雑な不具合も含まれていましたが、Sentry Logs を用いて調査し、根本原因を追跡して問題を解決しました。
 
 

問題:断続的なスパイクと 100% のサンプル率

A graph showing usage stats. It's showing many spikes in "Dropped (Server)"

 

最初の症状は明確でした。特定の時間帯の始まりに、社内のプロジェクトが大量のスパンであふれ、プロジェクトの「abuse layer(異常負荷防止層)」が Sentry プロジェクトから膨大なデータをランダムに破棄していました。ただし、すべての時間帯で発生するわけではなく、数日間連続で発生しないこともありました

調査の結果、ダイナミックサンプリング設定が「すべてをサンプリングする」ルールに上書きされていることがすぐに判明しました。つまり、{"type": "sampleRate", "value": 1.0} という設定です。

この設定の目的は、どのプロジェクトやトランザクションをどの割合で保存するかを指定することです。そして、その値が 1.0 の場合、すべてをサンプリングすることを意味します。Sentry の目標サンプリング率は 2% であるため、突如として 50 倍のトラフィックを受け取る事態は冗談では済みません。

しかし、なぜこのようなことが起きていたのでしょうか?

最初の仮説は、ルール生成ロジックがフォールバックケース(代替処理)に入ってしまっているというものでした。これを確認するためには、より多くの可視性が必要でした。まず最初のステップとして、問題の設定状況を把握するために、コードに詳細なログ出力を追加し、動作を記録するようにしました。

 

 

調査に Logs を活用する

まずは設定の JSON をそのままログに出力しましたが、この設定は非常に大きくなることがあり、GCP Logs が受け付けるサイズを超える場合があると分かりました。一方で Sentry Logs は JSON を自動的に切り詰め、重要な情報を直接得られるようにしてくれました。

ログのペイロードを縮小し、意味の明確化も図って迅速に改善した結果、必要なデータを取得できるようになりました。次に問題が再発した際には、すぐにSentry Logsを確認して状況を追っています。その結果、当初の仮説は誤りで、フォールバックケースではなかったことが分かりました。むしろ、より興味深い問題であると判明しています。

 

 

その前に…ダイナミックサンプリングの仕組みについて簡単に説明

ダイナミックサンプリングは、複数のタスクによって構成され、それぞれが異なるメトリクスを参照し、どのプロジェクトやトランザクションにどのサンプリング率を適用するかを決定します。これらのメトリクスは ClickHouse に保存されており、Sentry はそれをもとに各プロジェクトのサンプリング率を算出し、最終的にどの程度のデータを保存するかを決定しています。

 

Sentry Logs でクエリするだけで行えたこの比較が転機となりました。入力に基づいてサンプリングロジックが正しく動作していることが証明できたのです。

問題は私たちのコードではなく、コードに与えられているデータ側にありました。

Sentry Logs によって、私たちの焦点はアプリケーションロジックのデバッグから、上流のデータソースの調査へと切り替わりました。ログのプレフィックスを使ってダイナミックサンプリング用の一種のネームスペースを作ることで、連続して実行される各タスクの状態を 1 か所で確認できるようになったのです。

問題の修正

最もトラフィックの多いプロジェクトでサンプル数が 0 だったことを手掛かりに、問題の原因を追跡して特定しました。このクエリは 3600 秒(1 時間)の粒度を使用しており、時間ウィンドウの区切りの関係で、ちょうど時間の切り替わり(XX:00)に実行されると 0 を返してしまう構造になっていたのです。(ClickHouse の粒度やデータスキップインデックスの仕組みについては、こちらのドキュメントに詳しく説明されています。
 
とはいえ、なぜこの問題が最近になって発生し始めたのかはまだ説明がつきませんでした。最後のピースは、同じ粒度に関するバグがリバランス処理タスクのスケジューリングジョブにも存在していたことです。
数か月もの間、そのジョブは静かに失敗し続け、XX:00 のジョブをキューに登録していませんでした。最近、新しいタスク実行システムへ移行したことで、組織全体にはデータがあるが特定プロジェクトにはまだデータがないタイミングでこのタスクが実行されるようになり、スケジューラ自体は成功したものの、ジョブは count:0 のデータで動作してしまったようです。
 
 

解決とまとめ

問題点:メトリクスを時間バケットで再計算する処理にレースコンディションがあり、ちょうどダイナミックサンプリングの判定を行う瞬間にサンプル数が 0 になってしまっていました。
 
対応はシンプルでした。クエリの粒度を 60 秒に変更し、その結果を合算するようにしました。
 
1週間にわたる調査の末、結果的に修正はたった1行で済みました。(もちろん、もし誤っていても全体を壊さないよう、オプションで切り替えられるようにしています。)
 

そして最終的にうまく機能し、Sentry プロジェクトの異常負荷保護の違反件数は以前の水準に戻りました。

本件は複数のシステムが複雑に相互作用した事案でしたが、私たち自身のプロダクトによって可視化されました。構造化ログを素早く追加し、確実に取り込ませ、UI 上で探索して問題箇所を特定できることは、根本原因の解明に非常に有用でした。そうでなければ、かなり難しく時間もかかったはずです。特に、今回のメカニズムはトレースで相互に結び付いておらず、ロジックの異なる部分が別々のタスクで実行されているためです。

Sentry Logs が、複数のタスクや状態にまたがる複雑な問題のデバッグにどのように役立つか、そして私たちが自社ツールを用いて Sentry 自体を改善しているかを示す、分かりやすい例です。

Logs をまだ使っていない方は、ぜひお試しください。すべてのプランで 5GB を無料でご利用いただけます。

Sentry をこれから始める方は、無料でサインアップしてご利用ください。

 

 

Original Page: Using Sentry Logs to Debug a Dynamic Sampling Issue

 




IchizokuはSentryと提携し、日本でSentry製品の導入支援、テクニカルサポート、ベストプラクティスの共有を行なっています。Ichizokuが提供するSentryの日本語サイトについてはこちらをご覧ください。またご導入についての相談はこちらのフォームからお気軽にお問い合わせください。

 

シェアする

Recent Posts