あらすじ
- Web技術が複雑になる中で、JavaScriptのプロファイリングをとる方法とは。
- プロファイリングを取るためのコードを手で書いてみましょう。
- とてもシンプルで、かつ最高のJavaScriptプロファイラ sjsp を作りました。
本当にあった怖い話
上司 「とにかくJavaScriptのコードを速くしてくれ」
私 「分かりました、速くします」
(次の日)
私 「いいプロファイラがないなら作ればいいじゃない」
同じチームの人 「えっ？」
私 「最高のJavaScriptプロファイラ作ったよ」
同じチームの人 「「えっえっ？？？」」
私 「早速使ってみたらこことここが遅いって分かったよ」
同じチームの人 「「「この子は一体…」」」
JavaScriptのプロファイリングの難しさ
近年、Webブラウザーの処理速度は著しく向上し、その可用性の高さから、アプリケーションのプラットフォームとして広く利用されるようになりました。 JavaScriptは誕生して20年経ちましたが、当初からは考えられないほど巨大で複雑なコードが、日常的に実行されるようになりました。 端末の処理速度は向上しましたが、アプリケーションの複雑さも増してきており、また比較的リソースの少ない端末にも対応しなければならないといった要求もあることから、JavaScriptのプロファイリング技術はますます重要になってきています。
Web技術の進化はあまりにも速く、書かれるアプリケーションのコードは複雑化してきているにもかかわらず、プロファイリングの手法は従来よりほとんど進化していません。
そのほとんど唯一と言っていい手段、それはWebブラウザーの開発者用ツールを使うことです。
JavaScriptのコードは複雑化し、Webフレームワークによりコードの抽象度が高まっているのに、プロファイルといえば開発者用ツールしかなく、時にこのプロファイラが開発者を悩ませます。
一体ここから何を読み解けばいいのでしょうか。
一体どれだけ関数をたどれば、私の書いたコードが出てくるのでしょうか。
Webフレームワークは私たちの書くコードの抽象度を高めてくれます。しかし処理系からすると、私たちのコードはフレームワークの様々な複雑怪奇な仕組みにより隠蔽されてきています。フレームワークがあまりに複雑になってきているので、ご丁寧にもあらゆる関数の実行時間を表示してくださるプロファイラ様は、もはやほとんど私たちの要求にそぐわなくなっています。フレームワーク製作者ならばいざ知らず、
私たちがプロファイルを取りたいのは、フレームワークの関数ではなく、私たちが書いたコードのはずです。
私たちのやりたいプロファイルとは、フレームワークの関数の一覧から一所懸命我々の書いた原因箇所を掘り当てる行為ではないはずです。あなたは本当に、そのプロファイラが便利だと思って使っていますか？情報は多いけど結局自分で原因箇所を探さなくてはいけない、そんなプロファイラに疲弊していませんか？
プロファイラとは
いま一度、プロファイラの仕事とは何なのか考えてみましょう。私の考える、使いやすいプロファイラに求められる責務とは次のようなものになると思います。
- 私たちが書いたコードの中から (あるいはこちらが指定したコードに限定して)
- 実行に時間がかかる箇所を
- 分かりやすく提示する
この3つの条件を前提条件に考えてみますと、ブラウザーのプロファイラはとにかく2つ目の「実行に時間がかかる箇所を」単に提示しているだけにしか見えません。フレームワークの関数ばかり提示してくれるようなのは、(少なくともフレームワークの作者ではない私には) 使い物になりませんし、分かりやすいとは思えません。また、本来は私たちのコードが原因なのに、プロファイラのせいで「遅い」という不当な評価を受けるフレームワークもかわいそうです。
簡単なプロファイラを手で書いてみよう
他のプロファイラのことは一旦忘れて、私たちの書いたコードの中で時間がかかる箇所を特定するにはどうすればいいかをゆっくり考えていきましょう。 実行にどれくらい時間がかかるかというのは、どうやって取ればいいでしょうか。 例えば、次のようにコードがあったとします。
function test1() { // 何らかの処理 } function test2() { // 何らかの処理 } function test3() { // 何らかの処理 } test1(); test2(); test3();
さて、どの関数の実行に時間がかかったでしょうか。それを調べるには、現在時間を取って差を取ればいいはずです。
function test1() { var startTime = Date.now(); // 何らかの処理 var endTime = Date.now(); // endTime - startTime が関数の実行にかかった時間 }
test2、test3にも同様に、Date.now()を取るコードを関数の最初と最後に差し込めばいいはずですね。
上のコードでは実行にかかった時間が保存されないので、保存するコードも書いてみます。
var profileResult = {}; function logProfile(funcName, time) { profileResult[funcName] = profileResult[funcName] || 0; profileResult[funcName] += time; } function test1() { var startTime = Date.now(); // 何らかの処理 logProfile("test1", Date.now() - startTime); }
あまりにシンプルですが、すでに十分な機能を持ったプロファイラです。
上のプロファイラに求められる条件を考えますと、「私たちの書いたコードの中から」はクリアしたように思えます。なぜなら、test1は私が書いた関数だからです！
しかし、次のような関数を考えて下さい。returnがある関数です。
function test2() { if (x) { // 何か処理 return; } // 何か処理 if (y) { // 何か処理 return; } // 何か処理 }
このコードにはどこにプロファイルコードを差し込めばいいのでしょうか。関数の最初と最後？
function test2() { var startTime = Date.now(); if (x) { // 何か処理 return; } // 何か処理 if (y) { // 何か処理 return; } // 何か処理 logProfile("test2", Date.now() - startTime); }
これはダメですね。関数は実行されるのにlogProfileが呼ばれることなく終了する可能性があります。どうやら、全てのreturnの直前に置く必要があるようです。
function test2() { var startTime = Date.now(); if (x) { // 何か処理 logProfile("test2", Date.now() - startTime); return; } // 何か処理 if (y) { // 何か処理 logProfile("test2", Date.now() - startTime); return; } // 何か処理 logProfile("test2", Date.now() - startTime); }
良さそうですね。関数の最初でstartTimeを取り、returnの直前と関数の最後でlogProfileすればいいわけですね。
では、次のようなコードを考えてみましょう。
function test3() { if (x) { return [ (重い処理), (重い処理) ]; } return [ (重い処理), (重い処理), (重い処理) ]; }
関数の最初と最後とreturnの直前にコードを差し込んでみましょう。
function test3() { var startTime = Date.now(); if (x) { logProfile("test3", Date.now() - startTime); return [ (重い処理), (重い処理) ]; } logProfile("test3", Date.now() - startTime); return [ (重い処理), (重い処理), (重い処理) ]; logProfile("test3", Date.now() - startTime); }
これでは全然ダメですね。きちんとプロファイルを取るには、returnで返される値の計算時間も考慮しなくてはいけません。変数に入れてみましょう。
function test3() { var startTime = Date.now(); if (x) { logProfile("test3", Date.now() - startTime); var returnedValue = [ (重い処理), (重い処理) ]; logProfile("test3", Date.now() - startTime); return returnedValue; } var returnedValue = [ (重い処理), (重い処理), (重い処理) ]; logProfile("test3", Date.now() - startTime); return returnedValue; logProfile("test3", Date.now() - startTime); }
この方法では、次のようなぶら下がりreturnには括弧でくるまないといけないという罠があります。
function test3() { var startTime = Date.now(); if (x) return [ (重い処理), (重い処理) ]; }
function test3() { if (x) { logProfile("test3", Date.now() - startTime); var returnedValue = [ (重い処理), (重い処理) ]; return returnedValue; } logProfile("test3", Date.now() - startTime); }
括弧なしのぶら下がりreturnは、if文やwhile文の変換になり、少し手間がかかります。ifとwhileの本体、そしてreturn文自体のように複数ケースあるのも大変です。
そこで、次のようにすると、単純にreturn文の変換だけになって、変換コードも綺麗にかけます。
function test3() { var startTime = Date.now(); if (x) { return (function() { var returnedValue = [ (重い処理), (重い処理) ]; logProfile("test3", Date.now() - startTime); return returnedValue; }).call(this); } return (function() { var returnedValue = [ (重い処理), (重い処理), (重い処理) ]; logProfile("test3", Date.now() - startTime); return returnedValue; }).call(this); }
さて、以上の試行錯誤で、ある関数のプロファイルを取るために必要な処理が分かりました。
- 関数の最初で現在時刻を取る
- 関数の最後でプロファイル結果を報告 (
returnが一つもない関数があることを忘れてはいけません！) - 各
returnで、返される値を一時的に変数に保存し、プロファイル結果を報告する即時関数を呼ぶようにする。
とても簡単ですね。 複雑でかつ謎技術により動いているブラウザーのプロファイラと比較すると、私たちの書いた手動プロファイルはとても単純明快です。
sjsp
さあ、JavaScriptのコードをプロファイリングするのに、必要最低限のことは全てお伝えしました。 私の知りうる手の内はすべて明かしました。 上記の処理を、私たちのコードのすべての関数について行えばいいはずです。
ここで質問です。 あなたが普段触るプロダクトコードには、関数はいくつありますか。 いちいち上の処理を全ての関数に適用しますか。
もちろん、プログラマーは、こういうことをするためにプログラムを書くはずです！ というわけで、上記の処理を、すべて自動で行うプログラムを作りました。
その名も sjsp です。Simple JavaScript Profilerの略です。sjspはHaskellで書かれています。抽象構文木を扱うにはとても適した言語だと思います。sjspのインストールはとても簡単です。まず、stackコマンドをcommercialhaskell / stack - GitHubよりインストールして下さい。そして、次のように実行して下さい。
$ git clone https://github.com/itchyny/sjsp $ cd sjsp $ stack install $ export PATH=$PATH:$HOME/.local/bin
こうすると、sjspがインストールされるはずです。
sjspコマンドは、私たちのJavaScriptのコードをプロファイリングコード付きのJavaScriptコードに変換してくれます。
プロファイルしたい JavaScript ファイル test.js
｜
｜ sjsp コマンド
↓
プロファイリングコードが差し込まれた JavaScript ファイル test.sjsp.js
使い方はとても簡単です。
$ sjsp test.js # test.sjsp.js が生成される
そして、普段ならtest.jsを読み込むところを、test.sjsp.jsに書き換えて下さい。
Webサイトを開きJavaScriptコンソールを見ると、一定時間ごとにプロファイリング結果が流れてきます。
例えば次のような感じです。
========== SORT BY TIME ==========
time: 30.20sec count: 71 test6 test.js (line: 31, col: 18) function test6() {
time: 16.47sec count: 41 test7 test.js (line: 37, col: 18) function test7() {
time: 15.49sec count: 133 test4 test.js (line: 19, col: 18) function test4() {
time: 5.98sec count: 216 test1 test.js (line: 1, col: 18) function test1() {
time: 4.37sec count: 18 test5 test.js (line: 25, col: 18) function test5() {
time: 3.24sec count: 512 test3 test.js (line: 13, col: 18) function test3() {
time: 0.87sec count: 67 anonymous test.js (line: 49, col: 24) setInterval(function() {
time: 0.80sec count: 2 test2 test.js (line: 7, col: 18) function test2() {
time: 0.44sec count: 2 anonymous test.js (line: 43, col: 23) setTimeout(function() {
========== SORT BY COUNT ==========
time: 3.24sec count: 512 test3 test.js (line: 13, col: 18) function test3() {
time: 5.98sec count: 216 test1 test.js (line: 1, col: 18) function test1() {
time: 15.49sec count: 133 test4 test.js (line: 19, col: 18) function test4() {
time: 30.20sec count: 71 test6 test.js (line: 31, col: 18) function test6() {
time: 0.87sec count: 67 anonymous test.js (line: 49, col: 24) setInterval(function() {
time: 16.47sec count: 41 test7 test.js (line: 37, col: 18) function test7() {
time: 4.37sec count: 18 test5 test.js (line: 25, col: 18) function test5() {
time: 0.80sec count: 2 test2 test.js (line: 7, col: 18) function test2() {
time: 0.44sec count: 2 anonymous test.js (line: 43, col: 23) setTimeout(function() {
上記のモックアップから、sjspの便利さを読み解くのは難しいかもしれません。
しかし、私は実際にプロダクトコードで使ってみて、Webフレームワークにがっちり乗っかった複雑なコードのプロファイリングに、とても役に立っています。
こちらがプロファイルを取るファイルを指定できるため、当然プロファイル結果には(sjspで変換していない)フレームワークの関数は出てきませんし、苦労してスタックトレースを辿らなくても良いわけです。
sjsp コマンドは、複数ファイルの変換にも対応しています。
$ sjsp *.js
$ mv *.sjsp.js /some/other/path
あるいは、findやxargsなど他のツールと組み合わせて使用して下さい。
生成されるファイル名は、常に入力ファイルの.jsを.sjsp.jsにしたものです。
sjspは常に入力ファイルと同じディレクトリーにファイルを生成します。
そのディレクトリーに何らかの事情で書き込めない場合は、--print オプションを利用してください。
出力先が標準出力になります。
では、具体的にsjspが吐くコードを覗いてみましょう。
例えば、次のようなコードがあるとします。
function test() { console.log('test'); }
これをsjspで変換すると、次のようになります。
/* sjspの準備コード */ function test() { var sjsp__state = sjsp__start("test.js",1,1,"test","function test() {"); console.log('test');; sjsp__end(sjsp__state); }
おや、 sjsp__start とは何でしょうか。「準備コード」の中にあります。
sjsp__start = function(fname, line, col, name, linestr) { return { time: Date.now(), line: line, col: col, name: name, fname: fname, linestr: linestr }; };
関数ローカルな変数 sjsp__stateのsjsp__state.timeに現在時刻が入るということですね。
関数名やファイル名などの状態もとっていますが、本質的にはこれまで書いてきた手動プロファイルと同じです。
それではsjsp__end関数を見てみましょう。
これも「準備コード」の中にあります。
sjsp__end = function(x) { if (!x.time) return; var key = x.fname + ' :: ' + x.line + ' :: ' + x.col; sjsp__result[key] = sjsp__result[key] || { count: 0, time: 0, line: x.line, col: x.col, name: x.name, fname: x.fname, linestr: x.linestr }; sjsp__result[key].time += (Date.now() - x.time); sjsp__result[key].count += 1; };
sjsp__result という辞書に、「ファイル名」「行番号」「列番号」をくっつけたキーで、プロファイル結果を保存しています。
sjsp__result[key].time += (Date.now() - x.time); sjsp__result[key].count += 1;
この二行が重要ですね。
もう少し複雑なコードを変換してみましょう。
function test() { if (x) { return someHeavyExpression; } return otherHeavyExpression; }
これを変換すると、次のようになります。
/* sjsp準備コード */ function test() { var sjsp__state = sjsp__start("test.js",1,1,"test","function test() { "); if (x) { return (function(){ var sjsp__return = someHeavyExpression; sjsp__end(sjsp__state); return sjsp__return; } ).call(this); } return (function(){ var sjsp__return = otherHeavyExpression; sjsp__end(sjsp__state); return sjsp__return; } ).call(this);; sjsp__end(sjsp__state); }
returnの返り値を、ローカル変数sjsp__returnに代入し、プロファイルを終わった後にsjsp__returnを返す匿名関数が生成されていることが分かります。
本当に上記の手動プロファイルとまったく同じことをやっていることが分かります。
開発秘話
一昨日、上司に本気でJavaScriptのチューニングをするように言われて、なかなかいいプロファイルが取れないので困ってしまいました。
会社から帰るときに、やはりコードをパースして抽象構文木でプロファイリングコードを差し込まないとダメだと思い、家に帰ってからコードを0から書き始めました。
最初はJavaScriptのパースを行うところからでしたが、良いライブラリーのおかげでJavaScriptのパースは簡単にクリアし、直ぐに構文木の変換処理にとりかかることができました。
昨日の午前中、会社で作業してなんとかsjspは完成し、早速プロダクトコードのプロファイリングを取りました。
私の関わっているプロダクトのJavaScriptは数万行ありますが、十分な速度で変換してくれる上 (数100ms程度)、複数のJavaScriptファイルを変換したものを読み込んでも干渉せずにうまく動作します。
また、ブラウザーのプロファイラではなかなか分かりづらかった処理の重い関数を、sjspを使うととても簡単に見つけることができました。ブラウザーのプロファイラにきちんと見限りをつけて、自分でプロファイリングツールを作って正解だったと思います。
結論
sjsp は、本当にシンプルで、最高のプロファイリングツールです。
関数の最初と最後やreturnで現在時刻を取り、その差を保存するだけです。
しかし、Web技術が高度に発達し、複雑なフレームワークに支えられた大規模なWebアプリケーションには、
このようにシンプルなやり方こそが、ボトルネックを発見できるのではないでしょうか。
ブラウザーのプロファイラが提示する結果は複雑で、読み解くのが難しく、「なぜその関数をチューニングしなくてはいけないのか」というのを他の開発者に説得するのも困難でした (変なチューニングをしてコードを複雑にすると怒られます… )。
sjspのプロファイリング結果は私たちのコードにフォーカスし、分かりやすいフォーマットで伝えてくれるため、「やっぱりこの関数がこれだけ重いんです」ということを簡単に他の開発者と共有できます。
作っていきなり実戦投入したsjspは、私の関わっているプロダクトで大変役に立っており、実用に耐えうるプロファイリング方法だと考えています。
JavaScriptのプロファイリングに悩んでおられる方は、ぜひご検討下さい。
sjsp のコードやドキュメントの30%くらいと、このエントリーの30%は勤務時間内に書かれました。この機会を与えてくれたチームと会社に感謝しています。
はてなでは、自分の能力を最大限に活かして、Webアプリケーションのパフォーマンスのボトルネックになっている原因を突き止めたい人や、既存のものは使いものにならないときちんと腹を立てて自ら新しいものを生みだす人、そして最高のWebアプリケーションを構築したいエンジニアを募集しています。
