James FisherはGHCのランタイムシステムが彼らのHaskellのプログラム上でレイテンシに悪影響を及ぼしたケースを、ブログに投稿しています。

低レイテンシ、大きなワーキングセット、そしてGHCのガベージコレクタ：3つのうち2つを選べ

この記事では、その問題（基本的に、レイテンシはコピー時間の影響を受ける）を示す非常にシンプルな合成ベンチマークを提案していて、さらに「50ミリ秒のレイテンシは過剰」と言っています。それで、他のGCがどのようにこの問題を処理しているかを見るため、OCamlとRacketで合成ベンチマークを再現したら面白いだろうと思いました。

細かい話は抜きにすると、要点は次のとおりです。OCamlのGCは古い世代にある大きなオブジェクトに関しては問題はありません。コレクションをコピーするのではなくマーク & スイープで処理するためで、このベンチマークではワーストケースでも停止は3ミリ秒以下です。

Racket GCも古い世代をコピーしませんが、インクリメンタルGCは（うまく機能するスループット指向の設定と比較した場合）まだ初期段階にあり、結果は劣ります。現状、後述する “Ramp-up” 効果の負荷を被っており、それがベンチマークの始まりで長い停止時間（最大120ミリ秒のレイテンシ）を起こす原因になっています。しかし、安定した状態の停止時間は最長でも22ミリ秒です。

元のベンチマークは、非常に具体的なワークフローを実行するように設計されていて、それはGHCのガベージコレクタにおけるワーストケースの振る舞いを起こし得ることに留意してください。一般にGHCのレイテンシが悪い、他のテスト済み言語のレイテンシのほうが低い、と言っているわけではありません。

今回は、実行と解析のロジックをカプセル化するMakefieを使って実装しました。Gitlabレポジトリで入手できます。

• git: https://gitlab.com/gasche/gc-latency-experiment.git
• ファイル: https://gitlab.com/gasche/gc-latency-experiment/tree/master

Haskellのベンチマーク

James FisherによるHaskellのベンチマークは、とてもシンプルです。関連テーブルを生成し、その中にミディアム長の文字列を繰り返し、100万回挿入します。チャネルが200_000メッセージに到達すると、全体のワーキングサイズを一定に保つため、1つの文字列が生成されるたびに1つの文字列が削除されます。

import qualified Control.Exception as Exception
import qualified Control.Monad as Monad
import qualified Data.ByteString as ByteString
import qualified Data.Map.Strict as Map

data Msg = Msg !Int !ByteString.ByteString

type Chan = Map.Map Int ByteString.ByteString

message :: Int -> Msg
message n = Msg n (ByteString.replicate 1024 (fromIntegral n))

pushMsg :: Chan -> Msg -> IO Chan
pushMsg chan (Msg msgId msgContent) =
  Exception.evaluate $
    let inserted = Map.insert msgId msgContent chan in
      if 200000 < Map.size inserted
      then Map.deleteMin inserted
      else inserted

main :: IO ()
main = Monad.foldM_ pushMsg Map.empty (map message [1..1000000])

以下のように、プログラムをコンパイルし、実行します（私のレポジトリでは make run-haskell も走ります）。

ghc -O2 -optc-O3 Main.hs  # compile the program
./Main +RTS -s            # run the program (with GC instrumentation enabled)

私のマシンでは、プログラムの実行に約1.5sかかります。総合的な実行時間（アルゴリズムのスループット）は置いておき、GCが誘発した停止時間に注目しましょう。ワーストケースの停止時間は51ミリ秒であり、これは先のブログ記事で報告されていた数字と同じです。予測するワーストケースのレイテンシでも「数ミリ秒」であり、それは過剰だとも書かれていました。

（私はGHC 7.8でテストを行ないました。Fischerの報告は7.10によるものですが、どちらも根本的には同じです）

このHaskellコードは、ベンチマークをさらに他の言語に移植しにくくする Map データ構造（不変連想マップ）について2つのことを前提としています。要素の総数はデータ構造に前もってキャッシュされているため、 Map.size は一定であること。OCaml、Racketにとってもそれはリニアです。そして最小のキーを取り除きやすくするキー配列を使っていること。OCamlも同様ですが、Racketは代わりにハッシュを使います。

最初、このために総数と最小限のキー情報を移植したバージョンに格納する作業を行ないました。実際には、同じ振る舞いで、ベンチマークの変数を書くほうがずっと良く、これらの細かい機能も必要ありません。

type Msg = ByteString.ByteString
type Chan = Map.Map Int Msg

windowSize = 200000
msgCount = 1000000

