OmoikaneのRealm生成が遅かったので、Boaのscope検索と字句解析を調べた

OmoikaneのCIの待ち時間を調べた記事では、文書だけの変更に重い検証を走らせないことや、ビルドキャッシュを見直した話を書いた。それとは別に、実行する必要のあるテストそのものにも時間がかかっていた。

OmoikaneはJavaScriptの実行にBoaを使っている。ページやiframeのためにJavaScriptのRealmを作るたび、DOM APIを用意する大きなスクリプトを実行する。その処理がテスト時間の相当部分を占めていた。Issue #1154では、テストの数やRealmの数を減らすのではなく、この初期化そのものを調べた。

先に結果を書くと、macOSのtest profileでRealm生成時のbootstrap処理は約0.58秒から約0.13秒になった。ただし、これはrelease buildのページ表示時間を測った結果ではない。何を測り、どこを変えたらそうなったのかを順に残しておく。

Realmを作るたびに何が起きていたか

RealmはJavaScriptの組み込みオブジェクトやグローバル環境を持つ実行単位で、Omoikaneではページやiframeごとに必要になる。Realm自体については以前の記事に書いた。

新しいRealmを作ると、OmoikaneはDOMをJavaScriptから使えるようにするbootstrapを読み込む。dom_bootstrap.js、xpath.js、font_loading.js、find_in_page.jsを連結したソースは約1.1MBある。evaluate_dom_bootstrapはそのソースをmoduleとして解析し、load、link、evaluateまで進める。内部のhost bindingをページのglobalに露出させていないかも、この初期化時に確認している。

Realmを作る
  ↓
bindings.module_source()  約1ms
  ↓
Module::parse             約335ms
  ↓
module.load + link        約240ms
  ↓
module.evaluate           約10〜25ms

これは変更前に一回だけ実行したときの、おおよその内訳である。全体で約0.58秒かかる。特にparseとload・linkが重かった。bootstrapソースは毎回ほぼ同じなのに、Realmごとに解析とコンパイルを繰り返している。

一時的な計測コードを入れてlibのユニットテストを全件走らせると、1069件のテストからbootstrapが計1414回呼ばれていた。0.58秒を掛けると約820秒になる。libテストのCPU時間は約1160秒だったので、概算で7割ほどがこの初期化に対応する。一方、実時間は160〜222秒だった。テストが並列に走るため、CPU時間と時計で測った実時間は同じ値にはならない。

実際、Realmを25個作るテストは単体で16.1秒、13個作るテストは7.8秒かかっていた。遅いテストを一つだけ削っても、根本の費用は残る。そこで「bootstrapを何度も処理しない」「処理するなら処理自体を速くする」の両方を検討した。

最初の案は解析済みmoduleのキャッシュだった

最初に立てた子Issue #1155は、解析済みのbootstrap moduleをプロセス内でキャッシュするというものだった。同じソースを何度もModule::parseへ渡すのだから、一回作ったASTを使い回せれば分かりやすい。

ただ、Boaの解析結果をそのままスレッド間で共有できるわけではない。ASTのScopeはRcとRefCellを含み、ASTのシンボルはContextごとのInternerにも依存している。libtestはテストごとに別スレッドで動く。測定した1414回のうち、同じスレッドで二回目以降のRealmを作ったのは345回だけだった。残りの大半には、スレッド内だけのキャッシュを置いても効かない。

「キャッシュすればよい」という方向で実装を進める前にプロファイルを取ると、別の問題が見えた。解析とコンパイルの上位に、JsStringの比較がいた。呼び出し元は、Boaのscope解析やbytecode生成で行うbindingの名前検索だった。

大きなscopeを何度も線形探索していた

JavaScriptの変数や関数の名前を解決するとき、パーサーとコンパイラはscopeのbindingを調べる。Boaでは、そのbindingを宣言順のVecに持ち、名前を探すたびに先頭から比較していた。小さな関数のscopeならこれで十分だが、DOM bootstrapのmoduleトップレベルには大量のbindingがある。

名前の参照が増えるたびに、長いリストをまた走査する。binding数をB、参照数をRとすれば、この部分の仕事はおおむねR × Bに増える。約1.1MBのソースをRealmごとに処理すると、その費用を毎回払うことになる。

PR #1160では、宣言順のVecは残し、名前からその位置を引けるFxHashMapを追加した。ただし、すべてのscopeに最初からハッシュ表を持たせたわけではない。bindingが16件以下なら従来どおり線形探索し、17件目を追加したときに索引を作る。普通の小さなscopeで索引の確保費用が増えるのを避けるためだ。

bindingは追加されるだけで、削除や改名はしない。そのため索引に入れたVec上の位置は後から無効にならない。宣言順、binding index、外側のscopeからの参照、再宣言、escapeの扱いは変えない。しきい値の前後でこれらが変わらないこともテストした。

結果は、単なるparseの短縮にとどまらなかった。名前検索はscope解析だけでなくbytecode生成でも使われるため、load・linkも大きく短くなった。

