Go専用対ISUCON兵器 「graqt」を書いた

ISUCON OSS Golang middleware graqt

f:id:serinuntius:20180430224626p:plain

はじめに

この記事でも書いたけど、最近ISUCONの面白さに気づいた。 serinuntius.hatenablog.jp

社内ISUCONはRubyで書かれていたけど、本家ISUCONでは使用言語が選択できる。 そうなったら、今なら迷わずにGoを選ぶ。

それは、何故かと言うとGoが速いとかそういう理由よりも、GolandというIDEのおかげである。 こいつの補完やらなんやらがとても良くできているので、ソースを読むのも書くのも爆速になるからである。

RubyにもJetbrains製の Rubymine というのがあるけれど、動的言語だからか完全にはコードジャンプできない。 同名のメソッドがあったときには、選択肢が出てユーザにどのメソッドですか？みたいな感じで問いかける感じ。

けど、Golandは型があるからか100%の精度でコードジャンプできる。 そのおかげで、爆速コードリーディングが可能になる。

Golangが最高という話はおいておいて、Go用のクエリのロガーとアクセスログを出すミドルウェアを書いたので、その説明をしたいと思う。

graqtとは

github.com

go-request-and-query-loggerです。*1

発音は、 グラクトか、ガラクタでお願いします。

僕はガラクタって読んでるw*2

Go用のアクセスログとクエリのログを記録するためのhttp handlerミドルウェアです。*3

主にISUCONで使うだろうな〜と思って書いたけど、全然普通のプロジェクトでも使えば便利そう。

alpとpt-query-digestを合体させたものが作りたいな〜というのが、この構想の始まり。

どんなログが出るの？

access.log には 主に time, request_id, path, method が記録される。

  • time => このリクエストにかかった時間
  • request_id => 1リクエストごとにユニークなid
  • path => リクエストされたpath
  • method => GET, POSTとか
{"level":"info","ts":1525082389.1337767,"caller":"graqt/middleware.go:25","msg":"","time":0.011566198,"request_id":"5914e629-6746-42c5-b342-702f224f48e1","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.2157433,"caller":"graqt/middleware.go:25","msg":"","time":0.003945689,"request_id":"4e743b2a-59be-4692-b36b-3b6a9ba78b01","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.2983494,"caller":"graqt/middleware.go:25","msg":"","time":0.014426681,"request_id":"f1d68fb3-5450-48f3-9f46-1ea5ad2370fb","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.3756797,"caller":"graqt/middleware.go:25","msg":"","time":0.004002398,"request_id":"e727db2b-df12-410c-91a4-4dd3117b9452","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.47504,"caller":"graqt/middleware.go:25","msg":"","time":0.005889232,"request_id":"57df4708-9705-4401-98b2-fad4bacfe585","path":"/user","method":"POST"}
{"level":"info","ts":1525082389.554212,"caller":"graqt/middleware.go:25","msg":"","time":0.016009073,"request_id":"58957516-c7b2-4f64-8889-b39496e6597f","path":"/user","method":"POST"}

