2014年09月

「golang で sql, template, http リクエストのパフォーマンスメトリクスとるライブラリ作った」の実装メモ

golang で sql, template, http リクエストのパフォーマンスメトリクスとるライブラリ作った #isucon の実装メモ。


時間計測コード

最初はこう書いていた。

func (proxy *DB) Exec(query string, args ...interface{}) (sql.Result, error) {
    if Enable {
        startTime := time.Now()
    }
    ret, err := proxy.Original.Exec(query, args...)
    if Enable {
        proxy.measure(startTime, query)
    }
    return ret, err
}

が、golang なら defer があるので、それを使うとすっきりする。

func (proxy *DB) Exec(query string, args ...interface{}) (sql.Result, error) {
    if Enable {
        startTime := time.Now()
        defer proxy.measure(startTime, query)
    }
    return proxy.Original.Exec(query, args...)
}

startTime と elapsedTime (proxy.measure の呼び出し) の計測箇所を1つにまとめられて良い。

埋め込みを使うと共有インスタンスへの委譲はできない

golang で委譲といったら埋め込みであるが

type Foo struct {
    Embeded
}

type Bar struct {
    Embeded
}

foo := &Foo{}
bar := &Bar{} 

のようにしてしまうと、当然であるが、Foo インスタンス、Bar インスタンスそれぞれに対して、Embeded インスタンスが1つずつできる。

Foo インスタンス、Bar インスタンスで共通のインスタンスに委譲したい場合は、

type Foo struct {
    embeded *Embeded
}

type Bar struct {
    embeded *Embeded
}

embeded := &Embeded{}
foo := &Foo{embeded}
bar := &Bar{embeded}

のように埋め込みをやめて、通常の has-a 関係にして、同一のインスタンスを設定するしかない。埋め込みではなくなるので、メソッドを自分で1つずつラップして委譲を実現するしかない。

go-sql-metrics では db の複数インスタンスが connection pool されて使い回される可能性、もしくは都度接続するために毎回作り直される可能性があるため、インスタンスごとに metrics オブジェクトがリセットされてしまわないように、共通の metrics オブジェクトを持たせたかった。そのため、こうする必要があった。

追記:コメントで、ポインタの Embed にすればインスタンスを渡せると教えてもらった。

type Foo struct {
    *Embeded
}

type Bar struct {
    *Embeded
}

embeded := &Embeded{}
foo := &Foo{embeded}
bar := &Bar{embeded}

なるほど!
しかし、よくよく考えたら、go-sql_metrics では、db.Original のように生の委譲オブジェクトを取り出せるインターフェースを用意しておいてあげたいという要件があるので、結局

type Foo struct {
    Original *Embeded
}
のように書く必要があり、結果 Original へのメソッドを自分で1つずつラップして委譲を書かないといけないのであった。それとも、埋め込みで委譲オブジェクト取り出せるのだろうか?まだ良くわかっていない。

interface は後付け定義できる

Java のイメージで interface というと

interface TemplateInterface {}
class HtmlTemplate implements TemplateInterface {}
class TextTempalte implements TempalteInterface {}

のように、まず interface 定義があったうえで、class が定義されるものだった。

go-template_metrics を作る際に、html/template, text/template 両方に対応したかったが、 構造体定義をみても共通の interface が定義されていなかったので、Java のイメージで「interface ないのか、じゃあ無理だな」と思ってしまっていた。

ところが、golang では interface を後付けで定義することができる。go-template-metrics では

type templateInterface interface {
    Execute(wr io.Writer, data interface{}) error
    ExecuteTemplate(wr io.Writer, base string, data interface{}) error
}

のように interface を内部で定義し、メソッドの定義をこの interface に対して行う事で、html/template, text/template 両方に対応したメトリクスライブラリを作る事ができた。

interface を後で自由に定義して静的ダックタイピングできるというのは自分にとって大きな気付きであった。 

#isucon ISUCON4に参加してスコア 40618 でした (GoMiami)

ISUCON4 に GoMiami チームとして去年と同じメンバの @SpringMT と @niku4i と自分(@sonots)で参加してきた。名前だけ Miami から GoMiami に変えた。

事前戦略

優勝賞金100万円!今年もやります 第4回 ISUCON 開催と日程のお知らせ #isucon

  • 予選はAmazon Web ServiceのEC2を利用
  • 出題者側で作成したお題アプリ、ベンチマークツールが乗ったマシンイメージを公開

と書いてあったので、去年と同じような形式かな、とこの時点で勘ぐっていた。

ruby だと GVL があるので、マシン1台でも複数プロセス立ち上げる必要があって、そうなるとキャッシュ戦略進めるときに redis を使ってマルチプロセス間メモリ共有とかする必要があるけど、golang なら1プロセスでもコアを有効に使い切れるので、マシン1台だったらグローバル変数にでも保存してアプリ内のメモリに載せちゃえばいいだけだし、単体でも速いので、予選最強言語なんじゃないか?とか思って、勉強もかねて golang で出る事にした。

