コマンドラインを複数回実行して実行時間を計測するツールを書いた

walf443/benchcmd · GitHub

なんか最近ツール系のやつを趣味で高速化したりしていて、PR投げるときに速くなったよと説明するときに手元で何度か計測して、平均値とか調べるのがめんどいなと思って、複数回実行して平均/標準偏差を表示してくれるツールを作った。

もっと定番のがあるような気がするけど、あんまり聞いたことがない。

Usage of benchcmd:
  -n int
          number of times to run (default 10)
  -summary
          only output summary result

$ benchcmd -n 10 'go version'
run "go version"
15.711435ms
19.42685ms
19.967876ms
24.896109ms
19.557516ms
21.698995ms
16.499163ms
22.28795ms
23.461732ms
18.743192ms
count:  10 times executed
avg:    20.225081ms
stdev:  2.634089ms

importするだけですべてのHTTP通信をログる

今回のisuconに対応できなかったので、作ろうと思ったけど、id:motemenさんが既に作ってた

昔見た記憶があったのだけど、すっかり記憶から忘れていた。

motemen.hatenablog.com

何msぐらいかかったかとかは出てこないので出力できるようにしてみたが、拡張方法が互換性がないのでmergeしてもらえないかもしれない。

github.com

とりあえずmergeされなくても使えるように整えておいた。

github.com

2行書きかえるだけでSQLをログに出力できるようになるgo-sql-tracerを作りました

isucon予選中に、SQLを出力したくなったのだけど、ふとgithub.com/shogo82148/go-sql-proxyを使ってみようとしてとりあえず簡単に使う方法が書いてなくて少し使い方を調べるのに苦労したので、isuconで時間のロスなく使えるようにそのwrapperを書きました。

package main

  import (
    database/sql
    "github.com/go-sql-driver/mysql" # load driver before load go-sql-tracer
    _ "github.com/walf443/go-sql-tracer"
  )

  func main() {
    db, err := sql.Open('mysql:trace', dsn)
  }

ポイントは、

• 元々使っていたドライバ名に":trace"とつけること
• go-sql-driver/mysqlをimportしたあとに、importすること

です。

今database/sqlに登録されているドライバ一覧から、go-sql-tracerのinit内で、':trace'をつけてドライバを登録しているので使いたいドライバの後でimportする必要があります。

go-sql-proxyはカスタマイズも柔軟にでき、非常に素晴らしいライブラリですが、カスタマイズしなくてもいいのでとりあえずSQLのログみたい、というときは非常に便利かと思います。

github.com

じわじわチャットへ通知する

なんかのバッチを実行していて、それが出力するログをじわじわチャットへ通知したい。(そのバッチはそれなりに時間がかかるものとする)

何も考慮しなければ、たとえばslackであれば、

# #!/bin/bash
# notify_chat.sh

exec tee >(while read line; do curl -s --data '$line' $SLACK_ENDPOINT -o/dev/null; done

みたいにやれば、

$ ruby batch.rb | notify_chat.sh

で毎行slackさんへ通知してくれる。

このやり方だと、場所によってはAPIをどばっと叩いてしまって負荷をかけてしまったりするので、1秒間の出力はまとめてわたせるようにするコマンドthrottleというものを書いてみた。

  $ ruby batch.rb | tee >(throttle -interval 1s "curl -s --data '%%DATA%%' $SLACK_ENDPOINT -o /dev/null")

みたいにやると、1秒間の出力はまとめてcurlコマンドへ渡してくれる。1秒間の出力は、%%DATA%%の部分が置きかえられて実行される

$ go install github.com/walf443/throttle

でインストールできる

ソースは、

github.com

ppの出力先を変えられるようにした

pp( k0kubun/pp · GitHub
)は非常にお気軽に使えてよいのだけど、デバッグ中にちょっと出力がウザいので抑えたり、また見たりしたいなー、というときに、import文をコメントアウトしたり変数を_に変えたりするのがめんどくさかった(それがGo wayなのではあるけれども)

そこで、DEBUGが有効なときに使える、Debug*みたいな関数群を追加するのを提案したところ、出力先を切り替えられるようにしてはどうか?という話になったので、実装して無事、取りこまれた。

customizable Print* functions output by walf443 · Pull Request #6 · k0kubun/pp · GitHub

import (
  "github.com/k0kubun/pp"
  "io/ioutil"
  "os"
)

func init() {
    if os.Getenv("DEBUG") == "" {
        pp.SetDefaultOutput(ioutil.Discard)
    }
}

こんな感じにしておくと、pp.PrintしているところがDEBUG環境変数が有効じゃないと出力されなくなるので、コードを変更しなくてもppの出力を抑制できるようになる。

自分は、今書いているパーサーで、実際に使われているデータとかをparseしてASTをdumpするやつ(コミットしていない)をgo testで走るようにしておいてそれをたまにppでdumpしたりしている。便利。

ppは、さらに欲をいえば、

import ( 
  "github.com/pp/pp"
)

みたいにpp organizerでホストされているようになれば、pp/ppで何も考えずimportできるようになって個人的にはとてもうれしい。githubはアクティビティが低いユーザーで良い名前を抑えていた場合、交渉して取れるようになっていると聞いたことがあるような気がするが、この場合はどうだろうか。

pp · GitHub

追記

import "gopkg.in/pp.v1"

できるようになったらしい。すばらしい。

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

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の話を聞いたけど、何って名前だったか覚えてなかったので、適当に作った。あっちの方がライブラリとしてはよっぽどちゃんとしている。