2020/12/07

人生N回目の飛行機に乗り遅れそうなところからなんとかして乗った話

なんとかして乗るといっても、締め切り過ぎた保安検査場にいって土下座して乗るとかそういうやつではないです! 人生N回目の飛行機乗り遅れ危機一髪話です。

今年はコロナ禍ということもありさすがに旅行はできんじゃろということで12月になるまで1回も飛行機に乗っていなかったのですが、ちょっと色々あって1回実家に帰る必要が生じ、12/5〜7で帯広に行ってきました。さすがに年末年始に帰るのは気が引けるけど、とはいえ帰らないといけないのでとりあえず12月頭に帰ってしまおうみたいな感じです。元々いつも実家に帰っても地元の友人に会うとかそういうこともなく基本的に実家でゴロゴロして滞在してるだけなので、今回も大体そんな感じでした。外でご飯食べたのは平和園の小上がり(個室)で焼肉食べたくらいのものです。

そんなわけで現在はもう関東に帰ってきていますが、なにぶん飛行機に乗るのが1年以上ぶりだったもので、なんかぽわぽわしてて行きの飛行機に乗り遅れそうになったんですよ。ということでそういう話を書きます。

今、羽田から地方空港に飛ぶ飛行機は減便による欠航がけっこうたくさん発生していて、帯広行きも御多分に漏れずJALとAirDOで1日合計7往復飛ぶところが、だいたい3〜5往復に減らされています。で、私はANA派なので12/5の羽田発12:15の便で帰ろうとしていまして、これを逃すともうこの日のANA/AirDO便はないというところでした。

10:20くらいに家を出まして、実家にお菓子を買って行くべくクルミっ子でおなじみの鎌倉紅谷の本店に寄って買い終わったところで10:42くらい。このとき初めて気付いたんです、よく考えてみるともう電車の時間的に飛行機に間に合わないんじゃないかと。いつもだとちゃんと前日には翌日の電車移動をちゃんと調べて頭に入れておくのですが、ちょっと前日ぽわぽわしてまして何の準備もしてなかったんですよね〜。

ということで、脳内で移動をシミュレーションしはじめました(遅い)。電車が十分に走っている昼間であれば、鎌倉駅から羽田空港までの所要時間は1時間が目安です。JR横須賀線で横浜まで26分、横浜駅で京急の羽田直通のエアポート急行に乗り換えて26分、乗り換え時間含めると大体1時間といった具合です。で、羽田から飛行機が12:15に飛ぶので、保安検査締め切りは……そういえば保安検査締め切りは15分前から20分前になったんだよな〜って計算したら、11:55には保安検査を通らないといけません。

で、羽田に着いて京急を降りて保安検査場まで最低でも5分はみといたほうがいいので(ダッシュすると3分くらいでいけるけど、しんどい)、乗換案内アプリで羽田空港到着を11:50で検索すると、鎌倉駅10:43→羽田空港11:46 という案内が出てきました。いや、いま10:42だよ、紅谷から鎌倉駅まで歩いて10分くらいあるよ。一応、その次の横須賀線に乗るとどうなるか調べてみた所、鎌倉駅10:58→羽田空港11:55と出ました。ちょうど保安検査締め切りの時間に羽田に着くわけです。つまり、まだ鎌倉出てないのにこのまま向かっても飛行機乗り遅れるの確定しているわけです……。

うーーーーん困ったな〜、これ乗り遅れるとJALに振り替えるとかしないと今日中に帯広に帰れないな〜、まぁいずれにせよ最悪そうなっても仕方ないけど、とりあえず羽田には向かおう……。ということで、鎌倉駅へ。一応乗換案内アプリで、鎌倉駅10:43のやつが5分程度の遅れと出てたので、ワンチャン乗れるのでは? と思って紅谷本店から鎌倉駅まで雨の中ダッシュしましたが、10:48に鎌倉駅ついたら見事に発車直後でホームに誰も居ませんでした。つらい。