ISUCONすでに始まっている。

事前準備

nginx.conf や my.cnf のチートシートなんかはあらかじめ作っておいて、メンバに共有してた。

あと、golang でも ruby で newrelic 使ってやっていた時みたいに、HTTPリクエストにかかった時間、DBへのクエリでかかった時間、テンプレートの処理にかかった時間、I/Oでブロックされた時間、とか見れないものかと、golang の勉強がてらプロファイラ調べたりメトリクスライブラリ作ったりしてた

作ったメトリクスライブラリについては別の記事にしているのでそちらを見てもらいたい => golang で sql, template, http リクエストのパフォーマンスメトリクスとるライブラリ作った #isucon

当日(午前中)

午前中はメトリクスとったり、アプリの動作把握、戦略を立てる時間にあてた。これは去年の反省を活かしている。

インフラ担当の @niku4i に公開鍵とかミドルウェアのセットアップとかメトリクス取るための準備とかやってもらって、自分はまずアプリにメトリクス計測コード仕込むのやってから golang のコード読んで、SpringMT 氏は ruby のコード読んでアプリの仕様把握とかやってた(ruby のほうが一枚のファイルに書いてあってシンプルで読みやすいとか言い訳してた)

午前中にとったメトリクスはこんなかんじだった(全体はこちら)

nginx アクセスログ集計(自作スクリプト)。

sum(sec)                count   mean(sec)               endpoint
49.86099999999994       812     0.06140517241379303     /login
19.007  1       19.007  /report
4.347999999999992       178     0.024426966292134786    /mypage
1.4199999999999682      1624    0.0008743842364531824   /images/isucon-bank.png
1.2739999999999734      1446    0.0008810511756569664   /
1.2629999999999764      1624    0.0007777093596058967   /stylesheets/isucon-bank.css
1.2209999999999812      1624    0.0007518472906403826   /stylesheets/bootstrap.min.css
1.1919999999999826      1624    0.0007339901477832405   /stylesheets/bootflat.min.css

クエリ集計 (mysqldumpslow)

Count: 812  Time=0.03s (25s)  Lock=0.00s (0s)  Rows=1.0 (812), root[root]@localhost
  SELECT COUNT(N) AS failures FROM login_log WHERE ip = 'S' AND id > IFNULL((select id from login_log where ip = 'S' AND succeeded = N ORDER BY id DESC LIMIT N), N)

Count: 805  Time=0.03s (20s)  Lock=0.00s (0s)  Rows=1.0 (805), root[root]@localhost
  SELECT COUNT(N) AS failures FROM login_log WHERE user_id = N AND id > IFNULL((select id from login_log where user_id = N AND succeeded = N ORDER BY id DESC LIMIT N), N)

Count: 4037  Time=0.00s (17s)  Lock=0.00s (0s)  Rows=1.0 (4037), root[root]@localhost
  SELECT COUNT(N) AS cnt FROM login_log WHERE user_id = N AND N < id

以下略

明確に /login と上3つのクエリが遅くて、コードを読むと、クエリ1つ目は isLockedUser という /login 時に user_id ベースのユーザがロックされているか判定しているメソッド、クエリ2つ目はisBannedIp という /login 時に IP が Ban されているか判定しているメソッド、クエリ3つ目はbannedIPs という /report で使われている所だったのでチューニングしなくてよさそう、ということが分かった。

また、クエリ1つ目、2つ目はどうやらログイン失敗回数を数えているだけっぽい。ということがわかった。

この時点で、1回ミーティング開いて、どういうアプリかシェアしたり、どういう戦略でいくか決めたりしてた。この時に出たアイデアはこんなかんじ

  1. 起動のタイミング(init.sh)で login_log テーブルを読み込んで failure count の構造体に突っ込んでオンメモリキャッシュさせる。1分の制約があるけど間に合うかどうかまずはやってみる。
  2. login_log テーブルへの insert のところ(/login)で、failure count++ するか reset するかロジックを入れる。
  3. isLockedUser と isBannedIp でキャッシュを参照するように書き換える。キャッシュにヒットしなかったら今まで通りのコードに通して1回だけ SELECT してキャッシュするようにする(1. がうまくいかなかった時用)
  4. ユーザデータを丸ごとキャッシュ
  5. Last Login をキャッシュ
  6. レギュレーションに静的ファイルの md5 が違っても加点されないだけで失格にならないと意味深なことが書いてあるしいじってみる?

1 〜 3 が支配的で、4 以降はそんなに効かないだろうなって認識だった。

当日(午後)

昼飯食べながらコードもくもく読んで、キャッシュの構造体とか考えて、実装しはじめた。

担当は最初、次のように決めてからスタートした。

  • (sonots) 1. の実装
  • (SpringMT) 2., 3. の実装
  • (niku4i) 残りのミドルウェア設定(nginx で静的ファイル返すとか)とテーブルにインデックス貼る作業(init.sh)

