last update: 2014/11/09

2014/11/09

#isucon 4の本戦で3位を取ってきました (追記あり)

みなさんISUCON4お疲れ様でした。まずはじめに運営のLINEさん、出題のクックパッドさん、そしていつも大量のサーバを提供していただいているデータホテル改めテコラスさんありがとうございました。ピザとお寿司おいしかったです。

さて、今回はベンチマークの気持ちになってCache-Controlヘッダをつけることが出来たかどうかだけがブレイクスルーできるかどうかを左右するという潔い問題でした。結果は既に既報のとおりで上位2チームだけブレイクスルーし、3位以下はずーっとネットワーク帯域にめいっぱいデータを流し続けてドングリの背比べとなりました。

1Gbpsの帯域を使い切るレベルまでアプリを高速化できると大体スコアが8000〜9000程度となるようで、最後の1時間までほぼ8000台に団子となっていましたが、Cache-Controlでブレイクスルーした2チームを除くと私の所属するfujiwara組の15000というのはそれの約2倍近くとなっており、逆にCache-Controlなしでどーやってそこまで行ったんだと気になる方もおられるかと思います。そんなわけで簡単にやったことを振り返っておきたいと思います。あ、「簡単に」って書きつつ例によって長いです。

11:00〜12:00 初動が大事

コードとレギュレーションをよく読んで、初期実装からPerl実装に切り替えてローカルモードでベンチマークして約10000。しかし、リモートモードはまだベンチマークサーバが不安定だったので試さず、ざっくり眺めて何が必要かを洗い出すことと、ベンチマークがどういう負荷のかけ方をしているかを確認しました。

11:58:36 acidlemon: まず
11:58:42 acidlemon: POST /slots/4-dreamy_lovelace/ads
11:58:48 acidlemon: の入稿が5本走り
11:58:55 acidlemon: GET /slots/4-dreamy_lovelace/ad
11:59:01 acidlemon: のImpressionが走り
11:59:22 acidlemon: GET /slots/4-dreamy_lovelace/ads/20 で実際に広告をとりにくる
11:59:52 acidlemon: 実際の動画は GET /slots/4-dreamy_lovelace/ads/20/asset で配信
12:00:01 acidlemon: これが5Mくらい返してる
12:00:29 acidlemon: そのあと
12:00:30 acidlemon: POST /slots/4-dreamy_lovelace/ads/20/count
12:01:02 acidlemon: でimpressionをincr
12:02:35 acidlemon: GET /slots/4-dreamy_lovelace/ads/20/redirect もよんで一通りのシーケンスがおわりかな
12:03:37 acidlemon: 43 POST /slots/__SLOT__/ads
12:03:41 acidlemon: これが入稿なんだけど
12:03:50 acidlemon: 入稿がおわったらあとずっとimpressionしかしてない

この時点でとりあえずベンチマーカーが一通り入稿しおわったらあと広告表示しかしてこないことを把握して、そこをいかによく回すかが勝負なんだーと確認しました。

12:00〜13:00 動画をRedisにいれるのをやめる/動画をアプリで返すのをやめる

とりあえずこの時点でネットワーク負荷をみたところガッツリOutトラフィックが出ていたので、こりゃ今回も複数台で返すようにしないと帯域勝負で勝てないなということで、1台専用になってたアプリをよく読んで何を改造しないと複数台で動かせないかを確認しました。

あと、この時点で1号機は1コア、2号機と3号機は2コアということがわかり、なんでやねん…という気持ちでいっぱいでした。

12:08:13 handlename: get_logするたびにファイル読んでパースしてってやってるので、パース済みのものをredisか何かに保存するとよさそう
12:08:18 acidlemon: srv1はredisにしてsrv2とsrv3でフロントにして捌くというのがよいような気がする
12:08:33 handlename: get_logはGET /me/reportと GET /me/final_reportで呼ばれてる
12:09:00 acidlemon: いま複数台構成にするネックがそのファイルに書いてるところなので
12:09:15 acidlemon: それをredisかなんかに吐くようにするのは必須

で、手はじめに使ってるモジュールでちょっと速くなりそうなところから手を入れました。具体的にはRedisをRedis::Fastにしたのと、JSONをJSON::XSにしたあたりですね。あと、Redisを1台にまとめて全部のサーバが1号機のRedisにアクセスするように変更しました。

