株式会社ヘンリーでオブザーバビリティをやっているsumirenです。
弊社ではトレースバックエンドにHoneycombを活用しています。いまや多くの方が日々の業務で使うようになり、プロダクトの運用になくてはならないものになりました。
この記事では、ヘンリーのメンバがHoneycombをどのように使っているか、Honeycombのアクティビティログから事例紹介します。
ヘンリーにとってのHoneycombの価値
トレースバックエンドというと、おそらく多くの方が1リクエストのツリーを可視化する用途を想像するかと思います。しかし、ヘンリーでHoneycombが定着しているのは、スパンの集計が非常に強力だからだと筆者は考えています。
この記事を通じて、ログの集計やメトリクスではなく、スパンを探索的に集計できることの価値の大きさや面白さが伝われば幸いです。
事例1. ある機能を各テナントのユーザーが何名くらいリクエストしているか集計する
id:horsewinの利用ログを参考にしています。
マイクロサービスAについて、目玉となる新機能をリリースしたようです。特定のアクター向けの機能であり、テナント別にも機能のオンオフをしています。各テナントのどれくらいのユーザーがこのエンドポイントを利用しているか確認することで、リリースがうまくいって使ってもらえているかを確かめることができます。
Honeycombではこうした集計は簡単です。WHEREで特定マイクロサービスの特定エンドポイントに絞ったうえで、テナント別にGROUP BYし、ユーザーIDでCOUNT_DISTINCTします（下図）。
同じことをアプリケーションメトリクス で実現するには、エンドポイントやユーザー ID、テナント ID などの属性ごとにメトリクスを分割・生成できるようあらかじめ定義しておく必要があります。ここで言う属性を一般にディメンションと呼びます。しかし、こうしたディメンションを含むメトリクスが都合よく収集されていることはそう多くありません。
Honeycombではインデックスなどの設定なしで、スパンに含まれる全ての項目を集計対象にできます。そのため、テナントを絞ってGraphQLオペレーションごとのレイテンシと実行数をカウントするなど、アイデアとニーズ次第で様々な軸でリクエストを集計することができます。
事例2. 問題のあるDBクエリがどのエンドポイントから呼ばれたときに遅いか集計する
id:nabeopの利用ログを参考にしています。
あるクエリでスロークエリが発生していたようです。一方で、いつも遅いわけでないため、どうやらクエリの使われ方に依存していそうです。Query InsightsなどマネージドDB側でわかるのは普通ここまでです。
トレースバックエンドでエンドポイントごとにクエリを集計することで、問題のあるエンドポイントを絞り込むことができます。
Honeycombでは、こうしたユースケースのために、「トレースとのJOIN」のような集計ができます。この例は、「db.statementを持つスパンを、そのルートにあたるスパンのgraphql.operation.nameでGROUP BYする」といった内容になっています（下図）。
集計結果を見ると、ListPatientSummariesというエンドポイントから使われたときだけこのクエリが遅いことがわかります（下図）。
あとは当該エンドポイントのコードを読んでもいいですし、さらに分母を絞って、次の事例のように異常検知を利用してもよいでしょう。
事例3. 異常検知で遅いリクエストの属性を絞り込む
id:giiita22の利用ログを参考にしています。
集計から洞察を得るには、異常値を示すメトリクスと相関のあるディメンションを特定することが重要です。例えば、前の例では「DB クエリの遅さ」という異常メトリクスと、「エンドポイント名」というディメンションの相関を検証し、その結果、特定エンドポイントだけが遅いと判明しましす。ここで、どのディメンションに着目するかという仮説の立案自体を自動化できれば、さらに効率的です。
さて、ある機能について、顧客から応答が遅いという問い合わせを受けたようです。過去のメンバーの記事にもあるとおり、マイクロサービスのモジュラモノリス移行といったアーキテクチャ的な変更や、大規模なリニューアルもあり、モジュラモノリスが怪しいのはわかっていました。
ヒートマップを見てみると、時間帯によらずリクエストの応答時間にばらつきがあることがわかります（下図）。
ここで、ディメンションをあれこれと入れてみるかわりに、異常検知を実行して、2秒以下のものと2秒以上のものでどのような属性の違いがあるかを調べていました。「EncounterTemplatesQuery」のエンドポイント（GraphQLオペレーション）が、異常な集合において76%を占めていることがわかります（下図）。これで、インフラ起因ではなくアプリ起因のようだということがわかりました。
さらに、ここから分母を絞り込んでもう一度集計と異常検知をしています。問題のあるエンドポイントだけの集計結果を見ると、必ずしもそのエンドポイントが常に遅いとは言えなさそうで、データに依存していそうです（下図）。ここでまた異常検知の出番です。
こうして分母を絞り込んで異常検知をすることで、無関係な分母と属性値が減るため、より異常なものと正常なものの差がクリアに見えるようになります。この例では、特定のparentFolderIdが指定されている場合は明らかに異常側に入る割合が多くなっています（下図）。ただし、それでも8%と少ないため、おそらくnullの場合も遅いのでしょう。この情報と、遅いトレースの確認により、DataLoader周りの実装に問題があることがわかったようです。
まとめ
ヘンリーでは製品組織全体でHoneycombを日々使いこなしています。カスタマーサクセスの方がアクティブユーザーを計測するのに利用したり、正式リリース前から使用していることもログからわかっています。
また、用途としては、単にトレース1つ1つを見るだけでなく、集計や全体の分析が大きく役立っています。障害や問題に対する仮説の検証も即座にデータで行うことができ、異常検知で経験や勘といったアートに頼らない仮説立案まで進めています。
GraphQLオペレーション名やリクエストボディ（マスキング含む）などの手動計装は、主に筆者が実装しました。他にもフィーチャーフラグやレスポンスのサイズなど豊富な計装があります。事例を踏まえると、手動計装がいかに強力か理解できるのではないでしょうか。スパンに1つ属性を足すことは、問題分析の手札を1つ増やすことと全く同義だからです。ヘンリーでは、機能個別のドメインロジックに対する手動計装も進めています。
Honeycombを導入した直後は、本当に組織に浸透するか不安もありましたが、この記事を書きながらヘンリーのメンバが日々大量のクエリを投げているログを見て、杞憂だったと安心しています。ご興味がある方はぜひカジュアルに弊社メンバとお話しましょう。
