<p><a href="https://twitter.com/money166" target="_blank">@money166</a><br>
<a href="https://github.com/tatsuo48" target="_blank">@tatsuo48</a><br>
と一緒に今年も YO!HEYHEYHEY! として <a href="https://isucon.net/archives/55706291.html" target="_blank">ISUCON11</a>に参加してきました。</p>
<p>今年も非常に楽しく参加できました。<br>
運営の皆さま、ありがとうございました！</p>
<h2 id="結果">結果</h2>
<p>予選の結果は参考スコアで 47258 で全参加チーム598チーム中80位でした。<br>
<a href="https://isucon.net/archives/56021246.html" target="_blank">ISUCON11 オンライン予選 全てのチームのスコア（参考値） : ISUCON公式Blog</a></p>
<p>17:00以降の固定ダッシュボードで25位まで上昇していたので、これは！？と思ったのですが、壁は厚かったです。</p>
<p><img src="/images/posts/isucon11/dashboard-last-score.jpg" alt="ダッシュボードでの最終スコア" loading="lazy" width="1798" height="330"></p>
<p>5年間毎年参加して、ずっと初期実装のスコアから大きく点数を上げられなかったので、6年目の今年は非常に大きな進歩があって嬉しかったです！</p>
<h2 id="テーマ">テーマ</h2>
<p>今年のアプリケーションのテーマは自分が持っている椅子の状態を監視するWebサービスでした。<br>
登録している椅子が定期的にサーバーに自身の状態を送信して、ユーザーはその状態をWebサービスで確認することで椅子の状態を管理できます。</p>
<p>いわゆる IoT です。</p>
<p>サービスの説明からも予想できる通り、今年は常に大量のデーターがサーバーに送信されDBに書き込まれ続けるので、DBのCPU負荷が常に高い状態でした。（ベンチ回したら最初からCPU負荷が150%とか出ていました）<br>
このDB負荷をどう処理するかが問題のキーとなっている印象でした。</p>
<h2 id="振り返り">振り返り</h2>
<h3 id="良かった点">良かった点</h3>
<ul>
<li>今年はZoomで繋いでオンラインで作業をしており、画面共有などでチームでの作業がやりやすかった</li>
<li>ベンチ回して効果が無い場合は前の状態に戻す徹底できたので、アプリケーションが動かなくなる問題が発生しなかった</li>
<li>基本は2人以上のペアプロを意識して進めたので、それによって気付ける事が多かった
<ul>
<li>ボトルネックの原因とか</li>
</ul>
</li>
<li>しっかりマニュアルを読み込んでスコア計算の仕様を意識して対応方針が決められた</li>
<li>Miroでタスク管理して誰が何をやっているか把握しながら進められた</li>
</ul>
<h3 id="反省点">反省点</h3>
<ul>
<li>Go言語をあまり勉強しておらずアプリケーションの修正に時間がかかった</li>
<li>勉強不足で New Relic での DB の監視を導入できなかった</li>
<li>全体的にスコア上がってから次の一手が思いつかず頭打ちになった</li>
</ul>
<h2 id="チームでやったこと">チームでやったこと</h2>
<ul>
<li>インフラ環境の初期構築をしてサーバーを立ち上げ</li>
<li>当日マニュアルやアプリケーションマニュアルを熟読</li>
<li>アプリケーションを実際に動かして機能一覧を把握</li>
<li>競技用サーバーへのデプロイ環境の整備</li>
<li>アプリケーションに New Relic のエージェントを追加</li>
<li>DBのスキーマ情報を整理</li>
<li>New Relic のダッシュボードでHTTPリクエストを確認してボトルネックを調査して対応方針を検討</li>
<li><strong>==== ↓ ここからボトルネック対応 ====</strong></li>
<li>サーバー構成を サーバー1:DB, サーバー2: アプリケーション に変更: 1000 =&gt; 8000</li>
<li>isu テーブルで画像カラムをクエリしない修正を追加: スコア変わらず</li>
<li>椅子の状態のデータ送信をサーバー3台に分散: スコア変わらず</li>
<li>椅子の状態のDBへの書き込みをバルクインサートに変更: 上手く実装できず</li>
<li>サーバー構成を サーバー1: DB, サーバー2: アプリケーション, サーバー3: 椅子状態のデータ受信 に変更: スコア変わらず</li>
<li>対応方針を再検討</li>
<li>isu_condition の jia_isu_uuid にインデックスを追加: 8000 =&gt; 25000</li>
<li>isu_condition の timestamp にインデックスを追加: 25000 =&gt; 28000</li>
<li>データを捨てる割合を 90% =&gt; 75% に変更: 28000 =&gt; 33000</li>
<li>画像をクライアントにキャッシュさせる: 対応が上手くできなかった</li>
<li>Nginx や アプリケーション のデバッグログを停止: 33000 =&gt; 35000 （影響あった気がする）</li>
<li>/api/trend のリクエストもサーバー3に流すように変更: 35000 =&gt; 47000</li>
</ul>
<h3 id="アプリケーションを実際に動かして機能一覧を把握">アプリケーションを実際に動かして機能一覧を把握</h3>
<p>今回は例年と比べてアプリケーション規模が小さい？印象だったので、全体の把握がスムーズにできた。<br>
オープニングでの事前のサービス紹介で概要が掴めたのも大きかった。</p>
<h3 id="New Relic の Go エージェントの追加">New Relic の Go エージェントの追加</h3>
<p>次のドキュメントを参考に echo のミドルウェアとしてエージェントを追加した</p>
<ul>
<li><a href="https://docs.newrelic.com/jp/docs/agents/go-agent/installation/install-new-relic-go/" target="_blank">Go向けNew Relicのインストール | New Relic Documentation</a></li>
<li><a href="https://docs.newrelic.com/jp/docs/agents/go-agent/get-started/go-agent-compatibility-requirements/" target="_blank">Goエージェントの互換性と要件 | New Relic Documentation</a></li>
</ul>
<h3 id="HTTPリクエストを確認してボトルネックを調査して対応方針を検討">HTTPリクエストを確認してボトルネックを調査して対応方針を検討</h3>
<p>リクエストの大半は <code>POST /api/condition/:jia_isu_uuid</code> が占めていた。<br>
これは椅子の状態を受け取ってDBに書き込むAPIエンドポイントなので、当初の想定通り。</p>
<p><code>GET /api/trend</code> が最大で60sec、平均しても20secのレスポンス時間となっていた。</p>
<p>上記2つのAPIエンドポイントに絞って、実装の詳細を確認しながらボトルネックの調査と対応方針を決めた。</p>
<h3 id="サーバー構成を サーバー1:DB, サーバー2: アプリケーション に変更: 1000 =&gt; 8000">サーバー構成を サーバー1:DB, サーバー2: アプリケーション に変更: 1000 =&gt; 8000</h3>
<p>DBのCPU負荷が150~180%とかなり高かったので、サーバー1をDB専用にして、リクエストをサーバー２で捌くように変更した。</p>
<p>7000点ほどスコアが上昇</p>
<h3 id="isu テーブルで画像カラムをクエリしない">isu テーブルで画像カラムをクエリしない</h3>
<p>isu_conditions テーブルには画像がバイナリで含まれていた。<br>
/api/trend では <code>SELECT * FROM isu</code> と未使用にも関わらず画像カラムも取得していたので、これで読み込みに時間がかかってレスポンス時間に影響していると予測して、必要なカラムだけをクエリするようにしたが、大きな変化は無かった。</p>
<pre><code class="language-go">- &quot;SELECT * FROM `isu` WHERE `character` = ?&quot;,
+ &quot;SELECT `id`, `jia_isu_uuid` FROM `isu` WHERE `character` = ?&quot;,
</code></pre>
<h3 id="椅子の状態のデータ送信をサーバー3台に分散">椅子の状態のデータ送信をサーバー3台に分散</h3>
<p>椅子状態のデータ送信が大量にリクエストされているので、これにより他のリクエストが待機状態で捌かれていないのでは？と思い3台にリクエストを分散してみた。<br>
あまり効果は無かった。</p>
<pre><code class="language-go">- postIsuConditionTargetBaseURL string // JIAへのactivate時に登録する，ISUがconditionを送る先のURL
+ postIsuConditionTargetBaseURLs []string // JIAへのactivate時に登録する，ISUがconditionを送る先のURL

