KLabGames Tech Blog

KLabは、多くのスマートフォン向けゲームを開発・提供しています。 スマートフォン向けゲームの開発と運用は、Webソーシャルゲームと比べて格段に複雑で、またコンシューマゲーム開発とも異なったノウハウが求められる領域もあります。 このブログでは、KLabのゲーム開発・運用の中で培われた様々な技術や挑戦とそのノウハウについて、広く紹介していきます。

カテゴリ: Go

(本稿はKLab Advent Calendar 2016 の1日目の記事になります)

今年もアドベントカレンダーの季節がやって来ました。お祭り騒ぎと年末進行の勢いで、普段は書かないような変なネタも含めてKLabエンジニア陣が多彩なエントリーをお届けします。

最初は昨年に引き続きKLabアドベントカレンダーの旗振り役をさせていただいてますoho-sからです。 よろしくお願いします。

はじめに 「進歩した科学は魔法と見分けがつかない」

皆さんは不老不死に興味はありますか? 古今東西、人々は伝説に宗教にそして現実にそれを追い求めて来ました。 でも、そもそも「生きている」ってどういうことなのでしょう。 現代の生物学においても、その定義は非常に曖昧です。 特に急進的な主張としては、一個体の生物を構成する物理化学生物的な現象を全て完全に正確に模倣したら、それは生きているということではないか、というものです。 そして、その主張にのっとり、近年のSFで科学的に現実的? な方法としてよく見られるのが、脳のコンピュータへのアップロードです。

これは、人間の脳を構成するあらゆる情報をデータ化したうえで、ものすごい性能のコンピュータにシミュレーションさせることで、人間がコンピュータ上で生きていけるのではないか、という考え方です。 そうすれば、コンピュータ上のあらゆるデータと同じように、バックアップもとれるし、コピーもできるし、電源がある限り動き続けられるし、これ、不老不死じゃん! ということです。

もちろん、人間の神経細胞は140億個以上あるといわれ、それら同士の結合はさらに大変な数になります。当然現在の最高性能のコンピュータをもってしても、シミュレーションは不可能です。 さらに、神経細胞同士の接続の性質も完全にわかっているとはいいがたい状況です。

では、一方で、「その人」を維持するに足る正確さで各神経細胞や、その相互の接続の情報を取得することができるのでしょうか?

生物学の世界では、生物の全遺伝情報、いわゆるゲノムがデータ化できた現在、次のターゲットは、脳の神経細胞とその全結合情報のデータ化となっています。 電子顕微鏡やその他の観測手段を用いてデータ化していくのです。 そして、一個体の全神経細胞とその全接続の情報のことを「コネクトーム」と呼び、一部の生物のコネクトームはインターネットで公開さえされているのです。

つまり、自分自身のコネクトームを作成し、それをシミュレーションできたら不老不死になれそうです。 そう、SFの登場人物たちはきっとこうやって、いとも簡単に脳をコンピュータにアップロードし、コピーし転送しバックアップしアップグレードし、そして進化しているのでしょう。

しかし、ちょっと待ってください。エンジニアなら「それどんなミドルウェア使ってるの?」って気になりませんか? RDBMSのバックアップさえ一仕事なのに、一貫性や同一性やその他諸々は本当に大丈夫なのか。むしろどんなデータ構造なのか。 気になるところはいくらでも出て来ます。 そこで、GraphDBです。

コネクトームとGraphDB 「電気線虫はアンドロイドの夢を見るか?」

まずはコネクトームとはどのようなデータになるのかを具体的にお話ししましょう。 現在、公開されているコネクトームとしては、線虫( C. Elegans )のコネクトームがあります。 線虫は体長1mmほど、全細胞数およそ1000個、神経細胞は300個くらいです。 コネクトームの実態は、神経細胞をノード、それらの接続をエッジとしたグラフデータです。エッジの属性として、電気的・化学的結合の強さが格納されます。 つまり、このようなデータを永続化したり神経活動をシミュレーションしたりなどの様々な処理をするには、グラフデータを扱うのに適したデータ管理システム、そう、GraphDBがあればいいということになります。

GraphDBとは、その名の通りグラフデータ構造を格納して処理するためのDBMSです。 有名なものとしては、Neo4jなどがあります。 ノードとエッジからなるネットワークのようなデータ構造を、テーブルからなるデータ構造を管理するRDBMSのように、管理するものです。 RDBMSでグラフ構造を扱ったことのある人は、その煩雑さと低性能に悩まされたことがあるかもしれません。RDBMSでグラフ構造を扱うのは非常に難しいと言われています。GraphDBは最初からグラフデータ構造を扱うために設計されているために、はるかに速く安全にグラフ構造を管理できるのです。

