スレッドプールの枠を数えてみる

目標

同じ計算がどこで動くかによって、ループを塞いだり塞がなかったりすることを自分で測って確かめ、libuvスレッドプールの枠がいくつあるかを数字で数えます。

なぜ重要なのか

crypto.pbkdf2とcrypto.pbkdf2Syncは同じ計算をします。ところが片方はスレッドプールに行き、もう片方はイベントループの上で動きます。名前の末尾のSyncという4文字が、「このリクエストだけ遅い」と「全部が遅い」を分けます。

そして、スレッドプールは無限ではありません。デフォルトが4枠なので、重い非同期の仕事を5つ送ると、5つ目は前の1つが終わるまで開始すらできません。 ファイル読み取りとDNSの名前解決と圧縮が同じ4枠を分け合うため、圧縮の仕事がファイル読み取りを遅らせることが実際に起こります。逆に、ソケットの読み取りとdns.resolveはその枠を使わないので、何も影響を受けません。この地図を暗記するのではなく、測って確かめる方法を身につけるのがこのラボです。

ステップ

/root/work/blocking/probe.mjsにclassify(name)でAPIの居場所を書きます。
同じファイルにpct(samples, p)とwithLag(fn, options)を作ります。
crypto.pbkdf2Syncとcrypto.pbkdf2を測り、 /root/work/blocking/report.jsonのruns.pbkdf2Sync・runs.pbkdf2Asyncに書きます。
大きなJSON文字列をパースしながら測り、runs.jsonParseに書きます。
/root/work/blocking/wave.mjsを作って同じ仕事を複数、一斉に送り、 runs.pool4とruns.pool8に書きます。
UV_THREADPOOL_SIZE=8で同じプログラムを動かし、runs.pool8bigに書きます。
zlib.gzipSyncとzlib.gzipで同じ方法をもう一度適用します。

参考

classifyは"loop"(ループ上で動く)・"threadpool"(libuvスレッドプール)・"kernel"(カーネルが知らせるまでループは待つだけ)の3つのうち1つを返し、表にない名前には"unknown"を返します。
withLag(fn, {durationMs, intervalMs, startAfterMs})は測定を先に開始し、少しあとでfn()を呼び(Promiseなら待ちます)、その時間をworkMsに入れて {intervalMs, durationMs, samples, workMs}を返します。
wave.mjsはprocess.argv[2]で個数を受け取り、 {"n": .., "threadpoolSize": .., "finishMs": [..]}を1行出力します。 finishMsは終了した時刻(ms)を昇順に並べたものです。
よくある間違いは、process.env.UV_THREADPOOL_SIZE = "8"をプログラムの中で設定することです。スレッドプールはそれより先に作られているので、何も起きません。

まず地図を描く

/root/work/blocking/probe.mjsにclassify(name)をexportしてください。fs.readFileSync・crypto.pbkdf2Sync・zlib.gzipSync・JSON.parse・JSON.stringifyは"loop"、fs.readFile・crypto.pbkdf2・crypto.randomBytes・zlib.gzip・dns.lookupは"threadpool"、dns.resolve4・dns.reverse・dns.resolveMxは"kernel"、残りは"unknown"です。

この一覧は暗記したものではなく、公式ドキュメントに書かれています。コマンドラインドキュメントのUV_THREADPOOL_SIZEの節と、DNSドキュメントの「実装上の考慮事項」の節です。

dns.lookupとdns.resolve4が分かれるのが、この一覧の核心です。前者はOSのgetaddrinfoをスレッドプールで呼び、後者はネットワークに直接問い合わせてスレッドプールを使いません。

仕事をさせながら測る物差し

同じファイルにpct(samples, p)(1つ目のラボと同じ規則)とwithLag(fn, {durationMs, intervalMs, startAfterMs})をexportしてください。{intervalMs, durationMs, samples, workMs}を返します。

測定を先に開始し、startAfterMs後にfn()を呼びます。fn()がPromiseを返す場合は待ってから、かかった時間をworkMsに入れます。

仕事が終わったあとも、durationMsが満ちるまで測り続ける必要があります。塞がれた区間は、塞ぎが解けた次のサンプルに大きな値として現れるからです。

同じ計算、違う居場所

crypto.pbkdf2Syncとcrypto.pbkdf2(非同期)で同じ計算を1回ずつ行いながら測り、/root/work/blocking/report.jsonのruns.pbkdf2Syncとruns.pbkdf2Asyncに書いてください。それぞれにsamples・p50・p99・max・workMsを入れ、最上位にnodeも書きます。

1回で150ms以上かかるようにしないと違いが見えません。反復回数を上げてください(例: sha512で300000回)。

2つのケースのworkMsは似た値になります。仕事の量が同じだからです。 変わるのは、その間にループが何をできたかです。

移す先のない仕事

4MBを超えるJSON文字列を作ってJSON.parseでパースしながら測り、bytesと一緒にruns.jsonParseに書いてください。

JSON.parseには非同期版がありません。fs.readFileでファイルを非同期に読んでも、パースはループの上で行われます。

そのため、大きなJSONを受け取るエンドポイントでは、本文サイズの制限がそのままレイテンシバジェットになります。ここで測った数字が、その制限を決める根拠になります。

枠がいくつあるか数えてみる

/root/work/blocking/wave.mjsを作ってください。process.argv[2]個のcrypto.pbkdf2(非同期)を一斉に送り、終了した時刻(ms)を昇順に並べて{n, threadpoolSize, finishMs}を1行出力します。threadpoolSizeはprocess.env.UV_THREADPOOL_SIZEがなければ4です。4個と8個で動かした結果をruns.pool4・runs.pool8に書き、runs.pool8.waveRatioにfinishMs[7] / finishMs[3]を書きます。

仕事1つが150ms以上かからないと、枠が分かれるのが見えません。

4つはほぼ同じ時刻に終わるのに、8つは2つの塊に分かれます。後ろの4つは、前の4つが枠を空けてくれるまで開始すらできなかったのです。

枠を増やせば解決するのか

UV_THREADPOOL_SIZE=8を指定して同じwave.mjsを8個で動かし、runs.pool8bigに書いてください。threadpoolSize・finishMs・waveRatioと一緒に、speedupにpool8.finishMs[7] / pool8big.finishMs[7]を書きます。

環境変数はプログラムを起動するときに渡す必要があります。UV_THREADPOOL_SIZE=8 node wave.mjs 8のようにします。

波は消えます。けれども、全体が終わる時刻を見てください。このPodのCPUは2コアしかないので、増えたのは同時に開始できる仕事の数であり、計算をしてくれる手の数ではありません。

新しいAPIに同じ方法を適用する

4MBを超えるバッファーを作り、zlib.gzipSyncとzlib.gzip(非同期)で1回ずつ圧縮しながら測り、bytesと一緒にruns.gzipSync・runs.gzipAsyncに書いてください。

ステップ1の表でzlibの居場所を先に確認し、その表が正しいかを測って確かめる順序です。初めて見るライブラリに出会ったときにすることが、まさにこれです。

よく圧縮できるデータはすぐ終わって、違いが見えません。crypto.randomBytesで作ったバッファーを使うと、圧縮器が実際に仕事をします。