【Go言語】Fake timeつかったら並行処理のテストの景色が変わった

昨日のAdvent Calendarで、Fake timeつかったら時間のかかるコードのテストが一瞬で終わったという記事をアップしましたが、引き続きFake timeについて書きます。
（ネタが足りなくなって記事を分割した・・・わけではないです念の為😅）

注： 現時点（2020/12）で "Faketime isn't currently supported on Windows."だそうです。Windows Gopherの方はDockerとか使って下さい🙇‍♂️

前置き

Go言語にはGoroutineが標準で組み込まれており並行処理を比較的簡単に書くことが出来ます。
Goroutineはとても強力ですが、いざそのテストを書くときになって悩んだりしたことはないでしょうか（私はあります）。

Goroutineのテストが難しくなる理由を挙げてみます。

• 処理のタイミングや実行順序が不定で処理の度に値が変わったりする
• アサーションのタイミングが難しい
• 時間がかかりがち（TimerやTickerを使った処理のテストetc）

本稿は、Fake timeを使うことで上記の問題を（全てではないですが）一部解決することができるのではないか？ と思い立って書いた実験的記事となります。

Fake timeとは

Fake timeについての詳細は昨日の記事を参照下さい。
ここではテストにFake timeを利用する手順だけざっとおさらいしておきます。

テスト実行

--tagsオプションを付与するだけです。

go test --tags=faketime [packages]

Fake timeのときだけ実行

テストコードにbuildタグを付与しておくとFake timeが有効の場合のみ実行するテストを記述出来ます。

// +build faketime

package hoge

出力からPlayback headerを削除

ツールを作りました。
trimfaketime

インストール↓

go get -u github.com/knightso/trimfaketime/cmd/tft

テスト実行↓

go test --tags=faketime [packages] |& tft

テスト例

経過時間を制御する

ちょっとマイナーなネタですがCloud Firestore（Datastore）に"500/50/5"ルールというベストプラクティスがあります。
大量のデータアクセスが必要な場合にいきなりスパイクさせるのではなく最初は500くらいからスタートして5分毎に50%増えるくらいのペースで徐々にアクセスを増やしていきましょう、というものですが、サンプルとしてこの"500/50/5"ルールを制御するユーティリティを作成してそのテストを書きたいと思います。

テスト対象コード

package faketime

import (
    "sync"
    "sync/atomic"
    "time"
)

type RampUp struct {
    rate       float64
    interval   time.Duration
    maxCount   int
    throughput int64
    closeCh    chan struct{}
    closeOnce  sync.Once
}

func NewRampUp(initial int64, rate float64, interval time.Duration, maxCount int) *RampUp {
    return &RampUp{
        rate:       rate,
        interval:   interval,
        maxCount:   maxCount,
        throughput: initial,
        closeCh:    make(chan struct{}),
    }
}

func (r *RampUp) Start() {
    ticker := time.NewTicker(r.interval)

    go func() {
        defer ticker.Stop()

        count := 0
        for {
            select {
            case <-r.closeCh:
                return
            case <-ticker.C:
                if count >= r.maxCount {
                    continue
                }
                atomic.StoreInt64(&r.throughput, int64(float64(r.throughput)*r.rate))
                count++
            }
        }
    }()
}

func (r *RampUp) Throughput() int64 {
    return atomic.LoadInt64(&r.throughput)
}

func (r *RampUp) Stop() {
    r.closeOnce.Do(func() {
        close(r.closeCh)
    })
}

RampUp#Startを実行すると内部でGoroutineが起動し、Tickerで5分毎にthroughput値を1.5倍にしています。

テストコード

// +build faketime

package faketime

import (
    "testing"
    "time"
)

func TestRampUp(t *testing.T) {
    rampup := NewRampUp(500, 1.5, 5*time.Minute, 18)
    rampup.Start()
    defer rampup.Stop()

    time.Sleep(1)

    if expected, actual := int64(500), rampup.Throughput(); expected != actual {
        t.Fatalf("throughput - expected:%d, but was:%d", expected, actual)
    }

    time.Sleep(5 * time.Minute)

    if expected, actual := int64(750), rampup.Throughput(); expected != actual {
        t.Fatalf("throughput - expected:%d, but was:%d", expected, actual)
    }

    time.Sleep(5 * time.Minute)

    if expected, actual := int64(1125), rampup.Throughput(); expected != actual {
        t.Fatalf("throughput - expected:%d, but was:%d", expected, actual)
    }

    time.Sleep(5 * time.Minute)

    if expected, actual := int64(1687), rampup.Throughput(); expected != actual {
        t.Fatalf("throughput - expected:%d, but was:%d", expected, actual)
    }

    // omit

    time.Sleep(14 * 5 * time.Minute)

    if expected, actual := int64(492319), rampup.Throughput(); expected != actual {
        t.Fatalf("throughput - expected:%d, but was:%d", expected, actual)
    }

    time.Sleep(5 * time.Minute)

    if expected, actual := int64(738478), rampup.Throughput(); expected != actual {
        t.Fatalf("throughput - expected:%d, but was:%d", expected, actual)
    }

    time.Sleep(5 * time.Minute)

    // exceed the maxCount
    if expected, actual := int64(738478), rampup.Throughput(); expected != actual {
        t.Fatalf("throughput - expected:%d, but was:%d", expected, actual)
    }
}

