ISUCON7予選1日目にチーム「ババウ」で参加して最終スコアは205148でした

Webサービスをいい感じにパフォーマンスチューニングするコンテスト

ISUCON7予選1日目に @netmarkjp, @ishikawa84g, @matsuu でチーム「ババウ」にとして参加しました。最終スコアは 205148 でした。

考察

netmarkjp

例年通りの役割分担がしっかり機能して気持ちよくできた
視点を変えたり休憩とったりがいい感じにできた
去年の何もできなかった無念は多少供養できた
練習をきちんと活かせた
ベンチが安定しててすごくよかった
BGMは東京スカパラダイスオーケストラでした

matsuu

トラフィックがボトルネックになる問題をなかなか解決できずにいたが、Cache-Controlにpublicを入れることを思いつけた
304応答が安定して発生しない理由が生成される画像の更新日時がサーバ毎に異なるためであることに気づけた自分を褒めてあげたい
- tcpdumpでベンチマークのトラフィックをtcpdumpしてみたのが大きかった
Pixiv社内ISUCONを使ってじっくりチューニングしたときの経験がとても役に立った。ありがとうPixiv
Discordチャットが結構よかった。ゲームじゃなくてもこういったイベントにとても向いていると思うのでオススメ
NEW GAME!!を初めて見たがエンジニアあるあるでグッときた。なるほど。

ishikawa84g

Microsoft Wireless Display Adapter は便利。
- ただし、6時間くらい連続稼働するとハングすることもあるようです。しばらく寝かせると復活した。
開始時間が伸びていたが慌てずリラックスして開始で来た。(流石みんなトラブル慣れしているぜ！)
- DiscordでおすすめされたNEW GAME!は3話まで見ました。
- 常に緊張状態ある必要はなく、締めるところを締めれば問題なし！
DiscordのコマンドにFF14のWikiを検索するとかあった。

最終構成

[nginx -- (varnish) -- gunicorn]x2 -- [mysql]x1