駅について、とりあえずもう傘の出番はないから駅のベンチで傘をカバンに入れて、ベストを尽くせるよう横浜駅で京急の乗換がスムーズにいく7〜8号車あたりのところから乗るようにホーム上を移動して、なんとかして京急に乗るタイミングを早めて保安検査締め切りの5分前に羽田空港に到着する方法を調べようとポケットに手を入れたらiPhoneが入ってない。ん……? Apple Watchをみると、たしかにiPhoneと通信出来てないマークになっていて、えっ、こんなときにiPhone無くすとかあるの……? となりました。

ただ、改札を通るときにiPhoneで通っているのでそこまであったのは確実で、その後iPhoneに触れたのは駅のベンチで傘をカバンに入れたつい3分前だけなので、急いでそのベンチまで戻ったら既にiPhoneはなく、駅員に聞いてみたら「さっき回収して事務室に持っていきましたよ〜」とのことでした。あわててそばの事務室にいったらApple WatchがiPhoneにつながって、「あーそれですそれです〜〜」みたいな感じでとりあえずiPhoneは見つかりました。いやはやマジでテンパってるときっていうのはどこまでもそういうミスが出てくるもんですよね。障害対応もそういうもんですよね(突然仕事の話で例えるおじさん)。

乗り遅れ濃厚そうなところからどう挽回したか

その後無事横須賀線に乗りまして、ここで一旦深呼吸して状況を整理します。

今、乗換案内アプリに提示されている乗換はこれです。

• 鎌倉 10:58 → 横浜 11:24 → (5分乗換) → 横浜 11:29 → 羽田空港国内線ターミナル 11:55

で、この11:29の京急だと保安検査締め切りと同時に到着する形になり詰んでしまうので、11:29の1本前の京急にのることを考えます。エアポート急行の前は普通の快特(一番速いやつ)が11:24に来るので、これで京急蒲田までいってそこから乗り換えることで到着を早めることができそうでした。

• 横浜 11:24 → 京急蒲田 11:34 → (6分乗換) → 京急蒲田 11:40 → 羽田空港国内線ターミナル 11:48

ちなみに乗換案内アプリで出てくる時刻はだいたい出発時間ベースなので、たまに1分停車の駅とかだと実は1分余裕があって、横浜駅で横須賀線ホームから階段を駆け下りて連絡改札を通って京急の階段を駆け上がるとギリギリまにあったり間に合わなかったりみたいなことがあります。ただ、あれの間に合うパターンは横浜駅の乗降客が多いときくらいなので、やはり最低でも乗換に2分はみておかないとなりません。

横浜から後ろの電車の見通しはわかったけど、依然としてこの横須賀線に乗ってると横浜駅の乗換の余裕は0分しかないのでこのままだと確実にアウトです。さーてどうするか……。

横須賀線は、大船から横浜の間で東海道線が並走しています。で、東海道線は横須賀線と違い、東戸塚と保土ヶ谷に止まらないので、戸塚を同じ時刻に出る場合、東海道線のほうが約2分ほど早く横浜に着きます。なので、向かい側ホームで乗換ができる戸塚駅で同着の電車を華麗に乗換みたいなのができれば横浜駅での乗り換え時間を2分捻出できます。今乗ってる電車が戸塚に着くのが11:11なので、東海道線の時刻表を見てみると…

• 横須賀線: 鎌倉 10:58 → 大船 11:06 → 戸塚 11:11 → 横浜 11:24
• 東海道線: 藤沢 11:01 → 大船 11:06 → 戸塚 11:11 → 横浜 11:22

いやー運がよいとはこのことですな! というわけで、これでなんとか乗換案内よりも1本繰り上げて電車を乗り継ぐ目算が立ちました。全部繋ぐとこうなります。

経路検索で出た乗換案内

1. 鎌倉 10:58 → 横浜 11:24 (横須賀線)
2. 横浜 11:29 → 羽田空港国内線ターミナル 11:55 (京急エアポート急行)

時刻表を調べまくってなんとかした乗り換え

1. 鎌倉 10:58 → 戸塚 11:11 (横須賀線)
2. 戸塚 11:11 → 横浜 11:22 (東海道線)
3. 横浜 11:24 → 京急蒲田 11:34 (京急本線快特)
4. 京急蒲田 11:40 → 羽田空港国内線ターミナル 11:48 (京急空港線快特)

