この記事はもともと別場所にて公開していました。
#TL;DR
Go 用 SQL スロークエリ解析ツール Aquery を書いて ISUCON10 の本選に出たけど、再起動試験を適当にやったせいでちゃんと起動せずに fail して涙を飲んだり飲まなかったりした。
ISUCON10 本選についてはメンバーの梅の仁が詳しく書いてくれているので省略。一言だけ付け加えておくと、今年は全然戦力になれなかったので申し訳なかった。
以下では Aquery の話をします。
#概要
database/sqlを使う Go コードに仕込むことで得られる SQL トレースをよしなに解析してくれるソフトウェアを作った。
GitHub で大公開中。下みたいな画面を出力できる。
気分としては ALP の SQL バージョン。現状 MySQL だけしか対応していないが、中身を適当にいじればほかの SQL でも対応できるはず。
#使い方
Go コードでsql.Openを呼んでいるところを次のように改変する。ちなみに直接database/sqlを呼んでいなくても、内部でそれを呼び出すライブラリ（sqlx[1]とか）なら同様に使える。
import "github.com/ushitora-anqou/aquery"
func main() {
thresholdSlowQuery, err := time.ParseDuration("0ms") // どのくらい遅いクエリを記録するか
handler := aquery.RegisterTracer(thresholdSlowQuery)
http.DefaultServeMux.Handle("/debug/aquery", handler) // HTTPエンドポイント/debug/aqueryを作る
go func() {
log.Println(http.ListenAndServe("localhost:6060", nil))
}()
db, err := sql.Open("mysql:trace", "data source") // トレース付きのSQLドライバを開く
if err != nil {
log.Fatalf("Could not open db: %s", err.Error())
}
// dbを通常と同様に使ってコードを書く
}
これを起動するとhttp://localhost:6060/debug/aqueryで Aquery が口を開けて待ってくれるようになるので、それを使ってログをとれる。
# 60秒間ログを取って、その結果をquery.gzに保存する。
$ curl "http://localhost:6060/debug/aquery?seconds=60" > query.gz
次いで解析用のaqueryコマンドをインストールして、結果を整形する。
$ go get github.com/ushitora-anqou/aquery/aquery
$ aquery/aquery -group=fullct query.gz
Aquery はとった SQL クエリログを集計して表示する。集計の仕方は-groupオプションを使って指定できる。デフォルトではコールトレースの一番上だけを見るが、これはほとんどの場合有用ではない。ソースコードについて何の情報も無いときは-group=fullctとすることで、コールトレース全体を考慮にいれて集計できる。関係のある関数呼び出しに限って集計する場合は、
-match-ct=正規表現オプションを使うと、正規表現にマッチするエントリにフィルタしてくれる。ファイル名のみの表示にする場合は-short-ctオプションを、表の横幅を広げたい場合は-colオプションを使う。
表示は、デフォルトではSUMが大きい順にソートされる。これを変えるには-sortオプションが使える。列の意味はおおよそタイトル行のとおりだが、Kだけは説明が必要かもしれない。これは Kind の略で、そこで行われた操作を示している。例えばOpなら Open だし、Quなら Query である。
#例
コマンドの実行例はややこしいと思うので、実際に使ってみる。手元に ISUCON 9 本選をチューニングしたときのデータがあるのでこれを使う。
まず-group=fullctで集計する。
$ aquery -group=fullct isu9f1.gz | head -50
+-------+-------+-------+--------+-------+-------+-------+-------+-------+----+------------------------------------------------------------------------------------------------------+--------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STD | K | CALLTRACE | DESC |
+-------+-------+-------+--------+-------+-------+-------+-------+-------+----+------------------------------------------------------------------------------------------------------+--------------------------------+
| 656 | 0.006 | 0.086 | 20.471 | 0.031 | 0.006 | 0.033 | 0.073 | 0.016 | Op | 00:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/hooks.go:405 | |
| | | | | | | | | | | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/connector.go:31 | |
| | | | | | | | | | | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/connector.go:52 | |
| | | | | | | | | | | 03:/usr/local/go/src/database/sql/sql.go:1294 04:/usr/local/go/src/database/sql/sql.go:1616 | |
| | | | | | | | | | | 05:/usr/local/go/src/database/sql/sql.go:1598 06:/usr/local/go/src/database/sql/sql.go:1612 | |
| | | | | | | | | | | 07:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:363 | |
| | | | | | | | | | | 08:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:685 | |
| | | | | | | | | | | 09:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:328 | |
| | | | | | | | | | | 10:/home/isucon/isutrain/webapp/go/main.go:1695 11:/usr/local/go/src/net/http/server.go:2042 | |
| | | | | | | | | | | 12:/home/isucon/go/pkg/mod/[email protected]+incompatible/dispatch.go:17 | |
| | | | | | | | | | | 13:/home/isucon/go/pkg/mod/[email protected]+incompatible/mux.go:74 | |
| | | | | | | | | | | 14:/usr/local/go/src/net/http/server.go:2843 15:/usr/local/go/src/net/http/server.go:1925 | |
| | | | | | | | | | | 16:/usr/local/go/src/runtime/asm_amd64.s:1374 | |
| 614 | 0.006 | 0.113 | 17.810 | 0.029 | 0.006 | 0.027 | 0.079 | 0.014 | Op | 00:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/hooks.go:405 | |
| | | | | | | | | | | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/connector.go:31 | |
| | | | | | | | | | | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/connector.go:52 | |
| | | | | | | | | | | 03:/usr/local/go/src/database/sql/sql.go:1294 04:/usr/local/go/src/database/sql/sql.go:1616 | |
| | | | | | | | | | | 05:/usr/local/go/src/database/sql/sql.go:1598 06:/usr/local/go/src/database/sql/sql.go:1612 | |
| | | | | | | | | | | 07:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:363 | |
| | | | | | | | | | | 08:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:685 | |
| | | | | | | | | | | 09:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:328 | |
| | | | | | | | | | | 10:/home/isucon/isutrain/webapp/go/main.go:1191 11:/usr/local/go/src/net/http/server.go:2042 | |
| | | | | | | | | | | 12:/home/isucon/go/pkg/mod/[email protected]+incompatible/dispatch.go:17 | |
| | | | | | | | | | | 13:/home/isucon/go/pkg/mod/[email protected]+incompatible/mux.go:74 | |
| | | | | | | | | | | 14:/usr/local/go/src/net/http/server.go:2843 15:/usr/local/go/src/net/http/server.go:1925 | |
| | | | | | | | | | | 16:/usr/local/go/src/runtime/asm_amd64.s:1374 | |
| 1215 | 0.000 | 0.225 | 10.078 | 0.008 | 0.000 | 0.001 | 0.132 | 0.026 | Qu | 00:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/hooks.go:447 | SELECT * FROM reservations |
| | | | | | | | | | | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/conn.go:264 | WHERE date=? AND train_class=? |
| | | | | | | | | | | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/conn.go:296 | AND train_name=? FOR UPDATE |
| | | | | | | | | | | 03:/usr/local/go/src/database/sql/ctxutil.go:48 04:/usr/local/go/src/database/sql/sql.go:1643 | |
| | | | | | | | | | | 05:/usr/local/go/src/database/sql/sql.go:3284 06:/usr/local/go/src/database/sql/sql.go:1638 | |
| | | | | | | | | | | 07:/usr/local/go/src/database/sql/sql.go:2375 08:/usr/local/go/src/database/sql/sql.go:2380 | |
| | | | | | | | | | | 09:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:433 | |
| | | | | | | | | | | 10:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:670 | |
| | | | | | | | | | | 11:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:427 | |
| | | | | | | | | | | 12:/home/isucon/isutrain/webapp/go/main.go:1714 13:/usr/local/go/src/net/http/server.go:2042 | |
| | | | | | | | | | | 14:/home/isucon/go/pkg/mod/[email protected]+incompatible/dispatch.go:17 | |
| | | | | | | | | | | 15:/home/isucon/go/pkg/mod/[email protected]+incompatible/mux.go:74 | |
| | | | | | | | | | | 16:/usr/local/go/src/net/http/server.go:2843 17:/usr/local/go/src/net/http/server.go:1925 | |
| | | | | | | | | | | 18:/usr/local/go/src/runtime/asm_amd64.s:1374 | |
| 190 | 0.007 | 0.073 | 6.532 | 0.034 | 0.007 | 0.032 | 0.069 | 0.014 | Op | 00:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/hooks.go:405 | |
| | | | | | | | | | | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/connector.go:31 | |
| | | | | | | | | | | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/[email protected]/connector.go:52 | |
| | | | | | | | | | | 03:/usr/local/go/src/database/sql/sql.go:1294 04:/usr/local/go/src/database/sql/sql.go:1616 | |
| | | | | | | | | | | 05:/usr/local/go/src/database/sql/sql.go:1598 06:/usr/local/go/src/database/sql/sql.go:1612 | |
| | | | | | | | | | | 07:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:363 | |
| | | | | | | | | | | 08:/home/isucon/go/pkg/mod/github.com/jmoiron/[email protected]/sqlx.go:685 | |
コールトレースがとても長いが、よく見ると関係あるのはwebappの中にあるコードだけなので、これをフィルタする。
$ aquery -group=fullct -match-ct=webapp isu9f1.gz | head -20
+-------+-------+-------+--------+-------+-------+-------+-------+-------+----------+-------------------------------------------------+--------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STD | K | CALLTRACE | DESC |
+-------+-------+-------+--------+-------+-------+-------+-------+-------+----------+-------------------------------------------------+--------------------------------+
| 3244 | 0.000 | 0.086 | 23.214 | 0.007 | 0.000 | 0.001 | 0.056 | 0.014 | Cl,Op,Qu | 00:/home/isucon/isutrain/webapp/go/main.go:1695 | SELECT * FROM seat_master |
| | | | | | | | | | | | WHERE train_class=? AND |
| | | | | | | | | | | | car_number=? AND seat_row=? |
| | | | | | | | | | | | AND seat_column=? AND |
| | | | | | | | | | | | seat_class=? |
| 2156 | 0.000 | 0.113 | 20.182 | 0.009 | 0.000 | 0.001 | 0.059 | 0.015 | Cl,Op,Qu | 00:/home/isucon/isutrain/webapp/go/main.go:1191 | SELECT * FROM train_master |
| | | | | | | | | | | | WHERE date=? AND train_class=? |
| | | | | | | | | | | | AND train_name=? |
| 1215 | 0.000 | 0.225 | 10.078 | 0.008 | 0.000 | 0.001 | 0.132 | 0.026 | Qu | 00:/home/isucon/isutrain/webapp/go/main.go:1714 | SELECT * FROM reservations |
| | | | | | | | | | | | WHERE date=? AND train_class=? |
| | | | | | | | | | | | AND train_name=? FOR UPDATE |
| 1617 | 0.000 | 0.073 | 9.113 | 0.006 | 0.000 | 0.001 | 0.054 | 0.012 | Cl,Op,Qu | 00:/home/isucon/isutrain/webapp/go/main.go:354 | SELECT * FROM `users` WHERE |
| | | | | | | | | | | 01:/home/isucon/isutrain/webapp/go/main.go:1386 | `id` = ? |
| 3794 | 0.000 | 0.141 | 6.520 | 0.002 | 0.000 | 0.001 | 0.009 | 0.005 | Qu | 00:/home/isucon/isutrain/webapp/go/main.go:1828 | SELECT * FROM |
| | | | | | | | | | | | seat_reservations WHERE |
| | | | | | | | | | | | reservation_id=? FOR UPDATE |
| 7977 | 0.000 | 0.033 | 5.515 | 0.001 | 0.000 | 0.001 | 0.004 | 0.001 | Cl,Op,Qu | 00:/home/isucon/isutrain/webapp/go/main.go:687 | SELECT departure FROM |
次に-group=fullctを外す。これで「コールトレース全体」ではなくて「実際に SQL クエリを発行している場所」で集計できる。ついでに-short-ctオプションを使って、表示するのはファイル名だけにする。これは表示だけの問題で、集計の方法には影響を与えない。また、クエリの列の幅を大きくするため適当に-colオプションを指定する。
$ aquery -match-ct=webapp -short-ct isu9f1.gz -col=100 | head -20
+-------+-------+-------+--------+-------+-------+-------+-------+-------+-------+--------------+------------------------------------------------------------------------------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STD | K | CALLTRACE | DESC |
+-------+-------+-------+--------+-------+-------+-------+-------+-------+-------+--------------+------------------------------------------------------------------------------------------------------+
| 1012 | 0.000 | 0.086 | 20.498 | 0.020 | 0.000 | 0.015 | 0.071 | 0.020 | Cl,Op | main.go:1695 | |
| 736 | 0.000 | 0.113 | 17.818 | 0.024 | 0.000 | 0.025 | 0.077 | 0.017 | Cl,Op | main.go:1191 | |
| 708 | 0.000 | 0.076 | 11.559 | 0.016 | 0.000 | 0.008 | 0.065 | 0.018 | Cl,Op | main.go:354 | |
| 1215 | 0.000 | 0.225 | 10.078 | 0.008 | 0.000 | 0.001 | 0.132 | 0.026 | Qu | main.go:1714 | SELECT * FROM reservations WHERE date=? AND train_class=? AND train_name=? FOR UPDATE |
| 3794 | 0.000 | 0.141 | 6.520 | 0.002 | 0.000 | 0.001 | 0.009 | 0.005 | Qu | main.go:1828 | SELECT * FROM seat_reservations WHERE reservation_id=? FOR UPDATE |
| 7797 | 0.000 | 0.031 | 5.374 | 0.001 | 0.000 | 0.001 | 0.004 | 0.001 | Qu | main.go:687 | SELECT departure FROM train_timetable_master WHERE date=? AND train_class=? AND train_name=? AND |
| | | | | | | | | | | | station=? |
| 2180 | 0.001 | 0.035 | 5.329 | 0.002 | 0.001 | 0.002 | 0.009 | 0.002 | Qu | utils.go:64 | SELECT * FROM seat_master WHERE train_class=? AND seat_class=? AND is_smoking_seat=? |
| 787 | 0.003 | 0.127 | 4.165 | 0.005 | 0.003 | 0.004 | 0.014 | 0.005 | Ex | main.go:2136 | INSERT INTO `users` (`email`, `salt`, `super_secure_password`) VALUES (?, ?, ?) |
| 3412 | 0.000 | 0.040 | 4.073 | 0.001 | 0.000 | 0.001 | 0.017 | 0.003 | Qu | main.go:354 | SELECT * FROM `users` WHERE `id` = ? |
| 5026 | 0.000 | 0.032 | 3.788 | 0.001 | 0.000 | 0.001 | 0.005 | 0.001 | Qu | main.go:704 | SELECT arrival FROM train_timetable_master WHERE date=? AND train_class=? AND train_name=? AND |
| | | | | | | | | | | | station=? |
| 398 | 0.000 | 0.204 | 2.987 | 0.008 | 0.000 | 0.001 | 0.132 | 0.025 | Ex | main.go:1925 | INSERT INTO seat_reservations (reservation_id, car_number, seat_row, seat_column) VALUES (?, ?, ?, |
| | | | | | | | | | | | ?),(?, ?, ?, ?) |
| 2232 | 0.000 | 0.026 | 2.716 | 0.001 | 0.000 | 0.001 | 0.008 | 0.002 | Qu | main.go:1695 | SELECT * FROM seat_master WHERE train_class=? AND car_number=? AND seat_row=? AND seat_column=? AND |
| | | | | | | | | | | | seat_class=? |
| 1420 | 0.000 | 0.033 | 2.364 | 0.002 | 0.000 | 0.001 | 0.021 | 0.004 | Qu | main.go:1191 | SELECT * FROM train_master WHERE date=? AND train_class=? AND train_name=? |
これでおおよそ傾向がつかめるデータになった。例えばmain.goの 1695 行目などで接続の open/close に時間がかかっていることや、
1714 行目のSELECTが遅いことなどが分かる。
#-groupオプションの詳細
このオプションは結局「どの項目が一致していれば同じ SQL 文であるとみなすか」を指定している。例えば-group=fullctとすればコールトレース全体が一致していて初めて同じとみなすし、
-group=topctとすれば、コールトレースの一番上が一致していれば同じとする。ただしここで考慮するコールトレースは-match-ct（及びエントリを弾くための-inv-match-ct）で指定された正規表現でフィルタした後のものである。
上では-groupオプションのデフォルトはtopctであると言ったが、厳密にはtopct+descである。つまりDESCまで一致する場合にのみ同じとみなす。これによって「同じところで呼ばれているが、中身のクエリが異なる」といった場合を異なるものとして扱える。副作用として、DESCが空文字列のOpenやCloseが同じものと見なされてしまうが、妥協した。
#注釈
-
Go 言語に詳しくないので実際のところ sqlx が内部で
database/sqlを呼んでいるかは知らないが、やったら動いたので多分そう。 ↩