TDのパーカー等をずらっと並べてみる

自分の勤務先であるところのTreasure Dataは昨年めでたく買収されてArm Treasure Dataとなったが、最近ちょっと必要に迫られてタンスなどを整理しているところ大量にTDパーカー等が出てきてちょっと馬鹿にならない量になった。まあ処分するしかないものの割とレアなやつも混ざっててこのまま闇に葬るのもアレだったので、ちょっとずらっと並べたので記録しとく。

歴代パーカー

知っている限りで最初のTDパーカー。前面がFluentdで背面がTDというのがなんか会社の成り立ちを表してるみたいでけっこう好き。この頃はTD社員じゃなかったのになんで持ってるかというと、最初のFluentd meetupでしゃべったときにスピーカーとしてもらったんじゃなかったかなー。この頃は数も作ってなかったと思うので、今となってはかなりレア度高いはず。CEOの芳川さん*1がいまだにMountain Viewのオフィスでよく着てる。

最初のTDロゴがメインの(おそらく)ゆいいつのパーカー。これ、生地もゴワゴワだしジッパーもないしデザインもいまいちで、誰も着てるの見たことがない。自分もほとんど着たことがない新品同様のはず。同じくTD社員じゃない頃にもらったんだけどなんでもらったんだかもう完全に覚えてない。社員も誰も着てないもんだから見付けたときに思わずこんなんあったなーとか声が出た。レア……かな?

なおこのロゴ、Big Dataをやるぞ! というノリが表されたHDDベースのデザインだったんだけど、後に「いまどき誰もHDDなんか知らんだろ」というツッコミにより変更された(らしい)。

自分が入社した2015年あたりのロゴ(3世代目)とデザインのやつ。この紺色に "WE LOVE DATA" のデザインは長く使われて、いくつも細部の違うバリエーションがある。TDユーザーとかにもだいぶ配ってたような気がするので、持ってる人も多いかも。これは東京オフィス側で作ったんだけど、よく配られてるノベルティのパーカーに較べて生地が断然良くて、嬉しがって使ってた覚えがある。持ってるやつもだいぶ古びてる。

なおこの前に2世代目のロゴがあったんだけど、パーカーは作られてないような気がする。ロゴがなあ……*2。

その次、2017年くらい? のやつ。これも生地がいい。あまりバリエーションは無いのと、これもユーザー企業やTD関連勉強会のスピーカーとかに配ってた気がする。これはいまだに外部の人達が着てるのを見ることがある。

たぶん去年(2018)のはじめとかに作ったやつ。あまり印象がない……のは、割とすぐあれこれ会社的には変わる話があったからかな。ロゴがこの時点で最新のもの(4世代目)になっている。数はけっこう作ったのかなあ。もしかしたらレア度高いのかも。

Arm Treasure Dataになって初めて作られたやつ。USオフィスで一回だけ作られたので最近のだけどかなりレア。日本では超レアかも。目にしたことがあったらラッキー。

はい、日本での現行 Arm Treasure Data パーカーです。あちこちのイベントとかでこれを着た人を見掛けたらぼくたちとあくしゅ!

Tシャツなど

Tシャツはかなりのバリエーションが作られてたはずだけど、いろいろ雑に扱ったりでまともに手元に残ってるのが少ない。手元にあったのをざっと。

このロゴが2世代目のやつ。だいぶレア。なんかイマイチなデザインなのと、3世代目に変わった直後に放映された下町ロケットの帝国重工のロゴがこれに激似だと社員の間でちょっと話題になった。背中のサービス説明が Big Data as a Service だった往時のTreasure Dataを思わせる。

これが3代目ロゴで、単色ピンクなのがポイントで、その色とグレーがコーポレートカラーとして指定されてた。わりと長くこのロゴだったなあ。

Armに買収されたので色がArm色のブルーになったやつと、その後にちゃんと Arm Treasure Data として作ったやつ。右側が最新(現行)のTシャツですね。

おまけ: Fluentd関係

だいぶ昔にごく少数だけ作られたFluentd開発者向け(?)Tシャツ。たぶん10枚とかそれより少ない数しか作られてないんじゃないかなあ。超絶レア*3。Linusのアレをベースにしていることは一目瞭然。

で、後にFluentdの新ロゴ(現行ロゴ)でも作り直された。こっちのほうがもうちょっと枚数があるはず。とはいえレア度高し。

これはCNCFが作ったパーカーで、なんとCNCF Storeで誰でも買える。Tシャツもあるよ。買おう!
写真はないがこのパーカーにTresure Dataロゴが追加されたマイナーバージョン違いが存在して、これはFluentdがCNCFに加わった直後に社員だけに配られたはず。なかなかレア。

まとめ

いかがでしたか?*4 パーカーもロゴもいろいろありましたね!

*1:今ではArmのVP兼GM

*2:Tシャツ参照のこと

*3:だけど@repeatedlyがイベントとかでよく着てるので見たことある人は多そう

*4:これが書きたかった。後悔はしていない。

gradle installDist したときのディレクトリ名と実行ファイル名の設定

ビルドした環境に依存する起動スクリプトを生成してくれるように gradle installDist したとき、ディレクトリ名にはプロジェクトのディレクトリ名が使われる。

my-project$ ./gradlew installDist

# すると以下のツリーができる
# my-project/build/install/my-project/lib
# my-project/build/install/my-project/lib/...
# my-project/build/install/my-project/bin
# my-project/build/install/my-project/bin/my-project (executable)                                                           

普段手元でやる分にはいいんだけど、うっかりcommit hashを使って git repo をチェックアウトしたツリーの下で実行したりすると my-project の部分が全部 commit hash になったりして超めんどくさい気分になったので、これを build.gradle の設定で固定しとけないかと思った次第。

installDistタスクは application プラグインによるものだが、これは Distribution プラグインによってディストリビューションを構成している。また実行ファイルの作成は CreateStartScript プラグインによって行われている……ので、このふたつを調べた。

• https://docs.gradle.org/current/userguide/application_plugin.html
• https://docs.gradle.org/current/userguide/distribution_plugin.html#distribution_plugin
• https://docs.gradle.org/current/dsl/org.gradle.jvm.application.tasks.CreateStartScripts.html#org.gradle.jvm.application.tasks.CreateStartScripts

で、結論としてディレクトリの指定には Distribution プラグインのとこに書いてある baseName をセットすればよく、実行ファイル名の指定は CreateStartScripts プラグインの applicationName をセットすればよい……んだけど CreateStartScripts プラグインのドキュメントに書いてあるとおり application プラグインは暗黙に startScripts タスクをデフォルト設定つきで作成するので、そのタスクの applicationName をセットしなければならない。

結果はこう。

apply plugin: 'application'

distributions {
    main {
        baseName = 'my-own-app'
    }
}

startScripts {
    applicationName = 'awesome-script'
}

これで build/install/my-own-app/bin/awesome-script が常にゲットできる。

なんかちょっとググってみたらそのものの記述がなくて調べるのがめんどかったので書いておく。Gradle 5.0 のドキュメント読んでやってたけど Gradle 4 でも普通に動いた。
あと日本語で上のほうに出てくる Gradle 2.x ベースの日本語ドキュメントサイトは死んでほしい。

RubyConf 2018 に行ってきた＆しゃべってきた

タイトルの通り、と、ついでにシリコンバレー(Mountain View)にある自社オフィスに行ったり、バンクーバーに寄ってリモートで働いている同僚たちと会ってきたりしたので、合計3週間近くの長い北米出張をしてきた。

RubyConf 2018

