こちらの記事は、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) > 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 でした。