ISUCON4 に GoMiami チームとして去年と同じメンバの @SpringMT と @niku4i と自分(@sonots)で参加してきた。名前だけ Miami から GoMiami に変えた。

事前戦略

優勝賞金100万円!今年もやります 第4回 ISUCON 開催と日程のお知らせ #isucon

  • 予選はAmazon Web ServiceのEC2を利用
  • 出題者側で作成したお題アプリ、ベンチマークツールが乗ったマシンイメージを公開

と書いてあったので、去年と同じような形式かな、とこの時点で勘ぐっていた。

ruby だと GVL があるので、マシン1台でも複数プロセス立ち上げる必要があって、そうなるとキャッシュ戦略進めるときに redis を使ってマルチプロセス間メモリ共有とかする必要があるけど、golang なら1プロセスでもコアを有効に使い切れるので、マシン1台だったらグローバル変数にでも保存してアプリ内のメモリに載せちゃえばいいだけだし、単体でも速いので、予選最強言語なんじゃないか?とか思って、勉強もかねて golang で出る事にした。

ISUCONすでに始まっている。

事前準備

nginx.conf や my.cnf のチートシートなんかはあらかじめ作っておいて、メンバに共有してた。

あと、golang でも ruby で newrelic 使ってやっていた時みたいに、HTTPリクエストにかかった時間、DBへのクエリでかかった時間、テンプレートの処理にかかった時間、I/Oでブロックされた時間、とか見れないものかと、golang の勉強がてらプロファイラ調べたりメトリクスライブラリ作ったりしてた

作ったメトリクスライブラリについては別の記事にしているのでそちらを見てもらいたい => golang で sql, template, http リクエストのパフォーマンスメトリクスとるライブラリ作った #isucon

当日(午前中)

午前中はメトリクスとったり、アプリの動作把握、戦略を立てる時間にあてた。これは去年の反省を活かしている。

インフラ担当の @niku4i に公開鍵とかミドルウェアのセットアップとかメトリクス取るための準備とかやってもらって、自分はまずアプリにメトリクス計測コード仕込むのやってから golang のコード読んで、SpringMT 氏は ruby のコード読んでアプリの仕様把握とかやってた(ruby のほうが一枚のファイルに書いてあってシンプルで読みやすいとか言い訳してた)

午前中にとったメトリクスはこんなかんじだった(全体はこちら)

nginx アクセスログ集計(自作スクリプト)。

sum(sec)                count   mean(sec)               endpoint
49.86099999999994       812     0.06140517241379303     /login
19.007  1       19.007  /report
4.347999999999992       178     0.024426966292134786    /mypage
1.4199999999999682      1624    0.0008743842364531824   /images/isucon-bank.png
1.2739999999999734      1446    0.0008810511756569664   /
1.2629999999999764      1624    0.0007777093596058967   /stylesheets/isucon-bank.css
1.2209999999999812      1624    0.0007518472906403826   /stylesheets/bootstrap.min.css
1.1919999999999826      1624    0.0007339901477832405   /stylesheets/bootflat.min.css

クエリ集計 (mysqldumpslow)

Count: 812  Time=0.03s (25s)  Lock=0.00s (0s)  Rows=1.0 (812), root[root]@localhost
  SELECT COUNT(N) AS failures FROM login_log WHERE ip = 'S' AND id > IFNULL((select id from login_log where ip = 'S' AND succeeded = N ORDER BY id DESC LIMIT N), N)

Count: 805  Time=0.03s (20s)  Lock=0.00s (0s)  Rows=1.0 (805), root[root]@localhost
  SELECT COUNT(N) AS failures FROM login_log WHERE user_id = N AND id > IFNULL((select id from login_log where user_id = N AND succeeded = N ORDER BY id DESC LIMIT N), N)

Count: 4037  Time=0.00s (17s)  Lock=0.00s (0s)  Rows=1.0 (4037), root[root]@localhost
  SELECT COUNT(N) AS cnt FROM login_log WHERE user_id = N AND N < id

以下略