1. 起動時の failure count のキャッシュ

最初、users テーブルから user_id とりだして、全ユーザの failure count 計算の SELECT 文発行する、って愚直に書いてみたら全然終わらなかった。

SpringMT 氏がアイデアがあるって言って、login_log テーブルに記録されている user_id だけ取り出すように書き換えて(実際はもうちょいクエリ頑張ってある)、すぐフィニッシュするようになった。ナイス。

2. 3. /login での failure count のキャッシュ

SpringMT 氏から実装があがって来てたんだけど、なんか fail するって言われて 1. はまかせてこっちのバグ取りしてた。

attemptsLogin の中に defer があって、途中で return もされているので、attemptsLogin の一番下でキャッシュするのではなくて、defer の中でキャッシュしないといけなかった。

あと、isLockedUser のほうの閾値が IPBanThreshold に変わっててそれに気づかなくてハマってた。 静的片付け言語とはいえ、コンパイル通っちゃうし、golang でブレークポイント貼ってデバッグする方法がないから(gdb?)、printf デバグやってて時間かかった。簡単に使えるデバッガ欲しい!

大分もたもたしてて最初の実装が終わったのが 15:00 になってからで、ここで 17000 ぐらい。 完全に実装がおわって 30000 いったのが、16:00 になってからだった。出遅れた!!って話してた。

16:00

その後 4, 5, 6 もやってみて、38,000 ぐらいだったかな。6. は特に意味なかった。

あとはこの辺で too many open files とか TIME_WAIT なソケットが多すぎるよ的なエラーが出てたから @niku4i が ulimit 設定したり、tcp_tw_recycle を設定したりしてたと思う。その辺信頼してて完全におまかせしてたからあとでブログ書いてくれると思う。

16:50

この時点でもう1度メトリクスとってみた結果がこちら。もうほとんどクエリがないし、アプリにチューニングポイント残ってなくない?って話をしてた。

なのでもう niku4i と SpringMT 氏はミドルウェア側いじってたと思う。ログはずしたりとか keepalive ON/OFF してみたり workload 調整してみたりとかかな。完全におまかせしてたからあとでブログ書いてくれると思う。

自分は、Martini の template をなんとか外せないかともうひと踏ん張りしてた。もう 16:50 なので、Martini 外しはあきらめて top ページだけでもなんとかできないかと頑張って、martini-contrib/render の HTMLメソッドの中身みて、 template を展開している所を、ただの文字列結合にするようにおきかえた TopHTML という ISUCON4 専用のメソッドを生やすとかやった。 renderer が小文字スタートのプライベート構造体になっていて、外からメソッド生やせなかったので、fork して直接書いてやった。Martini マジ fxxk。これを滑り込みで入れてあと 2000 ぐらいあがった。

最後 40,600 ぐらいでフィニッシュした。


golang でやった感想

良かった点

  • 1台である限り、プロセス間メモリ共有しなくてすむのでキャッシュ戦略がすごい楽だった。
  • コンパイル時にチェックしてくれるので typo ミスとかだいぶ防いでもらえた。

悪かった点

  • ruby の byebug みたいにブレークポイントを貼ったデバグが実質できなくてデバグに四苦八苦してた。※ LiteIDE とか使うと IDE 上で breakpoint はったりはずしたりが簡単にできるけど、ISUCON 環境を Mac 上に作る時間なんてなかった
  • err 処理のコード量が多くて見通しが悪かった。ruby 実装のほうがシンプルだった。
  • defer 見逃しててハマってた。golang 特有の複雑さだ、とか言ってた。

競技の感想

良かった点 

  • 去年の反省を活かして、最初にメトリクスをとって戦略会議をやる、という流れで進めたのは良かった。
  • ハマったら交代してカバーし合ってたのはよかった。時間がない中1人でハマり続けると時間だけがすぎるので他の人に目を通してもらったほうが早い。
  • 去年と違って、時間内にやりきった感あった。

改善点

  • 最初もたもたしててスコアが出るまで時間がかかってしまった。瞬発力あげたい。

おわりに

たぶん 40k 〜 45k あたり団子状態で、土曜日1日目は再計測の点数がスコアになるのでマジドキドキしてる。本戦出たい!!!たのむ〜〜

追記:ISUCON4 本戦出場者決定のお知らせ 残った!終わってみれば 41705 点で全体の13位でした。本戦頑張るぞい!!


