App Service にデプロイした .NET アプリの応答遅延を分析する

はじめに

この記事ではApp Service にデプロイした .NET アプリの応答遅延を分析します。
下記の記事で事前準備してあります。

応答遅延の再現

10秒スリープするエンドポイントの例

ランダムに1~10秒遅延するリクエストを5分送ります。

sleepRandom.js

import http from 'k6/http';

import { sleep } from 'k6';

export default function () {

http.setResponseCallback(http.expectedStatuses(200));
// Generate a random sleep time between 1 and 10 seconds
const sleepTime = Math.floor(Math.random() * 10) + 1;
http.get('https://toshida-dotnet-buggyapp.azurewebsites.net/api/SlowRequest/sleep/' + sleepTime);

sleep(1);

}

平均応答時間は 5.67 秒でした。

メトリックをみる

「応答時間(HttpResponseTime)」を見ておきます。

なお App Service のメトリックは Kudu サイトへのアクセスも含まれるため、例えば Linux 環境で SSH 接続している場合などはメトリックに影響が出る可能性が大きいため注意が必要です。

以下のように平均、最大ともにクライアント側で得た実績と一致しています。

ログをみる

AppServiceHTTPLogs

AppServiceHTTPLogs を見ておきます。概ねメトリックのグラフと一致していることが確認できます。

AppServiceHTTPLogs
| where TimeGenerated >= ago(30m)
| where CsHost == "toshida-dotnet-buggyapp.azurewebsites.net"
| where CsUriStem startswith "/api/SlowRequest/sleep/"
| where UserAgent == "k6/0.48.0+(https://k6.io/)"
| summarize count(), min(TimeTaken),avg(TimeTaken),max(TimeTaken) by bin(TimeGenerated,1m),ScStatus

Application Insights

traces テーブル

アプリケーションがログを出力しているのであれば、ここである程度原因は絞り込めます。
アプリの実装を知っているという事情もありますが、ログからもスリープ処理に時間がかかっていることがわかります。

traces
| order by timestamp asc
| project-reorder timestamp,message,operation_Id,operation_Name

Live Metric

事象発生中であれば Live Metric を見てみるのもいいかもしれません。

問題の診断と解決をみる

Availability and Performance > Web アプリが遅い

Availability and Performance > 要求の実行が遅い

AppInsights ので Dependency で遅かった例がでてますが、ここは今回関係なさそうなので無視

Diagnostic Tools >Collect .NET Profiler Trace

「要求の実行が遅い」でも提案されている1つ目の方法としてプロファイラートレースをとってみます。
取得は問題の診断と解決から可能。説明にあるようにトレースを開始してから60秒以内に状況をリプロさせます。
今回のように問題が発生するURLが特定できていて、容易にリプロできる場合には有効そうです。

結果の見方については深堀が必要ですが、だいたいのことは下記のブログに書いてあります。

Slowest Request

アプリコードが遅いって教えてくれます。

.NET Core Slow Requets

Thread Callstacks

コントローラーのスタックで Thread.Sleep が呼ばれていることがわかります。

Application Insights を利用したプロファイラーの取得

プロファイラーについては Application Insights 側でも同様の機能が提供されています。

UI 的にはこっちのほうがわかりやすいかもしれないですね。どこで時間がかかったのかが一目瞭然です。

ダウンロードしたものを PerfView でも確認できます。

まとめ

処理遅延系はプロファイラートレースが有効そうです。
思考の順序としては以下の流れ

• メトリックからどの程度遅延が起きているのか確認
• AppServiceHTTPLogsから問題が発生しているURLの特定
• アプリのログから何か得られる情報がないか確認
• 再現可能かどうかの確認
• プロファイラトレースでの分析

その他の遅延のパターンについては別記事で書く予定。