こんにちは, @mecha_g3 です.

ISUCON6に「この技術部には問題がある!」チームとして出場し, 優勝しました.
メンバーは まとめ役の @methane, インフラ屋の @kizkoh, 僕がアプリ改造を担当しました.

他のメンバー参加記事:

• ISUCON6 で優勝しました
• ISUCON6 にインフラエンジニアとして参加して優勝した!!

予選とその反省

ISUCON6予選をトップ通過しました

余裕を持って優雅に戦えたとか書いてありますが, 僕は全然余裕がなく, 準備したツールが中々動かなかったり, git 操作のミスで変更が反映されてなかったり, DBコネクションを食いつぶす変なバグを埋め込んでしまったりで足を引っ張りまくりでした.

その反省もあって, 本選用にAWSの開発環境を用意し, 作業に必要なツールやエディタの設定は全て済ませておきました.
またこの開発環境では, ログの収集やアプリのデプロイ, ベンチマーク時のプロファイルの結果をhtml形式でレポートするスクリプト等を作っておきました.

さらに, 予めスタートダッシュチェックリストを作っておき, 問題公開後にしかできないけど必ず必要な作業の一覧を作り, 誰がやるか予め決めておきました.

この開発環境とスタートダッシュチェックリストのおかげで, 本選時にアプリの改造に集中することができました.

例えば

• ~/deploy で競技サーバにアプリのデプロイ
• ~/restart で競技サーバのアプリやnginx, MySQLの再起動.
• ~/applog で競技サーバ上のアプリのログをtail -f
• ~/make_report ベンチマーク後, 競技サーバ上のアプリのログを収集してレポートのhtmlを出力してslackに通知

これらを Makefile から呼び出すことで, 競技中に vim の中に閉じこもることができます.
問題に合わせて微妙に変更しないといけない所も, インフラ担当の @kizkoh が良い感じにメンテしてくれました.

本選

前半戦

スタートダッシュチェックリストに書いておいた事を淡々と進めました. 競技が始まると全然頭が回らなくなるので作っておいて本当に良かった.

僕は初期状態のアプリを git 管理してビルドが通るようにし, デプロイスクリプトを修正したり, 8080番ポートでLISTENするようにしたり, 予め用意しておいたプロファイル用のライブラリを挿入したりなどを行いました.

ISUCON のアプリには毎回 /initialize という, ベンチマーク前にデータセットを初期化するリクエストが存在します.
これをトリガにして nginx のログをローテートし, 1分間(ベンチマーク時間) pprofの記録, dstat, pidstat を裏で動かすスクリプトを事前に準備していました.
が, 本選の問題には /initialize は存在せず(やられた), アプリケーション側からベンチの開始を検出するのが難しかったので, ベンチマークをかける頃に /startprofile というパスを手動で叩くようにしました.

Webサーバのログを見ると UA に benchmarker というような文字があったのでこれを使うかも考えましたが, 意図せぬタイミングで暴発すると面倒なのでやめました.

作戦会議

お弁当を食べながらアプリを触ったり, 作戦会議を行いました.
ここまでスタートダッシュに集中していたのでアプリのソースは全然読んでませんでした.

スタートダッシュ中にログの集計やアプリの構成などを理解していた @methane からアプリの構成や, 現状考えている方針を共有してもらいました.

Server-Sent Events は全く触ったことがなかったけど, テキストベースのプロトコルだと分かった後は簡単でした.
svgは業務外で何度か触ったことがあり, xml形式だということは知っていたので怖くはなかったです.

リアルタイムのお絵かきサービスだけど, やることはテキストの共有. つまりチャットのような物.
普段業務でやっている事と大差ないよね, 多分go言語有利な問題だし, 実力出せれば勝てる.

お絵かき部分の共有をとにかく高速化しよう.
内容の変更をDBにポーリングしている構造になっている所を直せば劇的にスコアが上がるはず.
描いた内容は他のクライアントに2秒以内に反映されていれば良いので, 急いで返す必要はなく, ある程度バッファしてまとめて返すほうが効率いいよね.
という会話をしました.