明確に /login と上3つのクエリが遅くて、コードを読むと、クエリ1つ目は isLockedUser という /login 時に user_id ベースのユーザがロックされているか判定しているメソッド、クエリ2つ目はisBannedIp という /login 時に IP が Ban されているか判定しているメソッド、クエリ3つ目はbannedIPs という /report で使われている所だったのでチューニングしなくてよさそう、ということが分かった。

また、クエリ1つ目、2つ目はどうやらログイン失敗回数を数えているだけっぽい。ということがわかった。

この時点で、1回ミーティング開いて、どういうアプリかシェアしたり、どういう戦略でいくか決めたりしてた。この時に出たアイデアはこんなかんじ

  1. 起動のタイミング(init.sh)で login_log テーブルを読み込んで failure count の構造体に突っ込んでオンメモリキャッシュさせる。1分の制約があるけど間に合うかどうかまずはやってみる。
  2. login_log テーブルへの insert のところ(/login)で、failure count++ するか reset するかロジックを入れる。
  3. isLockedUser と isBannedIp でキャッシュを参照するように書き換える。キャッシュにヒットしなかったら今まで通りのコードに通して1回だけ SELECT してキャッシュするようにする(1. がうまくいかなかった時用)
  4. ユーザデータを丸ごとキャッシュ
  5. Last Login をキャッシュ
  6. レギュレーションに静的ファイルの md5 が違っても加点されないだけで失格にならないと意味深なことが書いてあるしいじってみる?

1 〜 3 が支配的で、4 以降はそんなに効かないだろうなって認識だった。

当日(午後)

昼飯食べながらコードもくもく読んで、キャッシュの構造体とか考えて、実装しはじめた。

担当は最初、次のように決めてからスタートした。

  • (sonots) 1. の実装
  • (SpringMT) 2., 3. の実装
  • (niku4i) 残りのミドルウェア設定(nginx で静的ファイル返すとか)とテーブルにインデックス貼る作業(init.sh)

1. 起動時の failure count のキャッシュ

最初、users テーブルから user_id とりだして、全ユーザの failure count 計算の SELECT 文発行する、って愚直に書いてみたら全然終わらなかった。

SpringMT 氏がアイデアがあるって言って、login_log テーブルに記録されている user_id だけ取り出すように書き換えて(実際はもうちょいクエリ頑張ってある)、すぐフィニッシュするようになった。ナイス。

2. 3. /login での failure count のキャッシュ

SpringMT 氏から実装があがって来てたんだけど、なんか fail するって言われて 1. はまかせてこっちのバグ取りしてた。

attemptsLogin の中に defer があって、途中で return もされているので、attemptsLogin の一番下でキャッシュするのではなくて、defer の中でキャッシュしないといけなかった。

あと、isLockedUser のほうの閾値が IPBanThreshold に変わっててそれに気づかなくてハマってた。 静的片付け言語とはいえ、コンパイル通っちゃうし、golang でブレークポイント貼ってデバッグする方法がないから(gdb?)、printf デバグやってて時間かかった。簡単に使えるデバッガ欲しい!

大分もたもたしてて最初の実装が終わったのが 15:00 になってからで、ここで 17000 ぐらい。 完全に実装がおわって 30000 いったのが、16:00 になってからだった。出遅れた!!って話してた。

16:00

その後 4, 5, 6 もやってみて、38,000 ぐらいだったかな。6. は特に意味なかった。

あとはこの辺で too many open files とか TIME_WAIT なソケットが多すぎるよ的なエラーが出てたから @niku4i が ulimit 設定したり、tcp_tw_recycle を設定したりしてたと思う。その辺信頼してて完全におまかせしてたからあとでブログ書いてくれると思う。

16:50

この時点でもう1度メトリクスとってみた結果がこちら。もうほとんどクエリがないし、アプリにチューニングポイント残ってなくない?って話をしてた。

なのでもう niku4i と SpringMT 氏はミドルウェア側いじってたと思う。ログはずしたりとか keepalive ON/OFF してみたり workload 調整してみたりとかかな。完全におまかせしてたからあとでブログ書いてくれると思う。