rubyconf.org

プロポーザルを出したらRubyKaigiトラックで通ったので @joker1007 さんとふたりでしゃべってきた。内容は RubyKaigi 2018 で話した内容のほぼ再演*1なんだけど、もちろん英語で。

RubyConf 2018に登壇するためにL.Aまで行ってきた - joker1007’s diary

前に RubyConf 2014に行ったとき は、正直に言ってトークがぜんぜんダメダメ*2で、それに較べればだいぶマシに英語でプレゼンできるようになったとは思う。当たり前だけどその後に体験した場数が違いすぎるからというのもあるけど。内容が二人で協力した自身のものということもあって、成功と言ってよかったと思う。良かった。 @joker1007 さん、いっしょにやれてよかったです、ありがとう!

Hijacking Ruby Syntax in Ruby (RubyConf 2018) from SATOSHI TAGOMORI

内容はいつもの通り、メタプログラミングであれこれ遊ぶぞ! ということで TracePoint や Binding や method hooks やらを使い倒す内容。
トーク直後に Ryan Davis (@the_zenspider)*3 から "You're terrible!" という非常に欲しかった反応をもらって、直接話しにも来てくれて、本当によかった。RubyConf でもこういうtechieなトークで聴衆を楽しませることはできる。できた。その後でもトーク聞いてたら「あのメタプログラミングのトークやった人?」って話しかけてもらったり、Twitterにもちょいちょい "crazy" と言及されてたりして、良かったなあ、という。「TracePointもBindingもmethod hookも単体では知っていたけど、ああいう風に組み合わせれば実際に使えるんだなと初めて知った」という反応もあったりして、これはもしかしたら世界に禁断の知識をバラ撒いてしまったかもしれんが、いやあ、いいんじゃないですかね。

RubyConf自体は4年前に来たときとあまり変わらず、soft talk *4が多いなー、という感じで、自分のトークが最終日だったこともあってあまり熱心にはセッションに参加せず、ふらふらしたりしてた。参加者の人とちょっと話したりすると割と技術の話が聞きたいよねーと言う人も多いので、もうちょっとそういうカンファレンスになってくれないかなとは思う。
今回は参加者*5に日本人の知り合いもけっこういたので、あまり英語でーとか考えずに知り合いとツルんでビールとか飲んでた。LAは初めてだったけどUS自体はもうけっこう慣れてきたので、その場その場でふらふら。

特にカンファレンス会場のすぐ近くに Karl Strauss Brewing Co. の店舗があるのを到着した直後に発見してしまい、ここで飲む店舗内で醸造されたビールがじつにうまくて通いまくってた。具体的にはLA滞在7日のうちに8回行った。最高*6。だってお昼に行ったら「いまそこで新しくできたビールなんだけど」って試飲を勧められて(おいしかった)、その夜にもう一度行ったらメニューに更にもうひとつ新作が追加されてるんだぜー? 南カリフォルニアに行く予定がある人はぜひ行ってみてほしい。

食事はとにかく肉。あとハンバーガー。USだとまじでこの選択が正義なので、連日外さずに食べてた。

肉だとカリフォルニアワインと組み合わせるのが正義で、行ったステーキハウスでオススメされたHALL St. Helenaのワインがじつによかった。日本で買えないかなあ。肉も、うっかり頼むとちょっと量が多過ぎることを除けば、じつにおいしかった。あとマッシュポテトは飲み物。

LAが発祥と言っていいっぽいカリフォルニアロールも、一度試したけどイマイチだった……んだけど、カンファレンスホテルのすぐそばにあったアメリカングリルの店を試してみたら美味しいやつが出てきたので最終的には成功。いい体験でした。

観光とか出張とか

Mountain Viewに行ってたけどあの地に観光ポイントなどほぼ皆無*7なのはよく知られた事実なので、週末の片方はSan Franciscoに遊びにいって知り合いとお昼を一緒にしてもらったあと、市内をふらふらしたりSF MoMAでよくわからないものを観たり、ビールを飲んだりしてた。

サンフランシスコの空が青くないのは山火事で流れてきてた煙のせい。こうして見ると本当に白いなあ。ひどい。街中はだいぶ煙くさかった。

日本でもニュースになってたみたいだけど、このときカリフォルニアは山火事がひどくて、San JoseからLAまでのフライトでちょうどLA北西で起きてた山火事の上空を通ったので、窓からその様子が見えていた。もう想像を絶する広範囲が黒く焼けていて、火事だとは信じがたい状況だった。こういう体験は日本にいるとできないなあ、とは思う。あとLAからバンクーバーに行く途中で日本人も大好き Mt. レーニア を見たり。おお、カッコいい山じゃん。

LA行くのは初めてだったので、カンファレンス後に3日オフをとってあった。1日目はAsakusa.rbなメンツでロングビーチに行って戦艦アイオワ観光。

もう戦艦、とにかくデカくてカッコいいというか。サンディエゴで観た空母ミッドウェーもそうだけど、これは日本で見られない。実に良かった。

あとはその周辺で、最近USに増えている電動キックボードサービスのLimeを試したりしつつ移動したり。写真はLimeを楽しむ某社CTO。個人的には直進安定性が悪過ぎるあんな乗り物であんなスピードを出すのは怖過ぎた。
あとロングビーチの反対側にある昔の豪華客船クィーン・メアリーも眺めてまわった。とにかくデカいよなー。

2日目はLAの南側にある公園の博物館に、スペースシャトル・エンデバーを観に @kakutani さんと。これも日本には無い……というかアメリカにしか無いやつ。じつに良かった。またしてもデカい。

博物館は主にNASAのものを中心にしつつ、自然科学一般も扱っているものだった。とにかくそこらじゅうに人工衛星だの飛行機だの戦闘機だのが置いてある。ブラックバードとかが野外に無造作に展示されててえええええってなったり、屋内に戦闘機やら飛行機やらが吊るされててどういうこっちゃってなったりした*8。実によかった。

3日目は一人だったので、まずハリウッド方面に行ってLA LA LANDで有名スポットになったグリフィス天文台に。人がめっちゃいた。あとどこまで眺めても陸地で、ちょっとよくわからない……みたいな景色になってる。遊歩道があったのでそのまま降りていってハリウッド中心部まで散歩。

その後はLAダウンタウンまで戻って、他のブルワリー巡りをやってた。リトルトーキョーの近くに集まってる場所があって、そこを4軒ハシゴ……したものの、うーん、Karl Straussがやっぱり一番美味しかったなーってことで、晩御飯はまたKarl Straussで食べてた。しかし街をあちこち歩きまわるのが好きで、今回は色々なものを見た。満足。

で、あとはバンクーバーに移動してあれこれ。カナダは初めてだったけど、バンクーバーは話に聞いていたとおりの綺麗で安全で住みやすそうな街だった。ダウンタウンは思ってたよりも都会という感じ。あと単位がメートル法で摂氏温度なのが最高です。この街でもこの数年でブルワリーがすごく増えたらしく、同僚にあちこち連れていってもらってた。
しかしこの時期はやっぱり寒くて夜が早い。滞在日数も少なかったのもあって、あんまりふらふら見て回るというのはできなかった。また春か夏に来る機会がありそうなのでそのときかな。

あとはいろいろ飲み食いしたものの写真があるので貼り付けておく。みんなも出張にいったらおいしいもの食べておいしいもの飲もうな!

*1:細部をアップデートしたり小ネタをUSに合わせたりはした

*2:ほぼ初体験だったjet lagの影響とか、あれこれ原因はあったんだけども