おわってから試したこと

  • benchmarker v2 で試す
    • benchmarker v1 にバグがあったという経緯があるので、benchmarker v2 ではかりなおしてみたら 43.1k 行った。
    • どうやらインスタンスガチャもあったっぽい。
  • nginx => app を unix domain socket に変える
    • golang 力低くて net/http はサポートしてないし、どうやるんだってなって競技中はできなかったけどやってみた => https://gist.github.com/sonots/87972440cd2063504902
    • やってみたけど、スコアあがらなかった。ポート枯渇対策としては良いと思う。
  • dummy_users.tsv 読み込んで生パスワード持ってきて、calcPasswordHash を避ける
    • 生パスワード見る銀行ってどうなん?とか思いながら一応あとでやってみたけど、全然スコア伸びなかった。
  • mysql のデータ保存先を tmpfs におきかえる
    • ほとんどアクセスない今、全然スコア伸びなかった。
    • ちなみにレギュレーションに「ベンチマーク実行時にアプリケーションに書き込まれたデータは、再起動後にも取得できること。」という規定があるので、シャットダウン時にディスクにコピーして、起動時にディスクから tmpfs にコピーするとかやらないと失格になると思う
  • nginx worker_process の数と GOMAXPROCS をコア数の 4 から 32 にあげる
    • これで 4000 ぐらいあがった。マジか ...
  • MARTINI_ENV=production
    • これで 3000 ぐらいあがった。そんなの知らなかった。Martini マジ fxxk。
  • Martini はずし
    • Martini はずして生の net/http にしてさらに 3000 ぐらいあがった。Martini マジ fxxk。
    • やっぱり golang 歴1ヶ月の自分では時間がかかったので、競技中は無理だったな、という印象。力量にあった判断だった。  
  • template はずし
    • Martini はずしの段階では html/template のままにしてたのをさらに、sprintf に置き換えてみた
    • スコアあがらなかった
  • トップページの静的ファイルを5パターン用意して、nginx で捌く
    • 3000 伸びた。む、そんなものか 

あとやってないもの

  • login_log の INSERT もキャッシュ
    • でもこれも省いてしまうと、レギュレーションの「ベンチマーク実行時にアプリケーションに書き込まれたデータは、再起動後にも取得できること。」という規定を満たせなくて失格になるから、やれるとしてもデータ構造変えるぐらいか?

いま、なんとか 53k いったぐらい。60k への伸ばし方がわからない。



追記: さらに試している

ブログ記事が公開されてきたので、そんな手が!と思ったものを試してみている。

  • INSERT は MyISAM のほうが早いらしいので、MyISAM にしてみる

    • 特に伸びす
  • INSERT を goroutine で逃がす

    • 伸びた気がしたが、もう一度測ったら下がったのでただの誤差っぽい
    • まずは単純に逃がしてみたけど、裏で goroutine の数膨れ上がってそう。ちゃんと1 goroutine 内で遅延実行するようにしないとホントはダメだけど次が本命なので手抜き。
  • login 時はキャッシュにいれるだけにしておいて /report アクセス時にDBに INSERT する

    • 4000 向上。なるほど〜、この発想がなかった。
    • 普通に INSERT したら1分以内に終わらなかったが、bulk insert にしたらちゃんと終わってくれた。
  • user_id をキーにしたキャッシュの構造体を map じゃなくて配列にする

    • fujiwara 組 はそんなところまで気にしているのかと感嘆
    • 手抜きで全部 map にしていたが、たしかに配列のほうが O(1) 確定するので早い。影響でるほどとは思わないけど
    • => 特に伸びなかった
  • ログイン失敗理由の頻度にあわせて switch 文の順番を変える

    • fujiwara 組 はそんなところまで気にしているのかと感嘆
    • しかし、実際は影響出るほどとは思えないがどうだろう
    • => 特に伸びなかった
  • nginx ではなく varnish で静的ファイルを捌く(トップページ含む)

    • 58k から 52k に下がってしまった。
    • varnish => nginx => app と階層が1つ増えてしまったから? nginx のほうでキャッシュ設定ちゃんとやればそれでいい気がする。
  • 標準ライブラリの StaticFileHandler ではなく、 ファイルの内容をメモリ上に置いて Write するだけのハンドラを用意 して golang で直接うける。

    • go-bindata と go-bindata-assetfs でやってみた
    • 3000 落ちてしまった。バイナリデータとしてビルド時に含めるからこれでいけるかと思ったんだけど、あまりパフォーマンス良くないライブラリなのかな ...
  • GOGC=500 で benchmarker 走らせる

    • 16k 伸びたw
  • おもむろに css, img リンクを消す

    • 60k 伸びたww
    • 試したかっただけなので JS は作ってない
  • tcp_fastopen

    • sudo sh -c "echo 0x403 > /proc/sys/net/ipv4/tcp_fastopen"
    • 700 ぐらい伸びたけど、誤差の範囲内か??

現在12万ww

まぁでも後ろの二つを除いて実質 58k かな。60k 超えないのはパラメータ微調整の問題だろうか

その他やるべきだったこと

  • pprof をちゃんとみてメソッド単位で重い処理を特定する
    • methane さんはそれで MARTINI_ENV=production にたどりついたらしい。仕込むだけ仕込んであまり見ないでしまったので反省
  • ベンチマークツールの挙動解析
    • fujiwara 組 はそれで静的ファイルのリンクを削る戦略にいきついたらしい。全く考慮に入れてなかったので反省

