504 を「遅い」と読んで、丸一ラウンド無駄にした

クライアントプロキシが空になる障害を直した直後、同じ画面に別のエラーが出た。

バックエンドの呼び出しに失敗しました。
[詳細] getSummary: Request failed with status code 504

症状が入れ替わったこと自体は、良い知らせだった。is not a function は関数が無いというエラーで、504 は関数が実行されて返らなかったというエラーである。プロキシは正常になり、呼び出しは届いている。

そのうえで、この関数は1回の呼び出しで5種類のデータを読む。注文、キャンセル記録、実行ログ、それに2種類のマスタである。読み取りが重くて時間切れになった、と考えた。まっとうな読みに思えた。

遅いという前提で1ラウンド使った

そこから、遅さに効きそうな手を順に入れた。互いに依存しない4つの読み取りを並列にした。ページングの上限を足した。1リクエストで注文を2回全件走査していた箇所を1回にした。そして、どの段階に何秒かかったかを画面へ出す計測を入れた。

貼り直して公開すると、今度は別のエラーが出た。

[詳細] getSummary: (0 , _dateUtils.parseDate) is not a function

依存が古いというエラーである。これを直したところ、集計は通しで動いた。そして計測の警告が出なかった。読み取りは上限の半分未満で終わっていたことになる。

逆算すると、遅かった余地が無い

ここで、最初の 504 の読みが崩れた。

この関数は1行目で日付を解釈する関数を呼ぶ。つまりコレクションを1回も読む前に、その行を通る。依存が届いていない状態なら、そこで必ず落ちる。数ミリ秒である。

504 が出ていた時点でも、同じ依存の状態だったと考えるのが自然である。だとすれば、バックエンドが読み取りに時間を使い切ったという説明は成り立たない。こちらが書いたコードは1行も走っていない。

残る説明として最も整合するのは、公開した直後の初回リクエストでバックエンドのバンドル読み込みに時間がかかった、というものだった。そのときはこちらが書いたコードが走らないので、依存の状態は症状に出ない。実際、別のページでも公開直後に10秒ほど「読み込み中」のままになり、待てば普通に表示されることを確認している。

504 が意味するのは「返らなかった」だけ

戻り値が消えるので、504 からは何も読み取れない。console.log も届かない。原因の候補は、少なくとも4つが同じ姿で残る。

• 公開直後の起動コスト。バンドルの読み込みに時間がかかっている

• 依存の解決に失敗している。読み込み自体が終わらない

• 無限ループ。ページングの終了条件が効いていない

• 本当に読み取りが遅い

このうち最初の1つは、対処が「もう一度押す」で済む。だから順番として、症状の直前に何をしたかを先に確認する。公開したばかりなら、まず1回試す。2回目も 504 なら、そこから切り分けを始める。今回はこの確認を飛ばして、いちばん手間のかかる仮説から入った。

無駄になった作業と、ならなかった作業

遅いという前提で入れた対策は、全部が無駄だったわけではない。

結果として仮説を否定できたのは、最後の計測を入れたからである。速くする作業と、遅い場所を見えるようにする作業は別で、後者は仮説が外れたときにも残る。順番として、先に測るほうが安い。