*3:有名人だ!

*4:どちらかというと技術面中心ではない内容のトークのこと

*5:というか登壇者

*6:ちゃんと調べてみたら近年のサンディエゴで始まったアメリカのクラフトビール流行における本物の始祖のブルワリーらしかった。我々が吸い寄せられたのは必然だったと言える

*7:唯一例外のスポットが Computer History Musium なんだけど

*8:シアトルのボーイングの航空博物館もそうだったけど、なんであんなデカい飛行機を屋内に吊るすんだろうな……

Webアプリケーションのベンチマークをとるときに気をつけている10のこと

10もないかも、と思いながら項目を書き出してみたら10以上余裕であってキリがないので10で収めた。いやあ、あるなあ。

仕事柄よくベンチマークを実行したりしてて色々と思うところが溜まっていたところ、以下のような記事を見掛けたのでなんか書こうと思った。ところでこの記事はベンチマークを実行するための準備作業がループを回して2時間かかるところの待ち時間に書かれている。

sfujiwara.hatenablog.com

ISUCONといえば多少縁があるコンテストで、文中でISUCON5のことについても言及されているので、それも含めて。
自分が業務でいじっているのは "Webアプリケーション" というとちょっと違うんじゃないのというものばかりだが、いやー、最近なんでもHTTPで外部APIを作るからベンチマークのコツとしては大体変わんなかったりするよね。

なおこの記事でベンチマークはどのようなものかとか、どう作るのかとか、そういう基礎的なことについては言及しない。
またベンチマークの対象となるシステムはいわゆるWebアプリケーション、HTTPでリクエストを送りレスポンスを返すシステムで、かつ1リクエストの処理時間は通常1秒未満と期待され、そのようなリクエストを並列でできるだけ大量に処理するシステムであり、計測するのはスループット(req/sec)、並列性、レイテンシ(sec/req)などであるとする。*1

1. 走行中に動的に負荷を変えない

ベンチマークを実行するとき、事前に設定した走行時間(1分なり5分なり10分なり)がある場合、その中で負荷を変えるようなことをしてはいけない。具体的にはベンチマークツールの並列度などを動的に変更するようなことはしてはいけない*2。

システムの性能というのは一瞬だけ走らせて確定するものではなく、ある程度の走行時間を必要とする。その中で全体の結果をサマリしてシステムの性能というものは推定されるのであって、一瞬だけのピーク性能は基本的にはほとんど参考にならない。このため、まずある程度の走行時間を確保する必要がある。
その中で動的に負荷を変えるようなことをすると、ベンチマーク走行のタイムラインにおいて、いつどの程度の負荷だったのかということが極めてわかりにくくなり、システムがいつどのような状況でどのような性能を発揮していたのかが確定できなくなってしまう。性能を明らかにするためのベンチマークにおいて、これは実行の意義を自ら捨てるといっても過言ではない行為である。

もちろんシステムのウォームアップ時などを考慮して走行初期に少しずつ負荷を増やしていくといった意図的な負荷の変更は考えられる。6時間の走行において1/3ずつ異なる負荷で走行させる、などのスケジューリングもありうるだろう。こういった負荷の変更は「静的に」「意図的に」行い、また結果からこの期間を容易に除外して考えられるようにすることが重要だ。

負荷の動的な変更は意図せずして発生することもある。例えば測定対象のアプリケーションが500 (Internal Server Error)を返したときなどに、ベンチマークツールがそれを意図しておらず内部的に例外を起こし、該当スレッドが停止することで並列度が下がってしまう、などの状況などはよく起きてしまう。ベンチマークだからといってクライアントコードを適当に書いているとドツボにはまる。

2. 各走行におけるベンチ対象・ベンチツールのパラメータおよびメトリクスを全部保存しておく

ベンチマークにあたっては、後に述べるように様々な要素を変更しつつ数え切れない回数を実行することになる。このため後から総合的に結果を見るときに必要なのが、いつどのようなパラメータでベンチマークを実行し、どのような結果になったのかを全て明確に参照できるようにしておくことだ。これを忘れると、いつ何を実行したかが簡単に分からなくなり、過去のベンチマーク実行のための膨大な時間が闇に消える。

ベンチマークを行うにあたっては管理しておく要素が極めて多数存在する。代表的には以下のようなものがある。

• 対象アプリケーションコードのバージョン
• 対象システムのインスタンスタイプ
• 対象システムのノード数
• 対象システムの起動時パラメータ
• ベンチマークノードのインスタンスタイプ
• ベンチマークノードのノード数
• ベンチマークツールの起動時パラメータ

「起動時パラメータ」とまとめたが、ここにはもちろん極めて多数のものが入ってくる。代表的には対象システム・ベンチマークツールそれぞれにおいて並列性(起動プロセス数やスレッド数など)があるだろう。他にも割り当てメモリ容量上限、バッファのメモリ・ディスク、各種キャッシュの使用可否、などなどなどなど。送信するリクエストの内容(GET/POST/PUTメソッド、ペイロードのフォーマット、圧縮の有無……)なども変更の対象になる可能性がある。

最初はこんなパラメータ変更しないと思っていても、様々なベンチマークパラメータを考慮した結果、最終的に変更して試してみる、といったことも非常によく起きる。その後で過去のベンチマーク結果を眺めて「このときこのパラメータの値はなんだっけ?」となってしまうケースも容易に起きる。このため変更の可能性は無いと思っているパラメータについても、細大漏らさず記録しておくことが肝要である。

3. ベンチノードのクライアント・インスタンスのリソース使用状況と並列性に気をつかう

ベンチマークを実行するとき、ベンチマーク対象システムのメトリクス(リソース使用状況)には多くの人が気を遣うだろう。しかしうっかりするとベンチマークツール側のメトリクスには注意を払うのを忘れるといったことが起きてしまう。リクエストを受ける側はまだまだ性能に余裕があるのに、ベンチマークツール側がいっぱいいっぱいになってしまってベンチマークスコアが全く上がらなくなり、しかし実行している人は原因に気付けない、という状況もしばしば発生してしまう。
こういったことが起きないよう、ベンチマークツール側のノードのメトリクスにも常に注意を払おう。基本的には各インスタンスのCPUかネットワーク帯域を使い切る近くになるまで*3、1ノード内における並列度を上げるのが望ましい。その上でベンチマークノードのインスタンス数を、並列度の合計が望ましい値になるまで増やしていく。

ただし、HTTPコネクションの並列度がベンチマークのパラメータになるケースもある。この場合には1インスタンスにおけるリソースの使用状況にかかわらず並列度の調整が最優先になる……など、例外ケースはいくつかある。頑張って考えること。

4. 1セットのベンチマークはパラメータ1軸のみを変更しつつ何度もとる

ベンチマークは、基本的に、あるパラメータひとつのみを変更しながら実行する。そのパラメータに対してどのように性能が変化するかを確認するためには、他のパラメータはすべて固定しておかなければならない*4。性能に影響を与えうる複数のパラメータを同時に変更することは絶対にしてはいけない。ベンチマークの意味がなくなってしまう。

これは当たり前のようにも思えることだが、実際にベンチマークを実行していると意外にやってしまうことが多い。どんなに退屈だろうと、あるいは複数の変更が独立していることが自明に見えても、複数のパラメータの同時変更は鬼門だ。本当に思わぬところで影響が出たりするし、最終的に結果を考察する上でノイズになったりもする。

5. 1セットの結果から仮定を立て、次セットは別のパラメータ1軸を対象に実行する