そもそもISUCONというのはベンチマークツールをいかに高速に回すかという勝負なのですが、100msかかっていたモノを99msにしてもスコアは1%しかあがらないですが、2msかかっていたモノを1msにすると同じ1msの短縮でもスコア自体は2倍になるんですね。

あ、はい。 

golang で sql, template, http リクエストのパフォーマンスメトリクスとるライブラリ作った #isucon

ruby とかでは newrelic を使うと HTTP リクエストを捌くのにかかった時間に加えて、DBアクセスにかかった時間、テンプレートレンダリングにかかった時間、I/O にかかった時間(外部サービスへの HTTP リクエストにかかった時間)、みたいな内訳が見れる。

今年の ISUCON は golang で出ようと思っていたので、チューニングするにあたって、golang でも気軽にそういうのを見れるツールがないと捗らないよな、と思って探したけどなかったので golang の勉強がてら作ってた。FYI: ちなみに gorelic というものはあったんだけど、あれは pprof の情報を newrelic を使ってグラフ化しているだけで欲しいものとは違った

net/http のメトリクスと、(text|html).template のメトリクス、database/sql のメトリクスが取れる。

ruby の場合は、メタプログラミングという名の黒魔術ができるので、計測したいコードに対して外から処理を追加しやすい。他所の gem からでも既存のクラスに対して差し込める。

golang の場合はそういうのができないので、ラップする形にした。どういうことかというと、sql_metrics の場合の実装はこんなかんじ

package sql_metrics

func WrapDB(name string, db *sql.DB) *DB {
    proxy := proxyRegistry[db]
    if proxy == nil {
        proxy = newDB(db, metrics)
        proxyRegistry[db] = proxy
    }
    return proxy
}

func (proxy *DB) Exec(query string, args ...interface{}) (sql.Result, error) {
    if Enable {
        startTime := time.Now()
        defer proxy.measure(startTime, query)
    }
    return proxy.Original.Exec(query, args...)
}

.... 以下略

使うときはこんなかんじ

  // db, err := sql.Open("sqlite3", "foo.db")
  _db, err := sql.Open("sqlite3", "foo.db")
  db := sql_metrics.WrapDB("foo", _db)

  // Use as usual
  result, err := db.Exec("INSERT INTO memos (id, body) VALUES (?)", id, body)

つまり、*sql.DB を *sql_metrics.DB にラップして、*sql_metrics.DB 経由でいつものようにメソッドが呼ばれると時間が計測されるようになっている。

template_metrics の場合は (text|html).Template をラップして、http_metrics の場合は http.Handle および HandleFunc をラップするようになっている。

実際の使い方はそれぞれの README を見てもらうと良い。

出力結果

lltsv と sort を組み合わせて整形しているけど、ISUCON3 のアプリに仕込んでベンチを走らせてサマリを出力させるとこんなかんじになる。 左から合計時間(秒)、呼び出し回数、平均時間(秒)、対象のクエリ(とかリクエストとか、テンプレートとか)である。

$ grep query app.log | lltsv -k sum,count,mean,query -K | sort -n -r
42.515819   411 0.103445    SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ? OFFSET ?
29.318021   836 0.035069    SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=?  ORDER BY created_at
23.003601   830 0.027715    SELECT count(*) AS c FROM memos WHERE is_private=0
19.085289   419 0.045550    SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ?
6.244089    170 0.036730    SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? ORDER BY created_at DESC
6.204839    158 0.039271    SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? AND is_private=0 ORDER BY created_at
0.702008    1303    0.000683    SELECT * FROM users WHERE id=?
0.636161    1085    0.000619    SELECT id, user, content, is_private, created_at, updated_at FROM memos WHERE id=?
0.260924    83994   0.000254    SELECT username FROM users WHERE id=?
0.125518    170 0.000738    SELECT id, username, password, salt FROM users WHERE username=?
0.119622    170 0.000704    UPDATE users SET last_access=now() WHERE id=?
0.101019    170 0.000594    INSERT INTO memos (user, content, is_private, created_at) VALUES (?, ?, ?, now())

$ grep handler app.log | lltsv -k sum,count,mean,handler -K | sort -n -r
112.595701  1085    0.109529    memoHandler
71.088976   411 0.172966    recentHandler
49.193846   419 0.117408    topHandler
10.577193   170 0.062219    mypageHandler
0.489704    170 0.002881    memoPostHandler
0.473548    170 0.002786    signinPostHandler
0.320596    5464    0.000312    public
0.281419    170 0.001655    signoutHandler
0.094454    170 0.000556    signinHandler

$ grep template app.log | lltsv -k sum,count,mean,base -K | sort -n -r
75.879037   994 0.076337    memo
8.848884    830 0.010661    index
2.688126    170 0.015813    mypage
0.060962    170 0.000359    signin

