たごもりすメモ

コードとかその他の話とか。

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

f:id:tagomoris:20180531102321j:plainf:id:tagomoris:20180602180507j:plain

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

しゃべってきた

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

Hijacking Ruby Syntax in Ruby - RubyKaigi 2018

スライドはこちら。

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

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

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

f:id:tagomoris:20180531134945j:plain

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

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


参加してきた

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

f:id:tagomoris:20180531212002j:plainf:id:tagomoris:20180531212745j:plainf:id:tagomoris:20180531215721j:plain

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が取り込めそうなのもあれこれあったりで議論が楽しいし、実にすばらしい。他のトークも聞いたものはみんなそれぞれの書いたコードについてしゃべりまくってて超面白かった。

f:id:tagomoris:20180601215016j:plainf:id:tagomoris:20180531223549j:plainf:id:tagomoris:20180601220104j:plain

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

f:id:tagomoris:20180531213102j:plainf:id:tagomoris:20180601214322j:plainf:id:tagomoris:20180601231026j:plain

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


Partyなど

f:id:tagomoris:20180602194812j:plain

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


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

f:id:tagomoris:20180601231605j:plainf:id:tagomoris:20180602220516j:plainf:id:tagomoris:20180602222041j:plain

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

f:id:tagomoris:20180602220908j:plainf:id:tagomoris:20180603020205j:plainf:id:tagomoris:20180602232927j:plain

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

まとめ

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

f:id:tagomoris:20180602232536j:plainf:id:tagomoris:20180602222527j:plainf:id:tagomoris:20180603020345j:plain

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

*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というところで、小学校跡地をイベントスペースに改装したところ。こういうところ、いいよなー。雰囲気があって。とはいえ元の建物がモノだけにひと部屋のサイズは小さめになってて、これはカンファレンス会場としてはちょっときびしいですね。

しゃべってきた

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

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

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

そのほか

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

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

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

Golangの defer をRubyでも使いたい

前にRubyでtry-with-resourcesが使いたいという話を書いてそのときにリリースしたgemもあるが、人類の安全に・便利にリソースを解放したいという欲求には際限がない。
try-with-resources は便利なんだけど欠点がないわけではなくて、リソースの確保と解放を一ヶ所でまとめてやらないとネストが深くなる。複数箇所に分けて書くならネストも2段になってしまう。
これはこれで整理されたコードを書く圧力になるので悪くない面もあるんだけど、とはいえもうちょっと自由にやりたい、いい方法は無いもんか、という話。

defer

ある。Golangの defer が便利そう。defer foobar って書いとくと、そのスコープを外れるときに自動的に foobar の内容が実行される。あるスコープのどこに何度書いてもいい。これは便利。

# GolangのdeferのままRubyにもってきたの図(イメージ)

def my_method
  # ...
  file = File.new("filename.txt", "w")
  defer file.close
  # ...
end

ただし上記のコードはRubyでは実現できない……syntaxに本当に手を入れない限りは。defer の後が即座に評価されてしまう。

なお try-with-resource ほしいよーって話をRubyのbugsに上げたときにライブラリとして実装できるじゃんって話があったけど、これじゃダメなんですよ。なおその例はこちら(引用)。

  Deferred.new do |d|
    r0 = Resource.new
    d.defer {r0&.close}

    r1 = Resource.new
    d.defer r1

    r2 = d.defer Resource.new
    abort unless Resource === r2

    r3 = d.defer(Resource.new) {|r|r.delete}
  end

defer 使いたいときにいちいちブロックで囲わないといけないのは、元の golang の defer と較べると圧倒的に使いにくいし、見た目も理想的ではない。deferしとけば必要なときに実行されるのがいいのに、この例だとわざわざブロックの終端という deferred な処理が発動する場所を明示してやらないといけないってことじゃないですか。コレジャナイんですよ。defの内側で必ずもう1段 Deferred.new do ... end でネストするとかイヤでしょ。

deferral

というわけでgemを作った。名前は空いてたところで deferral にした。

defer に与えるのがブロックであるところが元のgolangのと少し違うが、あとは同じような挙動になるはず。スコープを外れるとdeferredな処理が自動的に実行される。複数登録する場合は登録したのの逆順で実行される。例外が発生した場合でも実行される。

require "deferral/toplevel"
using Deferral::TopLevel

def my_method_name
  # ...
  file = File.open("my_file", "r")
  defer { file.close }

  file.write "data..."
  # ...
end

ほーら便利っしょ。あと記述がシンプル。余計なネストも作らないし。

実装

TracePoint 使って実装しているので本番環境で使い倒すのはオススメできません。またRubyの最適化処理をいろいろ台無しにする可能性があります。

あとdeferredな処理内で例外が起きたときには全部握り潰すようになってます。これはイマイチ。本当は例外が起きるならそれをそのまま上げる + 複数例外が起きた場合は suppressed な形にしてひとつの例外に他のをぶら下げる、みたいにするべきなんだけど、今はやってない。
これは何故かというと、メソッド(やブロック)内から例外が上がって強制的に脱出するとき、それがTracePointで捕捉できないことによる。メソッドから出ようとしていることはわかるが、それが通常のreturnによるものなのか例外によるものなのかの区別ができない + 上がってきた例外オブジェクトもつかまえられない。
これ、どうにかなんないかなあと思っているので、そのうち bugs に報告しようと思っている。忘れなければ。

で、TracePoint使えば実装できなくはないけど、ちゃんとやるにはやっぱり言語側でサポートしてほしいなあ、と思っている。ライブラリでいいじゃんというコミッタの意見で#13923が止まっちゃったけど、いや、ここに示した通り、ライブラリじゃダメなんですよ。