message :: Int -> Msg
message n = ByteString.replicate 1024 (fromIntegral n)

pushMsg :: Chan -> Int -> IO Chan
pushMsg chan highId =
  Exception.evaluate $
    let lowId = highId - windowSize in
    let inserted = Map.insert highId (message highId) chan in
    if lowId < 0 then inserted
    else Map.delete lowId inserted

main :: IO ()
main = Monad.foldM_ pushMsg Map.empty [0..msgCount]
111

この変数は同じ実行時間で、元のプログラム同様、ワーストケースの停止時間は50ミリ秒でした。

Haskellの結果を説明する

James Fischerはレイテンシがこれほど高い（50ミリ秒は高いとみなされている）理由を、GHCのガベージコレクタが世代間に渡り、古い世代がなおストップ & コピーのスキームを使用しているからだと説明しています。つまり、大きなオブジェクトを多く内包している場合、それらのコピーにたくさんの時間が費やされるということです。

先のブログ記事 には問題に関するより詳細な記述と、考えられる様々な最適化の方法が書かれています。残念ながら現状では、コードやGCのパラメータをチューニングしても、その手の作業負荷を最適化することはできないようです。古いヒープの振る舞いをコピーしても大して解決にはならないでしょう。

言ってみれば、このような設計が選ばれた理由を説明するとすれば、Haskellには並列ミューテータ（マルチコアのランタイム）のサポートに多大な労力が払われているということです。この極度に難しく有益な条件に伴うさらなる複雑さのために、ランタイムのオーサーはGCの全体の設計概念を可能な限りシンプルかつ合理的にせざるを得なかったのではないでしょうか。これで、全ての世代のスペースで同じコレクション方法を使うことも説明できるでしょう。

OCamlバージョン

コードはOCamlに簡単にポートできます。以下がその例です。

open Batteries
module IMap = Map.Make(Int)

let message n = String.make 1024 (Char.chr (n mod 256))

let window_size = 200_000
let msg_count = 1_000_000

let push_msg chan high_id =
  let low_id = high_id - window_size in
  let inserted = IMap.add high_id (message high_id) chan in
  if low_id < 0 then inserted
  else IMap.remove low_id inserted

let () =
  Seq.init msg_count (fun i -> i)
  |> Seq.fold_left push_msg IMap.empty |> ignore

スループットの評価は重要ではなく、HaskellとOCamlで使われる安定したマップは、明らかにそれぞれ少々別の方法で実装されているので、パフォーマンスが異なっても説明がつきます。それでもなお、全体の実行時間が1.5sと、基本的に同じであるのは面白いと思うのです。

最大の停止時間を測るには、2つの方法があります。

• OCaml 4.03に新たに測定用のランタイムを使う方法。これは使えますが、比較的新しい機能であり、あまりユーザビリティが考慮されていません。使いやすさはGHCの +RTS -s とは比べものになりません。

• 単純に各ループで費やされる時間を計測し（メッセージをプッシュする）、これを停止時間の上限とする方法。GCがループよりも長く停止することがないのは明らかだからです（私のMakefile、 make run-ocaml を使用）。

新たに測定用のランタイムを使うには、OCamlコンパイラのバージョン 4.03.0で、 --with-instrumented-runtime 設定時オプションを用いてコンパイルする必要があります。その後、計測有効の状態でコンパイルする、実行時間の i 変数（ “instrumented” の i ）が使えるようになります（私のMakefileルール、 make run-ocaml-instrumented はこの作業を代行しますが、測定用のランタイムでコンパイルした際のオプションだけは必要です）。

ocamlbuild -tag "runtime_variant(i)" main.native
OCAML_INSTR_LOG=ocaml.log ./main.native

ログファイル ocaml.log には、GCが関わる全実行時間の呼び出しの低レベルログが、ナノ秒単位で、かつ人間向けではなくマシン向けのフォーマットで書き出されています。 ocaml-instr-report ツールと ocaml-instr-graph ツールは、OCamlソースのディストリビューションであり（初期設定ではインストールされていないため、ソースをチェックアウトする必要があります）、ログを解析してテーブルやグラフを表示します。ワーストケースの場合のレイテンシにとって重要なエントリポイントは dispatch で、全てのGCのアクティビティで費やされた時間を含みます。 ocaml-instr-report と関連のあるセクションのアウトプットは次のように表示されます。

==== dispatch: 2506
470ns..1.0us:  1     (768ns)                       0.04%
1.0us..2.2us: # 2                                  0.12%
2.2us..4.7us: ### 8                                0.44%
4.7us..10us : #### 10                              0.84%
 10us..22us :  1     (14us)                        0.88%
 22us..47us :                                      0.88%
 47us..100us:                                      0.88%