GraphDBや、グラフデータを扱う仕組みは、例えばSNSのユーザー間の関係性であったり、検索対象ドキュメントの間の関係性であったりと、様々な対象が現実にあり、近年利用が進んでいる分野です。

ということで、本稿では、Go言語でグラフデータを格納し永続化できる簡単な仕組みを実際に作成し、そこに線虫のコネクトームを格納して、その線虫を不老不死にしてみましょう。

GraphDBを作る 「Connect! A to B」

まずはバックエンドのデータストアを決めます。もちろんここでグラフに向いた独自データストアを作り始めてもいいのですが、今回はLevelDBを使います。GoでLevelDBを使うに当たっては、公式ドキュメントと、こちらを参考にしました。 LevelDBはいわゆるKVSなので、グラフデータに適したキーを設計しなければいけません。今回は、以下のようなキーの構造にしました。

ノード

Name Size Description
NodePrefix=0x01 1byte プリフィックス
type 2byte タイプ
ID 4byte ID

エッジ

Name Size Description
EdgePrefix=0x02 1byte プリフィックス
FromID 4byte 始点ノードのID
Direction 1Byte エッジの方向
Type 2Byte タイプ
ToID 4byte 終点ノードのID

LevelDBはバイト列の前方一致による検索が可能なので、これで、

  • ノードの全検索
  • ノードのタイプによる検索
  • ノードのタイプとIDによる検索
  • エッジの全検索
  • エッジの始点IDでの検索
  • 始点IDと方向での検索
  • 始点IDと方向とタイプでの検索
  • 始点IDと方向とタイプと終点IDでの検索

ができます。 一方で、このキー構造だと、終点から始点への検索ができないので、エッジを格納するときは、始点から終点までの前向きエッジと終点から始点までの後ろ向きエッジを同時に格納することで解決しました。

こちらが、実際に作ってみたリポジトリです。

以下にノードとエッジのコードを提示します。

また、DBのOpenや検索等のためのコードが以下になります。

公開されている多くのGraphDBには、ロックやトランザクションや各種制約、クエリ言語やサーバーとして動かすための仕組みなどがありますが、今回はLevelDBにグラフ構造を永続化して、簡単なノードの検索とエッジの検索ができるようになったということで、ここまでにしておきます。

線虫のコネクトームを格納する 「発進」

線虫のコネクトームデータはこちらのものを利用しました。オリジナルのデータはdoi: 10.1126/science.1221762.を参照してください。dot形式のデータで取得してテキストエディタ等で置換とマクロでTSV形式の単純なデータに変換しました。

実際のデータはこのようなものです。

これを作成したGraphDBに読み込みます。

読み込みは以下のようなコードを書きました。

// InputFromTSV read two tsv files (node and edge) and insert node and edge into DB
func inputFromTSV(db *graphdb.GraphDB, nodefilename string, nodetype int16, edgefilename string, edgetype int16) {
    nodefile, err := os.Open(nodefilename)
    if err != nil {
        panic(err)
    }
    defer nodefile.Close()

    nodereader := csv.NewReader(nodefile)
    nodereader.Comma = '\t'
    for {
        record, err := nodereader.Read()
        if err == io.EOF {
            break
        } else if err != nil {
            panic(err)
        }

        node := &graphdb.Node{
            Nodetype: nodetype,
            ID:       no2ID(record[0]),
            Value:    []byte(record[1]),
        }
        db.AddNode(node)
    }

    // ==========================================================================

    edgefile, err := os.Open(edgefilename)
    if err != nil {
        panic(err)
    }
    defer edgefile.Close()

    edgereader := csv.NewReader(edgefile)
    edgereader.Comma = '\t'
    for {
        record, err := edgereader.Read()
        if err == io.EOF {
            break
        } else if err != nil {
            panic(err)
        }
        db.AddEdge(no2ID(record[0]), no2ID(record[1]), edgetype, []byte(record[2]+","+record[3]))
    }
}

func no2ID(no string) []byte {
    noint, _ := strconv.Atoi(no)
    id := make([]byte, 4)
    binary.LittleEndian.PutUint32(id, uint32(noint))
    return id
}

