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

  • Article

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