Go用SQLスロークエリ解析ツールAqueryを書いてISUCON10の本選に出たらfailした

2020/10/11

# TL;DR

Go用SQLスロークエリ解析ツールAqueryを書いてISUCON10の本選に出たけど、 再起動試験を適当にやったせいでちゃんと起動せずにfailして涙を飲んだり飲まなかったりした。

ISUCON10本選についてはメンバーの梅の仁が詳しく書いてくれているので省略。 一言だけ付け加えておくと、今年は全然戦力になれなかったので申し訳なかった。

以下ではAqueryの話をします。

# 概要

database/sqlを使うGoコードに仕込むことで得られるSQLトレースをよしなに解析してくれるソフトウェアを作った。 GitHubで大公開中。下みたいな画面を出力できる。

/teqblog/2020/10/go%E7%94%A8sql%E3%82%B9%E3%83%AD%E3%83%BC%E3%82%AF%E3%82%A8%E3%83%AA%E8%A7%A3%E6%9E%90%E3%83%84%E3%83%BC%E3%83%ABaquery%E3%82%92%E6%9B%B8%E3%81%84%E3%81%A6isucon10%E3%81%AE%E6%9C%AC%E9%81%B8%E3%81%AB%E5%87%BA%E3%81%9F%E3%82%89fail%E3%81%97%E3%81%9F/aquery-1.png

気分としてはALPのSQLバージョン。現状MySQLだけしか対応していないが、中身を適当にいじればほかのSQLでも対応できるはず。

# 使い方

Goコードでsql.Openを呼んでいるところを次のように改変する。 ちなみに直接database/sqlを呼んでいなくても、 内部でそれを呼び出すライブラリ(sqlx1とか)なら同様に使える。

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/go-sql-proxy@v0.3.0/hooks.go:405                    |                                |
|       |       |       |        |       |       |       |       |       |    | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/connector.go:31                 |                                |
|       |       |       |        |       |       |       |       |       |    | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/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/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:363  |                                |
|       |       |       |        |       |       |       |       |       |    | 08:/home/isucon/go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:685  |                                |
|       |       |       |        |       |       |       |       |       |    | 09:/home/isucon/go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/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/goji.io@v2.0.2+incompatible/dispatch.go:17                                |                                |
|       |       |       |        |       |       |       |       |       |    | 13:/home/isucon/go/pkg/mod/goji.io@v2.0.2+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/go-sql-proxy@v0.3.0/hooks.go:405                    |                                |
|       |       |       |        |       |       |       |       |       |    | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/connector.go:31                 |                                |
|       |       |       |        |       |       |       |       |       |    | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/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/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:363  |                                |
|       |       |       |        |       |       |       |       |       |    | 08:/home/isucon/go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:685  |                                |
|       |       |       |        |       |       |       |       |       |    | 09:/home/isucon/go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/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/goji.io@v2.0.2+incompatible/dispatch.go:17                                |                                |
|       |       |       |        |       |       |       |       |       |    | 13:/home/isucon/go/pkg/mod/goji.io@v2.0.2+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/go-sql-proxy@v0.3.0/hooks.go:447                    | SELECT * FROM reservations     |
|       |       |       |        |       |       |       |       |       |    | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/conn.go:264                     | WHERE date=? AND train_class=? |
|       |       |       |        |       |       |       |       |       |    | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/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/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:433  |                                |
|       |       |       |        |       |       |       |       |       |    | 10:/home/isucon/go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:670  |                                |
|       |       |       |        |       |       |       |       |       |    | 11:/home/isucon/go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/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/goji.io@v2.0.2+incompatible/dispatch.go:17                                |                                |
|       |       |       |        |       |       |       |       |       |    | 15:/home/isucon/go/pkg/mod/goji.io@v2.0.2+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/go-sql-proxy@v0.3.0/hooks.go:405                    |                                |
|       |       |       |        |       |       |       |       |       |    | 01:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/connector.go:31                 |                                |
|       |       |       |        |       |       |       |       |       |    | 02:/home/isucon/go/pkg/mod/github.com/shogo82148/go-sql-proxy@v0.3.0/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/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/sqlx.go:363  |                                |
|       |       |       |        |       |       |       |       |       |    | 08:/home/isucon/go/pkg/mod/github.com/jmoiron/sqlx@v1.2.1-0.20190826204134-d7d95172beb5/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が空文字列のOpenCloseが 同じものと見なされてしまうが、妥協した。


  1. Go言語に詳しくないので実際のところsqlxが内部でdatabase/sqlを呼んでいるかは 知らないが、やったら動いたので多分そう。 ↩︎

このエントリーをはてなブックマークに追加