2018/01/16

[翻訳] 遅いトランザクショントレースを有効活用する方法

New Relic APM を使って、どうやってサイト全体のパフォーマンス問題を調査していけばいいかについての翻訳記事。一見、一番遅いトランザクショントレースに注目しがちだけど、そうではなく平均的に遅いトランザクションのパフォーマンスから改善した方が効率いいよって話です。


タイトル: The Right Way to Use Slow Transaction Traces
著者: Bill Kayser
公開日: 2017.12.18


この投稿は、Web サイトの応答時間の予想分布とは何かについて、最近行った議論の続きの記事です。

よくあるシナリオとして、パフォーマンス低下を認識するタイミングは、Web アプリに変更を加え、デプロイした時(やリアルタイムでデプロイをチェックしている時)や、ベースラインのアラートが鳴ったり、Radar がパフォーマンスの回帰を提示している時でしょう。あるいは、最悪のシナリオである、顧客から直接、ページがすごく重いんだけどと聞いた時かもしれません。

すぐに原因を特定しなくてはならいませんが、どこからチェックし始めたらよいでしょうか?

まず、New Relic APM のトランザクショントレースを調べましょう。トランザクショントレースは、サンプリングレートとトランザクションの待ち時間に基づき、リアルタイムで連続してサンプリングされた個々のウェブトランザクションをウォーターフォール形式で詳細に表示します。アプリケーションの Oveview ページとトランザクション概要ページの両方で、直近のトランザクショントレースを確認できます。最悪のパフォーマンスを誇るトランザクションもあれば、よくあるトランザクションの応答時間を示すものもあります。

トランザクションが遅いことを気にしている場合は、最も遅いトランザクションの詳細を確認するとこから始めるのが良いのでしょうか。

そうではなく、根本原因を特定するために、最も遅いトランザクションではなく、よくある遅いトランザクションから調査し始る理由を示します。

遅いトランザクショントレース以外の箇所を見る

ここによくある光景があります。通常、50ミリ秒未満なのに、10秒かかっているクエリや外部呼び出しがあります。これは、一目みてすぐに問題だとわかるトレースです。


外部サービスの呼び出しに 42秒もかかっている。

これはあなたのアプリ自体の問題だろうか? 外部サービスへの呼び出しに42秒かかっています。なぜそんなに遅いのだろうか? コードは何も変更していません。このサービスの呼び出し自体は、特に珍しくはなく、この期間中にサービスに問題があったという兆候は見当たりません。ここで最も重要なことは、トランザクションの内訳を見ると、通話、この処理時間は25ミリ秒未満ということです。


通常、この外部呼び出しには 25 ミリ秒しかかかっていません。

他のトランザクショントレースでを見ても同じ問題が発生していることがわかりました。つまり、同じ外部サービスへの呼び出しが遅いようです。本当にそこが問題なんだろうか?

それを調べるには、まず、その外部サービスがなぜ非常に遅いのかを調べることです。しかし、問題のサービスを見ても、何もおかしなことは起きていないようにだとすぐにわかりました。パフォーマンスやエラー率に変化は見られません。スループットと応答時間は普段と変わりません。もちろん、いくtか外れ値はありますが、正常に処理されるリクエストの数に比べればノイズです。これ以上、ここを見てもしょうがなさそうです。

結局、まだ遅くなった原因がわかりませんでした。間違った場所を調査していたのです。

トランザクショントレースが遅いと、もっとも遅いトランザクション(外れ値)にフォーカスしてしまいがちです。大多数のトランザクションの応答時間が遅くなっている場合、その原因を知りたい場合は、異常値を調べても役立ちません。それは大多数のパフォーマンスを代表するものではないからです。私の前の投稿である「ウェブサイトのレスポンスタイムの予想分布はどんなものだろうか? [英語]」で、応答時間の予測分布がアーラン分布にどのように密接に追随しているかを示しました。このような状況では、本質的に大きな待ち行列ネットワークであるトランザクションのアプリケーションでは、外れ値は存在してしまいます。アプリケーションがどれほど速く応答しても、外れ値となるような遅いトランザクションが常に発生します。