インフラ方面では, dockerを潰し, node.jsをフロントから剥がし, nginxをフロントに置くなど大規模な構成変更を決めていました.

中盤戦

オンメモリ作戦

DBに毎回問い合わせている部分をなくせば良いので, オンメモリ作戦を実施しました.
起動時にDBの内容を全て SELECT しメモリ上に乗せ, 変更された内容は DB に保存しつつオンメモリの内容も更新します.
最新の情報はメモリ上にあるので, DBへの問い合わせをなくすことができます.

全部と書いていますが, ここで行ったのは room, strokes, points が対象です.

最初は, 最終的にアプリをroomで水平分散するかもしれないからそこを意識しつつオンメモリ化を考えていて手が中々動きませんでした.
難しいので1プロセスで動く前提で作ります! と割り切ってからはサクサクと作業が進みました. 最終的にアプリは1プロセスだったので結果論ですが正解でした.

具体的には以下のようなコードを書いていました.

type RoomRepo struct {
    sync.Mutex
    Rooms map[int64]*Room
}

func NewRoomRepo() *RoomRepo {
    return &RoomRepo{
        Rooms: map[int64]*Room{},
    }
}

func (r *RoomRepo) Init() {
    log.Println("room repo init start")
    r.Lock()
    defer r.Unlock()

    rooms := []Room{}
    err := dbx.Select(&rooms, "SELECT `id`, `name`, `canvas_width`, `canvas_height`, `created_at` FROM `rooms` ORDER BY `id` ASC")
    need(err)

    for i, _ := range rooms {
        strokes := []Stroke{}
        err := dbx.Select(&strokes, "SELECT `id`, `room_id`, `width`, `red`, `green`, `blue`, `alpha`, `created_at` FROM `strokes` WHERE `room_id` = ? ORDER BY `id` ASC", rooms[i].ID)
        need(err)

        var owner_id int64
        err = dbx.QueryRow("SELECT token_id FROM `room_owners` WHERE `room_id` = ?", rooms[i].ID).Scan(&owner_id)
        need(err)

        for j, s := range strokes {
            ps := []Point{}
            dbx.Select(&ps, "SELECT `id`, `stroke_id`, `x`, `y` FROM `points` WHERE `stroke_id` = ? ORDER BY `id` ASC", s.ID)
            strokes[j].Points = ps
        }

        rooms[i].ownerID = owner_id
        rooms[i].Strokes = strokes
        rooms[i].watchers = map[int64]time.Time{}
        r.Rooms[rooms[i].ID] = &rooms[i]
    }
    log.Println("room repo init end")
}

func (r *RoomRepo) Get(ID int64) (*Room, bool) {
    r.Lock()
    defer r.Unlock()

    room, ok := r.Rooms[ID]
    return room, ok
}

...

オンメモリ作戦のデバッグ

Go での開発はコンパイルエラーでしょうもないミスはすぐ分かるし, vim の QuickFix でエラー箇所に簡単にジャンプできるのでIDEで開発しているような気分になります.
競技時間中は頭が全然回らず, 焦って明らかに変なコードを書いてしまいがちですがかなり助けられました.

コンパイルが通った後は, 実行時にすぐ分かるエラーを数か所直しました.
ブラウザで動作確認してみると, 全ルームidが同じルームを参照してしまうバグが発生していましたが, forループの変数のスコープのあるある問題だなとすぐ気づき修正できました.

この頃にはインフラ担当の構成変更も終わり, HTTP2を喋っていて 10000点 以上でるようになっていました(すごい).
ここにオンメモリ作戦の改造を入れたアプリをデプロイし, ベンチマークをかけてみると一発でPASSし 23428点.

svg生成のGo移植