=======

- postIsuConditionTargetBaseURL = os.Getenv(&quot;POST_ISUCONDITION_TARGET_BASE_URL&quot;)
- if postIsuConditionTargetBaseURL == &quot;&quot; {
-	e.Logger.Fatalf(&quot;missing: POST_ISUCONDITION_TARGET_BASE_URL&quot;)
	return
}

+ postIsuConditionTargetBaseURLs = strings.Split(os.Getenv(&quot;POST_ISUCONDITION_TARGET_BASE_URLS&quot;), &quot;,&quot;)
+ if postIsuConditionTargetBaseURLs == nil {
+	e.Logger.Fatalf(&quot;missing: POST_ISUCONDITION_TARGET_BASE_URLS&quot;)
		return
}
</code></pre>
<h3 id="サーバー構成を変更">サーバー構成を変更</h3>
<p>引き続き椅子状態のHTTPリクエストにより /api/trend などの他のリクエストが待ち状態になっていると推測して、POST /api/condition/:jia_isu_uuid へのリクエストだけを全て別サーバーで処理するように変更した。</p>
<p>スコアへの影響は無かったが、CPU負荷は分散された。</p>
<ul>
<li>サーバー1: DB</li>
<li>サーバー2: アプリケーション</li>
<li>サーバー3: 椅子状態のデータ受信とDBへの書き込み</li>
</ul>
<h3 id="対応方針を再検討">対応方針を再検討</h3>
<p>最初に目星をつけた対応を色々と試したが結果が出なかったので、改めて対応方針を検討した。</p>
<p>ベンチマークをログを見ていると「タイムアウトが多く発生しているため、サービスの評判が下がりこれ以上ユーザーは増えません」という怪しげなログを発見。<br>
ベンチマーク実行後の <code>user</code> テーブルを見てみると、ユーザー数が13人しか登録されていなかった。</p>
<p>改めて当日マニュアルのスコア計算の仕様を読み直すと</p>
<blockquote>
<p>スコアはユーザーがISUのコンディションやスコアを確認すると加点されます。</p>
</blockquote>
<p>との事なので、</p>
<p>新規ユーザーは最初にTOPページにアクセスする<br>
=&gt; TOPページのトレンド情報がリクエストされる<br>
=&gt; リクエストがタイムアウトしてユーザーが離脱<br>
=&gt; ユーザー登録されずにユーザーが増えない<br>
=&gt; スコアが伸びない</p>
<p>タイムアウトが大量に発生<br>
=&gt; ユーザーが加点となるリクエストができない<br>
=&gt; スコアが増えない</p>
<p>という2つのシナリオを仮定して、スコアを伸ばすためにはユーザーを増やす必要がありそうと判断</p>
<p>そのためには、ログにも出ているタイムアウトを改善する必要があり、タイムアウトとなっているリクエストは明らかに <code>/api/trend</code> だったので、このエンドポイントを改善する方針でボトルネック調査を継続</p>
<h3 id="isu_condition の jia_isu_uuid にインデックスを追加: スコア改善: 8000 =&gt; 25000">isu_condition の jia_isu_uuid にインデックスを追加: スコア改善: 8000 =&gt; 25000</h3>
<p>改めて <code>/api/trend</code> のボトルネックを考えていたら <code>isu_condition</code> への書き込みが常に発生しているので、テーブルロックが発生して <code>isu_condition</code> の読み込みが待ち状態になっている影響で時間がかかっているのでは？と推測</p>
<p>実際に調べてみたら</p>
<blockquote>
<p>InnoDBは行ロックだが、ユニーク制約 or インデックスが張られていないカラムで検索した場合はテーブルロックになってしまう。</p>
</blockquote>
<p><a href="https://bluerabbit.hatenablog.com/entry/2013/12/07/075759" target="_blank">InnoDBで行ロック/テーブルロックになる条件を調べた #mysqlcasual Advent Calendar 2013 - あおうさ＠日記</a></p>
<p>という情報を発見</p>
<p><code>/api/trend</code> は以下のクエリでデータを読み込んでおり、テーブルロックによるりデータの読み込みが待ち状態になっている可能性がありそうだったので、検索カラムにインデックスを追加した。</p>
<pre><code class="language-sql">SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC
</code></pre>
<pre><code class="language-sql">+ CREATE INDEX jia_isucon_uuid_index ON isu_condition(jia_isu_uuid);
</code></pre>
<p>この修正 <code>/api/trend</code> のレスポンス時間が改善されて、スコアが大幅に上昇した。</p>
<h3 id="isu_condition の timestamp にインデックスを追加: 25000 =&gt; 28000">isu_condition の timestamp にインデックスを追加: 25000 =&gt; 28000</h3>
<p>同様の理由で <code>isu_condition</code> の <code>timestamp</code> にもインデックを追加して、スコアが上昇</p>
<pre><code class="language-sql">+ CREATE INDEX jia_isucon_uuid_timestamp_index ON isu_condition(jia_isu_uuid, timestamp);
</code></pre>
<h3 id="データを捨てる割合を 90% =&gt; 75% に変更: 28000 =&gt; 33000">データを捨てる割合を 90% =&gt; 75% に変更: 28000 =&gt; 33000</h3>
<p>初期実装では受信した椅子の状態の90%を捨てる実装になっていた。</p>
<pre><code class="language-go">// TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき
dropProbability := 0.9
if rand.Float64() &lt;= dropProbability {
	c.Logger().Warnf(&quot;drop post isu condition request&quot;)
	return c.NoContent(http.StatusAccepted)
}
</code></pre>
<blockquote>
<p>ISU のコンディション確認（GET /api/condition/:jia_isu_uuid）で、ユーザが前回確認したコンディションより新しいコンディションを確認した際に加点</p>
</blockquote>
<p>スコア計算では、ユーザーが新しい状態を確認した時に加点の対象となるため、椅子の状態を捨てていると加点の機会を大きく損なってしまうので、ここの割合を75%に減少させる調整を実施して、スコアが上昇した。</p>
<pre><code class="language-go">- dropProbability := 0.9
+ dropProbability := 0.75
</code></pre>
<h3 id="画像をクライアントにキャッシュさせる">画像をクライアントにキャッシュさせる</h3>
<p>ここまでの改善で新たに椅子の画像を取得する <code>GET /api/isu/:jia_isu_uuid/icon</code> が新たなボトルネックのエンドポイントとして浮上してきた。</p>
<p>ここは明らかにDBにバイナリで画像を保存している事による影響だと考えて、クライアント側に画像をキャッシュさせる対応を試みたが、上手く対応できなかった。</p>
<h3 id="ログの停止: 33000 =&gt; 35000">ログの停止: 33000 =&gt; 35000</h3>
<p>競技も終盤になっていたので、Nignx や アプリケーションのデバッグログ出力を停止した。<br>
ちゃんと覚えてないが、スコアが僅かに改善した気がする。</p>
<h3 id="トレンドのリクエストもサーバー3に流すように変更: 35000 =&gt; 47000">トレンドのリクエストもサーバー3に流すように変更: 35000 =&gt; 47000</h3>
<p>全体のCPU負荷を見ていて、サーバー2: アプリケーション のCPU負荷が高く、 サーバー3: 椅子の状態受信 のCPU負荷が低かったので、負荷を分散するために思い切って <code>/api/trend</code> のリクエストをサーバー3へリダイレクトする対応を追加</p>
<p>これが見事に成功してCPU負荷が分散されて、スコアが大幅に上昇した。</p>
<h3 id="競技終了">競技終了</h3>
<p>17:00で更新が停止された状態でのダッシュボード上での最終スコア</p>
<p><img src="/images/posts/isucon11/dashboard-last-score.jpg" alt="ダッシュボードでの最終スコア" loading="lazy" width="1798" height="330"></p>


ISUCON11予選に参加して自己ベストを更新しました

ISUCON 夏季講習 2017をやり、ボトルネック発見までの基本的なデータ収集の部分だけをまとめました。

ISUCONの夏季講習2017をやった

とあるフロントエンドエンジニアのブログ

isuconの記事一覧

ISUCON11予選に参加して自己ベストを更新しました

ISUCONの夏季講習2017をやった