また、アップロードされてきた5Mの動画がRedisに突っ込まれていたので、さすがにこれはねーだろーということでローカルディスクに保存するように変更しています。この時点では1台構成なのでローカルディスクに保存してnginxでそれをserveするだけでOKです。Rangeヘッダとかはnginxがよしなにやってくれるはず。

13:00〜14:30 複数台構成へ変更

動画をnginxで返すようにしてローカルベンチマークをすると大体スコアが16000くらい。ここでよーやっとリモートからのベンチマークがまともに使えるようになり、さっそくやってみると、えーとスコアが4100…?

dstatで確認してみると、ローカルベンチマークでは3台のサーバがほぼ青天井に近い速度で通信できますが、リモートベンチマークではそこまでスピードがでていません。おそらくVMの乗ってる物理マシンが与えられた3台では物理的に一緒だがベンチマークサーバーは別サーバーということで、物理的な制約でリミッターに当たっているようだと推測しました。

じゃあとりあえず複数台構成できるようにするねってことで、アプリを書き換えてTSVでログをファイルに書き出しているところをRedisのLISTに格納するように変更。30分くらいでサクッと書き換えて(珍しく)なんのバグも出ずに複数台構成が完了。ただ、動画ファイルは片方のサーバにしかないのでfujiwaraさんがnginxでtry_fileしてなかったら別のサーバにreverse proxyでfallbackするnginxの設定を書いてそれで捌くようにしました。

で、ローカルモードでベンチマークをかけて17000くらい。あれ思ったよりも上がらないな…。

14:30〜16:00 迷走の始まり

さて、この頃にはリモートベンチマークツールのベンチマークジョブが4チーム並列となり、スコアが安定しなくなります。うーんそうはいってもローカルベンチマークはめっちゃ安定して17000だしなぁ…ということで、いろいろなバリエーションを試しました。

  • ローカルIPでかけてみる
  • グローバルIPでかけてみる
  • workloadをあげてみる
  • 複数台をやめて1台だけでやってみる

などなど。結局の所スコアが非常にばらついて、300〜7000でばらついたのでこりゃわからんなという感じに。ただ、なんとなく傾向としては「グローバルIP側からリモートベンチをかけるとスコアが落ちる」「複数台にしてfallbackしてるとスコアがおちる」ような感じなので、そこをなんとかする方向で考えます。

複数台で捌きたいけどfallbackはしたくない、となると入稿があった時点で2台のフロントサーバの両方にファイルを配備すればよいのですが、GlusterFSは遅くて使いたくないし、だからといってじゃあどうやって撒くんだ…? となりました。

ここでfujiwaraがアプリの返すJSONを見て、JSONの中にassetのURLが入っているのを発見しました。Redisに保存している広告の情報にどこのサーバに格納しているかの情報を付加して、uri_forを使わずにそのサーバに行くように仕向けるということで対処をすることになり、handlenameが実装に着手しました。

この頃ぼくはなにをしてたかというと、帯域がいっぱいいっぱいなら転送効率をあげるっきゃないということで、じつはベンチマーカーのマシンがジャンボフレームとかに対応してたりするんじゃね? とping -M do 10.11.54.62 -s 5000を打ち込んだのですが、ベンチマークサーバからはMTUは1500だからあきらめろという感じのエラーが返ってきて「にゃーん」となったりしてました。

その他にやったのは、nginxでlimit_rateをかけて動画の転送速度を制限してみるなどもやったんですが、limit_rateはIPごとの制限になるので意味が無さそうということと、そもそも動画を転送しないとリクエストがどんどん押し寄せて飽和して結局ダメということがわかっています。

16:00-18:00 Hackを考える時間

どうしようもなくなってきたのと、リモートベンチマークが帯域をちゃんと使い切ってくれない(ゆらぎ/ブレがある)問題でなかなか解くのが進まないのとでじりじりする時間帯。

workloadを調整してみてもスコアは変わらず、相変わらず安定しないのでHackすることを考え始めました。ぼくが考えたのはスロット全部配信したらもう5倍確定だし、それ以降の動画は配信しない(めっちゃ遅く返す)というやつです。が、これをやるにはアプリが動画を返さなければならないので、えーそれはなーみたいな感じで躊躇して結局やりませんでした。

