ruby とかでは newrelic を使うと HTTP リクエストを捌くのにかかった時間に加えて、DBアクセスにかかった時間、テンプレートレンダリングにかかった時間、I/O にかかった時間(外部サービスへの HTTP リクエストにかかった時間)、みたいな内訳が見れる。

今年の ISUCON は golang で出ようと思っていたので、チューニングするにあたって、golang でも気軽にそういうのを見れるツールがないと捗らないよな、と思って探したけどなかったので golang の勉強がてら作ってた。FYI: ちなみに gorelic というものはあったんだけど、あれは pprof の情報を newrelic を使ってグラフ化しているだけで欲しいものとは違った

net/http のメトリクスと、(text|html).template のメトリクス、database/sql のメトリクスが取れる。

ruby の場合は、メタプログラミングという名の黒魔術ができるので、計測したいコードに対して外から処理を追加しやすい。他所の gem からでも既存のクラスに対して差し込める。

golang の場合はそういうのができないので、ラップする形にした。どういうことかというと、sql_metrics の場合の実装はこんなかんじ

package sql_metrics

func WrapDB(name string, db *sql.DB) *DB {
    proxy := proxyRegistry[db]
    if proxy == nil {
        proxy = newDB(db, metrics)
        proxyRegistry[db] = proxy
    }
    return proxy
}

func (proxy *DB) Exec(query string, args ...interface{}) (sql.Result, error) {
    if Enable {
        startTime := time.Now()
        defer proxy.measure(startTime, query)
    }
    return proxy.Original.Exec(query, args...)
}

.... 以下略

使うときはこんなかんじ

  // db, err := sql.Open("sqlite3", "foo.db")
  _db, err := sql.Open("sqlite3", "foo.db")
  db := sql_metrics.WrapDB("foo", _db)

  // Use as usual
  result, err := db.Exec("INSERT INTO memos (id, body) VALUES (?)", id, body)

つまり、*sql.DB を *sql_metrics.DB にラップして、*sql_metrics.DB 経由でいつものようにメソッドが呼ばれると時間が計測されるようになっている。

template_metrics の場合は (text|html).Template をラップして、http_metrics の場合は http.Handle および HandleFunc をラップするようになっている。

実際の使い方はそれぞれの README を見てもらうと良い。

出力結果

lltsv と sort を組み合わせて整形しているけど、ISUCON3 のアプリに仕込んでベンチを走らせてサマリを出力させるとこんなかんじになる。 左から合計時間(秒)、呼び出し回数、平均時間(秒)、対象のクエリ(とかリクエストとか、テンプレートとか)である。

$ grep query app.log | lltsv -k sum,count,mean,query -K | sort -n -r
42.515819   411 0.103445    SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ? OFFSET ?
29.318021   836 0.035069    SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=?  ORDER BY created_at
23.003601   830 0.027715    SELECT count(*) AS c FROM memos WHERE is_private=0
19.085289   419 0.045550    SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ?
6.244089    170 0.036730    SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? ORDER BY created_at DESC
6.204839    158 0.039271    SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? AND is_private=0 ORDER BY created_at
0.702008    1303    0.000683    SELECT * FROM users WHERE id=?
0.636161    1085    0.000619    SELECT id, user, content, is_private, created_at, updated_at FROM memos WHERE id=?
0.260924    83994   0.000254    SELECT username FROM users WHERE id=?
0.125518    170 0.000738    SELECT id, username, password, salt FROM users WHERE username=?
0.119622    170 0.000704    UPDATE users SET last_access=now() WHERE id=?
0.101019    170 0.000594    INSERT INTO memos (user, content, is_private, created_at) VALUES (?, ?, ?, now())

$ grep handler app.log | lltsv -k sum,count,mean,handler -K | sort -n -r
112.595701  1085    0.109529    memoHandler
71.088976   411 0.172966    recentHandler
49.193846   419 0.117408    topHandler
10.577193   170 0.062219    mypageHandler
0.489704    170 0.002881    memoPostHandler
0.473548    170 0.002786    signinPostHandler
0.320596    5464    0.000312    public
0.281419    170 0.001655    signoutHandler
0.094454    170 0.000556    signinHandler

$ grep template app.log | lltsv -k sum,count,mean,base -K | sort -n -r
75.879037   994 0.076337    memo
8.848884    830 0.010661    index
2.688126    170 0.015813    mypage
0.060962    170 0.000359    signin

LIMIT OFFSET なクエリが遅いな、とか memo テンプレートが遅いな、とかすぐわかる。

ベンチを通した全体のサマリだけじゃなくて(時間で指定)、リクエストのあるたびに出力することもできるので、ブラウザから手で叩きながら画面ごとのクエリの数をみて「げぇ、N+1 クエリだ」とか見つけるのもやりやすい。

あと、この出力結果をアプリから newrelic とか mackerel に投げてグラフ化できたりすると実運用でも捗りそうだな、と思っている。まだその仕組みは作ってないけど。

ISUCON4 では

これが ISUCON4 では大活躍しまっっっした！というと嘘で、このツールには制約があって、net/http, (text|html)/template, database/sql が露出されているフレームワークじゃないと仕込むのが難しい。

gorilla とかなら露出されているから良いんだけど、たとえば martini のようなフレームワークを使われると、中に net/http, html/template が隠されているので、ラッパーインスタンスを作れるタイミングがない。

で、ISUCON4 では martini だったわけで。。。 martini マジ martini 。。。

結局 nginx のアクセスログ集計スクリプト(自作)でなんとかしましたとさ。スクリプトも用意しておいて良かったね。ちゃんちゃん。

PS. どなたか golang で既存の struct の メソッドに時間計測コードを外から差し込む方法をご存知の方はいらっしゃいませんか？くやしいっっっ！！

追記: martini 外しは終わってからやってみましたが、やっぱり golang 歴１ヶ月の自分では時間がかかったので、競技中は無理だったな、という印象。力量にあった判断だった。