以下の典型的なアプリケーションのヒストグラムでそれを知ることができます。これは、Web アプリケーションの速い順からみて97%のトランザクションを示しています。

遅いトランザクショントレースは、通常、遅い方のリクエストから数えて 0.1% 以内に収まります。これは、上記のヒストグラムに現れません。以下は、リクエストの 99.8% を含むヒストグラムです。遅いトランザクショントレースは3〜5秒あたりに見えます。密集地域からは、非常に遠く離れています。

遅いトランザクショントレースを見ると、ほとんどすべてのケースで、あるセグメントが余分な時間のほぼ全てを費やしていることがわかりました。匿名化された 4,000 の低速のトランザクショントレースのサンプルを抽出し、そのうちの約半分で、最も遅いセグメントが総トランザクション時間の 96% 以上を占めていることを発見しました。それ以外は、通常通りのパフォーマンスでした。

サンプルデータでは、データベース処理が低速セグメントの 25% を占めていました。外部呼び出しは 18% でした。残りは、様々な種類の多くのコンポーネントにまたがって存在しました。データベース処理や外部呼び出しは、ネットワーク処理やリモートサーバーと関係しているため、非常に少数のケースでは、低速の原因である可能性が非常に高いです。このデータから、まだ対処が必要な問題があるかもしれませんが、サイトの応答時間がどこに費やされているかはわかりません。したがって、それらは、パフォーマンスの大幅な低下を調べる指標にはならないでしょう。

(slow transaction で示されている部分とはおそらく違う)全体的なパフォーマンス低下の原因がどこにあるかをどうやって知れば良いのでしょうか? データを見ることから始めましょう。

私たちは、すでに通常1つのセグメントによって遅いトランザクショントレースがどのようにトリガーされるのか把握しています。このセグメントを私のサンプルである 4,000 のトランザクショントレースの典型的なパフォーマンスと比較しました。そして、平均でトランザクショントレースの最も遅い箇所は、通常の場合と比べて600倍遅いことを発見しました。トランザクショントレースにある超遅いこれらの呼び出しは、本当に重症なケースです。

ここには見るべきものは無いので、次に行きましょう

この例で見られたように、遅いトランザクションで遅い外部呼び出しが特定の原因(一時的なネットワークエラーやリトライループ)であっても、外部呼び出し全体の平均レスポンスタイムを急激に落とすほどには外れ値は多くはありません。外れ値に注目することは、パフォーマンス低下の真の原因を探すため目くらましなのです。

このような状況では、トランザクショントレースをみない方がいいのだろうか? 必ずしもそうではありません。

最も遅いトランザクションではなく、典型的なトランザクショントレースを見ることができます。通常、約25%のトランザクションは典型的なトランザクションのパフォーマンスに収まります。それ以外の 25% は典型的な待ち時間の2倍以内に収まります。特定のトランザクションで確認できるトランザクショントレースを見ると、(パフォーマンスがトランザクショントレースの閾値以上である)通常のトランザクションと遅いトランザクションが交じっていることがよくあります。


トランザクション概要ページのトランザクショントレース一覧

重要なのは、常に”最も遅い”トランザクショントレースを調べないということです。代わりに典型的なケース、すなわちレイテンシが典型的なものに最も近いトランザクション追跡すべきです。

調べ始めるのに良い場所

現実的には、トランザクション概要ページで平均時間の内訳を調べる方が良いということです。それは、一貫してパフォーマンスの低いセグメントを確認します。過去のチャートは、時間の経過とともにパフォーマンスが低下している可能性のあるセグメントが表示されます。


アプリケーションサーバーの内訳チャートには、どのコンポーネントにもっとも多くの時間がかかっているか、もっとも遅い箇所が強調されています。

アプリサーバーの内訳表には、最も重要なコンポーネントが最初に表示されます。

問題の箇所を見つけるより良いアプローチは、まずアプリケーションの概要ページの内訳チャートから見始め、トランザクション概要を掘り下げ、そこの内訳チャートや表を調べ、考えられる原因を絞り込んでいくことです。

スロートランザクショントレース機能を利用するタイミング

