ISUCON13参加ログ
はじめに
素敵な夜ですね。
今回ISUCON13に一人で参加し、約680チーム中約380位でした。初期値に対して2倍のチューニングができました。
とても楽しかったです。
任意のステークホルダーにありがとうございました。
下記はログです。
どんな準備をしたか
- 一年半ほど前にISUCON本を読みました。
- 一年ほど前にvagrantイメージでISUCON予選数回の解説見ながらの素振りをしました。
- 三ヶ月ほど前に全ISUCONの全ブログ記事を読みました（ISUCON公式に載っている分）。
- 一日前にKOBA789氏のISUCONポータルシミュレートサービスISUNARABEを使って、ISUCON12の素振りをしました。FAILEDでフィニッシュでした。
上記の準備でおおまかな知識はついたといえばついたのですが、実践不足で具体的手順の実行力には欠けました。
当日の流れ
定石通りindexをつけて露払いの後、本体MySQLとDNSどちらに対応するかの選択肢を考えました。DNSは一切触ったことがなく、難しい選択でしたが、DNSをある程度追いかけました。しかし、dnsdistなどによる抜本対策に手をつけきれる知見がなく、追いかけ方が半端になりました。結果、うまく対応できたのはindex2件とN+1解消1件といったところになりました。
なお、当日ログは末尾に全文載せました。
反省
まず、今回の参加それ自体についての反省はなかったです。上位50％以内に入れなかったのは残念ですが、一人で戦い抜けた事を思うと誤差だと思っています。
ただし、さらに上を目指すのであれば、下記を考えています。
- DNSについては小手先はせず、一直線でdnsdistやiptablesの策を考えるのがよかったです。
- 画像DBの解消の必要性すぐわかりましたが、やった事がなかったので捨てました。これは過去問でも頻出であり手を動かしておくのがよかったはずです。
- 一度きりしか無い勝ちを狙いに行くなら、DNSを捨て他に全振りするべきでした。過去でも、メインの主題を放置して本戦出場したチームはいくつかあったはずです。
- ただ、これについては繰り返しですが今回の参加についての反省ではありません。何か手に入るものがあるかもしれないし、何かできることがあるかもしれない以上、一度は組み合ってよかったです。
- 複数人チームであれば上記を並行できましたが、一人チームなので一人でやる必要がありました。
- 素振りのネタは大量に残っているので、来年にかけて実力のギャップを埋めます。
DNS水攻めについてもう少し
対応策は今のところ下記イメージ。
- DNSパフォーマンスで殴る（主にオンメモリ化）
- アプリに組み込む・独自DNSを書く
- 俺はうまく使えませんでしたが、pdnsのBINDモードも使おうと思えば使えたようです
- 水責めに対する無視化
- DNSやそのプロキシで対応
- dnsdist
- アプリに組み込む・独自DNSを書く
- iptablesで対応（更新はコマンドで行う）
- DNSやそのプロキシで対応
- 完全放置（メインテーマが解けない際にそれ以外に全振りするパターンは過去の成績優秀者の中にもあった）
次回目標
次回目標としては、
- また一人参加なら上位30％、その次に上位5％（本戦出場レベル同等）
- チーム参加なら上位5％（本戦出場レベル同等）
を考えています。がんばります。
おわりに
技術の話に飢えており、ぜひmisskeyフォローお待ちしております。@kisihara_c@misskey.cloud
twitterは今あまり見ていませんが、フォローいただけると喜びます。@kisihara_c
当日ログ全文
1003
当日マニュアルを読む
DNSの説明文で嫌な予感、水責め攻撃の記述あり ボトルネックになるところまで踏み込めると嬉しいが…。
MySQLなのは嬉しい、ptを入れよう
MySQL再起動手順あり
スコアは投げ銭機能
1028
AWSに手間取ったが入った、まずベンチマーク
ベンチマークしながらブラウザ確認、git
1037
hostsファイルの上書きで手間取ったが設定完了、twitchだこれ
自由にサブドメインを設定できるサイト、これは確かにDNSがボトルネックになりそうだ
イメージは固まった、多分
1042
アプリケーション仕様確認、おそらくユーザーアイコン画像はキャッシュできるが、ボトルネックになるまで踏み込めるか
というかCDN対応はいい加減頻出だし、無意味選択肢なんじゃないかこれ
とはいえクソデカ画像とか載ってたらもちろん重いか
POST /api/livestream/7531/livecomment へのリクエストに対して、期待されたHTTPステータスコードが確認できませんでした
は無視でいいとの事 なんだろう
1055
コードをざっと見た限り、行数はいつもと変わらない、やれる事を多くしたんだったら、おそらくDNSやCDNの件も来るだろうな
topを回してみる
mysqldが最初80％くらいで途中から160％くらいに行ってる、とりあえずmysqlの改善でよさそう
なにか後半から重い処理が来るのか、それとも単純に初期だとそう見えるだけか？
名前解決数が出てる、初期は2512
例のDNS攻撃が来るのが後半ってことだろうか
1111
alpとpt入れる
alpではiconが重い、mysqlに入れてんじゃないか？ あとはlive周りが重い、直す必要がある
/api/user/[0-z]+/icon
/api/livestream/[0-z]+
/api/livestream/[0-z]+/livecomment
/api/livestream/[0-z]+/reaction
ptでは下記が重い
SELECT * FROM livestream_tags WHERE livestream_id = 圧倒的に重い、10msごえも
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and name='o3qur5f85kj3zg3dvmowxjydc9f0.u.isucon.dev' and domain_id=2\G 1msメイン、満遍なく重い
SELECT image FROM icons WHERE user_id = 1016\G 1msメイン、満遍なく重い
4位5位はtipのcountやらsumやらがなんとなく重いようだが、今は気にしなくて良さそう
第2位、これDNSか…意外と早く潰す必要が出るのかも…
1155
ボードを見たら0点ユーザーや初期状態より悪いユーザーがまあまあ多い
初期状態より悪いユーザーは別言語？
普段からこんなもんなのか、なにか落とし穴があるのか…
1156
やっぱりimageがlongblobに入ってる、過去問そのままで、こんなに頻出ならちゃんとやっておけばよかった
alp一位とslowquery一位どっちを優先するかは問題だが、一旦slowquery一位を優先するか
alp一位はCDNとの絡みも絡んでるのでアレ
現時点計画：slowquery上位→alp一位（CDN対応（→blob剥がし、は無理そうだが…））→（DNS含み何かできたら）→2台構成
1216
ボード上、上位40％だ…何かあったら終了時刻までにリセットしよう
現時点計画：1600時点で2台構成化目標、1700時点FAILEDならリセット（触ってないサーバーがあるならそこへ）
1224
slowquery一位対処
DB変更のうまい永続化がよくわからない、説明書にDBリセット手順はあるけど、これは多分ミスったときのものだろうし…
10_schema.sqlに書くしかないと思うが、どこで使われるのかよくわからないなこれ…ベンチマーカーが使うのかなあ
とりあえず10_schema.sql書く＋手打ちで対応
やっぱinitializeが呼ばれるみたいなので2台構成はinit.shからいけそう
1248
slowquery一位対処完了、スコアは4963
topの支配率は変わらず。
alpの順位はほぼ変わってない、
/api/livestream/[0-z]+
/api/livestream/[0-z]+/livecomment
が変わったくらい
pt-query-digestを見てみる、まだ重い。
見ると、一部は軽くなったようで処理が多くできているが、まだ10msが多い。なんでだろう。
# Query 1: 64.29 QPS, 1.71x concurrency, ID 0xF7144185D9A142A426A36DC55C1D2623 at byte 18830586
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2023-11-25T02:46:10 to 2023-11-25T02:47:42
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 11 5915
# Exec time 32 157s 2ms 107ms 27ms 51ms 17ms 28ms
# Lock time 8 35ms 0 10ms 5us 1us 167us 1us
# Rows sent 19 20.60k 0 11 3.57 4.96 1.85 4.96
# Rows examine 58 62.75M 10.71k 11.06k 10.86k 10.80k 181 10.80k
# Query size 1 323.24k 53 56 55.96 54.21 0.17 54.21
# String:
# Databases isupipe
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ###################
# 10ms ################################################################
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isupipe` LIKE 'livestream_tags'\G
# SHOW CREATE TABLE `isupipe`.`livestream_tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM livestream_tags WHERE livestream_id = 7522\G
# Query 1: 14.57 QPS, 0.35x concurrency, ID 0xF7144185D9A142A426A36DC55C1D2623 at byte 9283863
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2023-11-25T03:39:17 to 2023-11-25T03:47:07
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 5 6847
# Exec time 18 167s 1ms 137ms 24ms 51ms 17ms 26ms
# Lock time 3 24ms 0 5ms 3us 1us 68us 1us
# Rows sent 12 24.75k 0 11 3.70 4.96 1.83 4.96
# Rows examine 40 67.32M 0 11.06k 10.07k 10.80k 2.79k 10.80k
# Query size 0 374.22k 53 56 55.97 54.21 0.15 54.21
# String:
# Databases isupipe
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ##########################
# 10ms ################################################################
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isupipe` LIKE 'livestream_tags'\G
# SHOW CREATE TABLE `isupipe`.`livestream_tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM livestream_tags WHERE livestream_id = 7527\G
+----+-------------+-----------------+------------+------+----------------------+----------------------+---------+-------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+-----------------+------------+------+----------------------+----------------------+---------+-------+------+----------+-------+
| 1 | SIMPLE | livestream_tags | NULL | ref | lts_livestreamid_idx | lts_livestreamid_idx | 8 | const | 5 | 100.00 | NULL |
+----+-------------+-----------------+------------+------+----------------------+----------------------+---------+-------+------+----------+-------+
indexはちゃんと使われているはずだ。
呼び出し回数がおかしい気がするのでN+1があるにせよ、10msかかるのに説明がつかない。
変なロックでもかかってるのか…？ アプリケーションコードを見るか…？
アプリケーションコード、すんごいN+1になってる、とりあえずこれ解くしかないかな？
fillLivestreamResponseはほかファイルからも呼ばれてるし絶対に弄りたくない、新しい関数を生やすか
ただ10msかかる理由が説明付かない、それともこんなもんだっけ…？
1357
N+1解除中にベンチマーク異常。身動きができなくなったので、blobの件やslowquery第二位など見て時間つぶし。
private-isuとuser_handler.goを見たが、imageはやっぱDB直保存だし、
それをうまく静的ファイルに置き直す知識等の記載も少ない。
手は出せないか、やってもキャッシュまでか。
現時点計画：slowquery上位→alp一位（CDN対応（blob剥がしはやらない））→（DNS含み何かできたら）→2台構成
slowquery第二位だが、どこで初期化しているかわからず、謎…
init_zone.sh以外にスクリプトが見当たらず。
ファイルをそのまま突っ込んでるってことなんだろうか？
アプリとかにも一切記載がない。おそらくpdns側の問題というか、pdns側が内部でmysqlを使ってる気がする。
おそらくindexをつけるみたいな話ではなさそう。
# Query 2: 13.49 QPS, 0.13x concurrency, ID 0x42EF7D7D98FBCC9723BF896EBFC51D24 at byte 12118529
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:39:17 to 2023-11-25T04:03:25
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 11 19528
# Exec time 14 183s 1ms 72ms 9ms 21ms 7ms 8ms
# Lock time 5 65ms 0 13ms 3us 1us 101us 1us
# Rows sent 1 4.17k 0 1 0.22 0.99 0.41 0
# Rows examine 11 25.95M 1.25k 1.46k 1.36k 1.39k 53.98 1.33k
# Query size 3 2.63M 129 222 141.26 158.58 11.55 136.99
# String:
# Databases isudns
# Hosts localhost
# Users isudns
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms ####################################################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isudns` LIKE 'records'\G
# SHOW CREATE TABLE `isudns`.`records`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and name='x3gskf8t3s8q20.u.isucon.dev' and domain_id=2\G
対処としてはオンメモリ化になるのではないか。試してみよう。
dnsdistというのもあるらしいが流石に導入は厳しい。
現時点計画：N+1→DNSオンメモリ化試す→（alp一位（CDN対応（blob剥がしはやらない））→何ができたら→）2台構成
※オンメモリ化だが、残り時間によってはDNSを別サーバーに逃がすのみもありかも
1449
tagのみN+1を解除。
スコア5104。変わらずか、微増か。topも変わらず。
DNSでタイムアウトが発生してる。名前解決数は2200で変わらず。
alpのログは、tagのN+1で明らかに順位変化。
/api/user/[0-z]+/icon | 0.004 | 0.788 | 172.095
/api/livestream/[0-z]+/livecomment | 0.004 | 1.264 | 112.863
/api/user/[0-z]+/statistics | 5.132 | 20.004 | 107.089
/api/livestream/[0-z]+/reaction | 0.012 | 1.276 | 96.605 |
以下livestream系が団子
pt-queryからは明らかに消えてる。
1位image、2位dns、3位謎join。これはもうN+1は対応不要だろう。
一旦livestream側の、つまり根本のN+1への対応は止め、DNSオンメモリ化やalp一位への対応を行う。
後一時間でどこまでできるか。
DNSで重いのはコレ。
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and name='psz7rawy0oxmd7wul5ilr7bdq8cu2190.u.isucon.dev' and domain_id=2\G
alp一位でどうするかというとキャッシュレスポンス化か。
alpの件はアプリ側なのでなんとかなりそう、DNSの設定をいじる方が先か。
DNSの件の対応は、DNSキャッシュ化、MYSQL設定弄り、DNS水攻めに対する失敗返答など考えられるか。
DNS水攻めに対する失敗返答はひょっとしたらdnsdistっぽいかも。一旦考えるのを止める。
1510
DNS対応。
まずmysqldumpを取る。元となってるzoneファイルもバックアップする。
pdnsのドキュメントを確認。
キャッシュ化とMySQL設定弄りどっちが先か考える。
難しそうかつ手間の少ないキャッシュ化を先にやる。
pdns.confを見る。丁寧にデフォルトではいくらか数字があるttl系が0になっている。意図を感じる。
launch=bindという設定を試すがうまくいかない。mysqlの設定を呼び出そうとしていると言われる。
opt/init_zone_once.shというのを見つけたが、この中にはない。
/etc/powerdns/pdns.d/の方にあった。消した。
原因不明で落ちた。メモリ不足を疑い、対処不能と考える。切り戻しmysql策を取る。
1618
mysql策完了。エラーで落ちる他に考えられる事としては、むしろアクセスが詰まるようになる等か。
score3989。やはり、水攻め負荷があがっているログがある。
topは変わらず。水攻め前は少し負荷がマシになっている気もするが。
alpは変わらず。
pt-queryからはpdnsのクエリが消滅。よし。
これをロールバックする事はしない。やるべきではない逃げだと考える。
mysql支配のいま時点で2台構成にしても無駄と判断。このまま行く。最悪1台構成でも全力を出せたと考える。
pdnsキャッシュを有効化しよう。
16??
pdnsキャッシュの有効化。バックアップを取ってから、数字をいじられてるttl系の設定を全部戻す。
スコアは3726 名前解決65000
かなり耐えられている気がするし、水攻め負荷レベルは２倍に上がっているが、依然mysqlCPU使用率は100を超え、スコアは下がる。
こうなると、不必要で過剰な対処だったようだ。数時間かけてでも、dnsdistを入れるべきだった。
切り替えて考える。この時点で複数台構成にしても意味がないし、imageとかもたかが知れてるのではないか？
dnsdist導入か、imageのキャッシュ化か。
dnsdist導入は流石に無理だと考える。残り一時間はimageのキャッシュ化で使う。
キャッシュの有効化は戻す。水攻めレベルを下げる。
1651
pt-query一位の対処。
# Query 1: 152.95 QPS, 1.78x concurrency, ID 0x84B457C910C4A79FC9EBECB8B1065C66 at byte 36390347
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2023-11-25T07:21:49 to 2023-11-25T07:22:49
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 18 9177
# Exec time 30 107s 1ms 75ms 12ms 28ms 9ms 9ms
# Lock time 4 31ms 0 5ms 3us 1us 69us 1us
# Rows sent 9 7.90k 0 1 0.88 0.99 0.32 0.99
# Rows examine 3 1.35M 2 255 153.92 234.30 64.25 158.58
# Query size 1 393.43k 41 44 43.90 42.48 0.20 42.48
# String:
# Databases isupipe
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms #############################################################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isupipe` LIKE 'icons'\G
# SHOW CREATE TABLE `isupipe`.`icons`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT image FROM icons WHERE user_id = 1057\G
まずCREATE INDEX is_userid_idx ON icons(user_id);
score 5696 名前解決成功数 9465
topは変わらず
alp変わらず
pt-queryからは消滅。おそらく、クエリではなくmysqlからのblob読み込みに移った。
2台構成化と、キャッシュ化どちらにするか。
残り１時間なら、慣れているしrevertしやすいキャッシュ化にする。こちらが全力を出す選択肢だと考える。
キャッシュの方法はカラムに入れたりredisに入れたいところだがsqlにする。時間がない。
1737
キャッシュ機構作成完了。
ギリギリロールバック等も間に合う時刻か。
topは依然としてmysql支配的。おそらくこの状態で2台構成にしても無意味。
ただしalpは変わらず。バグを出してないとしたら、これはおそらくアクセス量が少なすぎてキャッシュを持ったレスポンスが飛んできてないか。
ここまでとする。
1753
キャッシュ機構はロールバック（git stash）。
再起動してベンチマークをパス。
最終スコアは6047。
手数不足と知識不足（dnsdist）があり非常に悔しいが（dns完全無視でも決勝進出レベルに行けた説があり、そうなると完全に手数不足）、2倍のチューニングには成功した。
694組中上位何％だろうか。
Discussion