ISUCON6予選惨敗日記

四年連続四回目の 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 とどっちが正しい？

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

Windows でだけ Linux サーバへの Chef のプロビジョニングが失敗する問題への対処

invalid byte sequence in UTF-8

とか言われて表題のような事象に悩んでる人向けに解決法を残しておく。

Cookbook を Git で管理していて、 git config core.autocrlf が true の場合、チェックアウト時に LF => CRLF 変換をかけてしまう。そのため、Linux サーバへのプロビジョニング時に問題が発生する場合がある (files でスクリプトを設置するときは特に注意が必要)

core.autocrlf

ProGit 引用

自分が Windows で開発していたり、チームの中に Windows で開発している人がいたりといった場合に、改行コードの問題に巻き込まれることがありがちです。Windows ではキャリッジリターンとラインフィードでファイルの改行を表すのですが、Mac や Linux ではラインフィードだけで改行を表すという違いが原因です。ささいな違いではありますが、さまざまなプラットフォームにまたがる作業では非常に面倒なものです。 Git はこの問題に対処するために、コミットする際には行末の CRLF を LF に自動変換し、ファイルシステム上にチェックアウトするときには逆の変換を行うようにすることができます。この機能を使うには core.autocrlf を設定します。Windows で作業をするときにこれを true に設定すると、コードをチェックアウトするときに行末の LF を CRLF に自動変換してくれます。

対策

.gitattributes ファイルで改行コードを固定したいファイルを指定して変換しないようにする

参考 https://help.github.com/articles/dealing-with-line-endings/

# Linux サーバ上に配置するスクリプトを想定
*.sh eol=lf
# そもそも全部 lf でいいやという場合
*.* eol=lf

または、ディレクトリ以下のファイルの変換を行わないようにする

# 例えば、cookbooks/ に設置
* eol=lf

既にリポジトリをチェックアウトしている場合は、対象のファイル・ディレクトリを一旦削除してから git chekout -- hogehoge.sh とかしてチェックアウトしなおすと、指定した改行コードのファイルで再作成してくれる。

YAPC::Asia Tokyo 2015 で CONBU スタッフとボランティアスタッフしてきた

例年ブログを書くのが遅いのですが、これでようやく自分の YAPC も終わることができます。

あなたと YAPC

今年で4回目の YAPC に行ってきました。スタッフ参加では3回目です。更に、去年の YAPC 後の HUB での縁があって、今年は CONBU の方のスタッフとしても参加していました*1。

普段は周りに YAPC を知ってる人のほぼ居ない職場で働いてたりするので、Web 業界界隈の話題で盛り上がれる知り合いは YAPC にスタッフ参加して得た大きな財産ですよ、はい。

YAPC ボランティアスタッフとして今年やったこと

YAPC のボランティアスタッフとしてやったことは例年とほとんど変わりません。前夜祭の受付前に集まって、年々洗練されてきたノベルティ詰めや Tシャツのたたみ直し*2を行い、各トークの司会・タイムキーパー・会場誘導等をやってました。会場での仕事は、同じ部屋のスタッフみんなや部屋係のリーダーがすごく頑張ってくれていたおかげで、大きな混乱もなくて良かったです。

ビックサイトになって会場キャパは倍増くらいしたけど、今年も満員のトークがいっぱい有りました。入れなかった人には心苦しいですが、「後で YouTube に上がるのでチェックしてみてください」とアナウンスするしかできませんでした。今年はアップロードが早くて、既に多くのトークが上がってるので、見れなかったトークや裏番組をチェックしましょう！

yapcasia - YouTube

CONBU スタッフとして今年やったこと

宣伝

みなさん、CONBU が会場混雑を推測できる API を提供していたことは知っていましたか？

YAPC::Asia Tokyo 2015 会場ヒートマップ | CONBU API

YAPC 期間中のヒートマップを再現するようにしました！会場ヒートマップ眺めるの結構楽しいですよ！上記リンクから見れるので、自分が居た会場の混み具合を思い起こすのもいいのではないでしょうか！

なぜ会場ヒートマップは作られたのか

CONBU スタッフとしては、設営はほぼ参加せず、大きな話題になった LT（ライトニング設営: Lightning seTsuei）にも出なかったのですが、代わりに何が出来るか考えた所、会場ヒートマップが生まれました。

もともとは、今回から CONBU API というものを公開して、YAPC 参加者が自由にアプリとか作ってくれるといいなという感じでした。

YAPC:Asia 2015 の会場無線ネットワークを担当している CONBU です。新しい取り組みとして、無線 AP の接続状況を API として公開することにしました。 CONBU API Server https://t.co/agVBCuWN0J #yapcasia

— CONBU (@conbu_net) 2015, 8月 20

自分は開発用に擬似的なサンプル値を返すアプリをちょろっと書いていて*3 API の仕様も把握したので、ちょっとでも動くものが見せられたらみんな API 使ってアプリ作りたくなるかもと思い、前夜祭前日の日付が変わったくらいから3時間程度で書いたアプリです。当初はサンプル値をマッピングするだけのデモアプリでした。

CONBU API の利用例として、会場ヒートマップを作成しています。 YAPC::Asia Tokyo 2015 会場ヒートマップ Powered by CONBU API http://t.co/fK9HYCOOTt #yapcasia

— CONBU (@conbu_net) 2015, 8月 20

この時はただのデモアプリです

ただ想定外だったのが、今年の YAPC スタッフが手際が良すぎてノベルティ詰めが予想以上に早く終わってしまい、空いた時間で実データを反映するように改修して公開したら自分でも楽しくなってきてしまいました。そこからちょくちょく機能追加*4したりするうちに、気づけば公式アプリっぽい雰囲気になっていきましたw

ヒートマップで隣の会場や他の部屋の混雑具合を（ほぼ）リアルタイムで確認することができます！ #yapcasia pic.twitter.com/Exd6QfJwjc

— CONBU (@conbu_net) 2015, 8月 21

まとめ

• YAPC 最高！！！
• ヒートマップばかり見てたからトークほとんど聞いてなかった
  • YouTube に上がってるので後でチェックする
• 来年（再来年？）もスタッフやるぞ！ 来年（再来年？）もスタッフやるぞ！

*1:正式には CONBU の方は今週末の LL の募集に応募してたけど、YAPC も当日設営以外は準備等参加してた

*2:Tシャツは本当にあっという間に全部捌けてしまった

*3:もともとネットワーク機器の設定チームだったけど、そっちではあまりにも無力で役に立てなかったためカッとなって書いた

*4:細かい無線AP の位置調整をしたり、当初は部屋単位のアソシエーション数をマッピングしていたのを無線AP 毎のアソシエーション数が反映されるように改修