そして、まずは永続化した線虫のコネクトームをDOT形式で書き出し、データの確認をします。

func main() {
    db, _ := graphdb.Open("celegans.db")
    inputFromTSV(db, "c.elegans_neural.male_node.tsv", NEURON, "c.elegans_neural.male_edge.tsv", CONNECTION)

    db.PrintGraph2DOT()
}

以下が出力したdot形式ファイルをGraphVizで書き出したものです。

C. Elegans のコネクトーム

次に、ノードに接続するエッジを検索してみましょう。 コードはこんな感じになります。

func main() {
    db, _ := graphdb.Open("celegans.db")

    start := db.GetNode(NEURON, no2ID("0"))

    edges := db.GetNodesEdge(start)

    for _, edge := range edges {
        fmt.Println(graphdb.Byte2string(edge.To))
    }
}

さらに、こうすると、Hop数を変えてノードを羅列できます。

func main() {
    db, _ := graphdb.Open("celegans.db")

    start := db.GetNode(NEURON, no2ID("0"))
    fmt.Println(graphdb.Byte2string(start.ID))

    rec(db, start, 0, 4)
}

func rec(db *graphdb.GraphDB, node *graphdb.Node, curdepth int, maxdepth int) {
    curdepth++
    if curdepth == maxdepth {
        return
    }

    edges := db.GetNodesEdge(node)

    for _, edge := range edges {
        fmt.Println(strings.Repeat(" ", curdepth) + graphdb.Byte2string(edge.To))

        next := db.GetNode(NEURON, edge.To)

        rec(db, next, curdepth, maxdepth)
    }
}

いかがでしょう。これで僕のPC上で線虫が不老不死となりました。

・・・そんなわけない!

まとめ 「未来を予測する最善の方法」

今回はあくまでも実生物の神経ネットワークを使いやすい形で静的に永続化したにすぎず、生物のダイナミックな「生きている」という性質は、シミュレーションを動かしたりしなければ得られません。不老不死ははるか遠い。

今回、なぜこのような題材を選んだかということを最後に説明しないと意味不明になりそうなので、説明しておきます。

まず、GraphDBに興味があったこと、特に、今あるものを利用するのではなく、どう実現されているのかに興味があったので実際に作ってみようと考えました。 また既存のGraphDBはサーバーを立てて使うものが多いのですが、プログラム組み込みで使うものが欲しかったというのもあります。 と言っているところで、EliasDBというものを見つけました。 今回は、それRDBMSでもいいじゃんというレベルしか実装できませんでしたが、GraphDBはとても面白いので、今後も勉強していきたいと思います。

そして、GraphDBを使った題材を考えていて、コネクトームというものを知り、これだ!と思ったわけです。 コネクトームに関しては、ロボットに線虫のコネクトームを元にしたシミュレーションシステムを接続し、電子線虫サイボーグを作る研究など、とてつもなく未来な研究が実際に行われています。例えば、ここです。興味のある方は調べてみると面白いと思います。

それでは、引き続きこの後のKLabアドベントカレンダーをお楽しみください。

こんにちは, @mecha_g3 です.

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

他のメンバー参加記事:

予選とその反省

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 の練習に業務時間をたくさん使わせて頂きました. 本当に感謝してます. いつか還元するので許してください :)

@tenntennです。

現地時間の2016年7月11日〜13日にアメリカのコロラド州デンバーにて開催されたGopherConにて発表をしてきました。

GopherConとは?

GopherConは、毎年デンバーで開催される世界でもっとも大きいGo(Go言語)のカンファレンスです。
今年で3回目の開催になります。
GopherConと名前の付くカンファレンスは、デンバーで開催されるGopherConの他にもGopherCon IndiaやGopherCon Chinaがあります。
GoのWikiに世界各地で行われているカンファレンスまとめてあるのでそちらを見ると分かりやすいかなと思います。

今年のGopherConの参加者は1500名を超えているらしく、3トラックに分けて発表が行われました。
他のカンファレンスと比べても非常に規模が大きいことが分かります。

GopherConで発表するまで

今年のGopherConも2種類の形式のセッションが募集されました。
通常セッション(発表30分・質疑なし)とチュートリアルセッション(発表50分・質疑込み)です。
通常セッションは午前中にメインステージ(1500人席)で行われ、チュートリアルセッションは3トラックに分かれて行われました。

