どんな問題を解決したのか
こんにちは、ダイニーの ogino です。
ダイニーでは、飲食店向けのクラウド POS レジを開発しています。その機能の一つとして、一ヶ月分の売上などの情報を印刷できる「月締伝票」があります。
月締伝票のサンプル
月締伝票に記載するデータは、Node.js バックエンドで集計をしています。この API はダイニーのバックエンド全体の中で最も重く、最近では一部店舗でレスポンスに 200 秒以上かかりタイムアウトエラーが発生していました。
その結果、月締伝票を発行することができないため顧客の業務に支障をきたし、複数の問い合わせが来ている状態でした。
プロファイラやログを手掛かりに調査したところ、ボトルネックを 2 行のコードだけに特定し、ほぼコストをかけずにレスポンス時間を 20 秒ほどに改善することができました。
改善リリース前後のレスポンス時間の変化
ボトルネック 1: Date#toLocaleString
API を遅くしていた要因の 1 つ目は、Date 型のメソッド toLocaleString です。
日付を文字列にフォーマットするだけの、何の変哲もない JavaScript 標準の組み込み関数なので、計算コストを全く気にせずに使っている方も多いのではないでしょうか。
しかし直感に反して、toLocaleString は桁違いに遅い処理です。大量のデータを集計する時など、ループの中で呼び出すとそれが顕著に現れます。
const date = new Date();
console.time("toLocaleString");
for (let i = 0; i < 1e6; i++) {
date.toLocaleString("en-US", {timeZone: "Asia/Tokyo"});
}
console.timeEnd("toLocaleString"); // 27.7 秒 🔥🔥
// 比較用
console.time("toISOString");
for (let i = 0; i < 1e6; i++) {
date.toISOString();
}
console.timeEnd("toISOString"); // 0.3 秒
toLocaleString がこれほど遅い理由は、内部で処理を Intl.DateTimeFormat に委譲しており、そのインスタンス作成のために世界中の膨大なロケール情報を読み込む必要がある[1][2]からです。
ECMAScript の仕様[1:1][3]によると、toLocaleString の実装は下記のコードと概ね等価になっています。
const toLocaleString = (dateObject, locales, options) => {
const x = dateObject.valueOf();
if (isNaN(x)) return "Invalid Date";
const formatOptions = { year: "numeric", month: "numeric", day: "numeric", hour: "numeric", minute: "numeric", second: "numeric" };
const options_ = {...formatOptions, ...options}
// 🔥🔥 ここが突出して重い
const dateFormat = new Intl.DateTimeFormat(locales, options_);
return dateFormat.format(x);
};
実際のユースケースでは locales, options のバリエーションは限られていることが多いので、以下のように Intl.DateTimeFormat のインスタンスをキャッシュして使い回すと大幅に計算コストを減らすことができます。
const toLocaleStringFast = (dateObject, locales, options) => {
const x = dateObject.valueOf();
if (isNaN(x)) return "Invalid Date";
const dateFormat = memoizedDateFormat(locales, options);
return dateFormat.format(x);
};
const cache = new Map<string, Intl.DateTimeFormat>();
const memoizedDateFormat = (locales, options) => {
const key = JSON.stringify({locales, options});
const cached = cache.get(key);
if (cached) return cached;
const formatOptions = { year: "numeric", month: "numeric", day: "numeric", hour: "numeric", minute: "numeric", second: "numeric" };
const options_ = {...formatOptions, ...options};
const dateFormat = new Intl.DateTimeFormat(locales, options_);
cache.set(key, dateFormat);
return dateFormat;
}
たったこれだけで、40 倍ほど高速化されます。
// 0.7 秒 ✅
for (let i = 0; i < 1e6; i++) {
toLocaleStringFast(date, "en-US", {timeZone: "Asia/Tokyo"});
}
ボトルネック 2: 独自定義の groupBy 関数
月締伝票 API が重くなっていたもう 1 つの要因は、独自で定義していた下記のユーティリティ関数にありました。
const groupByMap = <T, U>(array: T[], callbackFn: (value: T) => U): Map<U, T[]> => {
const result = new Map<U, T[]>();
for (const value of array) {
const key = callbackFn(value);
const values = result.get(key) ?? [];
// 🔥🔥 ここが突出して重い
result.set(key, [...values, value]);
}
return result;
};
groupBy と名の付く関数なら計算量は普通
array の長さを [...values, value] の部分で長さ
特に、key のバリエーションが少ないほど 1 つ 1 つの配列 values は大きくなるので計算量が悪化します。次のコードはその最も極端な例です。
const array = Array(1e5).fill({ taxRate: 0.1 }); // key が 1 種類しか無い
console.time();
groupByMap(array, x => x.taxRate);
console.timeEnd(); // 🔥🔥 8.8 秒
解決法は明らかで、配列を毎回新しく作らず push するように変更するだけです。その結果、上記と全く同じ実験をすると実行時間が 4 ミリ秒に短縮されます。
for (const value of array) {
const key = callbackFn(value);
- const values = result.get(key) ?? [];
+ const values = result.get(key);
- result.set(key, [...values, value]);
+ if (values) {
+ values.push(value);
+ } else {
+ result.set(key, [value]);
+ }
}
原因箇所を特定するまでの流れ
前述したボトルネックは、わかってしまえば解決方法は単純です。
しかし、ボトルネックの片方は JavaScript エンジン内部にあり、もう片方は長らく変更を加えていない utility 関数の中にある状況で、ただコードを見て推測するだけでは発見が困難でした。
I/O bound か CPU bound か
問題の API リクエストのログを見ると、時間がかかっていたのは DB クエリではなく、Node.js 側の同期処理の部分であることがわかりました。
下のログでは、リクエスト全体で 201 秒の内 DB クエリが占めるのは 16 秒だけです。
このログの中の "expensive async micro task" は、非同期処理に紐づく単一のコールバックの実行時間が長い場合に出力しています[4]。つまり、何らかの同期処理がぶっ続けで 185 秒間実行されていたことを示しています。
次の問題は、それがコード上のどこから発生しているかということです。
Date#toLocaleString
2 つのボトルネックの内 toLocaleString に関しては、別件の対応で既に解決済みでした。
月締伝票とは全く別の API でタイムアウトエラーが頻発しており、調査のために Cloud Profiler を本番環境の一部で新規導入しました。その際に得られたのが以下の結果です。
スタックの末端をほぼ全て f.tz が占めていることに注目してください。ダイニーでは、日時を扱うためのライブラリとして Day.js を利用しており、タイムゾーン変換のための tz メソッドを間接的に様々な箇所で使用しています。
そこで Day.js のソースコードを読んでみると、パフォーマンス問題に関連しそうなコメントが見つかります。
これをヒントに "Intl.DateTimeFormat slow" などで検索し、以下のような情報に行き当たりました。
- Performance of toLocaleString is slow, due to lack of caching. · Issue #352 · moment/luxon
- Fix: performance issue in tz plugin by logeyG · Pull Request #2019 · iamkun/dayjs
ここから toLocaleString に原因があることがわかり、実際に tz メソッドの中にも toLocaleString が含まれているのを見つけました。
groupBy 関数
もう一つのボトルネックである groupBy 関数も、同様にプロファイラから判明しました。
ただし、Cloud Profiler の導入はまだ限定的な範囲だけに留めているので、月締伝票 API のプロファイルはローカル環境で実施しました。
node に --inspect フラグを指定して起動し、Chrome で chrome://inspect を開くと、簡単にプロファイル結果を可視化することができます。
この結果から、groupBy が大半の時間を占めていることがわかります。
月締伝票 API に対する直近のコード変更で groupBy への呼び出しが追加されており、最近になってタイムアウトエラーが発生しだした事実とも整合していました。
更に、このコード変更は、groupBy の修正前の実装において計算量が理論上最悪になるケースを偶然踏み抜いていました。
月締伝票が扱う売上データには税率の情報が含まれており、この値は軽減税率の適用などによって変わることがあります。新しく加わったコードには、売上データを税率によってグループ化する処理が含まれています。
しかし、ほとんどのデータで税率は 10% です。一部の店舗では、約 10 万件の売上データについて税率の値が全て 10% という状態でした。計算量が悪化する最も極端な例として下記のコードを挙げましたが、これと同じ状況だったということです。
const array = Array(1e5).fill({ taxRate: 0.1 }); // key が 1 種類しか無い
groupByMap(array, x => x.taxRate);
上述した groupBy の改善後に再度プロファイルを取ると、以下のように結果が大きく変わり、100 秒以上かかっていた同期処理が数秒で完了するようになりました。
改善後のプロファイル結果
まとめ
改善の結果、本番環境でレスポンス時間が約 200 秒かかっていたケースを 20 秒ほどに減らすことができ、確実に月締伝票を印刷できるようになりました。
今回発見したボトルネックは当初全く予想していなかったものだったので、実際に計測することの重要性を改めて感じる事例でした。
Date 型の toLocaleString メソッドは誰もが一度は使うはずですが、見た目より 40 倍遅いので注意しましょう。
We're hiring!
ダイニーでは、バックエンドも含めて全て TypeScript で開発しています。JavaScript / TypeScript のパフォーマンス改善にご興味をお持ちの方は、ぜひ弊社のエンジニア採用ページをご覧ください。
-
i18n support - V8 より: V8 optionally implements the ECMAScript 402 specification. The i18n implementation adds a dependency on ICU. ↩︎
-
async_hooks の before, after フックを利用して計測しています。厳密には micro task ではないタイマーなどのコールバックも計測対象に含んでいます。 ↩︎
Discussion
こういうの読むと技術者って感じしてテンション上がるのと業務の実装でも参考に出来るから嬉しい。
ありがとうございます。