NTT Performance Tuning Challenge 2020 参加記
はじめに
2020年9月11日(金)に開催されたNTT Performance Tuning ChallengeにチームКошкаとしてはなかずさんと2人で参加しました。 終了2時間前くらいには結構上位に食い込めていたのですが、最終的にその状態に復元することが出来ず、結果正の得点を取ったチームの中で下から2番目となってしまいました。
とはいえ、今回のイベントにおいて学べたことが多かったので、ここに記すことにしました。
学べたこと
Slow Queryの探し方
Slow Queryを探すためにはpt-query-digestを使います。このツールはデータベースのSlow Queryログを解析するツールです。 Slow Queryは下記の記述をmysqldのconfファイルに追記することで出力できます。
slow_query_log = 1 slow_query_log_file = /tmp/slow-query.log long_query_time = 0.1
ここで出力されたログをpt-query-digestに渡すことで、下記のようにSlow Queryをまとめて出力してくれます。
$ pt-query-digest /tmp/slow-query.log # (snip) # Query 1: 2.41 QPS, 0.19x concurrency, ID 0xB09A20EF29F18029 at byte 84332154 # Scores: V/M = 0.07 # Time range: 2020-09-11T04:23:45 to 2020-09-11T04:25:04 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 1 190 # Exec time 51 15s 74us 327ms 78ms 266ms 76ms 48ms # Lock time 3 8ms 14us 381us 42us 98us 37us 31us # Rows sent 0 188 0 1 0.99 0.99 0.10 0.99 # Rows examine 0 188 0 1 0.99 0.99 0.10 0.99 # Query size 0 8.11k 41 46 43.71 42.48 0.54 42.48 # String: # Databases app # Hosts competition-068.c.sys0098096-1-80305617.inte... # Users ptc-user # Query_time distribution # 1us # 10us # # 100us #### # 1ms #### # 10ms ################################################################ # 100ms ###################### # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `app` LIKE 'events'\G # SHOW CREATE TABLE `app`.`events`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT image FROM `events` WHERE `id` = 3128\G
この出力から、SELECT image FROM events WHERE id = 3128に、最長で100[ms]単位を要していることが分かります。
更に、Slow Queryに関連して、カーネルパラメータやコネクション数の調整のような普段は触らない部分を知るきっかけになりました。
遅いエンドポイントの探し方
遅いエンドポイントを探すためには、kataribeが使えます。このツールは、httpサーバのログを解析するツールです。httpサーバのログはNginx等で出力できます。
このツールは、下記の通りtoml形式でフォーマットを指定することでアクセスログをまとめてくれます。
$ sudo cat /tmp/access.log | kataribe -f ./kataribe.toml
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
154 52.263 0.3394 0.4680 0.000 0.245 0.261 0.513 2.890 3.148 11 0 143 0 10662 31 69 399 POST /api/events HTTP/1.1
145 34.146 0.2355 0.0536 0.001 0.242 0.256 0.261 0.440 0.500 0 0 145 0 6920 31 47 55 PUT /api/events/1 HTTP/1.1
1 24.126 24.1260 0.0000 24.126 24.126 24.126 24.126 24.126 24.126 1 0 0 0 4718 4718 4718 4718 GET /api/events?limit=12&offset=889 HTTP/1.1
1 23.876 23.8760 0.0000 23.876 23.876 23.876 23.876 23.876 23.876 1 0 0 0 4791 4791 4791 4791 GET /api/events?limit=12&offset=1028 HTTP/1.1
1 23.483 23.4830 0.0000 23.483 23.483 23.483 23.483 23.483 23.483 1 0 0 0 4492 4492 4492 4492 GET /api/events?limit=12&offset=341 HTTP/1.1
1 23.412 23.4120 0.0000 23.412 23.412 23.412 23.412 23.412 23.412 1 0 0 0 4628 4628 4628 4628 GET /api/events?limit=12&offset=46 HTTP/1.1
1 23.408 23.4080 0.0000 23.408 23.408 23.408 23.408 23.408 23.408 1 0 0 0 4412 4412 4412 4412 GET /api/events?limit=12&offset=1584 HTTP/1.1
37 23.210 0.6273 0.6186 0.001 0.270 1.770 2.035 2.398 2.398 27 0 10 0 291 0 7 35 POST /api/logout HTTP/1.1
(snip)
このログから、GET /api/events?limit=12&offset=889 HTTP/1.1は1回しか呼ばれていないのに、24[ms]もかかっているので、ボトルネックになっている可能性があるなどのことが分かります。
このツールは、出力のどの部分を見れば良いのかよく分からないツールでした。実際に何度か使うと使い方がわかってくると思いますが、最初はこれを見ても見方や使い方がよく分かりませんでした。参考になる資料などありましたら教えていただきたいです。
N+1クエリ
N+1クエリとは、一覧の取得に1回、関連データの取得にN回、計N+1回のクエリを発行する際に起きる性能問題のことです。 これは、先述したkataribeのログを見て、極端に遅いエンドポイントのハンドラに含まれていることが多いです。
N+1クエリとは、下記のようなものです。なお、長くなるのでエラーハンドリングは割愛しています。脳内補完してください。
type Item struct {
Name string
UserName string
}
var items []Item{}
itemRows, _ := dbc.Query("SELECT user_id, name FROM items")
defer itemRows.Close()
for itemRows.Next() {
// idとnameをmap
var userID int
var item Item
itemRows.Scan(&userID, &item.Name);
userRows, _ = dbc.Query("SELECT username FROM users WHERE id=?", userID)
for userRows.Next() {
// UserNameをmap
userRows.Scan(&item.UserName)
items = append(items, resItem)
}
}
ここで、最初のクエリでitemsテーブルから得たrow1行ごとに、usersテーブルにクエリを実行していることが分かります。 このようにrow1行に対して別テーブルに呼び出しを行うことで、テーブルのレコード数が大きければ大きいほど実行時間が長くなるクエリがN+1クエリです。
そして、その改善方法のひとつとして、SQLの問い合わせは全部SQLに任せる、というものがあります。 今回の例でいえば、下記のようにテーブルへの問い合わせを別々に行わず、まとめて問い合わせることになります。
var items []Item{}
itemRows, _ := dbc.Query("SELECT u.name, i.name FROM items i INNER JOIN users u ON i.user_id=i.id")
defer itemRows.Close()
for itemRows.Next() {
// UserNameとnameをmap
var item Item
itemRows.Scan(&item.UserName, &item.Name);
userRows, _ = dbc.Query("SELECT username FROM users WHERE id=?", userID)
for userRows.Next() {
// UserNameをmap
userRows.Scan(&item.UserName)
items = append(items, resItem)
}
}
このように、INNER JOIN句を用いて内部結合を行うことで、各テーブルへの問い合わせをソースコードを介さずに行うことが出来ます。
そのため、直感的に早くなりそうだということが分かるはずです。
今回のイベントでの反省点
一言でいえば、変更点をメモしていなかったことです。 最初にも書いた通り、ちょこちょこ変更を加えている間にベンチに失敗するようになってしまいました。 小さな変更を加えるごとにベンチを回すのが理想だったのかもしれませんが、ベンチが回りきるまでに3分程度かかるので新しい機能の追加に応じてベンチを回すようにしていました。 その結果、新しい機能を追加したらベンチが正常終了しなくなり、元の状態に復帰できなくなってしまいました。
当初は、変更点くらいならGitのコミットで管理すれば良いかなと考えていたのですが、このイベントではソースコードのみならずDBやインフラのように複数変更する部分があります。
Git上では、stable version(1270)というコミットがあったのですが、このコミットにロールバックしてもインフラやDBの状態までは復元できませんでした :cry: 。
そのため、Gitのコミットのみでなく、何時ごろに何をしたかをざっくりとメモしておけばよかったと考えています。もっといい方法があれば教えていただきたいです。
ベンチマーカについて
今回のベンチマーカは、PythonのTevernを使っていたようです。 しかし、テストに失敗したときにそれっぽいログは出力されていましたが、あまり見たことのないフォーマットだったのでどの部分が原因で落ちたのかが分かりにくかったです。 例えば、logoutの機構に関して、ブラウザでは正しく実行できているのにローカルでのベンチでは落ちているというケースも散見されました。 本番中は焦っていたので、ExpectedとAcctualの部分からソースコードのどこがおかしいかをざっくり探していたのですが、今思うと危なかったかな、とも思います。
おわりに
こういうイベント系は、参加記を書くまでがイベントな感じがするので参加記を書きました。 イベント全体を通して、6時間半という長丁場でしたが、ドキュメントや初期設定等に1時間、想定していた3台構成にするまでに1時間、ベンチを回している時間をまとめると30分程度、椅子を温めている時間が1時間と、効果的に手を動かせていたのは1時間程度と、濃い時間だったように思います。とはいえ、その間もソースコードを見ながら雑にインデックスを貼ったくらいで、ドキュメントの情報は殆ど使えていなかったように思います。 その点で言えば、まだまだISUCON初心者だと思うので、また別の機会があればこういったイベントに参加してみたいです。
明日はISUCON10の予選ですが、私は参加権が得られなかったので次回のISUCON11や他のチューニング系イベントで再チャレンジしたいと考えています。 ISUCON11では誰か一緒に出てほしいです。お茶くみくらいならやります。
最後になりますが、運営メンバーの方々、面白いイベントを開催していただき、ありがとうございました。 またこのイベントを開催する可能性があるらしいので、興味のある方は参加してみてはいかがでしょうか。