さてそんなことを考えていると17時すぎにいきなり1位スコアが333555点に。えーなんだそれとなり、5Mのファイルをまともに配信してたら絶対でないスコアなので、やっきになって秘孔探しを始めます。

じゃあとりあえずということで、25%まではERRORがでても大丈夫というルールを使って動画を返すところでnginxからreturn 200 " "みたいな感じで動画じゃないものを返すというのをやってみました。リクエスト数の分布をみると、動画は全体の15〜20%程度なので、これが全部ERRORになってもFATAL判定じゃなければ他のAPIがガンガン回ってそれなりのスコアはでるはず!

しかし現実はそんなに甘くありませんでした。動画を見に来るgoroutineはassetcountredirectの順にアクセスするのですが、assetの検証に失敗するとそこでルーティーンがabortしてしまい、count/redirectが呼ばれないのでエラー率が25%を越えてしまうのです。

じゃあ、一定確率で動画を空で返すか? とも考えたのですが、結局ちょっとでも動画を返すとたちまち帯域は埋まってしまうことが予想できたため、そこを深追いするのはやめました。

その他にも、動画配信ラッシュがはじまらないように出稿速度を律速するのを狙ってupload_limit_rateをかけるとか、アップロードするファイルの受け取りをAppではなくnginxにしてみるとかのアイディアも出ましたが、結局いろいろ問題が予見されたのでやりませんでした。

そうこうしているうちに30万点のスコアは更新されて7000点くらいまで落ち、なんだ再現性のないスコアか、ベンチマークツールのバグだったのかなー、忘れようとなりました。生ハム原木は30万点スコアをみてずっとそのスコアの再現に取り組んでたらしいので、そこで差がでてしまった…という感じです。

18:00-19:00 1台構成に戻す

さて、ここまででどうやら3台構成だろうが1台構成だろうが、ベンチマーカー側の帯域が1Gbpsで埋まっていて受け側が複数台いてもどうしようもなさそうということが見えてきました。

ここで、Idobataのサポートチャットでまた3台のスペック違いについて質問がでていて、かたくなに「お答えできません」と回答しているのを見たので、こりゃCPUが1個しかついてない1号機になにかあるのでは…となりました。これ、もしかして1号機だけじつは帯域が広くなってるとかあるんじゃね? などと邪推して、CPUも余ってることだし思い切って1号機だけで捌いてみるというのはどうかというのを提案してやってみることにしました。

すると、帯域は1Gbpsまでしかいかなかったのですが通信の安定度が2号機3号機とは全然違い、非常に快適に帯域が全部埋まりました。これが意図したモノなのかどうなのかは今でもわかってないですが、これなら1台構成で1号機にかけるのが一番スコア安定するねーということになりました。とはいえ、リモートベンチマークのスコア的には9000前後です。

で、15000のスコアになったのはここからの押しの一手がありまして、fujiwaraが18時半くらいにトイレから戻ってくるなり「ベンチマーク、1台にローカルIPとグローバルIPの両方からかけてみましょう」と。なるほど、うまくいけばそれで2Gbps使えるかも? ということでやってみると、10800程度のスコアになりました。

うーんもうちょっと伸びるかなーと思ったのですが、このときでもリモートベンチマークは2チーム並列になっていて専有ではなく、10800を出したときの前半は帯域が1Gbpsも埋まってない状態でした。しかし、dstatで観察していると後半は2Gbps相当の速度が出ていたのでもしかすると本番ではいけるのでは? となりました。おそらく物理機でグローバル側とローカル側が1Gbpsで別々のNICになっていたという感じなんですかね。

このあと、じゃあ3台構成でに6個のIPアドレスに向けてやってみようぜというのもやってみたのですがベンチが詰まって完走せず、1号機の1台構成でグローバル&ローカルIPのデュアル構成でベンチパラメータを提出。その結果、本番計測では2Gbps相当の帯域をだいたい使い切ったらしく、1Gbpsを使い切ったときのの約2倍のスコアで3位となりました。

感想など