ベンチマークにより性能計測を行いたいという場合、性能に影響するパラメータがひとつだけということはあまり無いと思う。ある1セットのベンチマークでパラメータAについてベストな設定がわかったら、次はパラメータAをその値に固定した上で別のパラメータBを軸として設定を変更しつつ別のベンチマーク走行セットを実行する。

これによりパラメータBの最適値が分かったとするが、このとき即座に次のパラメータCに行ってはいけない。パラメータBの最適値が当初の値と異なる場合、それがパラメータAの最適値に影響を与えないとは限らないからだ。ということで今度はパラメータBを発見した最適値に固定し、一度パラメータAに戻って再度ベンチマークを実行する。パラメータBの変更がパラメータAに影響を与えていなければ前と同じ最適値が得られるはず。影響を与えていれば異なる最適値が得られる……ので、その値を使って再度パラメータBに戻りベンチマークをまたまた実行する必要がある。

このようにしてA, Bそれぞれについて完了したら、ようやくパラメータCに移ることができる……。

6. 納得するまで繰り返す、走行時間も変えてみる

ということで、様々なパラメータについてあれこれ変更しつつ、納得するまで試行錯誤を繰り返すことになる。長く根気の必要な作業である。

またこのとき、ある程度結果が見えてきたらベンチマークの走行時間についても気にかけてみるとよい。短時間であれば良い性能を示しても、同じ負荷で長時間走行させるとある時点で突然性能が劣化する、ということもよくある。そのような性能特性では当然本番のトラフィックに投入するとトラブルを引き起こすので、事前に見付けておく必要がある。

7. 計測する性能における期待値と最大値は明確に分けて考える

ベンチマークにおいて計測する性能とは、実際にはいくつもの数値によって総合的に構成される。典型的には処理の並列度(同時コネクション数)、処理時間(sec/req)そしてスループット(req/sec)だろう。また並列度やスループットは時間平均*5の推移をとればよいとしても、処理時間については平均値とともに各パーセンタイル値(50, 90, 95, 98, 99 など)を取るべきだ。

さてこういった性能指標をどう扱うか。システムのこれら全ての性能指標について最大値(最良値)を追求する、というのは実際には不可能といってよい。検証すべきパラメータは膨大なので、おそらくいくら時間があっても足りない。こういったときはベンチマーク全体の設計として、いくつかの性能指標は「この程度の性能を期待する」という値を設けておき、それが満たされてさえいるなら最大値は追求しない、という進め方をするほうが良いだろう。
そのシステムの実際のワークロードを考えたとき、例えば並列度はどう考えても10,000を超えない、というようなケースは多いはずである。またスループットは 1,000 req/sec 程度あればよいが処理時間は 100ms/req を切っている必要がある、などの要求の場合、最大スループットを計測することにはほとんど意味がない。ターゲットのスループット*6が問題なく処理できることを確認したら、あとは問題となる処理時間のメトリクスに集中して更なるベンチマークを実行するほうがよい。

8. 走行中の負荷はできるかぎり平準化する

ベンチマークツールの出来によるが、あまり適当にやると時間あたりに送るリクエスト数がひどく上下してしまう、というようなことが起きる。ある瞬間は500req/sec送っていたのが、次の瞬間には300req/secになってしまう、というように。これは測定対象の瞬間性能の上下*7に引きずられてリクエスト送出側の送信数も素直に上下する、という現象と区別がつきにくいが、区別するべきだ。
現実のワークロードはシステムの性能にあわせてリクエスト送信数を上下してくれることなどほとんど無い*8。このため可能なら、ベンチマークツールはベンチマーク対象の性能にかかわらず一定のスループットでリクエストを送信しつづけることができる構造のものを使用する*9べきだ。またその送出リクエスト数(負荷)は不用意に上下しないものがよい。

こういったベンチマークツールを作るのはわりと難しく、世の中にある単純なもの*10はこの機能をもっていないものも多い。
やむをえずこの機能のないベンチマークツールで負荷をかける場合は、測定対象のレスポンスタイム(sec/req)に注目するとよい。対象システムの性能上下によってスループットの上下が発生する場合、かならずレスポンスタイムの悪化*11が裏で起きるため、それをメトリクスで確認できるはずだ。

またこのような問題は、送出するリクエストの組み立てを事前にまとめて行う、といった構造のベンチマークツールを書いたときにも起きやすい。以下のようにして起きる。

リクエストを1,000,000件組み立て(無負荷) → 組み立てたリクエストを順次送出(負荷走行) → またリクエストを1,000,000件組み立て(無負荷) → ……

リクエストを事前に組み立てるのは負荷走行中のリクエスト送出毎のディレイを短くするためには有効だが、組み立てたリクエストを全て送出し切る前に完了する類のベンチマーク走行でしか使うべきではない。実際にベンチマークを実行する場合には数時間といったスパンの長時間走行も考えるべきだから、現実的には全てのベンチマークにおいて、あまり適切ではないといえる。
ベンチマークにおいては、全てのリクエストは送出ごとに組み立てから行うほうが負荷の平準化のためには良い。ベンチマークノード1ノードが送出できるリクエストのスループットは多少下がるが、それはノード数(並列数)の増加で補うべきだろう。

9. 異なる種類のリクエストは公平に混ぜて送る

現実のワークロードに近いベンチマークを行おうとすると、おそらくベンチマークツールから送るリクエストは複数の種類のものを混在させることになるだろう。複数のログインユーザを装うことになるかもしれないし、それぞれ異なるリソースを読み書きするリクエストを並列で発行させたい、ということもあるかもしれない。
このようなリクエストを送るときは、可能な限り綺麗に混在させるよう努力するべきだ。例えば時間によってアクセスされるリソースが偏っている場合は必要な情報がメモリキャッシュに乗りきってしまい、実際よりも高いパフォーマンスを示す、などということが起きうる。そのような状況から得た結果は考察を混乱させてしまい、悪影響が大きい。

実際にどう気をつけるかはベンチマークツールなどの実装に大きく依るが、自作する場合、リクエストタイプ毎にリクエストワーカースレッドを作る、などとするとこの偏りが発生しやすい。レスポンスタイムの短いリクエストを担当するスレッドだけが規定のリクエスト数を走行させきってしまい、あとはレスポンスタイムが長いリクエストだけが流れ続ける時間が生まれる、という状況が生まれやすいからだ。ベンチマークツールを自作する場合は、まず全種類のリクエストを綺麗に混ぜ、それを全ワーカースレッドに公平に割り当てるようにすればよい。

10. 結果は複数のスコアから総合的に解釈する

ベンチマークの結果は複数の性能指標を見て総合的に解釈するべきだ。前述したように典型的なWebシステムであれば処理の並列度(同時コネクション数)、処理時間(sec/req)そしてスループット(req/sec)が考慮の対象になるだろう。たとえスループットを最大化することが目的であっても、そのためにレイテンシの95パーセンタイル値が大幅に悪化する、などということになれば現実的には使えないシステムになってしまう。またベンチマーク走行中に性能値が極端に上下するようなものも好ましくない。

CPUやメモリ、ストレージI/Oなどのメトリクスにも注意を払う必要がある。現実的に運用不可能なリソース消費量になっていないか、長時間走行において不自然なCPU・メモリ使用の増加が起きていないか、などはチェックしておくべきだ。

まとまらない

もうかなり書いたのでこのくらいにしようかと思うが、何か大事な項目を書き忘れているような気もする。細かいことを言うとこれ以上にもあれこれ多数あるだろう。「大事なこれを忘れてるだろ!」というのがあったら教えてください。