ということで、これを調べ終わったときには既に北鎌倉を過ぎてましたが、大船で確かに向こう側の東海道線ホームに乗換対象の東海道線がいることを確認し、戸塚駅で0分乗り換えし、横浜に横須賀線より2分半早くついてJRから京急へ直接乗り換えできる改札をスッと通って京急ホームについたのが11:23。いやーなんとかなりました。

ここから先は慣れたもので、蒲田で3階ホームにあがってシュッと乗り換えて羽田に到着。小走りで第2ターミナル2Fの出発ロビーまで上がって一番近い保安検査場Bに滑り込んだのが11:53くらいです。セーフ……セーフ……! 保安検査を超えた後の移動もAirDOだとめっちゃ端っこの乗り場なので結構かかりましたが、まぁ10分はかからないのでちゃんと搭乗10分前には搭乗口に着きました。さすがに昼飯とか買う暇なかったですが、ひとまず乗れて一安心。すごいね、鎌倉から50分で羽田に着くもんなんですね!

教訓: ちゃんと時間に余裕持って出ような、というか家出る前に電車調べような。

過去にもこういう乗り換えで空港に向かったことはありましたが、今回のように乗り換え失敗したら完全にアウトなくらいギリギリになったのはこれが初めてで、東海道線が同じ時間で走ってたのはどうみても運が良かっただけみたいなところがあったのでとても心臓に悪いなーと思いました。完全にぽわわの極みです。

2020/10/05

ISUCON10決勝に並行チームとしてfujiwara組で参加してきました

先日「ISUCON10、予選で敗退した〜」というブログをかいたのですが、その後運営チームより「本戦のライブイベントで『本戦参加者と並列で解くエキシビション的なチーム』として参加しませんか!」というお誘いがあり、決勝の日はまだバッチリ開けてあったので「はい! 出ます!」ということで参加しました〜というレポートです。

結果

ライブ配信時に発表されたスコアとはちょっと異なってますが最終結果はこんな感じになっているそうです。

順位	チーム名	最終スコア
1st	takonomura(学生)	49545
2nd	Azeit(学生)	43366
3rd	がんもどき(学生)	34767

予選敗退勢の並行チームは4チームいて、ベストスコアと最終計測スコアはこんな感じ。

チーム名	best	最終スコア	備考
fujiwara組	41015	39689
鍋部（2人前）	19560	11113	(日本語が化けてるようだ)
失敗から学ぶISUCONの正しい歩き方 the Revenge	7340	失格(5784)	ブラウザログインできないため失格
NaruseJun	52567	失格(0)	試行3回目と4回目が0点で失格

ざっくりいうとfujiwara組は本戦でいうと2位と3位の間くらいでした、いやー予選さえ突破できていればな〜〜。それにしても今年は1〜3位が全部学生というのはすごいですね! 学生枠じゃなくて社会人枠作ったらというジョークもでるくらいの結果でしたが、お題的にもみんな知ってるISUCONということで参加者によってドメイン知識の偏りがなかった結果学生がいかんなく伸びてきたというところなのかなぁと思っています。

ということで、ここからはfujiwara組のやったことの話とかを書いていきます。

始まるまで

並列チームは運営チームより「ミライノタワーに来ますか?」と聞かれまして、「はい! 行きます!」と答えた我々は新宿で参加することにしました。私は鎌倉住まいなので湘南新宿ラインで新宿にいくにあたって9時までに行くには7時半すぎの電車に乗る必要があるので仕事いくよりもよほど早起きが必要でしたが、ISUCONのためなら普通に早起きできるのでその辺は余裕でした。ちなみに朝の検温は36.1度でした! 寝起きだと思ったよりも低い。

さて、朝起きてみると組長からちょっと喉痛いので大事をとって自宅でやりますという連絡がありちょっと想定外でしたが、そんなこともあろうかと持っていく予定の装備にモバイルディスプレイのほかにiPadも入れてあったので、会場ではiPadでHangouts Meetを繋ぎつつ普通に準備完了。あとは開始を待つだけ!

手元にデバイスがたくさんあってハウリングしないようにするためのMeetの準備とかに少し手間取ったので、ライブ配信の最初のお題発表はちゃんと見れなかったのですが、遠くのほうで同じく並列で解くチームのみなさんが「ISUCONのポータルがお題だ……」とざわついていたので「マジか〜」と思いつつ、競技開始になりました。

