[Advent Calendar 2017 Day18] Azure Web Apps パフォーマンスチューニング

  • [アーティクル]

こちらの記事は、Qiita に掲載した Microsoft Azure Tech Advent Calendar 2017 の企画に基づき、執筆した内容となります。
カレンダーに掲載された記事の一覧は、こちらよりご確認ください。

 

こんにちは。
d99 です。

今回は Azure のアドベントカレンダーという事で、Azure で動く Web アプリケーションのパフォーマンスボトルネックを見つける手順をご紹介します。

 

1) Azure で簡単な php コードを動かす

まずは、Azure App Service を作成し、以下のような sleep.php を置きました。パッと見て分かる通り、QueryString に id=3 と渡されたら5秒スリープする、というコードです。既に種明かししてますが。

[php]
<?php
if ( $_REQUEST['id'] == 3) {
sleep(5);
echo('sleeped');
} else {
echo('done');
} ?>
[/php]

この程度のファイルを配置するのであれば、kudu コンソール（https://<Web Apps 名>.scm.azurewebsites.net/DebugConsole にアクセスし、D:\home\site\wwwroot に移動してから、上の [+] マークから [New file] を選択してファイル作成、鉛筆マークの [Edit] アイコンから直接書いてしまうのが簡単だと思います。

私は、デスクトップにエディタでさらさらっと書いて、下記赤枠のところにポイっとドラッグ・アンド・ドロップしました。

 

2) クライアントからリクエストを送る

次にクライアントからリクエストを送りまくります。今回は C# の コンソール アプリケーションで以下のような簡単なコードを書いて、毎秒ごとにパラメーター id をずらしながら、60秒間リクエストを送ってみます。

[c language="#"]
while (starttime.AddSeconds(60 * 1000) &gt; DateTime.Now)
{
System.Net.Http.HttpClient h = new HttpClient();
uri = new System.Uri(args[0] + "?id=" + (DateTime.Now.Second % 4).ToString());
var r = h.GetAsync(uri);
r.Wait();
Console.WriteLine(r.Result.StatusCode);
System.Threading.Thread.Sleep(1000);
}
[/c]

 

3) ETW を採取する

sleep.php やコンソールアプリケーションがきちんと動く事を確認したら、コンソールアプリケーションを動かしながら ETW トレースを取ってみましょう。

 

テスト段階で PHP のホストプロセス、php-cgi.exe は起動していると思うので、kudu の Process Explorer（https://<Web Apps 名>.scm.azurewebsites.net/ProcessExplorer/）を表示すると、php-cgi.exe が見えると思います。[Collect IIS Events] にチェックを入れた上で、[Start Profiling] をクリックします。そして、コンソールアプリケーションからリクエストを送りまくりましょう。

なお、以下のような注意書きが出ますのでご確認頂いた上で、[Yes] をクリックします。この後、[Start …] が [Stop Profiling] に変わり、色が赤くなりますので、コンソールアプリケーションを一分ほど動作させたら、そちらをクリックして止めます。少し待つと、～.diagsession というファイルがダウンロード出来ますので、ローカルに保存します。

 

4) 遅いリクエストを見つける

ETW の解析には、PerfView を使用します。以下からダウンロードして展開します。

PerfView
https://www.microsoft.com/en-us/download/details.aspx?id=28567

PerfView の使い方は以下を見てみてください :-)

PerfView Tutorial（英語）
https://channel9.msdn.com/Series/PerfView-Tutorial

ハードコア デバッギング～Windows のアプリケーション運用トラブルシューティング実践
https://channel9.msdn.com/events/de-code/2017/MR15

今回の場合は、まず PerfView の左側ツールで .diagsession ファイルが置かれたフォルダまで移動し、当該ファイルをダブルクリックします。少し待つと .etl が展開されますので、その中の [Events] をダブルクリックします。取得された ETW のイベントが全てここで確認出来ます。