100us..220us: ## 3                                 1.00%
220us..470us: ########## 668                      27.65%
470us..1.0ms: ########### 1795                    99.28%
1.0ms..2.2ms: ##### 17                            99.96%
2.2ms..4.7ms:  1     (2.7ms)                     100.00%

見てのとおり、多くの停止時間は220マイクロ秒から1ミリ秒の間で、最長は2.7ミリ秒です。

その他に、測定用のランタイムなしに古いOCamlバージョンで動くこのプログラムのレイテンシを測るには、明示的なタイミングコールを挿入し、ループのワーストケースの時間を計算するやり方もあります。実際の挿入、削除の時間は小さいと仮定し、最大の停止時間を超える近似値を出すのです。

let worst = ref 0.
let time f =
  let before = Unix.gettimeofday () in
  let result = f () in
  let after = Unix.gettimeofday () in
  worst := max !worst (after -. before);
  result

let push_msg chan high_id = time @@ fun () ->
  let low_id = high_id - window_size in
  let inserted = IMap.add high_id (message high_id) chan in
  if low_id < 0 then inserted
  else IMap.remove low_id inserted

(* ..main loop.. *)
let () = Printf.printf "Worst pause: %.2E\n" !worst

このバージョンを走らせると、私のマシンではワーストケースのレイテンシは2ミリ秒と出ました（科学的記数法の %E フォーマッタを使ったので、 2.03E-03 と表示されます）。これは測定用のランタイムのせいでオーバーヘッドが加わっているため、実際には多少それよりも低くなります。

この気の毒な、ワーストケースのレイテンシ計測方法の不都合な点は、ワーストケースの時間以外は、他のいかなる時間の分布も分からないというところです。

OCamlの結果を説明する

OCamlのGCには、信頼に足るインクリメンタルフェーズが元から実装されています。そしてその古い世代にもコピーを使いません。マーク & スイープ処理でパフォーマンスも良く、始めからこの具体的なベンチマークがOCamlのワーストケースのケースではないことは予測できます。

OCamlの最新バージョン、OCaml 4.03.0では、Damien Doligezの手によって、いくつかの状況でワーストケースの場合のレイテンシが改善されています。Jane Streetの業務利用による後押しが大きかったのでしょう。とりわけ、上記で使ったレイテンシ計測ツールはDamienがこの機会に開発したものです。私は2つ目の計測方法で、レイテンシが以前のOCamlバージョンと同様に良いことを確認しました。この特殊なユースケースは4.03以前には改善の必要がなかったものです。

Racketバージョン

Max Newは、このベンチマークのRacketポートの最初のバージョンを記述しました。彼は、マップの総数と最小のキーを、オリジナルのGHCバージョンに合致するように明示的にトラッキングする必要がありました。彼のコードを簡素化した変数に適用すると、他の計測により近づきました。

#lang racket/base
(require racket/match)

(define window-size 200000)
(define msg-count  2000000)

(define (message n) (make-bytes 1024 (modulo n 256)))

(define (push-msg chan id-high)
  (define id-low (id-high . - . window-size))
  (define inserted (hash-set chan id-high (message id-high)))
  (if (id-low . < . 0) inserted
      (hash-remove inserted id-low)))

(define _
  (for/fold
     ([chan (make-immutable-hash)])
     ([i (in-range msg-count)])
     (push-msg chan i)))

最初に私は、明示的なタイミングコールでレイテンシを測るという惨めなやり方をとりましたが、その後により良い2つの方法に切り替えました。

• Sam Tobin-Hochstadtの gcstats パッケージがあれば、Racketプログラムで、GHCの +RTS -s アウトプットと同様のフォーマットでランタイムの振る舞いの要約を生成できます。特にワーストケースの停止時間も表示できます。とても使いやすいのも特徴です。

racket -l gcstats -t main.rkt

• 環境変数 PLTSTDERR=debug@GC を設定することで、Racketの実行時間は、GCのイベントを標準エラーアウトプットに記録します。それにより、大小のコレクションをグレップしたり、私が自作した下記のスクリプトを使って実行時間のヒストグラムを生成したりできるようになります。

cat racket.log | grep -v total | cut -d' ' -f7 | sort -n | uniq --count

