四年連続四回目の ISUCON は、最初の Perl 実装すらスコアが出ず、Go に変更してアレコレするも終始スコア0のまま終了を迎えるという最高に不甲斐ない結果に終わった。今後に向け、自戒の念をこめて日記を残しておこう。

日記

事前にチームで打ち合わせ。実装は Go で行こう。メンバーの共通言語が Java しか無いし、自分以外は Windows 使い、開発環境を整えやすい Go にしよう。消去法だ。実際、ほぼ初心者な状態でも Go の開発・デプロイ周りを整備するのには時間がかからなかった。いい選択だったと思う。

自分はインフラ等の足回りを引き受ける。Azure のアカウント作成や去年の予選問題を Azure でデプロイして素振りをする。この素振りが当日すごく役に立った。イメージを共有できない Azure では、当日も同じように Azure リソースマネージャーのテンプレートと Ansible によるプロビジョニングで始まる方式だった。素振りのおかげで SSH でサーバに入った直後にソースが見つからなくてパニックになるという事態を回避できた。感謝しかない。

デプロイが完了して今回の課題を見る。元ネタは、はてなキーワード（もしくは、はてな匿名ダイアリー：増田）とはてなスターかな？はてなさん出題だしなー、そうきたかー。このキーワードをリンクに置換してるのは重そうだな。

他のメンバーにはローカルで開発できる環境を整備してソースを読み込んでもらう。自分は足回り担当としてスロークエリの設定・解析 (pt-query-digest) や MySQL パラメータと ulimit のチューニング (Linux VM での MySQL パフォーマンスの最適化 | Microsoft Azure)、アクセスログの解析 (tkuchiki/alp: Access Log Profiler) を進めていこう。この辺りは流石に四回目ともなると慣れてきていい感じ。

ようやく昼頃に環境が整った。ソースを追ってボトルネックになりそうなところを探そう。アクセスログの解析で、/ が壊滅的に重いところまで把握。トップページの処理の中でどこがボトルネックになっているかな？後で思い返すと、このボトルネックの特定が雑だったのが致命的だった。Ruby 実装なら rack-lineprof でどの処理が重いのかしっかり見極めるんだが、Go のプロファイリングツールに良さそうなのが見つからない。ぱっと見、isuda から isutar へ HTTPリクエストでスターを取得している部分が目につく。スター周りの改善をやろう。この時点で、最初にアプリを見た時の直感は忘れさられおり htmlify は放置。今回の敗北を決定付けるミスである。

スター対策として、isuda と isutar を一つのサービスに統合する事も検討。いや、他でも使うだろうし Redis を入れて isuda はそちらを参照するように実装を変えよう。スターにユーザ名が必要なのか確認してみると Go実装でユーザ名を保存してない。他言語の実装だと保存されてるっぽいのになー。これはバグっぽいなと実装を直す。同時に公式のパッチが提供される。やっぱりかー。Redis 化の実装変更とバグ取りは思った以上に時間がかかり、動くようになる頃には17時近くになってしまう。

スター対策がスコアに反映されず、頭を抱える。最後の1時間でスロークエリを潰して悪あがきしよう。CHARACTER_LENGTH(keyword) が重そうなので、keyword_length を別カラムに持つ。ざくっと修正して最後の望みを託すもののこちらもスコアに反映されず無念のタイムアップ。

Go の正規表現が遅いの知らなかったので、みんGo 買います。

感謝

非常に悔しい結果だったけど、今回も非常に楽しい ISUCON でした。運営の皆さんありがとうございました。

反省

推測するな計測せよ

ちゃんとプロファイリングツールで重い処理を特定しないといけなかった
- せめて New Relic ぐらいは入れて置くべきだった
tcpdump でベンチマークツールのリクエスト解析したかった
Nginx での静的ファイル配信をすっかり忘れていた
- 最低限やれることは事前にリストアップしておかないと

作業メモ

おまけで、当日記録していたメモを貼っておく。時間は後で追記したものなのでブレがありそう。

09:00 システム構成の把握

Ansible の yaml が /tmp/isucon6-qualifier/provisioning/image/ansible にあったので読む
画面を見るに、増田とはてなスターっぽいアプリ
systemd を確認
- isuda, isutar, isupam が今回のアプリ名（マイクロサービスだ）

10:00 Go言語に切り替え

systemd にハマる
- stop/start, せず enable/disable だけで切り替えた気になっていた

10:30 pt-query-digest：スロークエリ解析ツール

sudo pt-query-digest /var/lib/mysql/mysql-slow.log > ~/digest.txt