ライブラリじゃ駄目なわけ (追記)

某所で指摘されたけど、ブロックが参照する変数の中身が書き変わったときもこのライブラリでは手当できません。たとえば以下のコードだと "fileB.txt" を開いた File オブジェクトが2回閉じられちゃう(いっぽう fileA.txt を開いたほうはリークする……GCの回収を待つ)。

require "deferral/toplevel"
using Deferral::TopLevel

def my_method_name
  f = File.open("fileA.txt", "w")
  defer { f.close }
  # ...

  f = File.open("fileB.txt", "w")
  defer { f.close }
  # ...

これは block で書く以上どうにもならないすね。

ライブラリじゃ駄目なわけがひとつ消滅 (追記2)

ローカル変数の中身を binding 経由で強制的に保存・再生するという悪魔的発想により上記コード例もちゃんと動く deferral v0.1.2 がリリースされました。

というわけで

興味がある人はぜひどうぞ。

Ruby誕生25周年記念イベントでしゃべった & After Partyやった

Ruby誕生から25周年を祝うイベントが開催され、そこの「Rubyの今」というセッションでデータ処理について話さないかという依頼があり、受けたので、話してきた。

Ruby25 | Top

本当にいろんな人が参加していて、みんなでわいわいとお祝いをする、という感じ。高橋会長やまつもとさんの話はあちこちのメディアに出ているから良いとして、Matzのご息女が出てきてMatzが壇上でものすごく動揺してたのがちょっと面白かった。いやあ、これこそがコンテンツだな。

他にスポンサー企業のブースがあったり、いろんなプロジェクト・コミュニティのポスター展示があったり。ポスター展示はよかったなー。あんなふうに自分のプロジェクトをアピールできるのはすごく良いと思う。見て回ったけどじつに楽しかった。

しゃべってきた

ということで、データ処理とは何を指すのか、どのようなプロダクトやサービスがあって、またその界隈を経由してどういうところでどのようにRubyが使われているかについてしゃべった。
自分が書いたコードについてではないスピーチ*1をするのはずいぶん久し振りで、また「お祝いをする」場だというのにあわせて内容もマインドセットも作ったものだから、15分弱という時間もあってだいぶ緊張した。が、まあまあうまくやれたと思う。他の人のプロダクトやプロジェクトを紹介するの、できるだけ紹介はしたいけど間違ったことを言うのは怖い、ということでけっこうキツい。今回はやれるだけのことはやった。

終わったあとで色々な人に良かったと言ってもらえたのはじつに嬉しいんだけど、ふたことめがだいたい「あんな話しかたもできたんですねえ」「酒が足りなかったのでは」などという感想で、複雑な気分というか普段のキャラクターが浸透しているというか、ううむ。

After Partyやった

Ruby25 After Party|IT勉強会ならTECH PLAY[テックプレイ]

気付いたときにはRuby25の大きいスポンサー枠は全部埋まってて、Treasure Dataとして何かできないかなーという検討の結果がこちらのイベント。180人定員のところ、最終的に170人弱は入っていたみたい。思ったよりだいぶ混雑した会場になっていたけど、やらないよりはだいぶ良かったかなという気がする。楽しんでもらえたかなあ。
技術評論社さんから最新号のWEB+DB PRESSを3冊いただいていたので、そこに著者陣のサインをいただいて会場プレゼント大会をやったりとかもしていた。わいわい。

ということで

じつにいいイベントでした。特に @_ko1 さんは本当にお疲れさまでした&ありがとうございました。
終わったあとも飲みにいってハシゴして、しかし疲れていたのか、最終的にはいっしょに飲んでいた人にちょっと迷惑をかけたかもしれぬ。君の名は。を途中まで観たところまでしか覚えてない……。おつかれさまでした。

*1:いや、幸運なことに自分が書いたコードのあるプロダクトも入ってはいるのだが

TD Tech Talk PLAZMAでBigdamについてしゃべった

今年はTreasure Dataの東京オフィスができて5年ということも兼ねてPLAZMAというイベントをやっているんだけど、その併催ということで TD Tech Talk をなんと2日間、初めて平日の午後の開催で行った。TD発のOSSが中心になるOSS Dayと、TDの内部実装についてあれこれ話すTD Internal Day。

techplay.jp
techplay.jp

あれこれ裏方もやっていたんだけど、多くの人に来ていただけたし、楽しんでもらえたような感じだった。またOSS DayとTD Internal Dayともに外部からの人にもしゃべっていただく時間を設けて*1みた。こっちも普段TDのエンジニアだけだと出てこない話がいろいろあって、本当によかったと思う。

しゃべった

ここ1年(!)やっているBigdamというプロジェクトがあるんだけど、そのプロジェクトの概要と全体の設計において重要なポイントをいくつか紹介する内容にしてみた。

これでも内容をだいぶ簡素化したんだけどそれでも30分に収まりそうにない分量になっちゃって、しょうがないからだいぶ早口でやりました。これは明らかによくないんだけど、うーん、他にどうにもならなかった。削れる場所がない。
分散システムをどういう目的で・何を達成するために設計するかという話はあまり聞いたことがない気がしたので、これはこれで新鮮な内容だったんじゃないかなという気はする。いっぽうでどうしても時間の制約から実装上のポイントとか他に検討した選択肢への言及(例えば、Kafkaを使わないの? などなど)が内容から漏れちゃうので、それは自分にとっても少し残念だった。懇親会ではけっこうそういう話をしていた。

なんにしろ疲れた、が、まあ、やっている話ができたのはよかった。

*1:これは実は昨年にあったFastly Yamagoya Meetupがすごくよかったので、これをパクらせてもらった