愚直にtime.Sleepで5分ずつ時間を進めながら、値の変化をアサーションしています。

Fake timeを使わずにこの様なテストを記述すると、いつもはパスするのだけど、たまに（マシンが重いときだけ）失敗する みたいな現象が起きたりします。これはSleepしている間にバックグラウンドのGoroutineの処理が実際にどのくらい進むかを制御出来ないからですが、Fake timeを使うとナノ秒単位で厳密にSleepと動作タイミングを制御することができる為何度実行しても結果が同じになります。

実行

test --tags=faketime -timeout=100m .

テストコード上100分弱かかっている為、timeoutオプションを付与しています。
ただ 実際にはFake timeの為すぐに終了します（スゴイ！！😂）

テストのタイムアウトも実経過時間ではなくFake timeの擬似経過時間で効いてしまう為、デフォルト10分を超える場合はtimeoutオプション指定が必要になります。

並行処理から使われるコードのテスト

内部でGoroutineを使っているコードのテストだけでなく、複数Goroutineから利用される想定のコードのテストを書くときにもFake timeは有用です。

弊作キャッシュライブラリのテストコードでもFake timeを使っていますので、よかったら参照ください。
https://github.com/knightso/kocache/blob/main/kocache_test.go

抜粋↓

func TestGetAndReserve(t *testing.T) {
    start := time.Now()

    cache, err := New()
    if err != nil {
        t.Fatal(err)
    }

    // create utility method to synchronize testing report.
    var mux sync.Mutex
    lock := func(f func()) {
        mux.Lock()
        defer mux.Unlock()
        f()
    }

    var wg sync.WaitGroup

    wg.Add(1)
    go func() {
        defer wg.Done()

        if _, err = cache.Get("key1"); err != ErrEntryNotFound {
            lock(func() { t.Errorf("ErrEntryNotFound expected, but was:%v", err) })
        }
    }()

    wg.Add(1)
    go func() {
        defer wg.Done()

        time.Sleep(time.Nanosecond)

        resolve := cache.Reserve("key1")

        time.Sleep(5 * time.Nanosecond)

        resolve("value1", nil)
    }()

    for i := 0; i < 10; i++ {
        wg.Add(1)
        go func() {
            defer wg.Done()

            time.Sleep(2 * time.Nanosecond)

            value, err := cache.Get("key1")
            if err != nil {
                lock(func() { t.Error(err) })
            }

            // キャッシュされるのを待機したことをアサーション
            // ↓の様にナノ秒単位で経過時間を厳密にアサーションできます＼(^o^)／
            if actual, expected := time.Now().Sub(start), 6*time.Nanosecond; actual != expected {
                lock(func() { t.Errorf("expected:%v, but was:%v", expected, actual) })
            }

            if actual, expected := value.(string), "value1"; actual != expected {
                lock(func() { t.Errorf("expected:%v, but was:%v", expected, actual) })
            }
        }()
    }

    wg.Add(1)
    go func() {
        defer wg.Done()

        if _, err = cache.Get("key2"); err != ErrEntryNotFound {
            lock(func() { t.Fatalf("ErrEntryNotFound expected, but was:%v", err) })
        }
    }()

    time.Sleep(time.Second)

    wg.Wait() // ↑のSleepで確実に全てのGoroutineが終了しているはずだが念の為
}

テストコード内で複数のGoroutineを起動し、ナノ秒単位で時間を調節しながら処理とアサーションを行っています。
通常のテストならば確実に通ることが保証されない書き方をしていますが、Fake timeならば繰り返し実行しても通ります。

最後の１秒Sleepで全てのGoroutineが終了しているはずで本来WaitGroupも不要ですが、さすがにちょっと気持ち悪いので念の為Waitしています^^;

あと、ちょっと脱線しますけど、*testing.Tのレポート系メソッド（ErrorとかFatalとか）ってgoroutine-unsafeなんですね。
テストコード上のGoroutine内で書く場合はロックをとる必要があるので注意です。

デメリット

昨日の記事でも書きましたが、Fake timeに依存したテストコードは、Fake time以外で正しく動作しなくなる可能性が高いです。

また、Fake timeと相性の悪いコードやライブラリもありそうです。
特に通信系（net や net/http 等）のコードはハングしてしまうのを確認しています(´･ω･`)

Fake timeのときのみ実行したいテストにはビルドタグ // +build !faketime をつければ除外出来ます。

今後いろいろ試して調べていきたいと思っています。

まとめ

• Fake time使うと並行処理（Goroutine）のテストが書きやすい！
• 実行時間も短縮される （場合がある）！
• デメリットもある

使い始めたばかりなので見えていない罠や落とし穴がまだまだありそうですが、今後いろいろ遊んで試してみたいと思います^^