GopherConで発表を行うためには、プロポーザルを提出する必要があります。
プロポーザルは、タイトル、概要、詳細などを英語で書きます。
タイトルと概要は採択後にWeb上で公開されるもので、詳細は公開されません。
そのため、詳細の方はネタバレの情報を含んでいても構わなく、できるだけ詳細に具体的なことを書きます。

今年の1月1日にCall For Proposal (CFP) がオープンし、締め切りは1月末でした。
私は、Droid Kaigi 2016のCFPが通った勢いでGopherConの方にもえいやと応募してみることにしました。
応募の動機は、GopherConに参加したかったことと、今年は英語能力をのばそうと考えていたので、その具体的な目標にちょうどいいかなと思ったからです。

発表するネタをあれこれ考えている間に、とうとう締め切りの日が近づいてきていました。
Droid Kaigiが50分の発表でしたので、GopherConも同じく50分のチュートリアルセッションに応募することにしました。
発表するネタは、Droid Kaigiでも発表したGo Mobileに決めました。

そこからプロポーザルを書いていきました。
はじめは日本語を書いて英語に翻訳するという作業でプロポーザルを考えていましたが、締め切り間際になると英語で直接文章を考えるようにしました。
これは英語の文章を書くいい練習になりました。

無事締め切りギリギリでプロポーザルを提出し、ひと安心しました。
しばらくすると、思いがけないプロポーザル通過の案内がきて大変驚きました。
それはGopherConに参加できる喜びと、最大規模のGoのカンファレンスで発表する緊張の入り混じった気持ちでした。

そこからは具体的な内容を詰めたり、新しい話のネタを探したりして、発表資料づくりを行いました。

Go for Mobile Games

私のセッションでは、「Go for Mobile Games」というタイトルで、Go MobileというGoのモバイルアプリ開発向けのツールキットについて発表を行いました。

発表資料は、GoogleスライドとSlide Shareにアップロードしてあります。

発表に使った原稿についても以下のURLから閲覧できるようにしてあります。

当日の発表の様子は録画されており、後日Youtubeにて公開されるとのことなので、Gopher Academyの再生リストに追加されるでしょう。

今回の発表では、このブログでも取り上げている、Go MobileのNativeアプリの開発について扱っています。

具体的には、

  • SDKアプリとNativeアプリについて
  • Nativeアプリでゲームを作る方法
  • Google Playへの公開
  • JavaのAPIをGoから呼ぶ方法

についてお話しました。

資料には記載していますが、Unityのネイティブプラグインを作る方法については、時間が足りずお話することができませんでした。
興味のある方はQiitaに記事を書いていますので、そちらをご覧ください。

当日の発表の様子

当日の発表は、写真のような500名ほど入る部屋で行われました。
緊張していてあまり覚えていませんが、それなりに人は入っていたような気がします。
プレゼンの様子

発表ギリギリまで資料を調整し、原稿を手直しました。
発表は原稿を読みながらやろうと割りきっていたので、そこまで不安はありませんでした。
ちなみに、発表原稿は紙に印刷して持って行きましたが、滞在中に修正を加えたため、結局はGoogle DocsをNexus 9で開いて発表しました。

しかし、その時になると機器トラブルが起こり、3台PCを取り替えてもスクリーンに映らず、4台目でようやく映りました。
プレゼンできないんじゃないかと不安になりましたが、カンファレンススタッフの方たちのおかげでどうにか発表を開始できました。

発表の途中に気づいたのですが、機器トラブルに加えて、別の問題も起きました。
自分のMacで発表できない場合に備えて、Googleスライドの原稿をpptxやPDFに変換したものを用意していました。
しかし、pptxまでは直前の調整の結果を反映していたのですが、PDFに反映を忘れており、ようやくスクリーンに映せた4台目のMacにはパワーポイントが入っておらず、結局古い状態の資料で発表することになりました。
PDFなのでスライド中に貼っていたGIFが動かなかったのは非常に残念でした。

また、発表時間は50分だったのですが、発表開始と同時にカウントダウンタイマーが動く予定でしたが、動いておらず、今自分が何分話しているのか分からないまま発表するという事態になりました。
発表練習では、だいたい時間どおりに発表できていたので、うまく時間どおりに発表できたと信じたいところです。

