月別: 2018年10月

文字通り(´・ω・｀)となった どうもこんにちは。 チーム(´・ω・｀)の顔担当のnagatech(ながてち)です。 10月20日に新宿ミライナタワーにあるLINE本社でIikanjini Speed Up CONtestことISUCONの本戦に同じサークルのますぐれ・takashi_trap(wtks)と参加してきたので参加記を書きたいと思います。 結果は記事タイトルと画像からお察しの通り、競技終了後の再起動試験にfailして0点でした。終了直前にアプリケーションをバグらせてアプリが正常に動かなくなっていたので納得の0点です。 Highestスコアは7840点で、全チームのHighestスコアで見ると全体14位でそこそこだった(盛大な負け惜しみ)ので、せめて正の点数が取れたらなあと後悔しかないです。くそう... なにはともあれ、ISUCON本戦自体はとても(とても)楽しいイベントでした。競技中の飲み物やお菓子などのサポートも充実しており、快適に競技に取り組むことができました。このような機会を与えてくださって本当に感謝感激です。 グラフはこんな感じになりました。(最後は0点なのでグラフには存在しない) ISUCON8本戦参加記 ブログを書くまでがISUCON本戦らしいので、いろいろ写真を交えながら参加記を書きたいと思います。 前日まで 予選から本戦まで約1ヶ月近くあったわけですが、それぞれがそれぞれで忙しく、集まって練習などができませんでした。 前日になって、「さすがになにも話し合わずに本戦当日はやばい」ということになり、大学図書館のグループ学習スペースで当日の作戦会議をしました。(と言っても大したことは話し合ってない) 前日はさすがに早く寝ましたが、緊張でなかなか寝付けませんでした。 当日朝 起床コンテスト予選通過です — ながてち (@syobon_titech) 2018年10月19日 (こういうイベントの起床成功率は高い) 何事もなく9:10に会場にたどり着きました。すでにチームメイトのtakashi_trap(wtks)が来ていました。 pic.twitter.com/hLvC5GpPm7 — ながてち (@syobon_titech) 2018年10月20日 カッコいい名札をいただきました。ありがとうございます！！ 名札を受け取ったあとは、ISU取り(席決め)をしました。 「景色のいい席に座りたい！」という自分の要望で窓際のカウンター席にしたのですが、その後でNaruseJunチーム(実は同じ大学のサークルのメンバー)に「席取り合戦に負けるとそこになるよね～」と言われました。確かに景色がいい代わりに結果発表とかのスクリーンは見えなかったのでそこそこ不便でした。ついでに言うと競技中はまぶしくてシャッターを閉じていたので外の景色は見えませんでした... 9:30くらいにますぐれが来て、チームメイト全員がそろいました。 開始前は競技中にやることリストを読んだり、予選でつまづいたCentOSのファイアウォールについて調べてたりしてました。 10:00 競技開始 オープニングムービーとともに本戦のお題となるアプリケーションが発表されました。(普通にオープニングムービーは面白かった。) お題は仮想椅子取引所「ISUCOIN」。SNS「いすばた」とのシェア機能の追加でアクセス数が爆発してやばいという設定でした。(いすばたはISUCON7の予選のお題アプリケーションだった気がします。アツい展開ですね。) お題の発表後、ポータルサイトが開かれ、競技開始となりました。 とりあえず、3人でマニュアルを読みましたが、その量の多さに圧倒しました。(マニュアル、アプリケーションの仕様書、外部APIの仕様書等々) とりあえずマニュアルはしっかり読んで、アプリケーションの仕様書は分からないところがあったらその都度参照していくという方針にしました。(これがのちに大きな失敗を生むことになる。) 初回ベンチマークのスコアは0点でした。というのも、ベンチマーク中なことに気付かず、自分がDBのバックアップを取ったのが原因でした。(ごめん) (実質)初回のスコアは608点でした。 初動は予選と同じく、takashi_trap(wtks)がnginxのチューニング、ますぐれがpprofなどの計測ツールの導入と分析、自分が4台のVMに自動デプロイの整備という感じで進めていきました。 11:00くらい tradeのSQLクエリを改善 ますぐれが最新のトレードだけ取得すればいいのにアプリでは全件取得していることに気付いて、GetTradeByIDとGetLatestTradeのSQLクエリにLIMIT 1を付けてくれました。 結果は4970点となり、一時的に全体2位になりました。(予選の時もそうだったけど、競技開始してからそこそこいい点数を取るのだけは早い。) これについては競技終了後の講評でここに気付くと(Go実装なら)得点が跳ね上がる的なことを言ってました。 その後はPOST /signup時ハッシュの計算をMinCostにしたり、アプリを複数台構成にしたりしました。 13:00くらい 自動デプロイ整備 思ったよりも時間がかかってしまいました。というのも自分がdocker-composeに不慣れでデプロイシェルの構築があやふやだったのと、GitHubのWebhook処理用アプリをsudoをつけて起動してしまい、それが原因で公開鍵認証に失敗してgitに接続できなかったことに気付かなかったり、そもそも本戦には初期実装にNode.jsがなく、Node.jsの環境構築から始めなければならなかったりと、まあいろいろとやらかしまくって競技中の大事な時間を削りまくってました。本当に申し訳なかったです... 自動デプロイを整備したあとは用意されたお弁当を食べました。 いいイベントには......... いい弁当！！！www pic.twitter.com/fkb6mIIDKN — ながてち (@syobon_titech) 2018年10月20日 (この激うまギャグ自体は去年のISUCON7本戦のお弁当ツイートからとってきてます) (画像がブレてるのはサークル伝統(?)の撮り方) お弁当はおいしかったです。 14:00くらい とりあえずシェア機能をON コードを読んでたらenable_shareをtrueにすることでシェア機能がONになるよということが書いてあったのでとりあえずONにしてみました。 結果はアクセス増加の負荷に耐えられず、ベンチマークが完走しないというオチでした。(それはそう) まあ分かっていたのでそこそこ速くすればここの問題も解決して点数跳ね上がるんだろうな～とかを話し合ったんですが、そこで自分が「一定確率でシェア機能有効にしたらいい感じにアクセスされるんじゃね」とかいう謎の発想をします。 実際のアプリケーションでやったら怒られそうな案ですが、ISUCONは速くなれば何やってもOKなのでこの案は取り入れられ、lastTradeIDの値の余剰でシェア機能の確率を操作することにしました。 (余談ですが、運営的にはこの解法は想定内だったようです。A/Bテストという言葉があるの知らなかった...) この時点では、たしか確率を1/100にしても負荷に耐えられず完走しなかったので、いったんシェア機能をfalseにした気がします。 この時間くらいになると、たまにログの欠損が原因でベンチマークのスコアが0点になる問題が多発したので、/orders関連は1台のサーバで管理するようにしたりしました。 自分はMySQLのチューニングをしてました。 16:00くらい ろうそく足チャートの改善 スロークエリログなどを見ると、ろうそく足チャートを表示させる用のSQL文が時間がかかる上に何回も呼び出されてるのに気づいたので、ここを何とかしようとしました。 MySQL側でクエリキャッシュ効かせればええやろ～くらいに思ってたのですが、MySQL8.0以降ではクエリキャッシュができない模様... いったんMySQLをMariaDBにするかどうかを議論しましたが、結局そのままにして、takashi_trapがアプリ側でキャッシュしてくれるようにしてくれました。(この実装力にはほんと頭が上がらない) これが効いてシェア機能ON確率1/100で6020点、確率1/50で7059点を出すことができました。 17:00くらい GET /infoのキャッシュ takashi_trapの鬼の実装力により、GET /infoの情報をキャッシュするようにしてくれました。 これがめちゃくちゃ効いてシェア機能を確率1でONにしても負荷走行に耐えた...のですが、ログの欠損によるfailで0点になるという悲しい結果になりました。 しかし、今回のベンチマークはfailしてもおおよそのscoreを算出してくれる仕様だった(本当に助かりました)で、確実に効いてる確信があったので、ログ欠損の原因をなんとかすることにしました。 (画像: まぼろしの2万点台) まあそれはそれとして、ログの欠損をしない(安定して最終スコアを出せる)シェア機能ONの確率を探し求めて、確率の試行錯誤してました。確率1/16で7840点(Highestスコア)を出しました。 ログ欠損の原因についてですが、予選と同じく排他制御でログの整合性が取れてないのが原因だと考え、コードを読んでやばそうなところを探そうとしましたが、原因が見つからず焦り焦りしてました。 17:30くらいにOSの再起動でアプリが動くことの確認と各種ログ消去、自動デプロイの停止を行いました。 17:40くらい ログ欠損の大事な原因に気付く ・1秒あたりのリクエスト数は20リクエストまで まさかのAPI制限... シェア機能でアクティブユーザーが増えまくった結果、ログ送信のリクエスト数が1秒あたり20リクエストに収まらず、制限を受けた結果、ログの欠損を引き起こしたことが原因だと判明します。 大事な文言を今の今まで見逃していたことに後悔と焦りが半端じゃなかったです。 とりあえずPOST /sendのリクエストが1秒間に20件以上来たら次回以降に回すように実装したものの、うまく動かず。(今思えばこの実装はPOST /sendが後のほうにつっかえてしまって結局ログの欠損を引き起こしてしまうので良くないですね、かなり焦ってました。さらに言うと、この時点では誰もPOST /send_bulkというAPIの存在には気付いていませんでした。) 18:00ちょっと前 そして終了へ さすがに0点で終わるのだけは避けたいということで、正の点数がとれていた状態(シェア機能が確率1/16でONになる状態)までgitを巻き戻してベンチマークを動かしましたが何故か動かず。(initializeに失敗) 原因が分からないまま、絶望しきった状態で18:00を迎え、タイムアップ。 記録は0点となりました。 (ベンチマークの時間が藁にも縋る思いって感じがする) 今回の最終結果は再起動試験でのスコアで決定されるというものでしたが、アプリケーションをバグらせたうえでの終了だったので、再起動試験もfailだろうなあという思いでした。 結果を待っている間は、チームメンバーでつらいねって話をしながら、gitで巻き戻しても動かなかった原因について考えてました。おそらくログの欠損をなんとかしようとしたときに追加したライブラリの依存関係がうまく解決できなかったのが原因だと思います。(詳細をまだ確認してないので真相は分からないです。) 残りの時間は、ぼーっとした頭で「このはちゃんは清楚かわいい」とか考えてました。 19:00くらい 結果発表 &amp; 懇親会 まず最初に上位チームの結果発表がありました。 同じ大学のサークルの「NaruseJun」チームが学生2位と特別賞を受賞しました。本当におめでとうございます！！！ 対する自分たちのチームは、OSを再起動してもアプリをバグらせたままだったようで、最終スコアも0点でした。 IDの順番もあって最下位に見えるのは本当に悔しい... 結果発表後はおいしい🍺と🍕と🍰とその他美味しいごはんがたくさん並んで懇親会が始まりました。 乾杯！！www pic.twitter.com/PRK7hrivRi — ながてち (@syobon_titech) 2018年10月20日 良さ pic.twitter.com/mgqzvtQyru — ながてち (@syobon_titech) 2018年10月20日 食べながら飲みながらひたすらNaruseJunチームと感想戦をしていました。POST /send_bulkの存在はここで教えてもらいました。(NaruseJunチームはｽｯと気付いてｼｭｯと実装したらしい) 次の日のIPAの情報処理技術者試験に支障が出るくらいに食べて飲んで、自分のISUCON8本戦は終了しました。 感想 マニュアルを読む。本当にこれに尽きると思います。 もう少し早くAPIの仕様に気付いていれば、余裕をもってログの欠損の対策ができ、アプリケーションをバグらせることなくスコアも大幅に上昇してたんだろうなあと物凄く後悔しています。マニュアルの大切さは分かってたつもりでしたが、API仕様書については参考程度にとどめてたのが今回の最大の敗因だったと思います。 講評を読んだ感じだと、おおかた(最初の方の)想定通りのチューニングが行えたように思います。PARTITIONについては知りませんでした。勉強になります。 初動は本戦でもうまく機能していたと思います。若干自分が足を引っ張りましたが... おわりに すばらしいイベントで、とても楽しかったです。運営のみなさんは本当にお疲れ様でした。 もし来年もISUCONが開催されるなら、また同じメンバーで出られたらいいなあと思っています。 講評で学生枠を無くすかもと言ってましたが、学生枠なんてものがなくても実力で本戦出場を勝ち取れるようになりたいですね。精進します。(来年は自分もバリバリGoで実装できるように...！)

ISUCON8の本戦で惨敗してきました