当初構成からあまり変えず
- ベンチ先は先頭2台
- ネットワークボトルネックの間は3台に振ったけど、結局DBサーバのCPUが足りず戻した
投稿された画像は静的ファイルとして出力し、nginxで静的ファイルを返却
- /icons/* はファイルに出力し基本的にnginxから。なければvarnishを経由してアプリでファイル生成
- その他のパスへのリクエストはvarnishを経由せず直接gunicornへ
varnishは /icons/* のThunerding Herd対策として導入
その他MySQL、nginx、アプリのチューニングを実施

事前準備

チーム内体制の構築

チャットはSlackで
gitリポジトリは Gitlab.com で
使ったことがないツールを使ってみようということで環境構築はitamaeでプロビジョニング
- 初期構築以降は短期決戦のためitamaeで管理しない
git pushベースのCIプロビジョニングは実施しない
- 事前練習で試したものの短期決戦ではどうやっても遅い
サーバで直接Vimを使って編集
- 他の人が編集してる場合は vim -R で参照

環境構築用レシピを用意

itamaeを使って以下のプロビジョニングを自動化

githubからSSH公開鍵を取得、設定
以下の解析ツールをインストール
- dstat
- kataribe
- MySQLTuner
- netdata
- Percona Toolkit pt-query-digestのため
- gprof2dot PythonのWSGIプロファイラWerkzeugのグラフ化ツール
以下のミドルウェアをインストール
- Varnish
ベンチマークをかける前の初期化処理/かけた後の解析処理を実行するスクリプトを用意
- 初期化処理
  - MySQLスロークエリーログを削除してmysqladmin flush-logs
  - nginxのアクセスログを削除してsystemctl reload nginx
  - アプリプロファイラの出力を削除してアプリケーションプログラムの再起動
- 解析処理
  - MySQLスロークエリーに対してpt-query-digestを実行
  - MySQLTunerを実行
  - nginxのアクセスログに対してkataribeを実行
  - pythonプロファイラWerkzeugの出力に対してgprof2dotとgraphvizを実行してグラフ生成

sshrc環境整備

sshrcでvim、tmux環境一発セットアップできるよう調整

過去問を解いて予行演習

事前公開のレギュレーションを熟読

大事

当日作業

9:00 - 10:00

集合

電源、椅子、モニターの設営までやって、あとはマッタリ
大事なのは横並びに座ること

11:30 昼食

落ち着いて美味しい昼食。ハンバーガー画像を参加者チャットに投下

12:00 - 13:00 ※開始前

ISUCON参加者専用チャットでNEW GAME!!の話題が盛り上がったためAmazonビデオで視聴開始

13:00 開始予定時刻

ポータルサイトが...オープンしない

13:10 運営よりDiscordで緊急連絡

methane - 今日 午後1時10分
もうちょっと、ごめん！

13:13 開始

SSH接続できないトラブルに見舞われるものの、その間に初回ベンチマーク実行と当日レギュレーションを熟読

13:30 ログイン後

予め用意していた環境構築レシピを実行
並行して、各マシンのスペックと、使われているミドルウェアを確認
サービスの画面を見たりコードを読んで、どんなアプリなのかざっくり把握

ポータル上でサーバが降順で並んでて、「先頭2台」がどれなのかちょっと混乱した

MySQLのチューニングで/dev/shmに格納しようとしたところAppArmorに引っかかったため、AppArmorを調整

/etc/apparmor.d/usr.sbin.mysqld に以下を追記

  # ISUCON2017
  /dev/shm/ r,
  /dev/shm/** rw,
  /proc/** r,
  /sys/devices/system/node/ r,
  /sys/devices/system/node/** r,

変更後、Profileをリロードし、MySQLを再起動する。

sudo apparmor_parser -r /etc/apparmor.d/usr.sbin.mysqld
sudo systemctl restart mysql.service

14:01 webapp配下をgit管理に

pythonで実装する方針にしたため、publicディレクトリとpython ディレクトリをgitに突っ込みcommit

14:08 インデックス追加

スロークエリーから遅いリクエストを調べてインデックス追加

ALTER TABLE image ADD INDEX (name);
ALTER TABLE message ADD INDEX (channel_id);

14:30

一瞬だけ1位獲得

https://twitter.com/matsuu/status/921609614881202178

netdata見たのはこの頃までで、あとはdstatとtop

tmuxで3台分並べて表示。操作はtmuxのsynchronized-paneで楽々実施

14:33 /icons/の静的ファイル化

DBに格納されている画像データを静的ファイルとして出力する実装を行う

def get_images():
    cur = dbh().cursor()
    cur.execute("SELECT name, data FROM image")
    for row in cur.fetchall():
        output = "/home/isucon/images/{}".format(row['name'])
        with open(output, 'wb') as file:
            file.write(row['data'])

出力した画像はnginxから直接応答するように変更

location /icons/ {
        expires 60s;
        alias /home/isucon/images/;
        try_files $uri @upstream;
}

location @upstream {
        proxy_set_header Host $http_host;
        proxy_pass http://127.0.0.1:5000;
}

14:34頃 DBとアプリ間のトラフィック改善

dstatで見ているとDBとWEBの間のトラフィックが多いのにベンチマーカーとWEBの間のトラフィックが少ないことに気づく。

同じ内容の画像が同じファイル名で重複登録されており無駄にDBからの取得が発生していることに気づいたので1行だけ取得するよう修正

    cur.execute("SELECT * FROM image WHERE name = %s", (file_name,))
    cur.execute("SELECT * FROM image WHERE name = %s LIMIT 1", (file_name,))

14:57 静的ファイルのgzip_static化

静的ファイルを予めgzipして保存しておき、nginxの gzip_static で応答するように

gzip_static on;
gzip_types image/svg+xml text/css text/javascript application/javascript application/font-wof
f application/vnd.ms-fontobject;

15:21頃画像を生成する

画像をINSERT時やSELECT時に出力するよう変更。
しかしサーバごとに画像を生成する実装のためこの後しばらくスコアが伸び悩む

画像にexpiresを付けてみる→多少改善するものの根本解決にはならず
/fetchの1秒待機を外してみる→効果なし
206レスポンスを返してRangeヘッダーで返せばいいのでは？→206応答を簡単に実装する方法がわからず
limit_rateで代用したらタイムアウト
302リダイレクトで応答を遅らせればいい？→302リダイレクトはエラーになった

17:24頃 /fetchのチューニング

SQLを見直してN+1を解消

SELECT
  channel.id AS channel_id,
  CASE WHEN message_id IS NULL THEN
    (SELECT COUNT(*) FROM message WHERE channel_id = channel.id)
  ELSE
    (SELECT COUNT(*) FROM message WHERE channel_id = channel.id AND message_id < id)
  END AS unread
FROM channel
LEFT JOIN haveread
  ON channel.id = haveread.channel_id AND user_id = ?

18:17頃画像ファイル生成時に更新日時を合わせる

ベンチマークからのHTTPリクエストをtcpdumpで記録してどのようなリクエストが届いている確認してみる

tcpdump -w dump tcp port 80

その結果をWiresharkに食わせて確認していたところ、If-Modified-Sinceヘッダーを見つけて思いついた。
「画像ファイルの更新日時を合わせてないから304応答を返せていないのだ」と。エウレカ！

def write_image(data, name):
    output = "/home/isucon/images/{}".format(name)
    with open(output, 'wb') as file:
        file.write(data)
    os.utime(output, (1508559193, 1508559193))

1508559193 は 2017/10/21 13:13:13 、ISUCON7予選1日目の開始日時。

18:33

帯域が多少マシになったのでwebサーバのCPU負荷を下げるために gzip off

18:51頃 /messageのチューニング

SQLを見直してN+1を解消

    if last_message_id > 0:
        cur.execute("SELECT message.id, name, display_name, avatar_icon, message.created_at, content FROM message JOIN user ON message.user_id = user.id WHERE message.id > %s AND channel_id = %s ORDER BY message.id DESC LIMIT 100",
                (last_message_id, channel_id))
    else:
        cur.execute("SELECT message.id, name, display_name, avatar_icon, message.created_at, content FROM message JOIN user ON message.user_id = user.id WHERE channel_id = %s ORDER BY message.id DESC LIMIT 100",
                (channel_id, ))

19:00頃画像ファイル生成時の出力先を/dev/shm/にする

            with tempfile.TemporaryFile(dir="/dev/shm/") as f:

19:10 PythonプロファイラWerkzeugの導入

打つ手が少なくなってきたのでWerkzeugでのプロファイルを実施。

from werkzeug.contrib.profiler import ProfilerMiddleware
app.wsgi_app = ProfilerMiddleware(app.wsgi_app, profile_dir="/tmp/profile")

gprof2dotを使ってdotファイルを生成し、graphvizを使ってpngファイルを生成。

gprof2dot -f pstats --colour-nodes-by-selftime --show-samples /tmp/profile/* > profile.dot
dot -Tpng profile.dot > profile.png

生成結果がこちら。

gprof2dot最高ですね。

19:48頃 rapidjsonの導入

Werkzeugによるプロファイルの結果、JSON生成に時間がかかっていることが判明したため、flask.jsonify()をrapidjsonに差し替え。

20:15頃 WSGIサーバをmeinheldに差し替え→差し戻し

WSGIサーバをgunicornからmeinheldへ差し替えてみたものの大幅に性能が下がり断念。

20:27

sleep対応でgunicornのワーカーを減らしてスレッドを大幅にUP

/etc/systemd/system/isubata.python.service で --workers=1 --threads=1000 と設定

20:31 MySQLパラメータ調整

アプリ側で Too many connections が出ていたのでMySQL設定変更

max_connections = 8192 と open_files_limit を設定
/lib/systemd/system/mysql.service に LimitNOFILE=65535 を追記

20:35頃テンプレートエンジンJinja2のチューニング

jinja2のbytecode_cacheを有効に

app.jinja_options = app.jinja_options.copy()
app.jinja_options['bytecode_cache'] = jinja2.FileSystemBytecodeCache()

20:49 画像データの設置周りを修正

アップロードされた画像をtmpファイルに出力した際に最終的な設置場所にハードリンク

os.link(f.name, output)

20:50過ぎ再起動テスト

再起動テスト実施

再起動後にベンチ実行したらスコアが乱高下したのでいい感じになるまで繰り返しベンチ実行

与負荷側が安定してて高速で助かった

21:07　ベストスコアがでるまでベンチマークを繰り返す

本日のベストスコア 205148 が出て歓声

21:13 終了

お疲れ様でした。

考察