発表した感触としては、英語はまだまだ改善の余地があり、内容についてはもう少し盛り上がる要素を入れればよかったなと思いました。
それでも50分の英語の発表は、これまでに経験したことのなかったのでいい経験になりました。
質問も発表時間内は時間がなくて受けれませんでしたが、発表終了後にいくつか頂いたので興味をもって頂けたのかなと思いました。
発表資料については、最後まで調整するのは仕方がないことだと思いますが、PDFへの反映を忘れたり、GIFのことを忘れたりしないようにしたいです。

次も機会があれば英語での発表に積極的にチャレンジできればと思います。

他のセッションについて

11日と12日は、通常セッション(30分)とチュートリアルセッション(50分)、そしてLT(6分)の3種類のセッションが行われました。
各セッションのスライドについては、以下のgithubのリポジトリに順次アップロードされると思います。

私が特に面白かったと思う発表は以下の通りです。
括弧の中は発表者の名前です。

Understanding nil (Francesc Campoy Flores)

nilについて理解を深めることのできるセッションでした。
各型におけるnilの意味、特にインタフェースのnilの話などを改めて復習できてよかったです。
またレシーバをnilにしてもメソッドが動くことを利用して、nilをうまく使う方法についても説明されていました。

Visualizing Concurrency in Go (Ivan Daniluk)

このセッションでは、ゴールーチンのビジュアライズの話がされてました。
ゴールーチンをビジュアライズすることで、ゴールーチンのリークや並列度の有効性などを視覚的に分かりやすくなるという話でした。

Inside the Map Implementation (Keith Randall)

マップがどう実装されているのかという話でした。
コアな話でしたが、面白かったです。

The Design of the Go Assembler (Rob Pike)

こちらはまだ完全に理解が追いついてないのですが、1.5で導入されたGoのアセンブラの話でした。
中間コードのようなものを吐き出して、そこから各アーキテクチャごとのバイナリを生成するというような話だったかと思います。
Go 1.5からクロスコンパイルが簡単になったのもこの機能のおかげのようです。
ビデオが公開されたらもう一度見なおしてみようと思います。

Go Mobile as the Backbone of Lantern for Android (José Carlos Nieto)

私のセッションと同じく、Go Mobileの話でした。
こちらのセッションでは主にSDKアプリの話がされていました。
LanternというサービスでどうGo Mobileを使っているかという話でした。

The Go Gopher: A Character Study (Renee French)

このセッションではGoのマスコットのGopherのャラクターデザインについて原作者自ら話すというものでした。
Gopherがどう生まれたのか、Gopherの体の仕組みやデザインのルールなどを知ることができました。
また、Goのコミュニティで描かれているGopherのイラストが紹介され、私もGopherアーティストとして紹介してもらいました(笑)
Gopherの原作者に私の描いたGopherが気に入ってもらえているようで、とても光栄です。

Hack Day

13日は、セッションが開催されず、かわりにHack Dayといういわゆるもくもく会が行われました。
いくつかテーマごとに部屋に分かれて、もくもくと手を動かすというものでした。
私は、GoBotのワークショップに参加しました。

Edisonのスターターキット(写真参照)を使ってLEDをチカチカさせたり、音をならしたりと一通りのセンサーを使ってみるというワークショップでした。
Edison上でもクロスコンパイルしたバイナリが簡単に動いて、Goのクロスコンパイルの偉大さが改めて身にしみました。
GoBotもお手軽につかえて楽しかったです。
今度はドローンの操作もやってみたいと思います。

ワークショップで使ったキット

ワークショップで使用した資料は以下のリポジトリで公開されています。

After PartyとSpeaker's Dinnerについて

1日目の夜は、お店を貸し切ってAfter Partyが行われました。
また2日目の夜は、スピーカーとカンファレンスオーガナイザー、Goチームが参加するSpeaker's Dinnerが行われました。
どちらも普段話せないような著名な方々と話す機会ができて、非常に嬉しかったです。
これだけでも十分GopherConで発表する意義があるかなと思います。

全体を通した感想

Goのみを扱っているということで内容の濃い3日間でした。
緊張と時差ボケで一部の発表があまり聞けなかったのが残念でしたが、聞けたものはどの発表も内容が濃いものばかりでした。
発表内容は、業務上で得たノウハウを基にしたものか、Goのコアな実装の話が多かったのではないかなと思います。

カンファレンスの運営という点から見ても、有料とはいえGopherConの運営はしっかりしているなと思いました。
スピーカーへ発表内容へのアドバイス、参加者に対する気配りなどが随所に見られて関心しました。

また来年もスピーカーとして参加できたら良いなと思っています。