左側の [Event Types] で [IIS_Trace/IISGeneral/GENERAL_REQUEST_START] をクリック、さらに Ctrl を押しながら [IIS_Trace/IISGeneral/GENERAL_REQUEST_END] をクリックしてから、Enter キーを押します。これが、リクエストの入りと出の一覧なのですが、これだとなんだかわかりませんね。

右上の [Cols] をクリックし、Ctrl を押しながら、ContextId、DURATIOIN_MSEC、RequestURL、ThreadID をクリックしていき、最後に Enter を押します。すると、DURATION_MSEC つまり経過時間（ミリ秒）が別欄になりますのでわかりやすくなります。ざーっとスクロールしていくと。。。ありました。5,000 ミリ秒、つまり 5秒 かかっているリクエストです。ContextId がリクエストに付けられる一意な ID ですので、少し上の START と見比べると、sleep.php?id=3 の処理、という事が分かります。

さらに追い込みます。その列の ContextId をクリックしてコピー、上部 [Text Filter] にペーストします。Cols の右の内容を消した上で、さらに、左側では IIS_Trace で始まるものをすべて、Shift キーを押しながら範囲選択して Enter を押します。ここで出てくるのは、IIS の [失敗した] 要求トレース、とほぼ同じものですので、リクエストが入り乱れている場合などは、遅延している URL は何かといった点もここで突き止められます。さて、[Time MSEC]、つまり、ETW を採取開始してからのミリ秒がぽんと飛んでいる箇所があります。ここが問題の場所ですね。今回は PHP なので、php-cgi.exe でこの期間に何をやっていたのかを追いましょう。

 

5) 遅いリクエストの遅い処理（ボトルネック）を見つける

PerfView のメインウィンドウに戻り、今度は [Events] ではなくて、[Thread Time (with StartStop Activities) Stacks] をダブルクリックしましょう。プロセスを選ぶウィンドウでは php-cgi をダブルクリックします。全時間範囲を見てもさっぱりなので、まずは時間範囲を絞ります。先程の FASTCGI_START の Time MSec を上部 [Start] に、FASTCGI_END の Time Msec を [End] にコピペし、さらに　[GroupPats] を空にして Enter を押します。

毎ミリ秒のスタックが記録されているので、ここから BROKEN を展開していくのですが、その前にシンボルを合わせておきましょう。Kudu コンソールで D:\ に上がり、"dir /s /b php-cgi.pdb" を検索すると、D:\Program Files (x86)\PHP\v5.6\debug\ にある事が分かります。使用している PHP バージョンに合わせて php-cgi.pdb とphp5.pdb などの PHP 主要モジュールの シンボルファイルをダウンロードし、適当なフォルダに入れます。Thread Time … のウィンドウ、[File] メニューから [Set Symbol Path] を選択します。表示されたダイアログで [Add Microsoft Symbol Server] をクリックした上で、.pdb をダウンロードしたフォルダを最初の列に記入します（セミコロンがデリミタになります）。

では、BROKEN から展開していきましょう。BROKEN は本来、スタック壊れているよ、という意味なのですが、まぁ往々にしてその下も展開できます。もし <モジュール名>? となってしまって関数が出ない場合は、そこを右クリックして、[Lookup Symbols] を選んでください。

もう一目瞭然ですね。php5.dll の zif_sleep() から、Windows の SleepEx() が呼ばれています。ポイントは、右の Inc %、つまり、この7.6 秒後から、12.7 秒後までの凡そ5秒間、このスレッドでは 99% の時間、ずっとスリープしてた、という事を示しています。

 

今回は以上となります。

本来はこんなシンプルな問題にはならないと思いますが、このように ETW + PerfView はかなり細かいところまで追い込めます。これが ASP.NET なら、さらに例外のスタックを引っ張り出したりなどもお手のもの。今回はあえて PHP でやってみました（なお、Java はシンボルが無いのであまり細かいところまでは追い込めません。Application Insights などの方がいいかもしれませんね）。

皆様のお役に立てば嬉しいです。

ではまた。
d99 でした。