こんにちは。斎藤です。
ここ半年ほど長年携わってきた Android を離れ、昨年にリリースしたFamm 出張撮影のWeb フロントを担当しています。
今回はそんな運用中のサービスで発生したメモリリークを見つけてから解決するまでの苦労と解決案を紹介します。
メモリリークは原因がわかるとなんてことなかったりするのですが、それまでは暗中模索の状態と思います。
同じくこの現象で困っている方の一助になれば幸いです。
前提
Nuxt.js を universal モード (SPA + SSR) で運用。
現象
フロントサーバーが定期的に再起動を繰り返す。
調査
いくつかの方法で調査しました。結果が出なかったものについてもアプローチを記載します。
1)ローカルで再現確認してみる
nuxt-tsでローカルサーバーを立ち上げるabコマンドでリクエストを大量に送る- 一晩放置
- 再現せず
のちに判明することですが、 nuxt-ts では再現せず、 nuxt-ts build && nuxt-ts start で起動しないと再現しない問題でした。
2)node サーバーのヒープ スナップショットを取得して解析してみる
こちらの記事を参考に node サーバーのヒープ スナップショットを取得できました。 developers.google.com
しかし、Nuxt のフレームワークがどう動いているか理解していないので、リクエスト毎にアロケーション・デアロケーションされるメモリの羅列を見てもこれが正常かどうかがわかりませんでした。 サンプルのような単純な node サーバーであれば可能そうですが、Nuxt のようにフレームワークを使用している場合、フレームワーク自体について深く理解していないと被疑箇所の特定は難しいかもしれません。
3)現象発生時のコードまで遡ってみる
原始的で時間のかかるやり方ですが確実性は高い方法です。
幸いなことに現象発生以前より CloudWatch で死活監視をしていたおかげで、現象発生直前の PR をいくつかに絞り込めることができました。 そのPRの中でほとんどが HTML や CSS の View の変更でしたが、1つだけ View 以外の変更がありました。
被疑箇所の詳細
問題の PR は axios のエラーハンドリングを共通化するため intercepters を追加した対応でしたが、これらの追加方法に問題があったようです。
axios intercepters とは
plugins と intercepters
弊社のアプリでは axios 共通処理の設定を nuxt.config.js の plugins で実行しています。具体的には、環境ごとにバックエンドの URL を切り替えるなど共通処理の設定をしており、ここにレスポンス直後にアクセストークンを更新する処理を intercepters に追加する設定も追加しました。
export const api = axios.create({ baseURL: process.env.BASE_URL }) export default () => { api.interceptors.response.use((res => res), (error => { // 401 ならトークンを更新する(略) })) }
追加した処理の問題
plugins は universal モードで SSR 時にリクエスト毎に実行されます。 つまり、100回リクエストされれば axios インスタンスが保持する intercepter は 100 になります。これが 1万, 10万, 100万 と増えていきメモリを食い尽くしてサーバーが再起動をするという流れです。
intercepters.use の処理をみると割り込み処理を表現する intercepter のコールバックを配列で保持しています。
function InterceptorManager() { this.handlers = []; }
そして use メソッドはその配列にコールバックを追加して、戻り値として id を返します。この id は配列の長さ(登録したコールバックの個数)です。
/** * Add a new interceptor to the stack * * @param {Function} fulfilled The function to handle `then` for a `Promise` * @param {Function} rejected The function to handle `reject` for a `Promise` * * @return {Number} An ID used to remove interceptor later */ InterceptorManager.prototype.use = function use(fulfilled, rejected) { this.handlers.push({ fulfilled: fulfilled, rejected: rejected }); return this.handlers.length - 1; };
nuxt-ts build && nuxt-ts start でローカルサーバーを起動して http://localhost:3000/ へアクセスを繰り返すと use メソッドの戻り値である id が増加していくことを確認できました。やはりこれが原因で間違いなさそうです。
対応方針の検討
原因が特定できたので、次はこの現象を解消していきます。
interceptors には追加する use だけでなく、削除するための eject メソッドが提供されています。 eject は指定した id(use メソッドの戻り値として返ってくる) の割り込み処理を削除します。登録されたコールバックを解除すると言った方が直感的かもしません。
eject をすれば次に use をした時 1 が返ってことを期待しましたが、リクエスト度にインクリメントされた値が返ってきます。つまり内部に保持しているコールバックの数が減りません。
そこで eject 処理の中身を確認すると。
/** * Remove an interceptor from the stack * * @param {Number} id The ID that was returned by `use` */ InterceptorManager.prototype.eject = function eject(id) { if (this.handlers[id]) { this.handlers[id] = null; } };
なんと interceptors 保持している割り込み処理のリストアイテムに null を代入するだけでした。
eject の懸念
上記の動作を見てある懸念が浮かび上がりました。
interceptors を eject しても保持している handlers の長さが変わらないのであれば、サーバーの起動から終了までに受けることができるリクエストの上限は Array の上限と等しい・・・？
Array.length の上限値については MDN web docs には 0 から 232-1 までと記載されています。
その仕様通り以下のプログラムを組んで実行したところクラッシュすることを確認しました。
let arr = [] for (let i = 0; i < 4294967295; i++) { arr.push(null) }
ログ。
<--- Last few GCs --->
[33440:0x103c9c000] 31929 ms: Scavenge 1090.8 (1129.7) -> 1090.8 (1129.7) MB, 60.0 / 0.0 ms (average mu = 0.990, current mu = 0.874) allocation failure
[33440:0x103c9c000] 32640 ms: Mark-sweep 1664.6 (1703.5) -> 668.0 (707.0) MB, 317.1 / 0.0 ms (average mu = 0.945, current mu = 0.752) allocation failure scavenge might not succeed
<--- JS stacktrace --->
==== JS stack trace =========================================
0: ExitFrame [pc: 0x100a944e2]
Security context: 0x0741fd89a2f1 <JSObject>
1: /* anonymous */ [0x7412d3802f1] [server.js:~1] [pc=0x756b9f96d69](this=0x07412d3d44e1 <Object map = 0x7413d215679>,0x07412d3d44f9 <Object map = 0x7413d252759>,0x07412d3d44e1 <Object map = 0x7413d215679>,0x07412d380261 <JSFunction r (sfi = 0x741a9cec441)>)
2: r [0x7412d380261] [server.js:1] [bytecode=0x74125df3b69 offset=89](this=0x07410b6044e1 <JSGlo...
FATAL ERROR: invalid array length Allocation failed - JavaScript heap out of memory
Writing Node.js report to file: report.20191213.161007.33440.0.001.json
Node.js report completed
1: 0x100075336 node::Abort() [/usr/local/Cellar/node/12.4.0/bin/node]
2: 0x1000759ae node::OnFatalError(char const*, char const*) [/usr/local/Cellar/node/12.4.0/bin/node]
3: 0x1001685f5 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/usr/local/Cellar/node/12.4.0/bin/node]
4: 0x100168597 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/Cellar/node/12.4.0/bin/node]
5: 0x100429643 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/usr/local/Cellar/node/12.4.0/bin/node]
6: 0x10040e357 v8::internal::Factory::AllocateRawFixedArray(int, v8::internal::PretenureFlag) [/usr/local/Cellar/node/12.4.0/bin/node]
7: 0x10040dcb1 v8::internal::Factory::NewFixedArrayWithFiller(v8::internal::RootIndex, int, v8::internal::Object, v8::internal::PretenureFlag) [/usr/local/Cellar/node/12.4.0/bin/node]
8: 0x1003cb132 v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastPackedObjectElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)2> >::ConvertElementsWithCapacity(v8::internal::Handle<v8::internal::JSObject>, v8::internal::Handle<v8::internal::FixedArrayBase>, v8::internal::ElementsKind, unsigned int, unsigned int, unsigned int, int) [/usr/local/Cellar/node/12.4.0/bin/node]
9: 0x1003c9cc5 v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastPackedObjectElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)2> >::GrowCapacity(v8::internal::Handle<v8::internal::JSObject>, unsigned int) [/usr/local/Cellar/node/12.4.0/bin/node]
10: 0x1005d4f72 v8::internal::Runtime_GrowArrayElements(int, unsigned long*, v8::internal::Isolate*) [/usr/local/Cellar/node/12.4.0/bin/node]
11: 0x100a944e2 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit [/usr/local/Cellar/node/12.4.0/bin/node]
12: 0x756b9f96d69
13: 0x1009fe124 Builtins_InterpreterEntryTrampoline [/usr/local/Cellar/node/12.4.0/bin/node]
つまり eject でコールバックの登録を解除をしたところでリクエストの回数が 232-1 を超えるとアプリケーションがクラッシュする事に。
実際は Array の上限の警告 RangeError: Maximum call stack size exceeded より先に OOMの警告 FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memoryが表示されるので実際には 232-1 よりも少ない数でクラッシュする可能性があります。
同様の懸念が Issue にも記載されていますが、未だ未解決です。
対応
axios インスタンスに interceptor が登録されている場合は登録しないという方針が一番安全そうです。
以下のようにチェックする処理を追加しました。
export const api = axios.create({ baseURL: process.env.BASE_URL }) export default () => { /* すでに登録されているかどうかを確認する処理 START */ if (!!id || id === 0) { return } /* すでに登録されているかどうかを確認する処理 END */ api.interceptors.response.use((res => res), (error => { // 401 ならトークンを更新する(略) })) }
まとめ
- フレームワークに精通していない人にとってヒープダンプの解析は効果的でない
- メモリリークの調査は
nuxt-tsではなくnuxt-ts build && nuxt-ts startで確認する - plugins で export した function は SSR 時にはリクエスト毎に呼ばれることに留意する
- axios interceptors は eject ではなく use しない
以上です。
積極採用中！！
子育て家族アプリFammを運営するTimers inc.では、現在エンジニアを積極採用中！
急成長中のサービスの技術の話を少しでも聞いてみたい方、スタートアップで働きたい方など、是非お気軽にご連絡ください！
採用HP: http://timers-inc.com/engineerings
