JavaScript コールバック関数のトレース
これは npm と github にソースコードを公開している 「Concurix profiling and monitoring ツール」 についてのブログです。そのツールは、もちろん、無料で使えます。マニュアルへのリンクは、npmjs.org にある cx-helloworld-readme-ja というパッケージになります。
いよいよ Flame Graph の真髄にせまる今回は、HTTP トランザクションのリクエスト側と、それを受けて処理するサーバ側のコールバック関数が、 Flame Graph の中でどのように見えるかを追跡します。helloworld を使います。helloworld のソースコードはnpmjs.org にある cx-helloworld-readme-ja というパッケージにありますから実際に試してみたい方はそちらからインストールしてください。
以下のように、helloworld.js はいたって簡単で、request を使うリクエスト側と express を使うサーバ側の機能を持っていますから、モッテコイの構成です。 :-)
Concurix ダッシュボード(下図)の Transaction History ビューには request GET と serve GET の二つのトランザクションが表示されています。
まず、request GET から見ていきます。request GET http://localhost:8123/ トランザクションをクリックすると、以下のように Transaction Sequence ビュー（下図）に移ります。
更に request GET http://localhost:8123/ をクリックすると Flame Graph ビュー（下図）に移ります。
"Synchronous vs. Asynchronous Waterfall"を見ると、 request GET には３つの処理ステップがあることが分かります。即ち、赤丸で囲んだ sync: http#request and 10 functions と async: request GET http://localhost:8123/ そして Request.prototype.onRequestResponse>response.on 'end' listener and 1 function です。これは 、http#request と レスポンスの間でサーバ側の処理がasync で行われていることを示しています。http#request and 10 functions とは、Flame Graph の下から２段目の request#Request.prototype.init>defer() fn argument 以上の全てのブロックを意味しています。全部で１１関数あるかどうか数えてみてください。もう一つ赤丸で囲んだ Total Cost はリクエストGET http://localhost:8123/ の発生に クライエント側で282 マイクロ秒かかったことを示しています。
Flame Graph を上に見ていくと下から５段目に request#Request.prototype.start とあります。そのブロックをセレクトすると同様の 情報が Inspector に表示されます。ここではスクリーンショットは載せてありませんが（試してみてください）、File name: cx-helloworld/node_modules/request/request.js の Line: 887 となっています。
そのソースファイルを見ると(上図)、909行目、 912行目、 913行目にそれぞれ copy, debug, self.httpModule.request の関数を呼んでいます。この三つの関数は Flame Graph では下から６段目にある三つのブロックに対応しています。debug は小さいです。
以上が request GET の三つのステップの最初のステップです。二つ目の async はここでは何も現れません。後述します。三つ目のステップは、request GET http://localhost:8123/ リクエストがサーバで処理されて、クライエント側のコールバック関数が呼ばれるステップです。下図にあるように、このステップは2.62マイクロ秒と極短く、Flame Graph でも赤丸で囲んだように極小さいブロックで表示されています。
Inspector を見ると、request#Request.prototype.onRequestResponse>response.on 'end' listener で、File name: request.js , Line: 976 (下図) を見ると response.on の 'end' リスナー関数が debug を呼んでいることが分かります。
果たせるかな、上図の Flame Graph の 赤丸で囲んだ部分の下から三段目の極細いブロックにマウスカーソルを移動してみると Inspector には request#debug と表示されます。
ここまでがリクエスト処理のトレースです。次にサーバ処理のトレースを見てみます。サーバ側の処理はクライエント側では、async として現れていました。
Concurix ダッシュボードから serve GET/ トランザクションをクリックし、Transaction Sequence の相当する行をクリックすると、Flame Graph ビューの "Synchronous vs. Asynchronous Waterfall" には一つの sync 処理が表示されているだけです。(下図) サーバ側の処理にかかった時間は 271 マイクロ秒です。
更に Flame Graph を調べると、cx-helloworld/node_modules/express/lib/router/layer.js の 73 行目から express#handle 関数を呼んでいることなど、細部の挙動を見て取れます。
来週はシアトルでクリスマス休暇をいただく予定です。「英語にローカライズしないの」という声も聞かれます。
