runn を使ってシナリオテストを順調に積み上げていった結果、順調にテスト実行時間が長くなってきました。
そこでテストのどの部分に時間がかかっているかを計測したくなったのですが、runnにその時間計測機能はなかったのでそれを作ろうと考えました。
ところが、実現したい時間計測機能を満たすちょうど良いライブラリがなかったのでそれを作ることから始めました。
実現したい時間計測機能
時間計測というと Start() と Stop() の間の開始時刻と終了時刻と経過時間がわかれば良さそうです。
しかし、runnに組み込むにあたって実現したかった時間計測は、「runnで実行している『どのシナリオ』の『どのステップ』の『どの処理』に時間がかかっているか？」を特定するためのもので、
上記の図でいうと横軸が時系列だとして、実現したい時間計測機能は
- 濃いめの青のライン全ての開始時刻と終了時刻と経過時間を
- 入れ子状態を維持した（表現した）状態で
- 1つの結果として
時間計測したいというものです。
stopw
というわけで作成したのが stopw です。
stopwは Start() し Stop() したあと、計測結果を Result() で取得します。
上記だけだとただの時刻計測です。
stopwは入れ子を表現するためにキーを複数渡すことができます。
キーを渡して時刻計測することで、次のように入れ子の計測結果を得ることができます。
package main import ( "encoding/json" "fmt" "github.com/k1LoW/stopw" ) func main() { stopw.Start() stopw.Start("sub span A") // do something for `sub span A` stopw.Start("sub span B") // do something for `sub span A` or `sub span B` stopw.Start("sub span A", "sub sub span a") // do something for `sub span A` or `sub span B` or `sub sub span a` stopw.Stop("sub span A", "sub sub span a") // do something for `sub span A` or `sub span B` stopw.Stop("sub span span A") // do something for `sub span B` stopw.Stop() r := stopw.Result() b, _ := json.MarshalIndent(r, "", " ") fmt.Println(string(b)) // Output: // { // "id": "cbt1386v9mc80ofooblg", // "started_at": "2009-11-10T23:00:00.436022+09:00", // "stopped_at": "2009-11-10T23:00:00.436883+09:00", // "elapsed": 860375, // "breakdown": [ // { // "id": "sub span A", // "started_at": "2009-11-10T23:00:00.436153+09:00", // "stopped_at": "2009-11-10T23:00:00.436594+09:00", // "elapsed": 441292, // "breakdown": [ // { // "id": "sub sub span a", // "started_at": "2009-11-10T23:00:00.436449+09:00", // "stopped_at": "2009-11-10T23:00:00.436594+09:00", // "elapsed": 145500 // } // ] // }, // { // "id": "sub span B", // "started_at": "2009-11-10T23:00:00.436303+09:00", // "stopped_at": "2009-11-10T23:00:00.436883+09:00", // "elapsed": 580083 // } // ] // } }
上記のコードをみたらわかるように、渡したキーの数で入れ子の深さを表現するという単純なものです。
ただ、いくつか使いやすくするためのしくみを入れています。
いきなり stopw.Start() ができる
これの何が便利かというと、stopw.Start() のスコープと stopw.Stop() のスコープが同じである必要がないということです。
例えば、ある関数スコープ内で stopw.Start() して、別の関数スコープ内で stopw.Start("keyA") して、さらに別の関数スコープ内で stopw.Start("keyA", "keyB") して、さらに別の関数スコープ内で stopw.Stop しても、1つにまとまった結果を stopw.Result() から取得できます。
これは組み込みやすさにつながります。
math/rand などでも使われているテクニックですね。
https://cs.opensource.google/go/go/+/refs/tags/go1.19:src/math/rand/rand.go;l=293
当然、別々の時刻計測をするためにインスタンスを分けることも可能です。
a := stopw.New() b := stopw.New() a.Start() // do something for a a.Stop() b.Start() // do something for b b.Stop() ra := a.Result() rb := b.Result()
defer stopw.Start().Stop() で、関数ブロックの時間計測ができる
これも組み込みやすくするためのしくみです。1行で時間計測ができるのは便利です。
func () { defer stopw.Start().Stop() // do something }() r := stopw.Result() [...]
このテクニックもどこかのライブラリで見た気がするのですが忘れてしまいました。
stopw.Disable() で、時間計測処理をスキップできる
一括してOFFにできるようにしていて、stopwを組み込んだ結果発生するオーバヘッドをできるだけ小さくできるようにしています。
キーに合わせてできる限り時刻を含め入れ子を保つように動く
例えば stopw.Start() を実行しなくても stopw.Start("key A") を実行すれば stopw.Start() で記録されるべき開始時刻が記録されますし、stopw.Stop("key B") を実行しなくても stopw.Stop() を実行すれば stopw.Stop("key B") で記録されるべき終了時刻が記録されます。
stopwはキーを元に入れ子をできるだけ保とうとします。
最後に
runnにはどう組み込まれているかというと、
runn.Profile(true) をオプションで渡して、最後に DumpProfile() を実行すると、計測結果をJSON形式で取得できるようになっています。
opts := []runn.Option{
runn.T(t),
runn.Book("testdata/books/login.yml"),
runn.Profile(true)
}
o, err := runn.New(opts...)
if err != nil {
t.Fatal(err)
}
if err := o.Run(ctx); err != nil {
t.Fatal(err)
}
f, err := os.Open("profile.json")
if err != nil {
t.Fatal(err)
}
if err := o.DumpProfile(f); err != nil {
t.Fatal(err)
}
というわけで、時間計測ライブラリ stopw の紹介でした。
良かったら使ってみてください。
