コンカレントGCの時間計測

Scheme Inside Ypsilon

LL Futureでid:sumiiさん、id:higeponさんと昼食をご一緒した時にコンカレントGCが話題となりました。
で、お二人に説明しながら思いました「http://code.google.com/p/ypsilon/とかに”It achieves a remarkably short GC pause time and the best performance in parallel execution...”とか書いておきながら実行時間の計測方法をまったく書いてないのはまずいな・・・」と（汗
そこで手始めにコンカレントGCのタイミング測定の方法と実行例を書きたいと思います。

起動オプション

  • --heap-limit=　イプシロンはヒープサイズの制限機能を持っています（デフォルトは32MB）。たとえば--heap-limit=1024を指定するとこの制限が1Gバイトになります。

手続き

  • (collect-notify )　パラメータです。Chez SchemeのAPIから名前をもらっています。#tをセットするとGCに関連する情報を出力します。
  • (collect-trip-bytes )　パラメータです。Chez SchemeのAPIから名前をもらっています。イプシロンはこのパラメータにセットされたバイト数をヒープからアロケートするごとにGCを起動します（デフォルトは2MB)。たとえば(collect-trip-bytes (* 32 1024 1024))を評価すると32MBのアロケーションごとにGCが起動するようになります。

実行例１：大量にPAIRを作りますが、それらがすべて回収される場合

$ ypsilon --heap-limit=1024
Ypsilon 0.9.6-trunk/r182 Copyright (c) 2008 Y.Fujita, LittleWing Company Limited.
> (collect-notify #t)
> (collect-trip-bytes (* 32 1024 1024))
> (let loop ((lst '())) (loop (cons loop loop)))
;; [collect overlapped: 26.01ms pause: 0.02ms/0.01ms/0.01ms]
;; [collect overlapped: 28.08ms pause: 0.11ms/0.01ms/0.01ms]
;; [collect overlapped: 26.78ms pause: 0.07ms/0.01ms/0.01ms]
;; [collect overlapped: 28.34ms pause: 0.03ms/0.01ms/0.01ms]
;; [collect overlapped: 26.88ms pause: 0.06ms/0.01ms/0.01ms]

ここで overlapped: とあるのは並列にmutatorとcollectorが動作した時間です。pause: に３つ時間が表示されますが、これはイプシロンでは３回あるmutatorのポーズそれぞれの時間を表示します。この時間にはmutatorとcollectorとの同期に必要とした時間も含まれます。時間はgettimeofdayで測定しています。
今回の実行環境は

で、GNOMEデスクトップのTerminal内で行っています。以下のテストも同様です。

実行例２：大量にPAIRを作り、それらがまったく回収されない場合

$ ypsilon --heap-limit=1024
Ypsilon 0.9.6-trunk/r182 Copyright (c) 2008 Y.Fujita, LittleWing Company Limited.
> (collect-notify #t)
> (collect-trip-bytes (* 32 1024 1024))
> (let loop ((lst '())) (loop (cons lst lst)))
;; [collect overlapped: 741.45ms pause: 0.01ms/0.08ms/0.58ms][mark stack overflow: 981]
;; [collect overlapped: 3899.38ms pause: 0.07ms/0.01ms/0.60ms][mark stack overflow: 4755]
;; [collect synchronized: 4335.77ms][mark stack overflow: 25010]
fatal: heap memory overflow (1024MB)
[exit]

この例ではメモリオーバーフローでイプシロンが終了します。これはCAR方向にもCDR方向にもリストが伸びていくパターンで、GCのmark処理用スタックがoverflowしている様子も表示されています。最後の synchronized: は残りのヒープが少ないためコンカレントGCを諦め、完全にmutatorをストップさせてGCを行ったことを示しています。でも解放できるメモリはないわけですから、結局fatalで実行を終了することになります。

実行例３：それなりに現実的なプログラム

Dorai Sitaram氏によるPortable regular expressions for Scheme（通称 pregexp、すべてR5RSで書かれています）を使用してメールアドレスのチェックを行います。（注：この正規表現は実用になるものではありません、そのまま現実世界で使わないように！）

$ ypsilon --heap-limit=1024
Ypsilon 0.9.6-trunk/r182 Copyright (c) 2008 Y.Fujita, LittleWing Company Limited.
> (import (pregexp))
> (collect-notify #t)
> (collect-trip-bytes (* 32 1024 1024))
> (let loop ((i 1000000))
    (cond ((zero? i) #t)
          (else (pregexp-match "^([a-zA-Z0-9!$&*.=^`|~#%'+/?_{}-]+)@([a-zA-Z0-9_-]+)[.]([a-zA-Z]{2,4})$" "hoge@foo.bar")
                (loop (- i 1)))))
;; [collect overlapped: 43.83ms pause: 0.07ms/0.02ms/0.01ms]
;; [collect overlapped: 31.56ms pause: 0.05ms/0.01ms/0.01ms]
;; [collect overlapped: 33.09ms pause: 0.05ms/0.01ms/0.01ms]
;; [collect overlapped: 45.90ms pause: 0.05ms/0.01ms/0.01ms]
;; [collect overlapped: 45.06ms pause: 0.06ms/0.01ms/0.01ms]
  .
  .

最後に

この方法による計測時間はOSのコンテキストスイッチの有無に影響を受けることに注意してください。イプシロンの他に負荷のあるプロセスが走っていたり、CPUのコアが１つだった場合にはレスポンスが低下します。