【Go言語】Fake timeつかったら時間のかかるコードのテストが一瞬で終わった

免責事項

まず最初に・・

タイトルの「時間のかかるコード」とは、time.Sleepや、time.Timer、time.Tickerなどが使用されてるものを想定しています。
CPU計算や外部サービス接続など他の理由で時間がかかるコードなどは本記事の対象外です。悪しからず🙇‍♂️

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

それから、本記事は思いつきで始めた実験的内容です。結構大きな罠（後述）もありますのでご了承の上お読み下さい🙇‍♂️

Fake timeとは

Fake timeはGo Playgroundに組み込まれた、擬似時間を扱う仕組みです。

ご存知の通りGo Playgrondはユーザーの書いた自由なコードをブラウザから実行することができます。
コードの実行はサーバー側で実行されますが、例えば長時間のSleepを行うコードをリクエストした場合、そのまま実行してしまうとサーバーが実行中ずっと接続と使用中メモリを開放しない状態になってしまい、DOS攻撃に対して脆弱になってしまいます。

これを解決する為、Go Playgroundサーバーは実際に指定された時間Sleepするのではなく、内部に保持する擬似的な経過時間を進めつつ即座に次にSleepから起きるGoroutineを見つけて実行する、というトリックを使っています。
つまりtime.Sleepやtime.Timer、time.Tickerなどによる待機は無視されて処理がすぐに完了します。

実際にGo Playgroundからtime.Sleepを含んだコードを実行するとちゃんと指定した通りのSleepが実行されている様に見えますが、ここにもトリックがあります。
Go Playgroundサーバーは標準出力や標準エラーへの出力があるとその時点の擬似経過時間を含む "playback header" を付与して出力します。サーバー側で全ての処理が完了してから、フロントでレスポンスのplayback headerを解析して追再生しているのです。

Fake timeの詳細は下記に詳しいです。
Inside the Go Playground（Faking time）

Fake timeをテストに利用したい

ある日ふと思いました。

Go playgroundのfake timeってライブラリとかで提供されてるのかな 🙄

コレ単体テストで使えたら時間に依存するテストの実行時間短縮できるのでは。

— Ikeda Daigo (@hogedigo) November 11, 2020

で、↑の様にツイートしたら、

-tags faketime すれば runtime が切り替わるのは知っているけど、全ての出力についてくる playback header を解釈しないといけないからやや面倒ですよねhttps://t.co/2rBrtu8Mit

— _ (@apstndb) November 12, 2020

↑の様な情報が！
公式にあるんですね！！🎉

どうやらGo1.14から導入された模様。結構新しい。

Austin's faketime #golang support is in master (1.14?). See https://t.co/kZO5PtJr7h & its prior two commits.

Note that the sleep is simulated and instead all writes are prefixed by a binary header containing the fake time, starting from usual Go epoch (https://t.co/0EIMMtXi6C). pic.twitter.com/bxJXuc0PHQ

— bradfitz (@bradfitz) September 4, 2019

やってみた

↓テスト対象コード

package faketime

import "time"

func DoSomethingWithSleep() string {
	time.Sleep(5 * time.Second)
	return "done"
}

func DoSomethingWithTimer() string {
	t := time.NewTimer(5 * time.Second)
	defer t.Stop()

	<-t.C

	return "done"
}

func DoSomethingWithTicker() int {
	t := time.NewTicker(1 * time.Second)
	defer t.Stop()

	count := 0
	for i := 0; i < 10; i++ {
		select {
		case <-t.C:
			count++
		}
	}

	return count
}

↓テストコード

package faketime

import (
	"testing"
	"time"
)

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

	result := DoSomethingWithSleep()

	if expected := "done"; result != expected {
		t.Fatalf("unexpected result - expected:%s, actual:%s", expected, result)
	}

	duration := time.Now().Sub(start)
	delta := duration - 5*time.Second
	if delta < 0 {
		delta *= -1
	}

	if delta > 5*time.Millisecond {
		t.Fatalf("illegal duration:%s", duration)
	}
}

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

	result := DoSomethingWithTimer()

	if expected := "done"; result != expected {
		t.Fatalf("unexpected result - expected:%s, actual:%s", expected, result)
	}
}