EX. ISUCONベンチマークの特殊性

発端がISUCONベンチマークの記事だったので、それについても書いておこう。

ISUCONのベンチマークは、通常業務で実施するベンチマークと較べると極めて特殊なものだ。上述したように通常ベンチマークといえばパラメータを変えながら何度も何セットも実行してようやく性能指標の最大値を求める。ところがISUCONのベンチマークはたった数分、一度きりの走行でスコアという名前の性能値を算出しなければならない。
また対象システムの性能は初期状態からコンテスト末期の状態でおよそ100倍の性能差があることも全く珍しくないが、この両方をひとつのベンチマークシナリオでカバーするのは、普通に考えると不可能に近い。

fujiwaraさんのエントリで記述されているので詳細は省くが、ISUCON 3, 4, 6, 7, 8 ではいくつかの方法*12で負荷が調整されるようになっている。これは実質的にはすべて並列度の操作だ。workloadを手動で指定する方法でも自動調節する方法でも様々な問題がある。特に自動調節はfujiwaraさんのエントリの「自動負荷増加の問題」に書かれている通り、本来(通常)のベンチマークからほど遠い思考を要求されることになる。コンテストだからといえば良いかというと、本来の「できるだけ本物の業務に近いことをやる」という主旨に外れること甚しく、個人的にはあまり好きではない。

ISUCON5のベンチマーク*13は何をやったかというと、並列度は固定してあった。走行中に並列度は上下しない。その上でリクエストに関する許容レスポンスタイムを大幅に引き上げ、非常に遅いリクエストであってもベンチマークツールが頑張って待つ、ということで初期状態でもなんとかスコアが出るように調節したように思う。その上でできるだけ高速に動作するベンチマークツールを作ることで、参加者がアプリケーションの高速化を行ってもそれに追随できるスループットが出ることを目指した……はず。
いま確認したら、それでも予選時には上位チームのスループットには追随できずサチったケースがあったらしい。本戦では並列度が高めに設定してあったから問題は出なかったようだ。

つまり実質的に、ISUCON 1, 2, 5 は固定の並列度に対してスループットを上げる(==レスポンスタイムの短縮を狙う)ゲームであり、それに対して他のISUCONは増加する並列度に対して追随することでスループットを上げるゲームである、と言える。
これが明示されていないことをどう思うかは、うーん、どうなんだろうなあ。まあいいのかなー、という気はする。

*1:同僚が詳しいのですが、たとえばRDBMSのベンチマークなどを実行する場合、共通する考え方はあるにせよ細部は大きく異なります

*2:もちろんこれは、だんだん負荷が上昇するようなケースで起きる問題を特定したい、というようなケースでは当然守られない。が、それはおそらくデバッグのためのケース再現であってベンチマークではない。

*3:本当に使いきってしまうとコントロールなどに色々弊害が出るので、いくらか下に上限を設けること

*4:もちろん実質的に複数のパラメータがセットになっているものはあわせて変更する必要があるが

*5:短時間、たとえば1秒や10秒ごとの平均値

*6:の、安全を見てさらにある程度上のスループット

*7:レスポンスタイムの上下といった形で現れることが多い

*8:例外ケースとして、現実のワークロードにおけるリクエスト送信側がキュー＆ワーカー構造になっていれば性能の上下に対して敏感にならず、平均のスループットだけを相手にすることができる

*9:あるいは自分でそのように作る

*10:abなど

*11:あるいは処理並列度の低下だが、処理並列度はベンチマークツール側で固定できることが多いので、実際には並列度の上下が動的に起きることは少ない

*12:workload, 自動調節およびSNSシェア

*13:実際にはISUCON 1, 2も根本は同じだが

RubyKaigi 2018 で仙台に行ってきた＆しゃべってきた

今年もRubyKaigiでしたねー。実によいカンファレンスでした。

rubykaigi.org

仙台は東京からも新幹線で1.5〜2時間で着けるというアクセスの良さ、加えてちょうど新緑の時期で街中も郊外も美しいし、日本酒も酒に合う魚もおいしい場所だし、地方開催のカンファレンスは本当にすばらしいなって話をずっとしてた。そういうところに隔離されてずっとソフトウェアの話ができるの、本当に良いと思う。

しゃべってきた

今年は去年のRubyKaigiから間が短いこともあってトークの応募どうしようかなと思ってたんだけど、最近Asakusa.rbで @joker1007 さんとよく盛り上がる技術ネタがあって、それを共同で応募してみたら通ったから話してきた。(jokerさんのエントリ)

Hijacking Ruby Syntax in Ruby - RubyKaigi 2018

スライドはこちら。

Hijacking Ruby Syntax in Ruby from SATOSHI TAGOMORI

内容はBindingとかTracePointとかRefinementsとかmethod hookとかを使いまくってやりたい放題やる、みたいな話だけど、実際の狙いは「有用なアイデアをRubyの機能だけを使って実現してみる」に近い。ちゃんと実装しようと思うとMRIにCでパッチを書くことになるんだけど、まず実装してみて有用性を確かめる(あるいはRuby的にこれで良いかと見てみる)、というステップは重要だと思っていて、このためにやれることを全部やったのだ、と思ってもらえれば嬉しい。

実のところトーク後にMatz含めたRubyコミッタの人々とも話してて defer みたいなのはあってもいいかもねえ、という話になった*1ので、Proof of Concept は重要だと思うし、それをRubyでやるためには今回のトークに含まれる技術要素は学んでおいて損は無いと思う。デバッグ大変だけどね!

Crazy Ruby talk by @joker1007 and @tagomoris #RubyKaigi pic.twitter.com/YnPGXW6A9a

— Vladimir Dem @ 🇯🇵 RubyKaigi (@palkan_tula) May 31, 2018

また今回たまたま時間がなかったのでこういう内容だったが、今までproduction systemの話ばっかりしてた自分としてはRubyKaigiで非常によく行われる言語機能や言語実装に深く入っていく類のトークをしたことがなく、ちょっとコンプレックスに思っていたところだった。今回は思いっきりRubyの機能や面白ライブラリの話をしまくって、そういう部分で実績解除できて嬉しかったなと思ってる。こういうネタを普段からいろいろ議論できる Asakusa.rb はホンマええところやで。みんなもおいで。*2

会場の聴衆の入りはめちゃくちゃよかった。今回サブ会場もだいぶ席数があったのにあんなにぎっしりになるとは。楽しめてもらえてたら良かったなあ。
@joker1007 さん、いっしょにできて楽しかったです! ありがとう!!

ところでRubyKaigiに向かう共同登壇者の息の合いっぷりをごらんください。

タイムライン見てて、共同登壇者と自分のツイートがジャスト同じタイム同じ構図で自分で笑ってしまったw pic.twitter.com/NXz3nSDUk5

— ジョーカー 1007 (@joker1007) May 30, 2018

参加してきた

今年のRubyKaigiもJITと型の話がアツかったですね! あとGuildの動くブランチ公開はまだですか!?!?

RubyにOptionalな型を入れる件については自分の意見はここに書いてあるようにコードにrespond_to?(:name)が通る集合を書く、みたいなやつですね。これがRubyのduck typingといちばん相性がいいと思うんだけどなあ。外部に型宣言ファイルを持つっていっても、クラスベースの型 + ジェネリクス的なやつで次の2行を共に安全にするのは無理じゃない?

obj = [1, "two", 3, "four"]
obj.select{|v| v.respond_to?(:upcase) }.map(&:upcase).join
obj.reject{|v| v.respond_to?(:upcase) }.sum