研修を担当しました

@tenntennです。

今年度の新卒研修でGo研修を担当しました。
スライドで100ページを超えるボリュームの資料を14時間かけて、じっくり網羅的に講義を行いました。
内容は今まで私が外部で発表したスライドをまとめて補足を足していった形になってます。
資料はSlide Shareに公開してあるので、ぜひチェックしてみてください。
また、資料中に扱っているソースコードもGithubで公開していますので、そちらも参考にしてください。

研修をやってみて

新卒の反応は、普段触れない言語に触れて新鮮だったという反応やゴールーチンとチャネルが難しいなどさまざまでした。
スパルタ気味で進め方が少し早かったせいか、ついていくのが大変だったみたいです。
それでも、自主的にpingコマンドを作ってくる強者もいたり、いい刺激になったんじゃないかと思います。

裏話

実は最初はGoで簡易ゲームエンジンを作って、さらにそこから各自ゲームを作る研修をしようと考えてましたが、ちょっとボリュームが大きすぎて、座学+課題の形に落ち着きました。
こちらで研修やっても面白かったでしょうが、それはちょっとスパルタすぎだったかもしれません(笑)

この記事は KLab Advent Calendar 2015 の19日目の記事です。

pprof 連載最後は、 ここまでで紹介してきたプロファイラがどういう仕組みでプロファイリングしているかを解説します。 pprof が表示している値がどう計算されているのかを把握することで、よりプロファイラを理解して使いこなすことができるようになるはずです。

goroutine profile

スタックダンプ (/debug/pprof/goroutine?debug=1) の出力は次のような形式でした。

...
1 @ 0x42d2b3 0x42d374 0x414cda 0x45d981
#   0x42d2b3    runtime.gopark+0x163        /usr/local/go/src/runtime/proc.go:186
#   0x42d374    runtime.goparkunlock+0x54   /usr/local/go/src/runtime/proc.go:191
#   0x414cda    runtime.runfinq+0xaa        /usr/local/go/src/runtime/mfinal.go:154

213 @ 0x42d2b3 0x42d374 0x403570 0x402ca3 0x4011a8 0x45d981
#   0x4011a8    main.NewCounter.func1+0x48  /home/inada-n/work/techblog/20151218_inada-n/stack-sample.go:13
...

実はこれも pprof が利用できるプロファイル結果と同じフォーマットです。 # で始まる行はコメントで、 サンプル数 @ コールスタック が pprof が利用しているデータです。 (コメント行は ?debug=1 をつけていないときは出力されません。)

スタックダンプは、取得時点の全 goroutine のスタックトレースを取得して、 1 goroutine を 1 サンプルとしてカウントしていました。
他のプロファイラーも、いつどこで1サンプルとなるスタックトレースを取得するかやファイルフォーマットは異なりますが、最終的に go tool pprof が表示する手前でコールスタックごとのサンプル数という形になります。

CPU profile

/debug/pprof/profile のハンドラーから追いかけて行きましょう。

// Profile responds with the pprof-formatted cpu profile.
// The package initialization registers it as /debug/pprof/profile.
func Profile(w http.ResponseWriter, r *http.Request) {
        sec, _ := strconv.ParseInt(r.FormValue("seconds"), 10, 64)
        if sec == 0 {
                sec = 30
        }

        // Set Content Type assuming StartCPUProfile will work,
        // because if it does it starts writing.
        w.Header().Set("Content-Type", "application/octet-stream")
        if err := pprof.StartCPUProfile(w); err != nil {
                // StartCPUProfile failed, so no writes yet.
                // Can change header back to text content
                // and send error code.
                w.Header().Set("Content-Type", "text/plain; charset=utf-8")
                w.WriteHeader(http.StatusInternalServerError)
                fmt.Fprintf(w, "Could not enable CPU profiling: %s\n", err)
                return
        }
        time.Sleep(time.Duration(sec) * time.Second)
        pprof.StopCPUProfile()
}

runtime/pprofStartCPUProfile を直接レスポンスに出力させて、指定時間 (デフォルトは30秒) 待ってから StopCPUProfile を呼んでいます。

StartCPUProfile は、 Unix では setitimer(ITIMER_PROF, ...) を使って、CPU使用時間 10ms ごとに一度 SIGPROF シグナルを受け取り、そのたびにスタックトレースを取得し渡された io.Writer にバイナリ形式で書き出していきます。 Windows では ITIMER_PROF が無いので、 優先度を最高にしたスレッドで 10ms 周期のタイマーを待ち、タイマーが発火する度に動作中の goroutine のスタックトレースを取得します。