LIMIT OFFSET なクエリが遅いな、とか memo テンプレートが遅いな、とかすぐわかる。

ベンチを通した全体のサマリだけじゃなくて(時間で指定)、リクエストのあるたびに出力することもできるので、ブラウザから手で叩きながら画面ごとのクエリの数をみて「げぇ、N+1 クエリだ」とか見つけるのもやりやすい。

あと、この出力結果をアプリから newrelic とか mackerel に投げてグラフ化できたりすると実運用でも捗りそうだな、と思っている。まだその仕組みは作ってないけど。

ISUCON4 では

これが ISUCON4 では大活躍しまっっっした!というと嘘で、このツールには制約があって、net/http, (text|html)/template, database/sql が露出されているフレームワークじゃないと仕込むのが難しい。

gorilla とかなら露出されているから良いんだけど、たとえば martini のようなフレームワークを使われると、中に net/http, html/template が隠されているので、ラッパーインスタンスを作れるタイミングがない。

で、ISUCON4 では martini だったわけで。。。 martini マジ martini 。。。

結局 nginx のアクセスログ集計スクリプト(自作)でなんとかしましたとさ。スクリプトも用意しておいて良かったね。ちゃんちゃん。

PS. どなたか golang で既存の struct の メソッドに時間計測コードを外から差し込む方法をご存知の方はいらっしゃいませんか?くやしいっっっ!!


「Server::Starterに対応するとはどういうことか」の補足

こちらの記事のように unicorn を Server::Starter 経由で起動できるようにして、daemontools の管理下におこうとしていてハマってたのでメモ。

おさらい

おさらいしておくと、config/unicorn.conf に次のようなコードを書く事で unicorn を Server::Starter 経由で起動できる。Server::Starter の環境変数から open した socket ファイルディスクリプタを受け取れて、unicorn のほうで使えるようになる。

if ENV.key?('SERVER_STARTER_PORT')
  fds = ENV['SERVER_STARTER_PORT'].split(';').map { |x|
    path_or_port, fd = x.split('=', 2)
    fd
  }
  ENV['UNICORN_FD'] = fds.join(',')
  ENV.delete('SERVER_STARTER_PORT')
else
  listen ENV['PORT'] || '10080'
end

unicorn はそれ自体でホットリスタートの機能 (SIGUSR2 => SIGQUIT のコンボ) を持っているけど、master プロセスがみなしごになって daemontools の管理下から外れてしまうので使わない。server starter の pid に SIGHUP を送って server starter の機能で unicorn プロセスを新しく起動してもらってホットリスタートする形になる。daemontools に svc -h する形になる。

新しい unicorn master が立ち上がったら Server Starter は --signal-on-hup オプションで指定したシグナルを古い unicorn master に勝手に送って殺してくれるので、unicorn のホットリスタート機能より使いやすい(unicorn の場合、手動で QUIT を送り直さなければならない)。--signal-on-hup=QUIT にしておくと、QUIT シグナルを送ってくれて、unicorn は QUIT では graceful shutdown (リクエストを捌いてから終了) してくれるので良い。

ということで、そうしようと思ったらハマったのでメモ。

事実1. bundle exec 経由で unicorn を起動するとファイルディスクリプタが子プロセス(unicornプロセス)に渡らない

$ start_server --port=10080 --signal-on-hup=QUIT -- \
    bundle exec unicorn -c config/unicorn.conf config.ru