query.log には 主にquery,args, time, request_id が記録される。

  • query => クエリ
  • args => prepareステートメントだと、その引数が入る
  • time => そのクエリにかかった時間
  • request_id => さっき↑で出てきた、リクエストごとに一意のid。これのおかげで、どのリクエストでどんだけのクエリが呼ばれるかを調べるという寸法
{"level":"info","ts":1525082389.1336403,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389130688404@hoge.com"},{"Name":"","Ordinal":2,"Value":57}],"time":0.001157627,"request_id":"5914e629-6746-42c5-b342-702f224f48e1"}
{"level":"info","ts":1525082389.215664,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389213632765@hoge.com"},{"Name":"","Ordinal":2,"Value":37}],"time":0.002013919,"request_id":"4e743b2a-59be-4692-b36b-3b6a9ba78b01"}
{"level":"info","ts":1525082389.2982852,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389287262677@hoge.com"},{"Name":"","Ordinal":2,"Value":74}],"time":0.011005944,"request_id":"f1d68fb3-5450-48f3-9f46-1ea5ad2370fb"}
{"level":"info","ts":1525082389.37562,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389372293507@hoge.com"},{"Name":"","Ordinal":2,"Value":64}],"time":0.003297617,"request_id":"e727db2b-df12-410c-91a4-4dd3117b9452"}
{"level":"info","ts":1525082389.474928,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389470871128@hoge.com"},{"Name":"","Ordinal":2,"Value":73}],"time":0.001937477,"request_id":"57df4708-9705-4401-98b2-fad4bacfe585"}
{"level":"info","ts":1525082389.5541484,"caller":"graqt/tracer.go:20","msg":"Exec","query":"INSERT INTO `user` (email,age) VALUES (?, ?)","args":[{"Name":"","Ordinal":1,"Value":"hoge1525082389550824448@hoge.com"},{"Name":"","Ordinal":2,"Value":39}],"time":0.001194376,"request_id":"58957516-c7b2-4f64-8889-b39496e6597f"}

使い方

変更しなくちゃいけないだろうな〜というところにコメントしておいた。簡単に移行できるはず。

package main

import (
    "database/sql"
    "fmt"
    "math/rand"
    "net/http"
    "os"
    "time"

    _ "github.com/go-sql-driver/mysql"

    // 2つパッケージを追加してください
    "github.com/justinas/alice"
    "github.com/serinuntius/graqt"
)

var (
    // 2つ変数を追加してください
    traceEnabled = os.Getenv("GRAQT_TRACE")
    driverName   = "mysql"

    db *sql.DB
)

func init() {
    rand.Seed(time.Now().UnixNano())
}
func main() {

    // ifを追加して 環境変数 GRAQT_TRACEが1のときだけログを吐きます。
    // ISUCONで本番ベンチのときは オフにしておいたほうがいいと思います。
    // しかし、パフォーマンスには結構気を使ったので、そんなに低下はしないと思います。
    if traceEnabled == "1" {
        // driverNameは絶対にこれでお願いします。
        driverName = "mysql-tracer"

        // もし、ログを吐く場所を変えたかったら以下のメソッドを呼んで下さい。
        // デフォルトは、 query.logとrequest.logが このGoファイル(main.go)と同じディレクトリに出ると思います。
        // graqt.SetQueryLogger("log/query.log")
        // graqt.SetRequestLogger("log/request.log")
    }

    var err error

    // ここを先程の変数に変更してください
    db, err = sql.Open(driverName, "root:@/graqt")
    if err != nil {
        panic(err)
    }
    defer db.Close()

    mux := http.NewServeMux()
    mux.HandleFunc("/user", createUser)

    // ミドルウェアを追加します。
    var chain alice.Chain
    if traceEnabled == "1" {
        chain = alice.New(graqt.RequestId)
    } else {
        chain = alice.New()
    }

    // ミドルウェアを渡します
    http.ListenAndServe(":8080", chain.Then(mux))
}

func createUser(w http.ResponseWriter, r *http.Request) {
    // contextを使用する方のメソッドに変えてください。
    ctx := r.Context()
    stmt, _ := db.PrepareContext(ctx, "INSERT INTO `user` (email,age) VALUES (?, ?)")
    t1 := time.Now().UnixNano()
    age := rand.Intn(80)

    stmt.ExecContext(ctx, fmt.Sprintf("hoge%d@hoge.com", t1), age)

    w.Write([]byte(`ok`))
}

仕組み(ミドルウェア側)

まずはhttp handlerのミドルウェアの説明から。

http.Handler を返す 関数を作ればそれをミドルウェアとして登録できる。 今回いろいろなミドルウェアを追加するときに面倒かな〜と思って、alice を利用した。

github.com

http.Handlerを返す関数はこんな感じ↓。 時間を測って、uuid-v4のrequestIDを生成してcontextに突っ込む。 next.ServeHTTPで本来の処理をして、終わってからログを吐くという形。

func RequestId(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        t1 := time.Now()

        id := newRequestID()
        ctx := setRequestID(r.Context(), id)

        next.ServeHTTP(w, r.WithContext(ctx))
        // 終わったあとにログを吐く

        RLogger.Info("",
            zap.Duration("time", time.Since(t1)),
            zap.String("request_id", id),
            zap.String("path", r.RequestURI),
            zap.String("method", r.Method),
        )
    })
}

仕組み(クエリロガー側)

shogo82148さんの go-sql-proxy がめちゃくちゃ便利でした。*4 github.com

こんな感じで、Execする前に何をするか、Execした後に何をするかっていうのを書けるので、好みの処理を書くだけ。 今回は、クエリごとの時間を計測することと、クエリのログを吐くっていうのが目的なので、以下のような感じにしている。

sql.Register("mysql-tracer", proxy.NewProxyContext(&mysql.MySQLDriver{}, &proxy.HooksContext{
        PreExec: func(_ context.Context, _ *proxy.Stmt, _ []driver.NamedValue) (interface{}, error) {
            return time.Now(), nil
        },
        PostExec: func(c context.Context, ctx interface{}, stmt *proxy.Stmt, args []driver.NamedValue, _ driver.Result, _ error) error {
            QLogger.Info("Exec",
                zap.String("query", stmt.QueryString),
                zap.Any("args", args),
                zap.Duration("time", time.Since(ctx.(time.Time))),
                zap.String("request_id", c.Value(RequestIDKey).(string)),
            )
            return nil
        },
         ...
    }))

go-sql-proxyにもデフォルトでほぼ同じ機能のロガーがあるのだけど、今回のポイントはリクエストごとに一意になるIDを付け加えたいというのと、構造化されたログ(json)を吐きたいというところなので、手を加えさせて貰った。

構造化ログを吐くのにパフォーマンスがいいと謳われている、zapを利用した。 github.com

パフォーマンスをそんなに気にしなくていいと言ったのはこのため。 ~実際wrkでベンチしたけど、ログを入れたからっといって有意な差はあまりなかった。~

追記

流石に雑すぎるので、次の項目でベンチ結果を貼る。

パフォーマンス

100query/recのアプリでログあり

$ wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   181.55ms   44.71ms 346.20ms   70.86%
    Req/Sec    27.58     10.54    50.00     63.02%
  549 requests in 10.06s, 63.26KB read
Requests/sec:     54.56
Transfer/sec:      6.29KB

100query/reqのアプリでログなし

$ wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   168.48ms   40.87ms 308.79ms   68.35%
    Req/Sec    29.59     11.74    50.00     78.87%
  594 requests in 10.09s, 68.45KB read
Requests/sec:     58.89
Transfer/sec:      6.79KB

1query/reqのアプリでログあり

wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     8.74ms   14.81ms 270.78ms   95.19%
    Req/Sec   780.89    156.08     1.19k    69.65%
  15628 requests in 10.10s, 1.76MB read
Requests/sec:   1547.08
Transfer/sec:    178.28KB

1query/reqのアプリでログなし

wrk http://localhost:8080/user
Running 10s test @ http://localhost:8080/user
  2 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     7.55ms    7.72ms 107.14ms   89.51%
    Req/Sec   811.16    187.08     1.55k    69.65%
  16235 requests in 10.10s, 1.83MB read
Requests/sec:   1607.31
Transfer/sec:    185.22KB

まぁ、遅くなるけど、本気ベンチじゃないときにこれぐらいのスコア下がってもまぁ良いよねって感じ。

TODO

  • このリクエストやクエリのログを読み込んで、ボトルネックをわかりやすくするための「graqtクライアント」作成*5
  • mysql固定で書いたけど、ドライバーの登録部分を変えるだけで他のドライバーにもできるはずなので、そこを調整する
  • context対応してないorm?だったらどうしよう？
    • ISUCONで使用されたorm?はsqlxかdatabase/sqlだけなのでcontext対応しているので大丈夫！

まとめ

対ISUCON兵器とか釣りっぽく書いてしまったけど、まだログを吐けるだけでボトルネックは簡単には探せないw

graqtクライアントを書いたときに真価が問われる。

graqtクライアントはこんな感じで考えている。

リクエストモード

全体的に俯瞰して、どのリクエストが重いかを調べるモード。

  • COUNT => そのリクエストの回数
  • AVG => 平均リクエスト時間
  • MIN => 最小リクエスト時間
  • MAX => 最大リクエスト時間
  • PATH => リクエストパス
  • METHOD => メソッド
  • QueryCount => 1リクエストのクエリの数
  • DB Rate => クエリの合計時間/リクエストの時間 (これで、1リクエストでどれだけDBが支配してるかわかる)
COUNT AVG MIN MAX PATH METHOD QueryCount DB Rate
300 20 13 30 / GET 30 0.39
300 20 20 40 /user POST 49 0.79
300 20 30 50 /hoge GET 59 0.38
300 20 50 80 /fuga GET 492 0.58
300 20 70 90 /fuga GET 543 0.33

クエリモード

重いリクエストがわかったら、そのリクエストを選んでそのリクエストで飛んでるクエリが閲覧出来るモード。

  • QueryTime => 1クエリの時間
  • Count => そのクエリが1リクエストで呼ばれた数
  • Args => Prepareステートメントの引数(サンプル1つだけ)
  • Caller => どこでそのクエリが発行されてるかを示す(今はない)
QueryTime Count Query Args Caller
300ms 30 SELECT * FROM USER WHERE id = ? 3 main.go:23
30ms 1 INSERT INTO user (email,age) VALUES (?, ?) ["hoge@hoge", 30] main.go:43

たぶん初めて自分のOSS書いたけど、浸透するまで時間かかりそう。(別にしなくてもいいけどｗ)

一番の浸透させる方法は、これを使って(または、使った人が)ISUCONに優勝することだろうな〜。 (けど、DBの負荷を減らすのなんて決勝に出る人達はこんなツールがなくても余裕でやってのけるんだろうな〜とかw)

*1:tはどこからきてlはどこ行ってしまったのかｗ

*2:作者にガラクタ扱いを受けるっていう

*3:正しい表現なのかは不明

*4:というか、まんま

*5:alpみたいなもん