10:00〜12:00くらい

インフラ構成をチェックしてみると、3台ともスペックが違うことがわかりました。

• isu01: 2コア 1GB
• isu02: 2コア 2GB
• isu03: 4コア 1GB

ということで、isu01が一番しょぼくて、メモリが倍なのが02、コアが倍なのが03という感じ。合計8コアでそのうち03に4コア偏っているので、分散構成にしない(できない)プロセスで、CPUヘビーなやつを03に置くのが良さそうです。

初期ベンチを分析

初期実装はRubyで設定されていて、isu01にベンチをかけてだいたい4000点ちょっと。CPUの偏りとしては、うろ覚えだけどたしかbundle(xsuportalのpuma)2プロセスで50%、mysqlで30%、ruby(benchmark_server)で20% みたいな感じでした。isu02もメモリが増えただけなのでとくに点数は伸びず、isu03はコア数が2倍になっているのでたぶんスコアも伸びるだろうと思ったのですが、isu03もほぼ同じ点数で伸びず。ただ、CPUの負荷の偏りは異なっていて、ruby(benchmark_server)がCPU1コアまるまるつかうようになっていてなんだこれは……みたいな感じです。

そのあと、言語をGoにきりかえて様子をみてみると、初期でスコアは6000点でした。GoにするとプロセスごとのCPU消費割合が異なっていて、Goだとmysqlが圧倒的にCPUを食うようになっていました。結構実装言語ごとにCPUの使われ方が異なる題材だな〜という感じです。このときまだレギュレーションちゃんとよみおわってないので中身も分からない状態でした。

とにもかくにも、初手でミドルウェアのマシンを分散しないとならないな〜という感想になったので、組長にmysqlをisu02に移してもらいました。そのほかいろいろと、12時くらいまでに、毎回やるじゃろ的な設定を入れました。

• mysqldをisu02に移設 (fujiwara)
• binlog止めて、書き込みヘビーなので innodb_flush_log_at_trx_commit = 2 (fujiwara)
• go-mysql-driverの設定で InterpolateParams = true する (acidlemon)

12:00〜14:00

さらに、レギュレーション読んであきらかにコレやった方がいいよね的なの追加でやっていきました。

• /api/audience/dashboard は最大1秒キャッシュできるので、Go上に900msオンメモリキャッシュする(acidlemon)
• レギュレーションに仮想選手の出場人数によるスコアボーナスが載ってたので、TeamCapacity = 15にあげる(acidlemon)
  • このときまだ勘違いしてて、出場選手数は join-member: 30 がそれだとおもってたので15に上げた(後述)
• contest_config が走行中は不変っぽいので、getCurrentContestStatus を90秒キャッシュする (macopy)

インフラ構成とレギュレーションを見ながらゴールイメージを考える

ひとまず、isu02にmysqldを逃がした後isu01でその他のものを動かしていましたが、isu03を使わない理由がないのでisu01にいたxsuportal, envoy, benchmark_serverを4コアのisu03に移設することに。だいたい基本的にISUCONって最終的にはmysqlの負荷を全部下げきってあとはアプリとかのCPU勝負になることが多いですしね。

Rubyのときはbenchmark_serverがisu03だとCPU100%食ってたのでGoでもそうなるのかなとおもいきやそうならなかったものの、おそらくxsuportalが高速になってきたら最終的にはbenchmark_serverをisu01に分離した方がよさそうかな、と目算を立てました。

で、4コアのマシンに乗せるとisu02もisu03もCPUが余ったので、TeamCapacityを60にしました(180人参加)。このときはまだ「TeamCapacity=60だから選手は120人なのでスコア1.4倍」と思ってたんですが、普通にあとからスコアみたら1.6倍になってました。この時点で何回か回して28000点で、本戦参加者からは並列チームのスコアが見えてないですが全チーム中トップになりました。

14:00〜ライブ配信出演