まあこれはともかく、JITとかはMRIの実装もどんどん進んでるし、他の実装の詳細が紹介されるトークからMRIが取り込めそうなのもあれこれあったりで議論が楽しいし、実にすばらしい。他のトークも聞いたものはみんなそれぞれの書いたコードについてしゃべりまくってて超面白かった。

RubyKaigiは明確に「自分が書いたコードの話をするトークがacceptされる」カンファレンスなので、こうやって超面白い話ばっかりになるのはすばらしい。
んだけど、次のRubyKaigiでまたトークをしなければまた話のネタになるコードを書かないといけないわけで、いやー、どうしよっかなーと今から思いますね。

あと3日目に恒例の(?)サイン会があったけど、技術評論社のWEB+DB PRESS総集編、記事を書いたことがある人が集められて巨大サインパイプラインみたいになってた。なかなか愉快な体験でした。ちゃんと買ってサインをもらいに来てくれる人がいて売り上げに貢献したぞ!!!

WEB+DB Press総集編に対する、居合わせた執筆者十数名によるパイプライン方式のサイン会 #rubykaigi pic.twitter.com/qeratrlkx8

— Yuki Yugui Sonoda (@yugui) June 2, 2018

Partyなど

今回はTreasure Dataが After Party のスポンサーをやらせてもらったので、そのあたりはちょっとあれこれやったり。人が大勢来てくれて、でもぎゅうぎゅう詰めという感じでもなくて、ちょうどよかったかなと思います。ちょっと食べ物が少なかったのはみなさんにその後に仙台のおいしいものを食べてほしかったから!!!!*3

RubyKaigi 2018 After Party で話したスライドです:
「327 種類の Ruby をビルドする方法 ~0.49 から 2.6.0-preview2 まで ~」https://t.co/J5MXgM2PNN

— Tanaka Akira (@tanaka_akr) June 4, 2018

RubyKaigiの飲み会の余興で突然ゲリラ的におっぱじまったトークがこれですよ。頭がおかしい。本当にクオリティがおかしかった。 https://t.co/OLC60P1YpQ

— Akira Matsuda (@a_matsuda) June 5, 2018

なんか面白ネタがあるならAfter Partyでどうすか、みたいに雑に振ってみたら出てきたのがこれで、まじやばかった。みんな超楽しんでたRubyKaigiの最終トークでしたね。正確にはその後にnobuのライブコミットがあったけど、なんかもう本人が酔っ払ってて何言ってるのかもよくわからず、超カオスであれはあれで面白かったｗ *4

Pre Partyから1日目、2日目は自分もあれこれのパーティーにお世話になっていた。あれやこれやの人と話したり、そこから別の店に流れたり。特に仙台行く前に会った @maciejmensfeld ‏と何度も話してポーランドの Kraków Ruby meetup について聞いたりとか。いいなあポーランド、行ってみたい。Tech Talk やりに行きたい。

After Partyのあとの川は……しばらく経ってから見にいってみたらだいぶ人数少なくなってて、その後に日が変わるあたり? であっさり解散していた。仙台の川は平和だった。

まとめ

超楽しかった! 上に書き忘れてたけどWi-Fiまじ快適で @sora_h 先生ありがとう! オーガーナイザーのみなさん(特に @a_matsuda さん)ありがとう!

来年の福岡も楽しみですね! またしても、日本酒も魚もうまい街だぞ!!!!

*1:いっぽう defer というキーワードをぶちこむのは難易度が高いのでどうしようかねえ、といういつもの話にもなった。きびしい。うーん……。

*2:いっぽう便利な人に「モリスさんともあろう人がproductionで使えない話なんかをするなんて!」とか煽られた、ぜったいにゆるさない

*3:いま考えた

*4:該当のcommitはこれかな? ruby-trunk-changesでも「うーん謎だ。」などと評されており大変面白い。

Nginx 1.13 の http_mirror_module を試す

みなさんにも、さまざまな過去の経緯からくる微妙挙動を満載した外部ユーザ向けのHTTPサーバをリプレイスしたりするとき、実際にガツンとやっちまう前にちょっとリクエストを分岐して挙動と性能を確認したい、と思うことがあると思います。考えるだけでつらい気分になってくるやつ。でもやったほうが100倍マシなやつ。
どうしよっかなとちょっと考えたところ、少し前にこんな話があったのを思い出すはずですね*1。

asnokaze.hatenablog.com

とはいえヨッシャ使うぞといきなりぶちこむこともできないので、まずいくつか試してみることにする。

準備

前提としては以下のように、元のアプリケーションと同じにホストにリバースプロキシが立っており、そこのnginxで http_mirror_module を使う、という想定*2。ミラー先はどこか適当なアプリケーションサーバ(あるいはロードバランサ)で、元アプリとまったく同じ機能を提供する、はず、ということにする。このNginxでstatic fileを扱うなどの処理については今回は考えない(すべてのリクエストがproxyされる)。

--->[nginx (port 8080)]--->[app P (port 8081)]
       |
  [http_mirror_module]
       |
       +------------------>[app Q (port 8082)]

ここでは簡単のため、全プロセスを同一ホストで起動、それぞれ port 8080, 8081, 8082 で実行する。

Nginxのdownloadページからおもむろに現在の mainline version であるところの 1.13.10 をダウンロードして適当なディレクトリに展開、あとは普通にビルドする。http_mirror_moduleはなんとデフォルトで有効。

$ ./configure --prefix=/usr/local/nginx-1.13.10
$ make
$ sudo make install
$ sudo chown -R tagomoris /usr/local/nginx-1.13.10 # 自分のユーザ名で

Nginxの設定としてはできるだけ簡単にして、最初は以下のように。proxy先の状況もちゃんとわかるよう、アクセスログには $request_time と $upstream_response_time の両方を記録しておく。

worker_processes  1;
error_log  logs/error.log;
events {
    worker_connections  1024;
}


http {
    include       mime.types;
    default_type  application/octet-stream;

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" '
                      '$request_time $upstream_response_time';
    access_log  logs/access.log  main;

    sendfile        on;
    keepalive_timeout  65;

    server {
        listen       8080;
        server_name  localhost;

        location /a {
            proxy_pass http://127.0.0.1:8081/a; # P
            mirror /mirror;
        }
        location /b {
            proxy_pass http://127.0.0.1:8081/b; # P
            mirror /mirror;
        }
        location /mirror {
            internal;
            proxy_pass http://127.0.0.1:8082; # Q
        }
    }
}

なお /mirror はリクエストの複製にのみ使う internal redirect 用のlocationなので、外部からアクセスされないようinternalディレクティブを有効にしておく。
設定内容を確認してnginxを起動。

$ /usr/local/nginx-1.13.10/sbin/nginx -t
nginx: the configuration file /usr/local/nginx-1.13.10/conf/nginx.conf syntax is ok
nginx: configuration file /usr/local/nginx-1.13.10/conf/nginx.conf test is successful
$ /usr/local/nginx-1.13.10/sbin/nginx

プロキシ先のアプリケーションは以下のようなものをrubyで適当に書く。環境変数で設定をいじれるようにしとく。

# app.rb
require 'sinatra'

port = ENV.fetch("PORT", "8080").to_i
sleep_time = ENV.fetch("SLEEP_INTERVAL", "0").to_i

configure do
  set :port, port
end

get '/a' do
  p(time: Time.now, here: "a")
  sleep sleep_time
  "ok #{sleep_time}"
end

post '/b' do
  p(time: Time.now, here: "b", body: request.body.read)
  sleep sleep_time
  "ok #{sleep_time}"
