カジュアルに実行時間を計測する

go

isuconの予選で、カジュアルにここどれぐらい時間がかかっているか計測したい、ということで作った。
pprofは(使い方間違っているだけなのかもしれないけど)CPU時間での計測なので、io待ちとか、channel待ちとかの時間は出てこないので、web applicationのチューニングにはあまり適さないのかなという気がする。

https://github.com/walf443/stopwatch

やりたいこととしては、

  • 計測コードを簡単に無効にできる
  • ここから、ここまで、という指定以外に前回の実行からどれぐらいたったのか? というのも自動でとりたい

ということを達成したかった。

package main

import (
        "flag"
        "github.com/walf443/stopwatch"
        "time"
)

func main() {
        flag.Parse()

        stopwatch.Reset("start request")
        time.Sleep(100 * time.Millisecond)
        stopwatch.Watch("after something")
        time.Sleep(100 * time.Millisecond)
        stopwatch.Watch("after something 2")

}

こんな感じで、HTTPのサーバーであれば、リクエストの関数の冒頭で、Resetを呼びだし、あとは、計測したいタイミングで、Watchを呼びだしていけばよい

デフォルトでは無効になっているので、計測するには、--stopwatchフラグをつけながら起動すると、

$ go run example.go --stopwatch
stopwatch|2014/10/07 09:27:33 [             0][             0] start request at /Users/yoshimin/project/go/src/github.com/walf443/stopwatch/example/example.go:12
stopwatch|2014/10/07 09:27:33 [  100.892037ms][  100.892037ms] after something at /Users/yoshimin/project/go/src/github.com/walf443/stopwatch/example/example.go:14
stopwatch|2014/10/07 09:27:33 [  201.129537ms][    100.2375ms] after something 2 at /Users/yoshimin/project/go/src/github.com/walf443/stopwatch/example/example.go:16

こんな感じで標準出力にログが出てきて、Resetを呼びだしてからの時間と、前回Watchをしてからの時間がわかる。

グローバル変数で実現しているので、関数間でも、別のファイル間でもカジュアルにstopwatch.Watchとか呼べばよい。
もちろんその反面、HTTPサーバーのハンドラに仕込んでいるときに、同時にリクエストが来て、Resetが呼ばれたりすると、カウンタがおかしくなるが、手動で動作させつつ、大まかな時間を調べるのが目的なので、使い勝手のカジュアルさを重視した。

使い終わったら、stopwatchが書いてある行を削除すれば、だいたい消えてくれると思われる。

matsuuさんに、Practical Goで、Nitroの話を聞いたけど、何って名前だったか覚えてなかったので、適当に作った。あっちの方がライブラリとしてはよっぽどちゃんとしている。