#isucon 8 で惨敗してきました - ps aux

以下のレポートは書いてる途中で力尽きてしまい不完全なものです・・・。あらかじめご了承ください。

2018/09/15(土)にISUCON8に参加して、ボロ負けしてきたのでそのレポートです。

SlackでのやりとりやGitHubのコードをベースに、時間ごとに何をやったかをざっくり書いていきたいと思います。

メンバー

@serinuntius アプリケーション・エンジニア

@dozen (会社の同期) インフラ・エンジニア

@kazasiki (会社の先輩) アプリケーション・エンジニア

面倒なので、このレポートでは敬称略とさせていただきます。

10:00~10:30

ポータルログインして、レギュレーションを読む。同時にSSHのコンフィグを書いてました。

次のようなことを確認しました。

ベンチマーが側の帯域がかなりでかい！
PHPは動かすのにH2Oのコンフィグ書き換えなきゃいけないのか〜大変そうだな〜（まだ、このときはGo実装でもH2Oが動いてるとはしらず・・・。ちゃんと「PHP以外の実装」という言葉がでてきているのにね
GET /initialize は１０秒以内に返す
なお、問題ページの内容はできるだけ最新の状態を反映させる必要がありますが、1秒以内の遅延は許されます。 非同期処理をおすすめするような文言
アプリケーションは全て、保存データを永続化する必要があります。 これも気になった。

あと、ポータルを確認すると、ベンチマーカのIPアドレスが1つしか設定できないので、ロードバランスしないといけないんだろうな〜という話はしていました。

僕が alp, pt-query-diegest,dstat,notify_slack を事前に用意してた温かみのあるコマンドの羅列を直接打って入れましたｗ

僕がGoの初期実装に変更して、ベンチ回すと1194でした。

f:id:serinuntius:20180917083831p:plain

topとかで負荷を確認したところ、すごくMySQLが支配的で、ループとかIndexやばそうだねっていう話をしました。

@kazasiki が、Redisを全台に入れてくれました。

10：30~

@kazasiki のMacがフリーズする

@dozen がホスト名をつけてくれて、今何でログインしているかとか、通信もisu2とかでいけるようになる。

@dozenがスペックを貼ってくれる

スペック
CPU: 2コア
MEM: 1GB / swap 2GB

@serinuntius が alpの設定をNginxに入れようと思ったら、H2Oで動いていることに気がつく。

H2O全然わからんし、剥がしてNginx(open resty)で行こう！ってなった。

けど、この判断は結論からいうとミスだったかもしれない。そもそも、H2Oはボトルネックではないし、ちゃんと動いてたし、なんならNginxよりパフォーマンスがいいという話を聞く。 alp形式のログにするのも、ちょっと調べてみるべきだった。

alpでボトルネックを調査して、初動を決めるというムーブが完全にできなくなってしまったので、レコード数の調査やアプリを読むことにした。 @dozenに、Nginx移行を進めてもらいながら、@serinuntius, @kazasikiはアプリを読むという割り振りになった。

MySQLのレコード数やIndexのサイズをパッと出してくれるSQLを、@serinuntiusが出す。

MariaDB [torb]> select
    ->     table_name, engine, table_rows as tbl_rows, avg_row_length as rlen,
    ->     floor((data_length+index_length)/1024/1024) as allMB, #総容量
    ->     floor((data_length)/1024/1024) as dMB, #データ容量
    ->     floor((index_length)/1024/1024) as iMB #インデックス容量
    ->     from information_schema.tables
    ->     where table_schema=database()
    ->     order by (data_length+index_length) desc;
+----------------+--------+----------+------+-------+------+------+
| table_name     | engine | tbl_rows | rlen | allMB | dMB  | iMB  |
+----------------+--------+----------+------+-------+------+------+
| reservations   | InnoDB |   192507 |   57 |    15 |   10 |    4 |
| users          | InnoDB |     5173 |  307 |     1 |    1 |    0 |
| sheets         | InnoDB |     1229 |   53 |     0 |    0 |    0 |
| administrators | InnoDB |      101 |  162 |     0 |    0 |    0 |
| events         | InnoDB |       21 |  780 |     0 |    0 |    0 |
+----------------+--------+----------+------+-------+------+------+
5 rows in set (0.01 sec)

11:00 ~ アプリを読んでみる

@kazasikiとわいわいしながら、「何これ糞すぎ」「なにこれヤバイ」といいながらアプリを読んでいると、いくつかこれは確実にボトルネックになるであろうヤバポイントがあった。

getEvent, getEventsの「N+1」

こんだけの箇所で、getEventが呼ばれていた↓。

f:id:serinuntius:20180917090542p:plain

これを直すだけでも、だいぶ良さそう。

SHA2 の計算をわざわざMySQLに問い合わせて計算してもらっている

それ自体はそんなに重くないかもだけど、回数が多くなるとレイテンシが乗るしかなり無駄。

@kazasiki がざっと読んで、こんなメモを残していた。(原文ママ

* [ループクエリ]func getEventsからfunc getEventを読んでいて、getEvent内でsheetsやreserveを引いてる

* 455行目totalPriceが毎回reserveをgroupbyしてsum()してるからまずい

* 385行目/509行目でpasswordのsha2変換をmysqlにやらせている

* 517行目でuserをもう一回引いてるけど無駄？

* 533行のsanitizeEventはオブジェクトコピーがいらない気がする

• 167行目のgetLoginUserが毎回ユーザ情報をdbから引いている

11：30〜

@dozenのNginxへの移行が終わり、やっとalpでの集計ができた。ちなみにNginxへ移行してスコアが200点ほど落ちた。

こんな感じのコマンドを叩いてました。

[root@118-27-24-38 nginx]# cat access.log |alp --aggregates="/api/users/.*, /api/events/.*/sheets/.*/.*/reservation, /admin/api/events/.*/actions/edit"|less

f:id:serinuntius:20180917091955p:plain