end

gem i sinatra してあれば ruby app.rb で起動できる。これを以下のようにふたつ起動する。

$ PORT=8081 SLEEP_INTERVAL=0 ruby app.rb # P
[2018-04-02 18:13:24] INFO  WEBrick 1.4.2
[2018-04-02 18:13:24] INFO  ruby 2.5.1 (2018-03-29) [x86_64-darwin17]
== Sinatra (v2.0.1) has taken the stage on 8081 for development with backup from WEBrick
[2018-04-02 18:13:24] INFO  WEBrick::HTTPServer#start: pid=19491 port=8081

$ PORT=8082 SLEEP_INTERVAL=0 ruby app.rb # Q
(省略)

準備完了。

普通にmirror proxyする

まず設定は上記の設定に入っていたこの部分から。/a および /b に来たリクエストを 8081 のupstream に流すが、同時にmirrorして 8082 にも流す。

        location /a {
            proxy_pass http://127.0.0.1:8081/a;
            mirror /mirror;
        }
        location /b {
            proxy_pass http://127.0.0.1:8081/b;
            mirror /mirror;
        }
        location /mirror {
            internal;
            proxy_pass http://127.0.0.1:8082;
        }

これでリクエストを流してみる。

$ curl -v http://localhost:8080/a
*   Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
> 
< HTTP/1.1 200 OK 
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:14:13 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
< 
* Connection #0 to host localhost left intact
ok 0

当たり前だけど普通に返ってくる。アクセスログを見てみると、やっぱり普通。