自分は、Martini の template をなんとか外せないかともうひと踏ん張りしてた。もう 16:50 なので、Martini 外しはあきらめて top ページだけでもなんとかできないかと頑張って、martini-contrib/render の HTMLメソッドの中身みて、 template を展開している所を、ただの文字列結合にするようにおきかえた TopHTML という ISUCON4 専用のメソッドを生やすとかやった。 renderer が小文字スタートのプライベート構造体になっていて、外からメソッド生やせなかったので、fork して直接書いてやった。Martini マジ fxxk。これを滑り込みで入れてあと 2000 ぐらいあがった。

最後 40,600 ぐらいでフィニッシュした。


golang でやった感想

良かった点

  • 1台である限り、プロセス間メモリ共有しなくてすむのでキャッシュ戦略がすごい楽だった。
  • コンパイル時にチェックしてくれるので typo ミスとかだいぶ防いでもらえた。

悪かった点

  • ruby の byebug みたいにブレークポイントを貼ったデバグが実質できなくてデバグに四苦八苦してた。※ LiteIDE とか使うと IDE 上で breakpoint はったりはずしたりが簡単にできるけど、ISUCON 環境を Mac 上に作る時間なんてなかった
  • err 処理のコード量が多くて見通しが悪かった。ruby 実装のほうがシンプルだった。
  • defer 見逃しててハマってた。golang 特有の複雑さだ、とか言ってた。

競技の感想

良かった点 

  • 去年の反省を活かして、最初にメトリクスをとって戦略会議をやる、という流れで進めたのは良かった。
  • ハマったら交代してカバーし合ってたのはよかった。時間がない中1人でハマり続けると時間だけがすぎるので他の人に目を通してもらったほうが早い。
  • 去年と違って、時間内にやりきった感あった。

改善点

  • 最初もたもたしててスコアが出るまで時間がかかってしまった。瞬発力あげたい。

おわりに

たぶん 40k 〜 45k あたり団子状態で、土曜日1日目は再計測の点数がスコアになるのでマジドキドキしてる。本戦出たい!!!たのむ〜〜

追記:ISUCON4 本戦出場者決定のお知らせ 残った!終わってみれば 41705 点で全体の13位でした。本戦頑張るぞい!!


おわってから試したこと

  • benchmarker v2 で試す
    • benchmarker v1 にバグがあったという経緯があるので、benchmarker v2 ではかりなおしてみたら 43.1k 行った。
    • どうやらインスタンスガチャもあったっぽい。
  • nginx => app を unix domain socket に変える
    • golang 力低くて net/http はサポートしてないし、どうやるんだってなって競技中はできなかったけどやってみた => https://gist.github.com/sonots/87972440cd2063504902
    • やってみたけど、スコアあがらなかった。ポート枯渇対策としては良いと思う。
  • dummy_users.tsv 読み込んで生パスワード持ってきて、calcPasswordHash を避ける
    • 生パスワード見る銀行ってどうなん?とか思いながら一応あとでやってみたけど、全然スコア伸びなかった。
  • mysql のデータ保存先を tmpfs におきかえる
    • ほとんどアクセスない今、全然スコア伸びなかった。
    • ちなみにレギュレーションに「ベンチマーク実行時にアプリケーションに書き込まれたデータは、再起動後にも取得できること。」という規定があるので、シャットダウン時にディスクにコピーして、起動時にディスクから tmpfs にコピーするとかやらないと失格になると思う
  • nginx worker_process の数と GOMAXPROCS をコア数の 4 から 32 にあげる
    • これで 4000 ぐらいあがった。マジか ...
  • MARTINI_ENV=production
    • これで 3000 ぐらいあがった。そんなの知らなかった。Martini マジ fxxk。
  • Martini はずし
    • Martini はずして生の net/http にしてさらに 3000 ぐらいあがった。Martini マジ fxxk。
    • やっぱり golang 歴1ヶ月の自分では時間がかかったので、競技中は無理だったな、という印象。力量にあった判断だった。  
  • template はずし
    • Martini はずしの段階では html/template のままにしてたのをさらに、sprintf に置き換えてみた
    • スコアあがらなかった
  • トップページの静的ファイルを5パターン用意して、nginx で捌く
    • 3000 伸びた。む、そんなものか 

