Promise を可視化する
ドラフトなところがあるのでこちらにだけ投稿。
3行で手短に話すと
- Safari(iOS/macOS)のブラウザエンジンを立ち上げた直後にPromiseをたくさん立ち上げるとPromiseがストールしいつまで経っても処理が完了しないケースがあった
- 組み合わせているSDKの問題なのか、ブラウザバグなのか最初検討つかなかったためPromiseの作成と実行結果を記録するコードとビジュアライズするツールをReactで作成し調査を進めた
- setTimeoutなどで処理を遅延させるととりあえず回避できることがわかったが、他社製SDK内部に原因がありバグを完全に原因を突き止めることができなかった
バグの発覚
全コードを掌握していないのであまり詳しくかけないのだが、下記条件で不具合が検知された:
- iOS Safari 最新
- WKWebViewController のインスタンスを作ってページを表示させる（リダイレクトなどはなし）
調べたところどうやら Promise が解決しないように見え、axiosによる非同期通信がうまくいっていない可能性も考えられた。
調査
もう忘れつつあるのだがまず読み込み系が怪しいと考え、内部で通信が行われるライブラリのメソッドの呼び出し(Promise.allで同時進行)しているところを await に分解したところ直ったように見えた:
// before
await Promise.all[fetchTaskA(), fetchTaskB(), fetchTaskC()]
// after
await fetchTaskA()
await fetchTaskB()
await fetchTaskC()beforeの段階ではfetchTaskAは動くがfetchTaskBが全く発火しないという明らかに正常ではない(しかもリロードすると治る)状態であった。
ところが表示と対応するデータによっては引き続き不具合が起きることがわかり再び調査する必要が出てきたのだが、コード量もそれなりにあり、原因の特定が難しく感じられたためツールの開発を行うこととした。(ここまでは業務の範囲でちょうど週末だったのとうまくいくか自信がないのもあってツールの開発は休日に行うこととした)
promise-visualizer
発想としては下記の通りである
記録側のプログラム
- Promise の prototype に手を加え resolve, reject, finally が呼ばれたらグローバル変数に開始した時間含め記録
- resolve, reject, finally のコールバックも無名関数でラップしておきそちらが呼ばれたら終了時間含めイベントとして記録する(実行時間がわかる)
- この際コールスタックも取得することでどこで作られたPromiseなのかを把握できるようにしておく
これを調査対象のページのHEADタグに仕込んでおけば自動的に記録される。データの保存はコンソールにJSONを吐き出してそれをテキストファイルとして保存すればOKだ。
Chrome Extensionなどを作って気軽に記録できるようにできれば Qiita などに投稿できたのだろうがそこまで情熱がなかったためここにコードを示すまでとする:
const promiseVisualizerRecorder = (function () {
let eventCount = 0;
const eventInfos = [];
const eventTargets = [];
const eventTargetIdentifiers = [];
function getEventEndHandler(index, action) {
return function () {
eventInfos[index].endTime = new Date().getTime();
eventInfos[index].action = action;
};
};
function addEventInfo(target, additionalInfo) {
const stack = Error().stack.split('\n').slice(2).filter(ln => ln.indexOf('_ObservableVisualizerPromise') < 0);
if (stack[stack.length - 1].match(/\(<anonymous>\)$/)) { // 2020/09/14追加、この制御がないとChromeで無限ループのような挙動となる
return -1;
}
if (target && !eventTargets[target]) {
const i = eventTargets.push(target) - 1;
eventTargetIdentifiers[i] = (new Date().getTime() * Math.random()).toString(16).replace('.', '');
}
const index = eventCount++;
eventInfos[index] = {
stack,
startTime: new Date().getTime(),
};
if (target) {
eventInfos[index].identifier = eventTargetIdentifiers[eventTargets.indexOf(target)];
}
if (additionalInfo !== void 0) {
eventInfos[index].additionalInfo = JSON.stringify(additionalInfo);
}
return index;
}
var _open = XMLHttpRequest.prototype.open;
XMLHttpRequest.prototype.open = function (method, url, async, user, password) {
var index = addEventInfo(this, {
method: method,
url: url,
async: async,
user: user,
password: password
});
this.addEventListener('loadend', getEventEndHandler(index, 'xhr'));
_open.call(this, method, url, async, user, password);
};
const _Promise = Promise;
class _ObservableVisualizerPromise extends _Promise {
constructor(executor) {
super(executor);
const index = addEventInfo(this);
if (index < 0) { // 2020/09/14追加、この制御がないとChromeで無限ループのような挙動となる
return;
}
_Promise.all([this])
.then(getEventEndHandler(index, 'then'))
.catch(getEventEndHandler(index, 'catch'));
}
}
Promise = _ObservableVisualizerPromise;
return new function () {
this.exportInfo = function () { return JSON.stringify(eventInfos); }
};
})();このコードをHEADタグなどHTMLの頭の方に追記しておく。最初に列挙した仕様とは最終的には異なっていて、
- Promise のコンストラクタが呼ばれたとき開始とするために prototype ではなくクラスを継承しそちらを Promise として書き換え (IE11非対応となった)
- XMLHttpRequest もイベントとしてタイムラインに記録
していたりする。記録完了したらコンソールで promiseVisualizerRecorder.exportInfo() を呼ぶとJSONが表示されるはずだ。Chrome/Safari/Edgeで動作するはずである(Firefoxは動かなくなってしまった…)。
個人的には copy(promiseVisualizerRecorder.exportInfo()) してVSCodeへ貼り付けてファイルへ保存する流れとした。
記録したデータを表示するプログラム
Reactで作ったアプリをこちらにアップした:
https://github.com/cubenoy22/promise-analyzer
こんな初期画面が出るので保存済みJSONをドラッグすると…
こんな風に表示が変わる。左側は横が時間軸(記録開始してから右に行けば行くほど遅い時間、1秒おきに縦線が入る)、縦の重なり同時に発生したイベント(Promise/XHR)が重ならないように回避した結果このような表示となった。緑はthenで終了、黄はcatch、紫はXHR、赤丸は終了しなかったpromiseである。右の領域は左でイベントをクリックするとスタックトレースが表示されるようになっている。
終わりに
このふたつを組み合わせることで成功時と失敗時を比較し問題がブラウザのバグでありそうなところまでは掴めたのだが、そこから先は調査依頼となり終了してしまった。またこちらの問題はどうやら4月の下旬ごろに対応したらしいのだが、当時ChromeやFirefoxでも確か動いていたのが今日確かめたところPromiseのトレースが全然動かなくなってショックを受けた。もともとお行儀の良いアプローチではないため仕方がないとはいえ残念。もしかしたら誰かの役に立つかもしれないため、このブログで供養としたい。