いやーいかがだったでしょうか。今回の問題、Cache-Controlに気づけなくて本当に悔しいですねー。ちなみに私はCache-Controlという話が講評で出たときはやられたーというよりはどちらかというとマジかよーという感じでした。広告って不特定多数に配信するので1分程度の試行だとCache-Controlが効くほどユーザの数に対して配信しきれるのかなーと。

ベンチマークツールが実際のブラウザを模しているとはいえ、実際の広告でCache-Controlが効くのってその広告を一度みたユーザだと思います。今回ベンチマークツールが送ってくるUAは30個くらいあって、そのUAごとにCache-Controlが制御されてたんですかねー、というのが気になりました。

UAごとじゃなくてベンチマーク全体でのCache-Controlだと、たぶん10〜20秒くらいで出稿された動画を全部配信し終わるので、そのあとが全力ぶん回し勝負だと60万みたいなスコアがでてもおかしくないです。しかし、UAごとにCache-Controlを判定していればだと広告150本に対して30ユーザいると4500通りなので、UAに偏りがない限り同じUAが同じ動画を引くことはそれほどなかったのかなーというのがなんとなーくモヤモヤと残りました。まぁ負け惜しみですけどね!

まぁその辺はtagomorisさんがISUCON Maker Night的なやつを開催してくれるとのことですので、その場のお楽しみということにしましょう! れもんでした。

2014/11/09 10:15 追記: Cache-Controlの件、朝起きてまだモヤモヤしてたのでもうちょっと考えてみました。

まぁそんなわけで、まず動画を各ユーザに逐一配る発想をしてる時点でダメで、ベンチマークがかなり賢いというのはブラウザを模しているというよりもPOSTをパススルーして、なおかつCache-ControlつけてるときだけキャッシュするというCDNを模して作られていたという感じで考えるべきだったんですかね。そう考えるとまぁまぁ納得かな…。

逆にCDN全部通す想定だと普通はキャッシュしちゃいけないやつにno-cacheつけないと…みたいになるんですが、参考実装にCache-Control: no-cacheがなかったのはベンチがCache-Controlないやつはキャッシュしないと言う実装になってるからつける必要がなかったのと、たぶんCache-Controlでコントロールできることに気付かせないためというところですかね。結局の所結論は変わらず、「我々はやられてしまった」ということです。

Comment

2014/10/22

cgoでGolangとC++ライブラリをリンクするとき、何が起きているのか

関東も秋が深まり、「紅葉を見にいこうよう」と言ってスベるシーズンがやってきました。みなさんいかがお過ごしでしょうか、れもんです。

さて、自社サイトでGoやるよって発表したので最近はずっとGoを書いているのですが、ついに難題がやってきました。C++で書かれたライブラリをGoで使うというやつです。今日は、GoからC++のライブラリを使おうとするときに何が起きているのかという話と、それゆえにこのオプションを指定するとドツボにはまるのでやめた方がいいよという話です。

GoからC++を使うときの基本的な考え方はRubyとかPerlでC++のライブラリを使うときと同じです。なので、いつものセオリーでやってみることにしました。まぁC++なら素直にSWIG使えよって話もあるんですが、何事も最初は挑戦だってことで手で書きます。

そのいつものセオリーとは何かというと、C++のライブラリをCインタフェースで使えるブリッジを書いてCライブラリとして別言語から使う、というやつですね。基本的にC++でライブラリを作ると、明示しない限りリンケージはC++になっていますので、別言語で使おうとするとマングリング問題で呼ぶのが大変です。なので、extern "C"したCスタイルの関数でC++オブジェクトのポインタを返して、オブジェクトのメンバ関数を呼ぶのは第一引数をオブジェクトのポインタにしたC関数経由にする…というやつです。WindowsのCOMと似たような感じですね。

2分でわかるマングリング

マングリング is 何という人のために簡単に説明します。分かってる人は読み飛ばしてオッケーです。簡単のために、クラスのメンバ関数じゃなくて普通のグローバルな関数でvoid Hoge(int, const char*)という関数を考えます。

#include <cstdio>

void Hoge(int i, const char* str) {
    std::printf("i is %d, str is %s", i, str);
}

これをgcc -c test.cpp -o test.oでコンパイルして中間ファイルを生成して、中のシンボルをみるnmコマンドで調べてみます。

$ nm test.o
0000000000000000 T _Z4HogeiPKc
                 U printf

