7: 基礎編 その3: 遅いトランザクションのパフォーマンス調査方法 - New Relic を使ったアプリケーションのパフォーマンス監視入門

New Relic Advent Calendar 2017 20日目。基礎編３日目。

New Relic APM を使って具体的にパフォーマンス監視、分析を行う一般的な方法を紹介していきます。

パフォーマンス異常に気付く方法は、アラート通知を受けるか、たまたま New Relic APM の画面を見ているかです。通常は、アラートを設定しておけば、通知によって異常を迅速に検知できます。

アラート通知を受けたら、どうしましょうか？ まずは、New Relic APM の Overview ページにアクセスします。原則、ここが常に出発点となります。

## トランザクショントレースを使って、SQL レベルまでパフォーマンスを確認する方法

最も一般的なパフォーマンス分析は、トランザクションを軸に分析していく方法です。これのいいところは SQL まで確認できるところです。DB処理が問題の場合は、この方法で SQL まで確認できるため、わざわざコードを確認する必要がありません。

1. アラートが発生している場合は、アラートが発生している時間帯のみを表示するように、タイムピッカーやチャート上でドラッグ&ドロップして時間帯を調整します。
2. 概要ページで通常より遅いトランザクションにあたりを付けます。
  ![スクリーンショット 2017-12-20 23.43.36.png](https://qiita-image-store.s3.amazonaws.com/0/46003/e544f309-ea60-8820-0b0e-aeadccad4f57.png)
  特に画面左下の遅いトランザクショントップ5を確認します。
  ![スクリーンショット 2017-12-20 23.45.01.png](https://qiita-image-store.s3.amazonaws.com/0/46003/78b75336-b9d2-96e4-dd31-21a847daaf78.png)
3. 今回の原因を思われるトランザクションをクリックします。すると、そのトランザクションが選択された状態で、トランザクションページが表示されます。時系列チャートで遅くなってきている処理はないか? どの処理が最も処理時間を占めているかを確認します。ここを見れば、このトランザクションのどこに、どういった処理(DBなのか、外部呼出しなのか、コードなのか）に時間が掛かっているか把握できます。
   ![スクリーンショット_2017-12-20_23_50_18.png](https://qiita-image-store.s3.amazonaws.com/0/46003/267fa52c-6e85-0f4e-a7f6-606c476e9ae0.png)
4. この処理では、外部呼出しとコード処理で半分くらいの処理時間がかかっていると分かります。ここが改善されれば、パフォーマンスは速くなることが期待できます。
3. さらに詳細を確認したい場合は、このページの下にスクロールすると、トランザクショントレースが表示されます。(されないこともあります。)トランザクショントレースは、ある時点の個別のトランザクションのことです。それだけでなく、遅いトランザクションです。平均が1.190msなのに、ここで表示されているのはどれも4秒くらいです。とりあえず一番上のトランザクショントレースをクリックします。
   ![スクリーンショット 2017-12-20 23.57.22.png](https://qiita-image-store.s3.amazonaws.com/0/46003/14c2b3b4-52af-dbf5-0545-86c40f23bd03.png)
4. トランザクショントレースの Summary タブが表示されます。まずはこの個別のトランザクションの処理の内訳。そして、このトランザクションのリクエスト属性(ユーザーエージェント等)が表示されます。
   ![スクリーンショット 2017-12-21 0.04.55.png](https://qiita-image-store.s3.amazonaws.com/0/46003/e17bbd3f-91e1-f801-cd95-e14c3743d133.png)
   重要なのはここよりも、この横のタブの "Trace details" です。では、"Trace details" タブをクリックします。
5. 処理順にどの処理に何秒掛かっているか詳細なパフォーマンス情報を確認できます。
   ![スクリーンショット_2017-12-21_0_08_23.png](https://qiita-image-store.s3.amazonaws.com/0/46003/fdb6e837-2176-8976-4689-9f307fec038c.png)
   特に重要なのが、赤い箇所です。この処理で最も時間が掛かっている箇所が一目で判断できます。なので、まずはここに注目すべきです。ここでは、全体の87%の3,550ミリ秒この処理に掛かっていると分かります。今回は処理の内訳にもあったように、これは外部呼出しですね。そのため、ここでは特に改善できそうにないです。先方に改善を依頼するくらいでしょうか。これが、自分たちが運営する別のサービスであれば、担当チームに具体的なデータをもって遅いと報告できるので非常にエビデンスとなります。このトランザクションに関しては特にここ以外で問題になりそうなところはなさそうです。あまり例は良くないですが、このようにして、New Relic APM を使うとかなり詳細なところまで調査することができます。

また、ここでは問題になっていませんが、DB処理がボトルネックになることはよく有ります。New Relic の調査によると遅いトランザクションの25%はDB処理が原因とのことです。トランザクショントレースでDB処理が遅いことが分かったら、トランザクショントレースの右にDBアイコンがありますので、それをクリックします。すると、そこで使われている SQL が表示されます。また、遅いDB処理であれば、以下のように Explain Plan やスタックトレースも表示されますので、SQL の改善のヒントも十分です。
![スクリーンショット_2017-12-21_0_19_56.png](https://qiita-image-store.s3.amazonaws.com/0/46003/dfe304ee-43ab-940f-1bdd-f34efda8ea0c.png)

また、"Database queries" タブを押すと、このトランザクションで呼び出されたクエリの一覧を確認できます。遅い処理はここでも、DBアイコンがついてるので、クリックすると上のように、Expalin Plan などが見えます。

![スクリーンショット_2017-12-21_0_24_55.png](https://qiita-image-store.s3.amazonaws.com/0/46003/0db4a236-e309-dbcd-1cba-110257fffcc4.png)

以上が New Relic APM で最も良く行われているであろうパフォーマンス分析の方法です。

## パフォーマンス改善の指針 - 基本的にいつも遅いトランザクションから改善しよう

ちょうど昨日、New Relic ブログに [The Right Way to Use Slow Transaction Traces (スロートランザクショントレース機能を活用する正しい方法)](https://blog.newrelic.com/2017/12/18/transaction-traces-uses/)という記事が投稿されました。(翻訳版を出す予定だが、現時点では英語のみ) この記事では、パフォーマンス改善する際は、最も遅いトランザクションに注目するのではなく、**基本的にいつも遅いトランザクションに注目すべき**である。最も遅いトランザクションは外れ値であることが多く、それを改善しても、1%くらいのユーザーにしか影響がない。だったら、いつも遅いトランザクションを先に改善するのが影響が大きいよ。と書いています。

## 最もひどいパフォーマンスを経験しているユーザーを改善するには、99パーセンタイルを見る

一方で、1%であっても大規模なサービスであれば無視できないので、改善しようとも言っています。では、99パーセンタイルのトランザクションとはどれでしょうか？もっとも手っ取り速いのは、APM の Overview 画面でメインチャートをパーセンタイルに切り替え、99パーセンタイルを表示しましょう。そうすると、99パーセンタイルのレスポンスタイムを知ることができます。(残念ながら具体的にどのトランザクションがそうかは分かりません。)で、そのレスポンスを目安に、遅いトランザクショントップ5を見て、そのレスポンスタイムより遅いトランザクションに焦点を当て、上で示した方法で詳細を確認していきましょう。

## まとめ

今回は APM を使った最も一般的なパフォーマンス調査の方法を紹介しました。今回はトランザクションを中心にした説明でしたが、次回は、別の項目を軸にして、パフォーマンスを分析していく方法を紹介します。