オンメモリ作戦が一段落したところで, @methane が node.js で動いていた /img/* へのリクエストの svg 出力部分をgoで出力する関数ができたので試したいという.
投入してみると, 空の svg が出力されていて動作せず. デバッグを任せられたのでとりあえず printデバッグで関数が呼ばれているかなどを確認しました.

DBから引いた状態の room には strokes は空なので, 空の svg が出力されていましたというだけでした. オンメモリ化とつなぎ込めば解決です.

また, 前回ベンチマークの警告からnginxの設定ミスがわかり, それを修正も入っており 39101点.

svg生成結果のキャッシュ

ベンチマーク時のプロファイルを見ていると, svg 生成部分がアプリ全体のうち 64.31% と中々重そうでした.
ここをなんとかキャッシュできると, 他チームに差をつけれそうです.

Strokeは内容は, アプリケーションの性質から, 追記のみであることがわかりました.
つまり, 1stroke毎に <polyline> ... </polyline> が1行増えるだけで, 1度書いた部分が変更されることはありません.

閉じタグを含めない状態の svg を Room 毎にキャッシュしておき, Stroke が増える度に1行ずつ追記します.
/img/* へリクエストが来た際は, キャッシュしている svg を出力し, 最後に </svg> を追加するだけで, 何度も同じ svg を生成しなくてすみます. あたまいい!

具体的には以下のようなコード.

room.svgInit が初回レンダリング済みかどうかのフラグ. 初回 svg 出力時に svgBuf を作ります.
Stroke が追加された場合は 同様の Fprintf で svgBuf に追記します.

func renderRoomImage(w io.Writer, room *Room) {
    room.svgMtx.Lock()

    if !room.svgInit {
        buf := bytes.NewBuffer(make([]byte, 0, 1024))

        fmt.Fprintf(buf,
            `<?xml version="1.0" standalone="no"?><!DOCTYPE svg PUBLIC "-//W3C//DTD SVG 1.1//EN" "http://www.w3.org/Graphics/SVG/1.1/DTD/svg11.dtd"><svg xmlns="http://www.w3.org/2000/svg" version="1.1" baseProfile="full" width="%d" height="%d" style="width:%dpx;height:%dpx;background-color:white;" viewBox="0 0 %d %d">`,
            room.CanvasWidth, room.CanvasHeight,
            room.CanvasWidth, room.CanvasHeight,
            room.CanvasWidth, room.CanvasHeight)

        for _, stroke := range room.Strokes {
            fmt.Fprintf(buf,
                `<polyline id="%d" stroke="rgba(%d,%d,%d,%v)" stroke-width="%d" stroke-linecap="round" stroke-linejoin="round" fill="none" points="`,
                stroke.ID, stroke.Red, stroke.Green, stroke.Blue, stroke.Alpha, stroke.Width)
            first := true
            for _, point := range stroke.Points {
                if !first {
                    buf.WriteByte(' ')
                }
                fmt.Fprintf(buf, `%.4f,%.4f`, point.X, point.Y)
                first = false
            }
            buf.WriteString(`"></polyline>`)
        }

        room.svgBuf = buf
        room.svgInit = true
    }

    svg := room.svgBuf.Bytes()
    room.svgMtx.Unlock()

    w.Write(svg)
    w.Write([]byte(`</svg>`))
}


func (r *RoomRepo) AddStroke(roomID int64, stroke Stroke, points []Point) {
    r.Lock()
    defer r.Unlock()

    room, ok := r.Rooms[roomID]
    if !ok {
        log.Println("[warn] no such room")
        return
    }

    stroke.Points = points
    room.Strokes = append(room.Strokes, stroke)

    room.svgMtx.Lock()
    if room.svgInit {
        buf := room.svgBuf
        fmt.Fprintf(buf,
            `<polyline id="%d" stroke="rgba(%d,%d,%d,%v)" stroke-width="%d" stroke-linecap="round" stroke-linejoin="round" fill="none" points="`,
            stroke.ID, stroke.Red, stroke.Green, stroke.Blue, stroke.Alpha, stroke.Width)
        first := true
        for _, point := range stroke.Points {
            if !first {
                buf.WriteByte(' ')
            }
            fmt.Fprintf(buf, `%.4f,%.4f`, point.X, point.Y)
            first = false
        }
        buf.WriteString(`"></polyline>`)
    }
    room.svgMtx.Unlock()
}

これで /img/* のCPU時間が数倍早くなり, 44655点.

終盤戦

@kizkoh は MySQL と node.js を別サーバに移したりなど, 複数台構成に向けての変更を行っていました.
@methane は node.js に文句をいいながら何かをやっていました.

僕は他にチューニングできるところが無いか探し, まだオンメモリ化できていない, /api/rooms をオンメモリ化する作業を行っていました.
ここには全然リクエストが来ていなかったので, 高速化してもスコアは伸びないと思ってましたが, 遅いせいでワークロードが下がりリクエストが来ていないのかもと思い一応着手しました.

インフラの構成変更が最優先だったので, この変更はなかなかベンチをかけれず..

終了30分前には複数台構成が落ち着き, node.js に対する謎の変更も入り, 最高点 83560点 を記録.
このあと /api/rooms のオンメモリ化をデプロイしてみると 13000点 程度に落ちてしまったのでエラーも見ずに巻き戻し.

安全にゴールしようという事で全台再起動試験. 問題なくうまく立ち上がり一安心.
しかし, ベンチをかけてみるとなぜか 55729点. 83560点 と同じ構成のハズなのに..

もう一度ベンチをかけると 59296点. なんだかスコアが不安定である.
会場の他チームがラストスパートをかけた為Azure東日本リージョン全体が重くなったのか, 再起動時にハズレインスタンス引いたのか.

とにかく1分毎に Enqueue を押して, 良いスコアが出るのを祈る... が 55855点 でFINISH.

終了後

ベスト時に比べると 27000点も低いスコアで終わってしまったので不完全燃焼.
ベスト時のスコアなら優勝だったのに! という事にならないかとても不安でした.

練習してきた事はちゃんと発揮できたし, 役割分担も良かった. 後悔は無いね, という感じでドキドキの結果発表.

最初に75000点を超えたということで特別賞を受賞.
その後, 2位の発表でスコアが3万点台だったのを見てガッツポーズ! 優勝を確信しました.

懇親会

初対面の方が多かったですが, 優勝チームということもありたくさん絡んでもらえました.
みなさん個性的で面白い方ばかり, 1日同じ問題に取り組んだ人同士の会話は盛り上がらないはずはなく, 懇親会はあっという間に終わりました.

他にも, 高専プロコンつながりで知っていた沖縄高専の学生チームと話したり, 秋葉さん imosさんの 競プロC++ チームと絡んだりでき, 非常に楽しかったです.

勝って飲む酒の美味しいこと!!!

感想

毎年予選あたりの時期は忙しい事が多く, 練習時間がとれず過去2回予選落ちし, 本選に出場できたのは今回が初めてでした.
今年こそ本選に行くぞ! という気持ちで今年は予選1ヶ月前から練習を開始しました.

ISUCON では, アプリの改造する為の知識はもちろん, HTTPのキャッシュの管理, MySQL や nginx のチューニング, カーネルパラメータのチューニングなど, 上から下まで知識が要求されます.
そもそも存在を知らなければチューニングできませんし, 付け焼き刃の知識では試行錯誤で時間が奪われます.

普段からGoでアプリを書いている人, 普段からインフラをメンテナンスしている人, 幅広い知識があり全体を見て方針を決めれる人 のチーム構成は完璧だったと思います.

優勝賞金は, もうすぐ発表になると予想されている MacBook Pro の新型を買って, ISUCONステッカーを貼ります. これでモチベーションを上げて来年からも優勝目指すぞ!

最後に, ISUCON の練習に業務時間をたくさん使わせて頂きました. 本当に感謝してます. いつか還元するので許してください :)