10:40 alp: アクセスログ解析ツール(https://github.com/tkuchiki/alp)

sudo alp -f /var/log/nginx/access.log > ~/access_log.txt

初期結果

+-------+--------+--------+---------+--------+--------+--------+--------+--------+------------+------------+-------------+-----------+--------+-----------------------------------+
| COUNT |  MIN   |  MAX   |   SUM   |  AVG   |   P1   |  P50   |  P99   | STDDEV | MIN(BODY)  | MAX(BODY)  |  SUM(BODY)  | AVG(BODY) | METHOD |                URI                |
+-------+--------+--------+---------+--------+--------+--------+--------+--------+------------+------------+-------------+-----------+--------+-----------------------------------+
|     1 |  0.000 |  0.000 |   0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /js/star.js                       |
|     1 |  0.001 |  0.001 |   0.001 |  0.001 |  0.001 |  0.001 |  0.001 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /css/main.css                     |
|     1 |  0.120 |  0.120 |   0.120 |  0.120 |  0.120 |  0.120 |  0.120 |  0.000 |     15.000 |     15.000 |      15.000 |    15.000 | GET    | /initialize                       |
|     6 |  0.028 |  0.428 |   0.664 |  0.111 |  0.000 |  0.029 |  0.137 |  0.148 |  86351.000 |  86351.000 |  431755.000 | 71959.167 | GET    | /js/jquery.min.js                 |
|     5 |  0.028 |  0.428 |   0.663 |  0.133 |  0.028 |  0.030 |  0.138 |  0.153 |   1092.000 |   1092.000 |    5460.000 |  1092.000 | GET    | /favicon.ico                      |
|     6 |  0.017 |  0.429 |   0.621 |  0.103 |  0.000 |  0.026 |  0.119 |  0.150 |  28631.000 |  28631.000 |  143155.000 | 23859.167 | GET    | /js/bootstrap.min.js              |
|    11 |  0.028 |  0.429 |   1.127 |  0.102 |  0.000 |  0.031 |  0.287 |  0.128 | 106015.000 | 106015.000 | 1060150.000 | 96377.273 | GET    | /css/bootstrap.min.css            |
|     6 |  0.028 |  0.431 |   0.667 |  0.111 |  0.000 |  0.030 |  0.138 |  0.149 |  16849.000 |  16849.000 |   84245.000 | 14040.833 | GET    | /css/bootstrap-responsive.min.css |
|     6 |  0.001 |  0.432 |   0.651 |  0.108 |  0.001 |  0.030 |  0.120 |  0.149 |     93.000 |     93.000 |     465.000 |    77.500 | GET    | /img/star.gif                     |
|    58 |  0.014 |  1.984 |  27.837 |  0.480 |  0.014 |  0.287 |  1.964 |  0.491 |     10.000 |     10.000 |      60.000 |     1.034 | POST   | /login                            |
|     1 |  2.320 |  2.320 |   2.320 |  2.320 |  2.320 |  2.320 |  2.320 |  0.000 |   2255.000 |   2255.000 |    2255.000 |  2255.000 | GET    | /keyword/121系                    |
|    42 |  0.023 |  2.545 |  34.590 |  0.824 |  0.023 |  0.672 |  2.193 |  0.580 |      0.000 |      6.000 |     192.000 |     4.571 | POST   | /keyword                          |
|     2 |  3.768 |  3.970 |   7.738 |  3.869 |  3.768 |  3.768 |  3.768 |  0.101 |   6973.000 |   6973.000 |   13946.000 |  6973.000 | GET    | /keyword/平尾山                   |
|     2 |  5.007 |  5.931 |  10.938 |  5.469 |  5.007 |  5.007 |  5.007 |  0.462 |   9367.000 |   9381.000 |   18748.000 |  9374.000 | GET    | /keyword/2100年                   |
|     2 |  8.629 |  9.163 |  17.792 |  8.896 |  8.629 |  8.629 |  8.629 |  0.267 |   2498.000 |   2498.000 |    4996.000 |  2498.000 | GET    | /keyword/ウーズ                   |
|     1 | 13.389 | 13.389 |  13.389 | 13.389 | 13.389 | 13.389 | 13.389 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/北消防署                 |
|     1 | 13.729 | 13.729 |  13.729 | 13.729 | 13.729 | 13.729 | 13.729 |  0.000 |   5370.000 |   5370.000 |    5370.000 |  5370.000 | GET    | /keyword/ジョージ・グローヴ       |
|     1 | 14.019 | 14.019 |  14.019 | 14.019 | 14.019 | 14.019 | 14.019 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/巨大基数                 |
|     2 | 11.320 | 14.478 |  25.798 | 12.899 | 11.320 | 11.320 | 11.320 |  1.579 |   2541.000 |   2541.000 |    5082.000 |  2541.000 | GET    | /keyword/輪状甲状筋               |
|     1 | 14.527 | 14.527 |  14.527 | 14.527 | 14.527 | 14.527 | 14.527 |  0.000 |   3162.000 |   3162.000 |    3162.000 |  3162.000 | GET    | /keyword/1051年                   |
|     1 | 14.992 | 14.992 |  14.992 | 14.992 | 14.992 | 14.992 | 14.992 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/パールヴァティー         |
|     1 | 14.998 | 14.998 |  14.998 | 14.998 | 14.998 | 14.998 | 14.998 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/きたのじゅんこ           |
|     1 | 14.999 | 14.999 |  14.999 | 14.999 | 14.999 | 14.999 | 14.999 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/西那須野駅               |
|     1 | 15.000 | 15.000 |  15.000 | 15.000 | 15.000 | 15.000 | 15.000 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/湯田村駅                 |
|     2 | 15.000 | 15.000 |  30.000 | 15.000 | 15.000 | 15.000 | 15.000 |  0.000 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/河出書房新社             |
|     2 | 14.998 | 15.000 |  29.998 | 14.999 | 14.998 | 14.998 | 14.998 |  0.001 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/内田修平                 |
|     2 |  0.123 | 15.000 |  15.123 |  7.561 |  0.123 |  0.123 |  0.123 |  7.439 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/1097年                   |
|     2 | 14.999 | 15.005 |  30.004 | 15.002 | 14.999 | 14.999 | 14.999 |  0.003 |      0.000 |      0.000 |       0.000 |     0.000 | GET    | /keyword/イギリス政府             |
|    22 | 14.986 | 20.838 | 335.785 | 15.263 | 14.986 | 15.000 | 15.001 |  1.217 |      0.000 |  60169.000 |   60169.000 |  2734.955 | GET    | /                                 |
+-------+--------+--------+---------+--------+--------+--------+--------+--------+------------+------------+-------------+-----------+--------+-----------------------------------+

11:15 MySQL チューニング

Linux VM での MySQL パフォーマンスの最適化 | Microsoft Azure
etcfiles/my.cnf at master · kamipo/etcfiles を参考に調整
- コピペミスって立ち上がらなくなるなどして焦る

12:00 limits.conf チューニング

Linux VM での MySQL パフォーマンスの最適化 | Microsoft Azure

sudo su -
cat << EOC >> /etc/security/limits.conf
* soft nofile 65536
* hard nofile 65536
* soft nproc 65536
* hard nproc 65536
EOC
ulimit -SHn 65536
ulimit -SHu 65536
echo “ulimit -SHn 65536” >>/etc/rc.local
echo “ulimit -SHu 65536” >>/etc/rc.local
exit

12:20 デプロイスクリプト用意

git pull
make を叩いてビルド
systemd の isuda.go.service, isutar.go.service をリスタート
アクセスログとスロークエリログを削除して nginx, MySQL もリスタート

13:00 ソースを読んで方針検討

isuda から isutar へ HTTP でスターの情報を取りに行ってるのが無駄そう

14:00 Redis 入れる

sudo apt-get install build-essential tcl
cd /tmp
curl -O http://download.redis.io/redis-stable.tar.gz
tar xzvf redis-stable.tar.gz
cd redis-stable
make
make test
sudo make install
sudo mkdir /etc/redis
sudo cp /tmp/redis-stable/redis.conf /etc/redis
sudo vi /etc/redis/redis.conf # supervised no => supervised systemd, dir ./ => dir /var/lib/redis
sudo sh -c "cat << EOF > /etc/systemd/system/redis.service
[Unit]
Description=Redis In-Memory Data Store
After=network.target

[Service]
User=redis
Group=redis
ExecStart=/usr/local/bin/redis-server /etc/redis/redis.conf
ExecStop=/usr/local/bin/redis-cli shutdown
Restart=always

[Install]
WantedBy=multi-user.target
EOF"
sudo adduser --system --group --no-create-home redis
sudo mkdir /var/lib/redis
sudo chown redis:redis /var/lib/redis
sudo chmod 776 /var/lib/redis
sudo systemctl start redis
sudo systemctl enable redis

15:00 スターの alt, title にユーザ名がつかない

/star の POST でユーザ名はクエリストリングと FormData とどっちが正しい？

=== メモはここで途切れている……。余裕がなくなったようだ。 ===

ikosin's diary

ISUCON6予選惨敗日記

日記

感謝

反省