上記のポイントにもかかわらず、New Relic はルールに則ってより遅いトランザクショントレースを収集します。場合によっては、異常値を追跡することにも気を配っています。Webサイトのパフォーマンス分析に利用できる最も一般的な顧客中心の指標の1つは、99パーセンタイルを見ることです。

Apdexのスコアや平均応答時間は、典型的な動作を確認できる良い方法ですが、最悪のパフォーマンスを経験している顧客体験は知ることはできません。レスポンスタイムの99パーセンタイルを追跡することで、異常値を含め、顧客全員をサポートできます。

そのため、異常値を分析することが理にかなっています。それらを最適化してもパフォーマンス全体のプロファイルに大きな影響はないかもしれませんが、分布は改善され、異常値を内向きに移動させ、応答時間を99パーセンタイル地点を小さくすることができます。

遅いトランザクショントレースというのは、一般的に遅いのはある特定の箇所であると上記で言及しました。遅いトレースの内の 約8%が、N + 1のアンチパターンが原因であるとわかっています。1回のコールでプリフェッチする必要のあるデータに対して、データベースや外部呼び出しが20回以上呼び出されていました。これらの問題を修正しても、全体のパフォーマンスは変わらないかもしれません。しかし、最悪のパフォーマンスを経験している1%のユーザーには大きな影響を与えるかもしれません。そして、スケールしている環境では、たとえ1%でもかなりの数に影響を与えることができます。

結論

トランザクショントレース機能を使うと、Webアプリケーションの詳細な動作を確認できます。しかし、遅いトランザクションのトレースについてとなると、その内容を正確に理解することが重要です。異常値を改善しても、アプリケーションの全体的なパフォーマンスは劇的に変わることはありませんが、99パーセンタイルにいるトランザクションの顧客体験を向上させることができます。結局のところ、「平均的な」ユーザーだけでなく、すべてのユーザーを気にする必要があるのです。

Qiita で New Relic Advent Calendar 2017 いろいろ書きました。特に、New Relic APM の入門的な連載を書きましたので、是非、ご覧ください。

New Relic 公式の日本 New Relic ユーザー会を立ち上げました。ワークショップの情報など日本のお客様向けに情報を発信していきますので、是非、参加ください。

過去記事

2018/09/13

翻訳: FutureStack18: New Relic 開発者向けプログラム-オープン化、シンプル化、活発化への道

今年も始まりました。New Relic の年次カンファレンス FutureStack 18。
この記事では、Elixir 用の New Relic APM エージェントの発表とデベロッパープログラムの発表がされています。

続きを読む

2018/08/27

翻訳: New Relic APM 新機能: 分散トレーシング

New Relic APM にDistributed Tracing (分散トレーシング)機能が追加されました。メニュー単位で機能が追加されたのはだいぶなかったのではないかと思います。マイクロサービスにおけるサービスをまたがったデータの流れを可視化できる機能のようです。是非、チェックしてみてください。

続きを読む

2018/05/18

SREcon18 と Rails デベロッパー向けアンケート結果の紹介

SRECon America カンファレンスにおけるアンケートの記事と Rails デベロッパーに対するアンケートの記事という2つの異なったレイヤーのアンケートに関する記事を見つけたので、ざっくり紹介します。違った視点での傾向が見れてなかなか面白いです。

続きを読む

2018/05/11

AWS Summit Tokyo を中心に直近の New Relic 関連イベントのご紹介

5/30 から始まる AWS summit Tokyo に参加するということで、海外から New Relic スタッフが来日し、イベント等を行います。是非、この機会に New Relic に興味のある人は参加してみてはいかがでしょうか。(基本、日本人スタッフいるので、日本語でも大丈夫なはず)

続きを読む

2018/03/17

翻訳: New Relic Browser JavaScript Error Analytics ベータ版 – エラーの早期発見、修正に役立つ

New Relic Browser の JS エラー機能が新しくなるようです (現在ベータ版)。APM で採用されているエラープロファイルが JS エラーにも対応したようです。これによって、エラーが起きている傾向が分析できるようになり、今後の JS のエラーが起きる前に対策が取りやすくなります。既存の PRO ユーザーはベータ版が使えるようなので、是非、使ってみてください。

続きを読む

 もっと見る