func TestDoSomethingWithTicker(t *testing.T) {
	result := DoSomethingWithTicker()

	if expected := 10; result != expected {
		t.Fatalf("unexpected result - expected:%d, actual:%d", expected, result)
	}
}

まずFake timeなしで実行↓

% go test .
ok  	faketime	20.308s

実行時間約20秒かかっています。（想定通り）

次にFake timeで実行。 --tags=faketime オプションつけるだけです↓

% go test --tags=faketime .
ok  	faketime	0.062s

一瞬で返ってきました！＼(^o^)／

オマケ

本記事の主題からは少し外れますが、テストにFake timeを利用すると嬉しい副作用があります。

経過時間アサーション

あまり用途ないかもですが、Fake timeを利用すると経過時間を厳密にアサーションできます。

通常経過時間は実行ごとに変動するので正確にアサーションすることができません。前述のテストコード例でも下記の様に許容誤差を含めたアサーションをしています。

	duration := time.Now().Sub(start)
	delta := duration - 5*time.Second
	if delta < 0 {
		delta *= -1
	}

	if delta > 5*time.Millisecond {
		t.Fatalf("illegal duration:%s", duration)
	}

これでも、何らかの理由で処理が遅延して許容誤差を超えるとテストが失敗する可能性があります。

Fake timeを使用するとSleepで内部の擬似経過時間がきっちり指定された期間進む為、下記の様に誤差なしでアサーション出来ます。

	if duration := time.Now().Sub(start); time.Now().Sub(start) != 5*time.Second {
		t.Fatalf("illegal duration:%s", duration)
	}

処理が遅延して実際にはもっと時間がかかっていても、アサーションは通ります。

並行処理のテスト

Goに限らず一般的に並行処理のテストを書くのは結構面倒ですが、それは複数の処理（GoだとGoroutine）の動作するタイミングがテストコードから制御しづらいのが主な理由かと思います。
Fake timeを使用することで、（完全には無理かもですが）ある程度解決できそうです。

具体的なハナシは本記事主題から外れるので近いうちに別記事で書きたいと思います。
→書きました！＼(^o^)／ Fake timeつかったら並行処理のテストの景色が変わった

注意

これらの手法はFake time使用時にしか通らないテストになってしまうというデメリットもありますのでご注意下さい。
（テストをFake time使用時のみ実行する方法については後述します）

出力のplayback headerを取り除きたい

テストが正常終了した場合は問題ないですが、エラーになると出力に前述のplayback headerが付与されます。

↓わざとテスト失敗

出力の前に変な文字化けが見えますが、その周辺がplayback headerです。
中身は 0 0 P B <8-byte time> <4-byte data length> <data> の16byteです。

出ていてもそれほど大きく困ることはなさそうですが微妙に邪魔ですね。

そこで削除するツールを作りました！

trimfaketime (tft)

インストール↓

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

実行↓

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

結果↓

文字化けヘッダ消えました！＼(^o^)／

注： Pipe使ってるので go test の結果ステータスは消えてます。CIなどの実行でステータス必要な方はPIPESTATUS変数などでよきにはからってください。

テストをfaketime使用時のみ実行したい

テストコードにbuild tagつけておけばfaketime指定時のみ実行されます。

// +build faketime

package faketime

（以下略）

罠

Fake timeと相性の悪いコードやライブラリもありそうです。

現状、ネットワークに接続にいくコードをテストしようとするとハングする、という現象を確認しています。
net や net/http などはimportされているだけでハングします（大きな問題ですね🤮）。
原因は調査中です。

Fake time実行がうまく動作しないテストはビルドタグ // +build !faketime を付与することで除外できますが、importだけでハングする様な問題の場合まずパッケージごと分割しないといけないので厄介ですね・・・

さいごに

Fake timeを利用してtime.Sleepなどを使用しているコードのテスト実行時間を大幅に短縮することができました＼(^o^)／
大きな罠もありますが、いろいろ可能性も感じています。
面白い利用方法が見つかったら記事をアップしていきたいと思います。