Racketは、現在は実験段階にあるインクリメンタルGCを持っており（スループットを低下させる可能性があるため、初期設定では有効になっていません）、環境変数 PLT_INCREMENTAL_GC=1 を設定すれば有効になります。インクリメンタルGCのある場合とない場合で比べたところ、一般にレイテンシのヒストグラムをより低いレイテンシに近づけるようでした。しかし、後述の理由により、さらにチューニングをしない限り、ワーストケースのレイテンシの改善には大して助けにならないことが分かりました。下記の全ての報告はインクリメンタルGCを用いたものです。

最新のRacket 6.5を使っている私のマシンでは、 gcstats がレポートする最長停止時間は約150ミリ秒であり、GHCの最長停止時間50ミリ秒よりもかなり悪い結果です。

Racketの結果を調査する

私は、GCのレイテンシを下げるべくコードを改善するための説明や助言をもらえたらと思い、Racket開発者のメーリングリストに eメール を送りました（GHCベンチマークの問題点は、ユーザがコードをいじって同じワークフローでより低いレイテンシを実現するための正規の方法がないということです。私たちは、初期値のレイテンシだけではなく、それを調整できるかどうかも評価のポイントにしているのです）。すると、非常に良い結果が得られました。

まず、Matthew FlattがRacketのコードベースで、すぐさまコミットを数回送信し、ベンチマークで問題となっていた幾つかの動作を改善しました。Racket 6.5ではなく開発版を使用すると、ワーストケースのレイテンシは私のマシンで150ミリ秒から120ミリ秒まで改善します。これ以後の時間は全て開発バージョンを用いた報告になります。

Matthew Flattはその結果についても分析を行い、ベンチマークの開始時点、チャネルが200,000メッセージの最大値に達したすぐ後に、ワーストケースのレイテンシが、体系的に発生することに気づきました。これはデフォルトのベンチマークパラメータでは見つけるのは困難です。チャネルが満杯になる “Ramp-Up” 期間は、全ての反復回数の1/5を占めています。このことを分かりやすくするため、反復回数を1,000,000回から10,000,000回に増やし、 make run-racket-instrumented を実行しました。 grep MAJ racket.log を実行すれば、メジャーコレクションの停止時間を見ることができます。私のマシンでの結果は以下のようになりました。

GC: 0:MAJ @ 50,634K(+37,221K)[+1,560K]; free 5,075K(-5,075K) 12ms @ 373
GC: 0:MAJ @ 101,983K(+35,024K)[+1,560K]; free 10,880K(-5,168K) 38ms @ 521
GC: 0:MAJ @ 192,491K(+38,404K)[+1,560K]; free 8,174K(-24,030K) 56ms @ 810
GC: 0:MAJ @ 377,716K(+49,259K)[+1,560K]; free 10,832K(-9,536K) 92ms @ 1571
GC: 0:MAJ @ 742,630K(+59,881K)[+1,560K]; free 140,354K(-156,738K) 138ms @ 3321
GC: 0:MAJ @ 1,214,486K(+112,313K)[+1,560K]; free 361,371K(-377,755K) 60ms @ 6046
GC: 0:MAJ @ 1,417,749K(+138,410K)[+1,560K]; free 600,291K(-600,291K) 23ms @ 8553
GC: 0:MAJ @ 1,400,780K(+155,379K)[+1,560K]; free 564,923K(-564,923K) 21ms @ 11048
GC: 0:MAJ @ 1,408,812K(+147,347K)[+1,560K]; free 583,454K(-583,454K) 21ms @ 13506
GC: 0:MAJ @ 1,404,757K(+151,402K)[+1,560K]; free 572,350K(-572,350K) 20ms @ 15983
GC: 0:MAJ @ 1,407,842K(+148,317K)[+1,560K]; free 579,079K(-579,079K) 22ms @ 18438
GC: 0:MAJ @ 1,405,641K(+150,518K)[+1,560K]; free 575,624K(-575,624K) 21ms @ 20907
GC: 0:MAJ @ 1,405,833K(+150,326K)[+1,560K]; free 577,191K(-577,191K) 21ms @ 23362
GC: 0:MAJ @ 1,405,763K(+150,396K)[+1,560K]; free 575,779K(-575,779K) 20ms @ 25897
GC: 0:MAJ @ 1,406,444K(+149,715K)[+1,560K]; free 577,553K(-577,553K) 20ms @ 28348
GC: 0:MAJ @ 1,406,409K(+149,750K)[+1,560K]; free 576,323K(-576,323K) 21ms @ 30827
GC: 0:MAJ @ 1,407,054K(+149,105K)[+1,560K]; free 577,961K(-577,961K) 21ms @ 33290
GC: 0:MAJ @ 1,404,903K(+151,256K)[+1,560K]; free 576,241K(-576,241K) 20ms @ 35774
GC: 0:MAJ @ 1,406,551K(+149,608K)[+1,560K]; free 575,352K(-575,352K) 22ms @ 38251
GC: 0:MAJ @ 1,405,775K(+150,384K)[+1,560K]; free 577,401K(-577,401K) 21ms @ 40730
GC: 0:MAJ @ 1,406,015K(+150,144K)[+1,560K]; free 575,563K(-575,563K) 20ms @ 43254
GC: 0:MAJ @ 1,406,129K(+150,030K)[+1,560K]; free 577,760K(-577,760K) 21ms @ 45730
GC: 0:MAJ @ 1,406,157K(+150,002K)[+1,560K]; free 575,394K(-575,394K) 22ms @ 48220
GC: 0:MAJ @ 1,406,514K(+149,645K)[+1,560K]; free 577,765K(-577,765K) 21ms @ 50697