CPUプロファイルの出力は pprof の元となった google perftools の CPU プロファイルのバイナリフォーマットで、スタックトレースを集計せずに追記していき、 pprof ツール側で集計しています。 表示するときは、 10ms に一度サンプルを取得しているので1サンプルあたり10msに換算して時間表示をしています。

この方式は sampling profiler と呼ばれ、ある程度のサンプル数がまとまらないと精度がでないので、 10ms や 20ms という表示は無視しましょう。

heap profile

Go のプログラムでメモリをヒープから確保するとき、アロケータ (runtimemallocgc という関数) が実際のメモリ確保を行います。
ヒーププロファイラはこのアロケータに統合されていて、 runtime.MemProfileRate で指定された容量を確保する度に、アロケータを呼び出した箇所のスタックトレースを取得します。

Memo: 実際には MemProfileRate を平均とした乱数でサンプリングすることで、プログラムのメモリ確保のパターンによって特定の箇所を実際の割合以上にサンプリングしてしまうことを避けています)

そしてアロケータはスタックトレースごとにアロケート回数、アロケートしたバイト数を記録しておき、さらにGCによってそのメモリオブジェクトが解放されるときに解放した回数、開放したバイト数を保存するようにします。

最終的にメモリプロファイルを取得しフォーマットするときは、 google-perftools のヒーププロファイラと同じフォーマットを利用しています。これは次のようなフォーマットになっています。

heap profile: 46592: 90221136 [105937: 236992760] @ heap/2048
1: 71303168 [1: 71303168] @ 0x40aaa2 0x4099eb 0x401289 0x401808 0x42dd60 0x45e4d1
1: 17768448 [1: 17768448] @ 0x440ed1 0x401739 0x401816 0x42dd60 0x45e4d1
15304: 244864 [15304: 244864] @ 0x445397 0x44521f 0x463876 0x401149 0x401808 0x42dd60 0x45e4d1
15284: 244544 [15284: 244544] @ 0x445397 0x44521f 0x463876 0x40123b 0x401808 0x42dd60 0x45e4d1

最初の1行はヘッダで、 46592: 90221136 の部分はトータルの inuse_objects: inuse_space で、 次の [105937: 236992760][alloc_objects: alloc_space] です。 @ heap/2048 は、 MemProfileRate * 2 が 2048 であることを示しています。 (2倍になっているのは google-perftools との互換性のため。)

以降の行がプロファイル結果です。 @ マークの後がスタックトレースなのは他のプロファイルと同様です。 @ マークの左側はヘッダと同じ書式で、そのスタックトレースにおける inuse_objects: inuse_space [alloc_objects, alloc_space] を表しています。

pprof ツールは、 inuse と alloc のどちらをパースするかを最初に選択したうえで、 objects: space を読み込んで、 MemProfileRate を元に推定値を計算します。
例えば 15304: 244864 の場合、平均のアロケートサイズは 244846 / 15304 = 16 バイトになります。 MemProfileRate が 1024 のとき、 16 バイトのアロケートは 16/1024 = 1/64 なので 64 回に1回の割合でサンプリングされることになります。 そこで objectsspace 両方を 64 倍した値が pprof が表示する推定値となります。

保存したプロファイルを利用するときの注意点

pprof は http 経由でプロファイルを取得したときに protobuf を圧縮した形式 (.pb.gz) で $HOME/pprof 配下にプロファイル結果を保存しますが、元になるプロファイル結果をパースする段階で inusealloc を選んでいるので、保存するファイルにも http 経由で取得する段階で選択していた方だけが記録されています。

前の記事でメモリーリーク調査のために pprof の -base オプションを使って差分を計算する手順を紹介しましたが、この時に inusealloc の差分を取ってしまうと全く意味のない結果が表示されることになるので注意が必要です。

なお、 objects: space はペアで保存されているので、例えば -inuse_objects で取得した .pb.gz-inuse_space で参照するのは問題ありません。

いっそのこと、ヒーププロファイルは生のプロファイル結果を curl で取得してしまって、差分を計算するスクリプトを作ったほうがリークの調査には良いかもしれません。この記事を書くために調査していて気づいたので、今度試してみます。

count profile