この時点で、/api/audience/dashboard が50秒の走行の間に12000回くらい呼ばれているため、240回/秒くらいのペースということでキャッシュがきれた瞬間におそらくThundering Herdな状態になってそうなので、golang.org/x/sync/singleflightで重複呼び出しを排除する という記事を参考にキャッシュ切れたときのダッシュボード読み直しを直列化しました(macopy)。これでスコアは29000→33000くらいかな。

14時半すぎに決勝ライブ配信に出演して、戻ってくる頃にはなぜかベンチマークが安定しなくなり、どうもenvoyが死んでいる様子。journalctlでsyslogとにらめっこした結果、ちゃんとenvoyの断末魔が記録されており、socket(2) failed, got error: Too many open files とのことで、fd上限あげてもらってまた安定。

ここからちゃんとした戦略を考える

大体半分過ぎたところで問題とレギュレーションはちゃんと理解できました。簡単にいうと

• 仮想選手がベンチを投入し、仮想負荷走行が終わり、通知を送って仮想選手がそれを確認したら10点
• 仮想選手が質問して運営が回答し、それを仮想選手が確認したら10点
• 仮想選手がダッシュボードを表示したら2点

なので、この10点のやつをいかに高速にぶん回すかということになります。また、仮想選手のベンチが1回おわると仮想オーディエンスが1人増えるので、この仮想ベンチマークをもりもり回せるようにするのがよかろう、ということでいくつか手を打っていきました。

ベンチマークジョブを並列取りだしできるようにする

ここで手をつけたのはまだなんにもしてなかったベンチマーカーです。ベンチマーカーは、キューの読み出し部と、スコアの記録部に分かれていて、入り口のキュー読み出し部がよくみると完全直列になっています。どういうことかというと、SELECT * FROM benchmark_jobs WHERE status = 0 ORDER BY id LIMIT 1;でベンチ未実行のジョブを1件取り出すんですが、ジョブの取り出し側は最大でチーム数の数だけ並列度があがるようなことがレギュレーションに書かれているものの、この実装だと並列にポーリングされても

• 複数のRPCで同じIDがよみだされる
• 最初にSELECT 〜 FOR UPDATEでロックを獲得したRPCがステータスを変更してジョブハンドルを返す
• 他のやつらはFOR UPDATEで待たされた上、statusが違ってrowが0行で返るので次のポーリングをする

となってしまっています。ということで、これだと並列に呼び出されても1ジョブずつしか処理されないので、ORDER BY idをORDER BY RAND() に変えて、ジョブの読み出しが並列で走るようにしました。ちなみにスコアは上がったかというとほぼほぼあがらなくて、このときのボトルネックはmysqldのあるisu02のCPUなので、結局mysqlの負荷を下げないと意味がないねということでつぎの作戦へ。

質問回答のところにN+1クエリがあるので撲滅する

macopyがやってくれた! これでまたちょっとmysqlとxsuportalのCPUが空いたので、同時にTeamCapacityを60から90にしました。

これも結果からいうとあんまり変わらなくて、うーんという感じだけど、TeamCapacityを増やすと倍率はあがるけど仮想ベンチの完走数が下がるからっぽいというのはスコアのbreakdownを読んでわかったので、mysqlがもっと楽になるようにあのデカイダッシュボードクエリに手をつけ始めました。

ダッシュボードクエリの計算をちょっと楽にする

この時点で、macopyがWebPushをなんとかすると宣言したのでそれは完全に任せたのと、組長が「静的ファイルをnginxで返したい」ということでnginxチャレンジをして一発で成功させている間、わたしは68行くらいあるダッシュボードの集計クエリに手をつけ始めました。改善できそうなところとしては

• スコアを raw - deduction でSQL上で計算してるので、benchmark_jobsにスコアを保存するときに計算した値を入れる
• 学生チームの判定のためだけにcontestantsテーブルをJOINしてたので、teams側にstudentフラグを保存するようにする
• best_scoreとlatest_scoreを毎回LEFT JOINで集計するのは無駄なので、別テーブルを新規に作ってそこにおく

の3つかな〜と目星をつけて、1個ずつやっていきました。raw - deductionのやつはわりとあっさり片付いて、macopyがWebPushのテストで苦労してる合間にシュッといれて無事高速化に寄与しました。