Hoge関数が_Z4HogeiPKcというシンボル名で格納されています。これが、C++のマングリング(名前修飾)です。なぜこうなるかというと、C++は名前同じで引数が違う関数を許容するので名前がシンボル名になってるとリンクする関数を解決できないからですね。このよくわからん_Z4HogeiPKcという文字列は、デマングルすることで可読性のある文字列に戻すことができます。それがc++filtコマンドです。

$ nm test.o | c++filt
0000000000000000 T Hoge(int, char const*)
                 U printf

こんな感じで読めるようになりました。ドヤッ!

で、別言語から呼ぶには_Z4HogeiPKcという関数名で呼べばいいんですが、さすがにマングリング規則を覚えてマングリングした関数名をすぐ書ける人はほとんどいないはずです。そこで使うのがextern "C"というリンケージ方法の変更です。さっきのソースコードをこう変更します。

#include <cstdio>

extern "C" {

void Hoge(int i, const char* str) {
    std::printf("i is %d, str is %s", i, str);
}

}

これをもう一度コンパイルしてnmコマンドにかけると、シンボル名が変わります。

$ nm test.o
0000000000000000 T Hoge
                 U printf

この状態なら、他の言語からHogeという関数名で呼び出しが可能です。

さてやっと本題です。そんな感じでC++のライブラリをCでラップしたのを書いたのですが、これをGoから呼び出すところで1日ほどハマりました。golangでC/C++のライブラリを使うときにはcgoという仕組みでライブラリをリンクします。

このとき、Goのソースコードでimport "C"する前にコメントでCヘッダと#cgoディレクティブを書くわけですが、これを書くと絶対失敗するので書いてはいけないオプションというのがあるのでそれのご紹介、というのが今日の本題です。

それは何かというと、リンクするライブラリがC++だからといって、#cgo CFLAGS-x c++を指定してはいけないという点です。

逆にこれを指定するとどういう悲劇が起こるかを知るには、cgo(gc)のビルドプロセスを知る必要があります。今回は最新のgo 1.3.3と、gcc 4.9.1を使っています(なお、go 1.2.2, gcc 4.4.7を使っても同じです)。

Goのビルドプロセスはgo [build|run]-xオプションをつけて実行すると実際に実行しているコマンドが見えます。長いのでここに掲載するのは省略しますが、その処理の中身を見ていくと、こんな感じです(x86-64環境なので6c/6lを使います)。

  1. import "C"しているgoのソースにcgoコマンドを実行して_objディレクトリにGoとCの間の呼び出しをブリッジするCソースコードを生成
  2. 6c, 6gコマンドで、cgoが生成したソースをコンパイルして.6ファイルを生成
  3. gccコマンドで、cgoが生成したソースをコンパイルして.oファイルを生成
  4. go tool packで.6ファイルと.oファイルを連結してgo形式の静的リンクファイル(command-line-arguments.a)を生成
  5. go形式の静的リンクファイルを6lコマンドにかけてネイティブ実行ファイルを生成

で、問題はCコンパイラ向けのCFLAGSに-x c++を指定したときに何が起こるかという話です。

こんな感じのGoとCヘッダをを書きます。前提として、別途Makefileでgccを使ってコンパイルするbridge.cppが別にあって、そこからbridge.aを生成しています。で、それを静的ファイルとしてGoが吐き出すバイナリに静的リンクするように#cgo LDFLAGSで指定しています。

$ cat bridge.h
extern "C" {

typedef void* App;
App CreateApp();
void Run(App);

}
$ cat main.go
package main
/*
#cgo CFLAGS: -x c++ -fpermissive
#cgo LDFLAGS: -lrt -lstdc++ bridge.a
#include "bridge.h"
*/
import "C"
func main() {
    app := C.CreateApp()   // create C++ app object
    C.Run(app)             // enter main loop
}

するとcgoはこんな感じのグルーコードを生成します。このコードはgo build -xで出てきたコマンドを1個ずつ手で実行しないとお目にかかれません。

$ cat main.cgo2.c
#line 2 "(...)/src/main.go"

#include "bridge.h"

// Usual nonsense: if x and y are not equal, the type will be invalid
// (have a negative array count) and an inscrutable error will come
// out of the compiler and hopefully mention "name".
#define __cgo_compile_assert_eq(x, y, name) typedef char name[(x-y)*(x-y)*-2+1];