メジャーGCの停止時間の発生状況を見てください。 140ミリ秒 で早いピークがありますが、その後の停止時間は短くなります。定常状態では約 22ミリ秒 の妥当な長さの停止時間を示しています。各GC中に解放されたメモリ容量を見れば、そのピークは多くのメモリを解放する最初のメジャーGCに対応していることが分かるでしょう。つまりメジャーGCとは、チャネルが最大サイズに達した後の最初のGCで、多くのメッセージを削除し始めます。

私の認識では、インクリメンタルGCはプログラムのメモリ割り当てのパターンを観察するランタイムパラメータを幾つか保持し、次のGCがいつ、どれくらいの作業をすべきかを予測しようとします。Matthew Flattは、この監視ロジックは今のところプログラムの状況の変化にうまく適応できず、現時点では大きなピーク停止時間を招くと説明しています。

これは、私たちのベンチマークにとっては朗報です。というのもプログラムの初めに非常に長い停止時間が発生しますが、一度だけだからです。これはJames Fischerの記事で話題に上っているレイテンシの最後の十分位数にはあまり影響しません。また実際のメッセージパッシングアプリケーションの定常状態においても問題になりません。

Racketのバージョンをチューニングする

Matthew Flatt氏は、GCに明示的な呼び出しを挿入すれば、Racketのヒューリスティック的な要求よりも頻繁にコレクションを実行し、停止時間の大きなピークを少しは回避できると述べています。しかし、あまりにも頻繁に明示的なGCを行うと、プログラムのスループットが低下します。

状況が変化する周辺、つまり最大チャネルサイズを繰り返し数える箇所で、GCに明示的な呼び出しを挿入して、少し試してみたところ、停止時間の問題がやや改善されていることが分かりました。私が定義した関数は以下のようなものです。

(define (maybe-gc i)
  (when (and gc-during-rampup
             (i . > . (window-size . / . 2))
             (i . < . (window-size . * . 2))
             (zero? (modulo i 50)))
        (collect-garbage 'incremental)
        (collect-garbage 'minor)))

これは、実験的に #t を明示して設定できる gc-during-rampup のパラメータによって制御されます。明示的なGCの呼び出しは、私のベンチマークコードではデフォルトで無効になっています。それから、main loopの中に （maybe-gc i） コールを挿入しました。

追加したGCの呼び出しはRamp-Up中にだけ発生するので、定常状態のパフォーマンスは変化せず、スループットに対する全体的なコストは適当です（2,000,000回の繰り返しを行った私の実験では、20%でした）。これは停止時間のピーク問題を軽減するのに効果的なようです。私のマシンでのワーストケースの時間は現状ではわずか38ミリ秒です。また、定常状態での停止時間は22ミリ秒程度です。

もちろん、これは応急処置にすぎません。長期的な解決策は、Racketの開発者がRamp-Upの問題を回避する、よりよい動的コントロールの方法を考え出してくれるのを待つことです。どうやら、インクリメンタルGCは、例えばゲームループの1サイクル毎に一時的なメモリが割り当てられるような、もっと簡単な割り当てプロファイルを持つゲームにおいて、そのようなRamp-Up段階が無い状態で、あらかじめテストされたようです。しかし、私は熟練のユーザーがコードを少し手直しして、ワーストケースの停止時間を大幅に短縮できるという点に依然として興味がありました。

要約すれば、RacketのインクリメンタルGCは、優秀ではないが適切な定常状態の振る舞いを見せ、この時の最大レイテンシは22ミリ秒程度です。しかし今のところ、ベンチマークのRamp-Up時にはるかに長い停止期間を生じるGCコントロール問題を抱えています。明示的なGCの呼び出しにより、それを少しは緩和することができます。