これはmacOS 8コアのtest profileでの測定である。libテストの実時間に幅がある変更前の値を使っているため、単一条件の厳密な倍率として読まない方がよい。ただ、解析だけをキャッシュする案では残っていたはずのコンパイル側まで改善したのは大きい。

次のプロファイルでは、GCが主犯に見えた

scopeの索引化後も、Realmを作るたびに約150msはかかっていた。最初にRealmを多数作るnode_lifetimeのテストをmacOSのsampleで観測すると、GCのtraceやephemeronの登録が大きく見えた。そこで子Issue #1163は、当初GC周辺の負担を調べる目的で起票した。

しかし、このテストは寿命管理を確かめるために、意図的にGCを動かす。Realm生成の純粋な費用を見る材料としては紛らわしかった。JsRuntime::new()だけを繰り返すハーネスに替えると、GCは約2.6%、hashbrownは約2.1%だった。最初の「GCが大きい」という観測を、そのまま一般のRealm生成に当てはめるのは間違いだった。

シンボルが正しく見えるようにリンカによる同一関数の統合を止め、frame pointerも付けて取り直すと、残りの重さは別のところにあった。

• ASCIIの識別子にもICUのUnicode文字判定表を引いていた。
• 字句解析のUTF8Inputがio::Bytes経由で1バイトずつreadしていた。
• 先読み用の4要素配列から1文字消費するたび、汎用のslice::rotate_leftを使っていた。
• var_scoped_declarationsが関数宣言の本体を複製して返し、scope解析とbytecode生成で繰り返していた。

1回だけなら細かい処理だが、1.1MBのJavaScriptソースを何度も通すと積み上がる。PR #1165では、ASCIIは直接判定し、非ASCIIは従来のUnicode判定を使うようにした。UTF8Inputには8KiBのバッファを持たせ、先読み配列は要素を直接移す。var宣言の収集には参照を返す内部APIを追加し、従来の公開APIは維持した。

識別子の判定は、全ASCII文字と代表的な非ASCII文字で従来のUnicode判定と一致することをテストした。読み込みは、マルチバイト文字がreadの境界をまたぐ場合やInterrupted、小さなチャンクを返すreaderでも確認している。速くなってもJavaScriptの解析結果を変えないための検証である。

計測値は段階を分けて読む

最後の変更までを、同じmacOS 8コア・test profileの計測として並べる。

最終列の約0.13秒はJsRuntime::new()を繰り返した計測で、約126〜128msという結果を丸めている。最初の約0.58秒はbootstrap処理の内訳を足した概算なので、表の一行を厳密な同一ハーネスによる三点比較とは扱わない。CPU時間と実時間、各テストバイナリの実行時間合計も、互いに違う指標だ。とくにcargo testのコンパイル時間まで136秒になった、という意味ではない。

最終PRではcargo test --lockedが3297 passed、0 failed、28 ignoredで、Boa側のAST・parser・GC・engineのテストや、baseline JITのテストも通っている。Realmの分離やhost bindingの非公開性を犠牲にしてテストだけを速くしたわけではない。

残した案もある

解析済みASTのキャッシュに加え、コンパイル済みbytecodeの共有も子Issue #1156で調べた。BoaのCodeBlockはGC管理下にあり、heapとroot登録はスレッドローカルで、定数中のScopeにもRc/RefCellがある。別スレッドのテスト間でそのまま共有はできない。同じスレッド・同じContextなら技術的な余地はあるが、module recordはRealmごとに必要で、inline cacheやJITの状態をどう扱うかも設計しなければならない。scope索引化後のload・linkは約25msなので、テスト内で共有できる345回を全部拾っても削減の上限は概算で9秒程度だった。今回は実装していない。

使われないWeb APIを最初は読み込まない案も子Issue #1157で検討した。ただ、bootstrapは大きな即時関数で、多くの宣言が非公開の変数を共有している。分割には依存関係の書き換えが必要になる。JSのgetterで遅延させれば、初回アクセス前のObject.getOwnPropertyDescriptorがdataプロパティではなくaccessorを返すなど、外から見える振る舞いまで変わる。残りの処理時間に対する見込みと変更規模を比べ、こちらも実装しなかった。

今回の改善は、巨大なbootstrapをキャッシュする仕組みを追加して達成したものではない。最初の案を保留し、Boaの「大きなscopeで名前をどう探すか」と「字句解析で1文字をどう読むか」を測り直して変えた結果である。特に、GCが重いという一度目のプロファイルを、そのテスト固有の条件から切り離して取り直せたことは大事だった。

ページやiframeを作る経路にも同じ初期化があるので、実際の利用時にも影響する可能性はある。ただし、release buildでページ1つとiframe1つを生成する時間の変更前後比較は行っていない。当初のIssueにはその完了条件を置いていたが、今回は計測せずに閉じた。ここで言えるのは、test profileでRealm生成とテスト実行が短くなり、既存の検証が通ったところまでである。