// Check at compile time that the sizes we use match our expectations.
#define __cgo_size_assert(t, n) __cgo_compile_assert_eq(sizeof(t), n, _cgo_sizeof_##t##_is_not_##n)

__cgo_size_assert(char, 1)
__cgo_size_assert(short, 2)
__cgo_size_assert(int, 4)
typedef long long __cgo_long_long;
__cgo_size_assert(__cgo_long_long, 8)
__cgo_size_assert(float, 4)
__cgo_size_assert(double, 8)

#include <errno.h>
#include <string.h>

void
_cgo_32105cabc2a6_Cfunc_CreateApp(void *v)
{
        struct {
                App r;
        } __attribute__((__packed__, __gcc_struct__)) *a = v;
        a->r = CreateApp();
}

void
_cgo_32105cabc2a6_Cfunc_Run(void *v)
{
        struct {
                App p0;
        } __attribute__((__packed__, __gcc_struct__)) *a = v;
        Run(a->p0);
}

で、この生成されたmain.cgo2.cをgccでコンパイルするときのオプションは#cgo CFLAGSで指定したものも使われるので、ここで-x c++を指定してしまうと、このCファイルがC++としてコンパイルされてしまい、リンケージがC++になってしまうわけです。ついでにいうと、C++的にはよくないキャストが含まれているので、-fpermissiveを指定しないとコンパイルが通りません。

ということで、これを実行するとこんな感じになります。

$ go run main.go
# command-line-arguments
./echo_client.go: In function ‘void _cgo_32105cabc2a6_Cfunc_CreateApp(void*)’:
./echo_client.go:36:53: warning: invalid conversion from ‘void*’ to ‘_cgo_32105cabc2a6_Cfunc_PrepareApp(void*)::*’ [-fpermissive]

                                                     ^
./echo_client.go: In function ‘void _cgo_32105cabc2a6_Cfunc_Run(void*)’:
./echo_client.go:46:53: warning: invalid conversion from ‘void*’ to ‘_cgo_32105cabc2a6_Cfunc_Run(void*)::*’ [-fpermissive]

                                                     ^
# command-line-arguments
/var/tmp/go-link-sVLoaz/go.o: In function `main._Cfunc_Run':
(.text+0x39a): undefined reference to `_cgo_32105cabc2a6_Cfunc_Run'
collect2: error: ld returned 1 exit status
/usr/local/go/pkg/tool/linux_amd64/6l: running gcc failed: unsuccessful exit status 0x100

いやいや、ちゃんと自動生成したCソースに_cgo_32105cabc2a6_Cfunc_Runあるしそれエラーになるわけないじゃない…と昨日1日ずーっと悩みました。で今朝電車でゆらゆらしながらずーっと考えてたんですが、よく考えたらcgoのCFLAGS指定はすべてのgcc呼び出しに付加されているので、自動生成したソースコードをC++としてコンパイルさせてしまっていたのでした。そりゃリンケージがC++になるからメソッド見つからなくなるわ! という話ですね。

では、最初になぜ-x c++ -fpermissiveをつけてドツボにハマリにいってしまったかというと、ヘッダにcgoのヘッダ部分にextern "C"を書いてその状態でコンパイルが通る様にするためだったんですね。Cコンパイラはextern "C"を解釈できません。ということは、CじゃなくてC++としてコンパイルしないとダメなんだなーということでcgoディレクティブを追加したのですが、そもそもcgoの吐くソースはCとしてコンパイルしないとダメなので、これは筋が悪かったというところです。

ではどうすればよかったというと、bridge.hextern "C"するのをちゃんと#ifdef __cplusplusのときだけに絞るという、当たり前のことを当たり前のようにやればよい、ということでした。

$ cat bridge.h
#ifdef __cplusplus
extern "C" {
#endif

typedef void* App;
App CreateApp();
void Run(App);

#ifdef __cplusplus
}
#endif

ということで、今日はGoがcgoを使ってネイティブコンパイルするときの流れと、指定すると絶対失敗するのでやめたほうがよいCFLAGSのオプションについてご紹介しました。ここ2日くらいこれが解決する気配なくて本当につらかった…。

Comment