127.0.0.1 - - [02/Apr/2018:18:14:13 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.011 0.009

が、このときアプリケーション側のログを見てみるとおかしい。Pの側は普通にリクエストを処理しているがQは /mirror/a というパスのリクエストを受け取ってエラーを出してる。

# P
{:time=>2018-04-02 18:14:13 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:14:13 +0900] "GET /a HTTP/1.1" 200 4 0.0067
- -> /a

# Q
127.0.0.1 - - [02/Apr/2018:18:14:13 +0900] "GET /mirror HTTP/1.1" 404 464 0.0074
- -> /mirror

このとき、error_log には何も出ていない。
これは /mirror 側でproxyするとき、pathをいじったのを元に戻さなかったからですね……ということで以下のように設定を変更。

        location /mirror {
            internal;
            proxy_pass http://127.0.0.1:8082$request_uri;
        }

なおこれはNginxのhttp_mirror_moduleのドキュメントを見ると冒頭に例でちゃんと $request_uri が指定されていて、見落としちゃダメですよ、という心遣いを感じる。
これで nginx -s reload して curl してみると、PとQで全く同じリクエストを受け取れるようになった。

# nginx access.log
127.0.0.1 - - [02/Apr/2018:18:20:36 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.003 0.003

# P
{:time=>2018-04-02 18:20:36 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:20:36 +0900] "GET /a HTTP/1.1" 200 4 0.0008
- -> /a

# Q
{:time=>2018-04-02 18:20:36 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:20:36 +0900] "GET /a HTTP/1.1" 200 4 0.0010
- -> /a

パスを /b にしてPOSTしてみても大丈夫。

$ curl -v -X POST --data-ascii '{"num":1}' http://localhost:8080/b
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> POST /b HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
> Content-Length: 9
> Content-Type: application/x-www-form-urlencoded
> 
* upload completely sent off: 9 out of 9 bytes
< HTTP/1.1 200 OK 
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:25:43 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
< 
* Connection #0 to host localhost left intact
ok 0

# access.log
127.0.0.1 - - [02/Apr/2018:18:25:43 +0900] "POST /b HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.003 0.003

# P
{:time=>2018-04-02 18:25:43 +0900, :here=>"b", :body=>"{\"num\":1}"}
127.0.0.1 - - [02/Apr/2018:18:25:43 +0900] "POST /b HTTP/1.1" 200 4 0.0006
- -> /b

# Q
{:time=>2018-04-02 18:25:43 +0900, :here=>"b", :body=>"{\"num\":1}"}
127.0.0.1 - - [02/Apr/2018:18:25:43 +0900] "POST /b HTTP/1.1" 200 4 0.0007
- -> /b

content body も両方にわたってて、あれ mirror_request_body を指定しなくてもいいの? と先述のblogエントリを読んだ印象からは受ける、が、そもそも mirror_request_body は default on だった。これはちゃんと該当ディレクティブのドキュメントを読んで、性能問題について考慮した上で必要な場合は off にしましょう。*3

mirror upstream を落としてみる

方法は簡単、単にプロセスを停止させる。この場合は Q のプロセスを止める。
で、その状態でアクセスしてみる。元々のproxy先である P は生きていることに注意。

$ curl -v http://localhost:8080/a
*   Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
> 
< HTTP/1.1 200 OK 
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:36:32 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
< 
* Connection #0 to host localhost left intact
ok 0

# access.log
127.0.0.1 - - [02/Apr/2018:18:36:32 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.003 0.002

# P
{:time=>2018-04-02 18:36:32 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:18:36:32 +0900] "GET /a HTTP/1.1" 200 4 0.0006
- -> /a

フツーに動いている……が、唯一、error.log に以下のようなログが出ていた。状況はわかる。

2018/04/02 18:36:32 [error] 19539#0: *19 kevent() reported that connect() failed (61: Connection refused) while connecting to upstream, client: 127.0.0.1, server: localhost, request: "GET /a HTTP/1.1", subrequest: "/mirror", upstream: "http://127.0.0.1:8082/a", host: "localhost:8080"

これをもうちょっとわかりやすくするため log_subrequest ディレクティブを有効にしてみる。これは http_core_module のディレクティブ。

    access_log  logs/access.log  main;
    log_subrequest on;

$ /usr/local/nginx-1.13.10/sbin/nginx -t
nginx: the configuration file /usr/local/nginx-1.13.10/conf/nginx.conf syntax is ok
nginx: configuration file /usr/local/nginx-1.13.10/conf/nginx.conf test is successful
$ /usr/local/nginx-1.13.10/sbin/nginx -s reload

この状態でもう一度 curl してみると、アクセスログに、処理に失敗しているリクエストがひとつ出てくる。んー、本来のリクエストとちょっと見分けがつかないな、これ。$upstream_addr でも入れますかね。*4

127.0.0.1 - - [02/Apr/2018:18:41:15 +0900] "GET /a HTTP/1.1" 502 0 "-" "curl/7.45.0" "-" 0.000 0.001
127.0.0.1 - - [02/Apr/2018:18:41:15 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 0.008 0.008

mirror upstream を遅くしてみる

今度は Q のプロセスを SLEEP_INTERVAL=5 で起動してみる。同じリクエストを投げてみると、同じレスポンスが即座に返ってくる。

$ curl -v http://localhost:8080/a
*   Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
> 
< HTTP/1.1 200 OK 
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 09:49:07 GMT
< Content-Type: text/html;charset=utf-8
< Content-Length: 4
< Connection: keep-alive
< X-Xss-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
< 
* Connection #0 to host localhost left intact
ok 0

が、アクセスログの方は、なんとQの処理が終わるまで表示されない。5秒経つと2行出力された。P側を処理したリクエストは $upstream_response_time は 0.003 なのに $request_time はQ側にひっぱられて 5.015 になっている。うーん。あとQ側の $body_bytes_sent がなんかおかしい数字。261bytesってなんだ。

# access.log
127.0.0.1 - - [02/Apr/2018:18:49:12 +0900] "GET /a HTTP/1.1" 200 261 "-" "curl/7.45.0" "-" 5.015 5.015
127.0.0.1 - - [02/Apr/2018:18:49:12 +0900] "GET /a HTTP/1.1" 200 4 "-" "curl/7.45.0" "-" 5.015 0.003

なおこの挙動とログ表示は log_subrequest off; でも変わらない。というか $upstream_response_time 0.003 なのに $request_time 5.015 な行だけが表示されてかなり不気味なことになる。実際のレスポンスはクライアントに返っているとはいえ、なかなか、どうしようかなこれ、という挙動だ。
またこの場合、PとQでは返しているレスポンスボディが異なる、が、特にそのことについて何らかのログが表示されたりはしない。コードもざっと読んだ*5が、そのような処理は書かれていないので当たり前だと言える。

primary upstream を落としてみる

逆にPが死んでるときQへのリクエストはどうなんの? というのもやってみる。Qは5秒sleepを入れたまま。

$ curl -v http://localhost:8080/a
*   Trying ::1...
* connect to ::1 port 8080 failed: Connection refused
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /a HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.45.0
> Accept: */*
> 
< HTTP/1.1 502 Bad Gateway
< Server: nginx/1.13.10
< Date: Mon, 02 Apr 2018 10:00:41 GMT
< Content-Type: text/html
< Content-Length: 174
< Connection: keep-alive
< 
<html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.13.10</center>
</body>
</html>
* Connection #0 to host localhost left intact

# access.log
127.0.0.1 - - [02/Apr/2018:19:00:46 +0900] "GET /a HTTP/1.1" 200 332 "-" "curl/7.45.0" "-" 5.006 5.006
127.0.0.1 - - [02/Apr/2018:19:00:46 +0900] "GET /a HTTP/1.1" 502 174 "-" "curl/7.45.0" "-" 5.006 0.001

# Q
{:time=>2018-04-02 19:00:41 +0900, :here=>"a"}
127.0.0.1 - - [02/Apr/2018:19:00:46 +0900] "GET /a HTTP/1.1" 200 4 5.0043
- -> /a

やはりレスポンスは即座に 502 Bad Gateway として返ってくる。アクセスログはQ側を5秒待ってから表示される。
Q側のターミナルには普通にリクエストが投げられてきたのが表示されている。まあ自然といえば自然な挙動ではある、けど……。

雑感

とりあえずリクエストを複製する、という目的には十分使えそう。ただしmirror upstream側がトラブルで性能低下したりしたとき、ログ出力だけとはいえ通常の処理も影響を受けるというのは気をつけておいた方がよさそう。ログ上では $request_time の数字が遅くなるというのも、知らないでトラブル時のログを見ると混乱しそう。
また当然だけど worker_connections の数字を mirror upstream 側の接続についても当然消費するだろうから、この数字をきっちりに設定している場合は修正する必要があるはず。

mirror側のリクエストについてnginx上でどうログっておくかはなかなか悩ましい気がする。何も表示させないというのもひとつの手ではあるけど、レスポンスが遅くなったりしたときに $request_time の数字が突如低下することになる。これはどう考えても混乱要因になる……が、nginxのアクセスログを直接何かに使ってなければ無視できるかも。
log_subrequest on; しておくのはこれはこれで、いきなりアクセスログの行数が倍*6になる、というのはちょっときびしいような気もする。悩ましい。

mirror_request_body on; の場合に proxy_request_buffering が無効になる。これは性能面での特性の変化と、あとはドキュメントによると proxy_next_upstream が使えなくなる、という感じかな。これは機能的に容認できないという人がいるかもしれない。
性能面はまたひとつの懸案だけど、これは手元でちょっと試すというのにほとんど意味がないので割愛。しかし実際のところ、あまり心配しなくてもいいんじゃないか、というような予感はある。根本的にイベント駆動モデルをベースにしたサーバだしね。

さて、どうしよっかなー。そういえばみなさん nginx mainline version をproduction投入するの、最近は心理的にどうなんすかね。

*1:とやって思い出せるので、こういうのを書いてくれる人は本当にすばらしい

*2:ロードバランス等はそこより上流で適当に行われている

*3:自分の例では off にしたら何も検証できなくなるので、しない

*4:http_mirror_moduleのコードを読んだ限り、この区別に使えそうな変数は特に増えてはいない様子だった

*5:超短くてわかりやすい!

*6:他の用途における internal redirect などを含めればもっと?

MANABIYA.tech にいってきた＆しゃべってきた

manabiya.tech

こちらのMANABIYA.techというカンファレンスでインフラ方面のセッションオーナーであるさくらインターネットの田中さんから何かどう? というお誘いがあったので、最近考えてたことを話すいい機会だと思ってひと枠しゃべってきた。あと、同トラックの前佛さん、長野(kazeburo)さんといっしょにパネルディスカッション的なやつも(モデレーターは田中さん)。

会場は以前にTDの社内イベントで使ったことがある、秋葉原の3331というところで、小学校跡地をイベントスペースに改装したところ。こういうところ、いいよなー。雰囲気があって。とはいえ元の建物がモノだけにひと部屋のサイズは小さめになってて、これはカンファレンス会場としてはちょっときびしいですね。

しゃべってきた

Tales of Modern Systems: Distributed / Containerized Systems from SATOSHI TAGOMORI

DockerとKubernetesの名前はおそらく多くのソフトウェアエンジニアが知っていると思うけど、Kubernetesというのは実際には分散処理基盤のコントローラに他ならなくて、これらはポッと出てきたものでもなんでもなくて、過去に分散ストレージあるいは分散処理などの流れがあって発展してきたものだと思うんですよー、みたいな話。このあたりを広めに見られていない人にとって、ざっくばらんな教養めいたものになるといいなと思って話した。
これはKubernetesがGoogleにおけるBorgのOSS版であることを考えれば明らか*1とはいえ、まあ、まあ、誰にでも公開されているものをベースに明らかな歴史として組み立てるのって大事だと思うんですよね。

またタイトルやトレンドへの名前のつけかたに困って "Modern Systems" というデカい単語を使ってしまった。話したときに最初にちょっと言ったけど、誰しもがこういうツールあるいは考え方を採用すべきだと思っているわけではなくて、とはいえそれでも「全体として進んできた/これからも進んでいく方向」みたいなところに分散処理やコンテナ化みたいなものが(今のところ)あるとは思っていて、それらをひっくるめて "Modern Systems" と言ってしまった。これはここにも注記しておく。

面白かったという反応をいくつか見聞きできたので、やれてよかった。40分の制限時間のところを5分オーバーしたのは反省しております。動画は公開されるのかな?

そのほか

パネルディスカッション的なのは、そもそも現代におけるITシステムの「インフラ」ってのはなんなんですかねー、みたいな話を多くしていた気がする。まあ、もうハードウェアをがんがんいじるお仕事も少ないですからねえ。
これは自分がそこで言ったことでもあるけど、ソフトウェアの割合が大きくなってくると、昔は会社に所属して案件ベースでしか試せなかったこと(ハードウェアをあれこれいじり倒す)よりも自分のPCででも動くものが仕事の中心になってくるので、個人でやれる範囲が広くなっている、ということだ。これは歓迎すべきだと思う。面白いこといろいろやっていきましょう。

で、お昼を挟んでふたつ話したら気力も体力も尽きて、あとはだいぶダラダラしていた。おしまい。

*1:……なんだけどこのあたりは話しはじめるとGoogle内タイムラインとOSS的タイムラインで矛盾が生じるのでしなかった、しはじめたら時間がいくらあっても足りない