runtime/pprof パッケージを使って、 goroutine プロファイルと同じように単純なスタックトレースごとのカウントを表現するプロファイラーを自作できます。次のソースコードは、コネクションプールの利用状況をプロファイルすることを想定したサンプルコードです。

package main

import (
    "math/rand"
    "net/http"
    _ "net/http/pprof"
    "runtime/pprof"
    "sync"
    "time"
)

var poolProf = pprof.NewProfile("conns")

type Conn int

type ConnPool struct {
    m        sync.Mutex
    freelist []*Conn
}

func (p *ConnPool) Get() *Conn {
    p.m.Lock()
    defer p.m.Unlock()
    var c *Conn

    if len(p.freelist) > 0 {
        last := len(p.freelist) - 1
        c = p.freelist[last]
        p.freelist = p.freelist[:last]
    } else {
        c = new(Conn)
    }

    poolProf.Add(c, 2)
    return c
}

func (p *ConnPool) Put(c *Conn) {
    poolProf.Remove(c)
    p.m.Lock()
    p.freelist = append(p.freelist, c)
    p.m.Unlock()
}

var pool = &ConnPool{}

func workerA() {
    for {
        time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
        c := pool.Get()
        time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
        pool.Put(c)
    }
}

func workerB() {
    for {
        time.Sleep(time.Duration(rand.Intn(50)) * time.Millisecond)
        c := pool.Get()
        time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
        pool.Put(c)
    }
}

func main() {
    go http.ListenAndServe(":6000", nil)

    for i := 0; i < 10; i++ {
        go workerA()
        go workerB()
    }
    for {
        time.Sleep(time.Second)
    }
}

pprof.NewProfile でプロファイルを作成し、 .Add でスタックトレースを登録し、 .Remove で解除します。 .Add.Remove の第一引数は、 .Remove が解除するスタックトレースを指定するためのキーで、 .Add.Remove のペアで同じ値を利用します。同じキーを並行で利用することはできませんが、 .Remove 後に同じキーを .Add で再利用することは可能です。

このプロファイルを pprof を使って解析してみます。

$ go tool pprof pool-prof localhost:6000/debug/pprof/conns
Fetching profile from http://localhost:6000/debug/pprof/conns
Saved profile in /home/inada-n/pprof/pprof.pool-prof.localhost:6000.conns.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
10 of 10 total (  100%)
      flat  flat%   sum%        cum   cum%
         6 60.00% 60.00%          6 60.00%  main.workerB
         4 40.00%   100%          4 40.00%  main.workerA
         0     0%   100%         10   100%  runtime.goexit
(pprof) list main.main
Total: 10
(pprof) list main
Total: 10
ROUTINE ======================== main.workerA in /home/inada-n/t/pprof/pool-prof.go
         4          4 (flat, cum) 40.00% of Total
         .          .     45:var pool = &ConnPool{}
         .          .     46:
         .          .     47:func workerA() {
         .          .     48:   for {
         .          .     49:       time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
         4          4     50:       c := pool.Get()
         .          .     51:       time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
         .          .     52:       pool.Put(c)
         .          .     53:   }
         .          .     54:}
         .          .     55:
ROUTINE ======================== main.workerB in /home/inada-n/t/pprof/pool-prof.go
         6          6 (flat, cum) 60.00% of Total
         .          .     54:}
         .          .     55:
         .          .     56:func workerB() {
         .          .     57:   for {
         .          .     58:       time.Sleep(time.Duration(rand.Intn(50)) * time.Millisecond)
         6          6     59:       c := pool.Get()
         .          .     60:       time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
         .          .     61:       pool.Put(c)
         .          .     62:   }
         .          .     63:}
         .          .     64:
(pprof)

workerA が4つ、 workerB が6つのコネクションを利用中であることが判りました。

このプロファイルは goroutine プロファイルど同じ種類 (カウントプロファイル) なので、 ?debug=1 というクエリパラメータをつけてプレインテキストで見ても十分役に立ちます。

$ curl http://localhost:6000/debug/pprof/conns?debug=1
conns profile: total 14
6 @ 0x401315 0x45dcf1
#   0x401315    main.workerA+0x45   /home/inada-n/t/pprof/pool-prof.go:50

8 @ 0x4013b5 0x45dcf1
#   0x4013b5    main.workerB+0x45   /home/inada-n/t/pprof/pool-prof.go:59

例えば DB にクエリを投げてから結果が返ってくるまでをプロファイルしてみると面白いかもしれません。

↑このページのトップヘ