lib/unicorn/http_server.rb:784:in `for_fd': not a socket file descriptor (ArgumentError)

該当行のコードを開くと Socket.for_fd で死んでいる。4 番の fd が socket file descriptor ではない、と言われて死んでいる。なので fd を確認してみる。

親である Server Starter

$ ls -l /proc/24663/fd
lrwx------ 1 sonots sonots 64  9月 17 23:44 0 -> /dev/pts/2
lrwx------ 1 sonots sonots 64  9月 17 23:44 1 -> /dev/pts/2
lrwx------ 1 sonots sonots 64  9月 17 23:44 2 -> /dev/pts/2
lr-x------ 1 sonots sonots 64  9月 17 23:44 3 -> start_server
lrwx------ 1 sonots sonots 64  9月 17 23:44 4 -> socket:[1725527471]

子である unicorn のプロセス

$ ls -l /proc/24664/fd
lrwx------ 1 sonots sonots 64  9月 17 23:45 0 -> /dev/pts/2
lrwx------ 1 sonots sonots 64  9月 17 23:45 1 -> /dev/pts/2
lrwx------ 1 sonots sonots 64  9月 17 23:44 2 -> /dev/pts/2
lr-x------ 1 sonots sonots 64  9月 17 23:45 3 -> pipe:[1725527518]
l-wx------ 1 sonots sonots 64  9月 17 23:45 4 -> pipe:[1725527518]
lr-x------ 1 sonots sonots 64  9月 17 23:45 5 -> pipe:[1725527519]
l-wx------ 1 sonots sonots 64  9月 17 23:45 6 -> pipe:[1725527519]

確かに unicorn の4番が socket fd じゃない!!

普通に fork していれば fd は子プロセスに引き継がれるはずで何かがおかしいので、 bundler のコードを読む。

lib/bundler/cli/exec.rb

 14       begin
 15         if RUBY_VERSION >= "2.0"
 16           @args << { :close_others => !options.keep_file_descriptors? }
 17         elsif options.keep_file_descriptors?
 18           Bundler.ui.warn "Ruby version #{RUBY_VERSION} defaults to keeping non-standard file descriptors on Kernel#exec."
 19         end
 20
 21         # Run
 22         Kernel.exec(*args)

なにやら keep_file_descriptors という怪しい名前が見つかったので調べてみると、どうやら bundle exec でファイルディスクリプタを引き継ぎたい場合は --keep-file-descriptors オプションを指定する必要があるらしい。ref. http://bundler.io/v1.7/bundle_exec.html

そうしないと、Kernel.exec に close_others オプションが渡って、ファイルディスクリプタが閉じられる。 ref. http://docs.ruby-lang.org/ja/2.1.0/class/Kernel.html

解決策: bundle exec --keep-file-descriptors を使う

start_server --port=10080 --signal-on-hup=QUIT -- \
  bundle exec --keep-file-descriptors unicorn -c config/unicorn.conf config.ru
$ ls -l /proc/26090/fd
lrwx------ 1 sonots sonots 64  9月 18 00:12 0 -> /dev/pts/2
lrwx------ 1 sonots sonots 64  9月 18 00:12 1 -> /dev/pts/2
lrwx------ 1 sonots sonots 64  9月 18 00:11 2 -> /dev/pts/2
lr-x------ 1 sonots sonots 64  9月 18 00:12 3 -> pipe:[1725540588]
lrwx------ 1 sonots sonots 64  9月 18 00:12 4 -> socket:[1725540548]
l-wx------ 1 sonots sonots 64  9月 18 00:12 5 -> pipe:[1725540588]
lr-x------ 1 sonots sonots 64  9月 18 00:12 6 -> pipe:[1725540589]
l-wx------ 1 sonots sonots 64  9月 18 00:12 7 -> pipe:[1725540589

4番が socket fd になって起動できた。

補足:bunlde exec start_server ... は良くない
他にも bundle exec start_server ... と起動することも出来そうだが、これは実は良くない。

bundle exec start_server --port=10080 --signal-on-hup=QUIT -- \
  unicorn -c config/unicorn.conf config.ru

bundle exec がやっていることは実質環境変数を設定しているだけなので、 このように実行しても unicorn にもその環境変数は渡ってアプリを起動することができる。そして、start_server, unicorn 間は bundle exec を挟んでいないので fd が閉じられることもない。

のだが、このように起動すると bundler を新しくすることができない。start_server に SIGHUP を送っても古い bundler のまま (RUBYLIB 環境変数が古いまま)となってしまい問題となる。

事実2. foreman 経由で unicorn を起動するとファイルディスクリプタが子プロセス(unicornプロセス)に渡らない

理由は先ほどと同様で、foreman が悪さをしているのでファイルディスクリプタが渡らない.

lib/foreman/process.rb

 68       wrapped_command = "#{Foreman.runner} -d '#{cwd}' -p -- #{command}"
 69       Process.spawn env, wrapped_command, :out => output, :err => output

ここで spawn に :close_others => false を渡せればなんとかやりようがあるのだが、foreman はサポートしていない。

パッチをあてれば対応できるが、確かに単純にここでオプションを渡すと全ての Procfile 内のプロセスに影響が出てしまうので悩ましい。微妙すぎて pull req を送れない。

解決策: foreman を使わないw

事実3. unicorn が立ち上がりきる前に QUIT シグナルを送ってしまう

start_server --port=10080 --signal-on-hup=QUIT -- \
  bundle exec --keep-file-descriptors unicorn -c config/unicorn.conf config.ru

として起動し、start_server に HUP シグナルを送ると、新しい unicorn プロセスがたちあがり切っていないのに、スタートしたものとみなして QUIT を送ってしまう。

unicorn のログ。spawned の前に reaped が来てしまっている。 

received HUP (num_old_workers=0)
spawning a new worker (num_old_workers=0)
starting new worker 31688
new worker is now running, sending QUIT to old workers:31611
sleep 0 secs
killing old workers
I, [2014-09-25T15:27:00.799636 #31688]  INFO -- : inherited addr=0.0.0.0:10080 fd=4
I, [2014-09-25T15:27:00.799905 #31688]  INFO -- : Refreshing Gem list
I, [2014-09-25T15:27:00.832733 #31611]  INFO -- : reaped #<Process::Status: pid 31638 exit 0> worker=0
I, [2014-09-25T15:27:00.832901 #31611]  INFO -- : reaped #<Process::Status: pid 31641 exit 0> worker=1
I, [2014-09-25T15:27:00.833078 #31611]  INFO -- : master complete
old worker 31611 died, status:0
I, [2014-09-25T15:27:04.144681 #31762]  INFO -- : worker=0 spawned pid=31762
I, [2014-09-25T15:27:04.145343 #31762]  INFO -- : worker=0 ready
I, [2014-09-25T15:27:05.148449 #31765]  INFO -- : worker=1 spawned pid=31765
I, [2014-09-25T15:27:05.149028 #31765]  INFO -- : worker=1 ready
I, [2014-09-25T15:27:07.157861 #31688]  INFO -- : master process ready

解決策: --kill-old-delay オプションを使う

--kill-old-delay オプションを使うと、立ち上げはじめて指定秒数待ってから新しいプロセスにデータを dispatch してくれるようになる。待ってから古いプロセスに QUIT を送ってくれるようになる。うちでは 10 にしている。

start_server --port=10080 --signal-on-hup=QUIT --kill-old-delay=10 \
  bundle exec --keep-file-descriptors unicorn -c config/unicorn.conf config.ru

事実4. デプロイしたのに古いディレクトリを追いかけてしまう

例えば capistrano でデプロイすると current シンボリックリンクの指す実体が新しい releases ディレクトリになるが、 次のように先に cd してしまうと、古いディレクトリに chdir してしまった後になるため、 HUP シグナルを送っても、カレントディレクトリが変わらず、古いディレクトリのコードを読み込んでアプリを起動してしまう。

cd $HOME/app/current
start_server --port=10080 --signal-on-hup=QUIT --kill-old-delay=10 \
  bundle exec --keep-file-descriptors unicorn -c config/unicorn.conf config.ru

解決策: --dir オプションを使う

server starter には --dir オプションという、コマンドを再実行する前に chdir してくれるものがあるのでそれを使うと解決できる。

start_server --port=10080 --signal-on-hup=QUIT \
--kill-old-delay=10 --dir=$HOME/app/current -- \ bundle exec --keep-file-descriptors unicorn -c config/unicorn.conf config.ru 


(追加) 事実5. 一時的にプロセス数が二倍になってしまう

See Server::Starter で Unicorn を起動する場合の Slow Restart 対応






Fluentd ソースコード完全解説 at RubyKaigi2014

rubykaigi2014

RubyKaigi 2014 で Fluentd Hacking Guide (Fluentd ソースコード完全解説) と題して 発表してきました。

題名は Ruby 界隈の人達ならご存知のとおり RHG こと Ruby Hacking Guide (Ruby ソースコード完全解説) をもじらせて頂きました。

今回の発表は

  1. Fluentd を使ったことがある
  2. Fluentd のプラグインを書いたことがある

という人を対象にしたかなり尖った発表であり、 一体何人の人にリーチするのやらと思っていたのですが、 Fluentd を使ったことがない人にもわかりやすかったと言ってもらえたので良かったです。

実際の発表では vim でソースコードを開いて実際にコードを追いかけていくという RubyKaigi のような大会場でやっているのは見た事がないスタイルで発表してきました。ちょっとチャレンジングでしたが、トチって時間オーバーしたりしなくて良かった ^^;

スライドには vim で開いて解説した部分はもちろん載っていませんが、 同時通訳の方用に読み原稿として用意しておいた gist があるのでそれもおいておきます。当初 gist でやってしまおうかと思って気合いを入れて作った文書で、実際の発表では時間の都合上はしょっている部分も丁寧に書いているので、発表の内容を追いかけたい方にはこちらを見てもらったほうが良いかと思います。

=> 読み原稿: Fluentd ソースコード完全解説.md
=> 追加:ビデオ出てました => https://www.youtube.com/watch?v=u6teInqqN_0


ちなみに、あとで聞かれたので書いておきますが、アスキーアートのようなシーケンス図は、 asciiflow.com というウェブアプリを使って書きました。密かなマイブームアプリです。

Fluentd の今後について

今回は現行の Fluentd のバージョンである v0.10 ブランチのソースコードリーディングを進めましたが、 master ブランチでは experimental な機能を入れていて、近々? v0.12 というバージョンがリリースされる予定になっています。

master ブランチでは内部構造がドラスティックに変わっていきますが、 v0.10 ブランチには大きな変更は入らない予定でいるので、今回やった発表の内容は当分有効に使えるはずです。セキュリティフィックスなどのメンテナンス作業は続けて行きます。

なお、その v0.10 ブランチですが、メンテナは私がやることになりましたので、この場を借りて報告させて頂きます。 今後ともよろしくおねがいいたします。

A Ruby and Fluentd committer working at DeNA. 記事本文および記事中のコード片は引用および特記あるものを除いてすべて修正BSDライセンスとします。 #ruby #fluentd #growthforecast #haikanko #yohoushi #specinfra #serverspec #focuslight
はてぶ人気エントリー