あとやってないもの

  • login_log の INSERT もキャッシュ
    • でもこれも省いてしまうと、レギュレーションの「ベンチマーク実行時にアプリケーションに書き込まれたデータは、再起動後にも取得できること。」という規定を満たせなくて失格になるから、やれるとしてもデータ構造変えるぐらいか?

いま、なんとか 53k いったぐらい。60k への伸ばし方がわからない。



追記: さらに試している

ブログ記事が公開されてきたので、そんな手が!と思ったものを試してみている。

  • INSERT は MyISAM のほうが早いらしいので、MyISAM にしてみる

    • 特に伸びす
  • INSERT を goroutine で逃がす

    • 伸びた気がしたが、もう一度測ったら下がったのでただの誤差っぽい
    • まずは単純に逃がしてみたけど、裏で goroutine の数膨れ上がってそう。ちゃんと1 goroutine 内で遅延実行するようにしないとホントはダメだけど次が本命なので手抜き。
  • login 時はキャッシュにいれるだけにしておいて /report アクセス時にDBに INSERT する

    • 4000 向上。なるほど〜、この発想がなかった。
    • 普通に INSERT したら1分以内に終わらなかったが、bulk insert にしたらちゃんと終わってくれた。
  • user_id をキーにしたキャッシュの構造体を map じゃなくて配列にする

    • fujiwara 組 はそんなところまで気にしているのかと感嘆
    • 手抜きで全部 map にしていたが、たしかに配列のほうが O(1) 確定するので早い。影響でるほどとは思わないけど
    • => 特に伸びなかった
  • ログイン失敗理由の頻度にあわせて switch 文の順番を変える

    • fujiwara 組 はそんなところまで気にしているのかと感嘆
    • しかし、実際は影響出るほどとは思えないがどうだろう
    • => 特に伸びなかった
  • nginx ではなく varnish で静的ファイルを捌く(トップページ含む)

    • 58k から 52k に下がってしまった。
    • varnish => nginx => app と階層が1つ増えてしまったから? nginx のほうでキャッシュ設定ちゃんとやればそれでいい気がする。
  • 標準ライブラリの StaticFileHandler ではなく、 ファイルの内容をメモリ上に置いて Write するだけのハンドラを用意 して golang で直接うける。

    • go-bindata と go-bindata-assetfs でやってみた
    • 3000 落ちてしまった。バイナリデータとしてビルド時に含めるからこれでいけるかと思ったんだけど、あまりパフォーマンス良くないライブラリなのかな ...
  • GOGC=500 で benchmarker 走らせる

    • 16k 伸びたw
  • おもむろに css, img リンクを消す

    • 60k 伸びたww
    • 試したかっただけなので JS は作ってない
  • tcp_fastopen

    • sudo sh -c "echo 0x403 > /proc/sys/net/ipv4/tcp_fastopen"
    • 700 ぐらい伸びたけど、誤差の範囲内か??

現在12万ww

まぁでも後ろの二つを除いて実質 58k かな。60k 超えないのはパラメータ微調整の問題だろうか

その他やるべきだったこと

  • pprof をちゃんとみてメソッド単位で重い処理を特定する
    • methane さんはそれで MARTINI_ENV=production にたどりついたらしい。仕込むだけ仕込んであまり見ないでしまったので反省
  • ベンチマークツールの挙動解析
    • fujiwara 組 はそれで静的ファイルのリンクを削る戦略にいきついたらしい。全く考慮に入れてなかったので反省

そもそもISUCONというのはベンチマークツールをいかに高速に回すかという勝負なのですが、100msかかっていたモノを99msにしてもスコアは1%しかあがらないですが、2msかかっていたモノを1msにすると同じ1msの短縮でもスコア自体は2倍になるんですね。

あ、はい。