Cloudflare WorkersでCPU・メモリの実行プロファイルを取得可能に
出典: Cloudflare Blog

Cloudflareは、WorkersとDurable ObjectsのCPU・メモリ使用状況を本番環境で記録し、フレームグラフで調べる機能を提供しました。関数ごとの負荷を可視化でき、CPU使用量の削減やメモリ問題の調査に利用できます。

本番環境のプロファイルを取得する方法

プロファイルはCloudflareダッシュボードまたはCLIから取得できます。ダッシュボードではWorkerのObservabilityタブを開き、「Flamegraph」を選んでCPUまたはメモリのプロファイルをリクエストします。

取得時には対象のバージョンと記録時間を選びます。CLIではcf workers versions profileコマンドにWorker IDまたは名前、記録時間、プロファイル種別を指定し、結果を.pprofファイルに保存できます。

記録対象は、すでに稼働しているWorkerの実行です。新しい実行環境を起動して記録する方式ではないため、対象バージョンに十分なトラフィックがあることが、プロファイル取得の条件になります。

幅と階層から関数の負荷を読む

フレームグラフの各長方形は関数呼び出しを表し、幅はCPUプロファイルならCPU時間、メモリプロファイルならメモリ割り当て量に対応します。幅の広い関数は、記録中に該当リソースを多く使った関数として注目できます。

長方形の階層をたどると、関数がどの呼び出しの中で実行されたかを確認できます。関数をクリックすると表示を絞り込み、ホバーすると詳細を見られます。表形式の表示では、プロファイルに現れる関数を一覧し、サンプル数で並べ替えられます。

CPUプロファイルは処理に使われた時間を、メモリプロファイルは割り当てられたメモリを記録します。Cloudflareの説明では、CPUのサンプリングは1ミリ秒間隔で行われます。TypeScript製Workerでは、ソースマップがないと関数名が難読化された状態で表示される場合があります。

CPUプロファイルで見つかった重複処理

Cloudflareは、R2バインディングを実装するWorkerのCPUプロファイルを50秒間取得した事例を紹介しています。表をサンプル数で並べ替えた結果、genericR2JsonReplacerがCPU時間の5%超を占めていることが分かりました。

この関数はJSONツリーを走査する一方、JSON.stringifyの各ノードからも呼び出されていました。そのため、深さ5段の値を5回処理する重複が発生しており、処理を改めると関数は2.7倍高速になりました。

同じプロファイルでは、メトリクス取得関数の重複呼び出しも見つかりました。1回の呼び出しがCPU時間の1%を占めていたため、最初の結果を変数に保存して再利用することで、余分な呼び出しを避けられました。

メモリプロファイルによる使用量の調査

Cloudflare社内のWorkerでは、メモリ使用量のP999が約133MBとなり、128MBの上限を超えたことで「Exceeded Memory」エラーによる退避が頻発していました。ヒーププロファイルを調べると、Prometheus関連コードが割り当ての約66.7%を占めていました。

無効化したつもりのコード経路が一部動作し、収集データをWorkerの外へ送っていない状態でもメモリを消費していました。チームがその経路を完全に削除した後、P999は133MBから118MBに下がり、上限まで約10MBの余裕ができました。

この事例では、メモリ使用量の推移はP50が70MBから54MB、P90が94MBから79MB、P99が113MBから97MBへ変化しました。集計値だけでは特定しにくい割り当て元をプロファイルで絞り込み、修正後の使用量も各パーセンタイルで比較しています。