で、学生判定は17時過ぎから入れてみたモノの、バグがあって通らず、17時半くらいの時点で断念。ちなみにスコアを別テーブルに保存するやつも、普段使わないechoとかでやりきる自信が全然なかったのでそのまま手をつけずにやめました。

学生判定は、studentフラグが関係するのは「CreateTeamしたとき」「JoinTeamしたとき」「UpdateRegistrationしたとき」「DeleteRegistrationしたとき」の4つなんですが、UpdateRegistrationとDeleteRegistrationに相当するPUTとDELETEの/api/registrationは集計されたalpログを見る限りベンチマークで呼び出してないっぽいので、「CreateTeamしたときにStudentが作ってたらTeamにフラグを立てる」「JoinTeamしたときに、Studentフラグのチームで入ってきた人がStudentじゃなかったらフラグを落とす」で実装しました。

で、これで普通にいけるとおもってたのでこれ以上わからんということでブランチを破棄したんですが、今になってコードをよく読むと既にどっかのチームに入ってる人がJoinTeamを呼び出したときにとくにどっかに所属してるかとかノーチェックでUPDATE文を発行しているので、その元いたチームから社会人が抜けて移籍して元のチームが学生だけのチームになったみたいなパターンがありますな! いやーそこまでケアしてなかったわ〜。

17:00すぎて、最後の追い込み

ということで、最後の追い込みだったのですが、なんと17時〜17時40分までベンチが全部フェイルしまして、さすがにこれはしんどい。フェイルしてた理由はいくつかあり、

• WebPushがどうしてもなんか「受け取るべき通知エラー」で安定しなかったので、結局WebPushは無効状態に戻した
• 学生判定が出来なくて通らなかった
• envoyからnginxに変えた後からHTTP2 GOAWAYフレームがどうのこうのというのが実ベンチマーカーまで返されてしまい、めっちゃ減点された
• TeamCapacityを120まであげたら負荷が高くなりすぎていた

というあたりだったので、WebPushは最終的に無効に、学生判定は切り戻し、nginxもenvoyに戻してもらいました。

TeamCapacityについては、17時過ぎにTeamCapacityから想定してた仮想選手人数と、実際のスコアリングのボーナス係数が異なることに気がついて運営に質問をしたんですが、直後に「あれ、これはCreateTeamで1人、JoinTeamで2人で合計3人チームなのでは……? ということはTeamCapacityの2倍ではなく3倍が仮想選手人数なのでは……?」と気付きました。そのときTeamCapacity=120で係数が2.0倍だったんですが、300人以上は一律で係数2.0になるので、こんなにTeamCapacityあげる意味無いな〜ということで100に落としたら無事スコアが安定し、最後に再起動試験をやって作業終了となりました。

結局Studentを倒せなかったのでisu02のmysqlのCPUボトルネックというところは変わらなかったのですが、でもmysqlも200%弱食ってるしxsuportalも200%前後食ってるので、たぶんこれはisu02と03の役割を入れ替えてもそんなに変わらなかったかなという印象。golang内のキャッシュのアレもあったりしてxsuportalを2台(2プロセス)に分散するのは時間内にやろうとするとたぶんハマるだろうと読んで、手をつけませんでした。envoyとbenchmark_serverもisu03においたままです。

isu03が4コアあるというのは本当に便利で、この状態ではenvoyはisu03に同居してもCPUあまるくらいなので、静的ファイルをxsuportalからenvoyに返すためのサーバ間ネットワークオーバーヘッドも不要なこの構成でいいかな〜というところでした。

ただこれ、mysqldのCPUを本当に完全にカツカツに使い切ってしまうといろいろと遅延して最後の検証処理で死んだりdashboardの反映遅延のペナルティが出たりとかあるので、TeamCapacity=100でちょうどバランスとれてよかったな〜というところです。

まとめ

いやーお題がお題なだけに楽しかった! あと、本戦のライブ配信の並行チーム紹介のときにわたし「本戦チームの3番目くらいに入っておきたいな〜」って言ってたんですが、まさに有言実行ということでがんばったかいがあったな〜 と思いました。まさか1〜3位まで学生だとは思いませんでしたが……。

それでは、また来年のISUCONでお会いしましょう〜。