ISUCON前線異状なし

2017-10-24



誰だか忘れてしまったが友達がこんなことを言っていた。
『教師というのは2種類いる。自分の傍で手取り足取り教えてくれる教師、そして遥か前方で目標として立っている教師だ』

今回ISUCONへ参加して得られた最も大きな収穫は後者の教師と数多く遭遇することが出来たことだ。後者の教師は必須だが前者は最悪いなくても進むことが出来る。目標がなければどこへも行けない。自分に何が足らないのか、何を学ぶべきなのか、自分の実力がどれほどの位置なのかを教えてくれる。圧倒的な技術力とスコア差でボコボコにすることによって。

事の起こり

事の起こりは僅か1ヶ月前だ。たまたまISUCONというWebアプリを高速化する競技コンテストがあることを知った。この大会では時間内にあらゆる手段を使ってWebアプリを高速化する、つまり既存のWebサーバやDBサーバを設定変更してもいいし、違うものに差し替えても良い。それどころか時間が間に合うならWebアプリを違う言語で全て書き直しても良い。必要な処理を外部のサーバへ委譲する以外は挙動を変えない限り自由だ。

幸運にも自分がISUCONの存在を知った時点でまだ参加を受け付けていた。直後に社内で同期と後輩からチームメンバーを募りさっさと参戦を決めた。そのため準備期間は2週間しかなかったが、それ以上長かったとしてもどうせ2週間前になるまで練習し始めなかっただろう。何も問題はない。

準備

他のメンバーにはisucon過去問をvagrantで環境作ってsinatraに触れておいてもらうように通達していたが、その、みんな色々と忙しいのだ。参加してくれるだけでも御の字である。自分が目標としての教師になれる日はまだ遠い。
(弊社だとRails開発がメインなので言語はRuby一択だったが、sinatraや直SQLなどにメンバーが不慣れだった)

全体としては一度だけ集まって定石の説明と実際のISUCON過去問を使ってISUCON攻略の流れを実践してみせた。プロファイリングの結果からSQLチューニングやRedisによるオンメモリ化などを実践してスコアが改善するのを説明していく。

個人的な準備としては使いそうなスクリプトの用意(後述)やパフォーマンス計測ツールの選定と導入の練習など。基本的には過去参加者の記事を参考にしながらISUCONの過去問で改善に挑戦していた。

一通り過去問に触れてみて自分なりにISUCONのコード改善の基本定石について大体こう考えた。

  1. INDEX付与や設定変更など、データ構造を変えないRDBMSのチューニング
  2. 無駄な処理の削減や回避
  3. データ処理のうち事前処理できることは全て事前にやって処理結果を保持しておく
  4. 負荷の高いSQLをRedisなどによるオンメモリに変える
  5. Webサーバで基本的な高速化処理(gz圧縮、静的ファイル処理)を行う
  6. これらをパフォーマンス測定から優先度付けしてひたすら潰していく

もちろん、基本的なことは参加者全員が実施するのだが……。

当日の動き

  1. バックアップとgit管理化
  2. 挙動の把握とコードリーディング
  3. パフォーマンス測定
  4. 改善方針の検討
  5. Just Do It

時間配分としては1-4までの工程に競技時間8時間のうち2時間を充てる想定で、実際これは2時間で完了した。

役割分担

チームメンバーは自分の保守案件を引き継いだ後輩くんと同期の競プロマン。バックアップやパフォーマンス測定、FAQやDiscordの監視といったオペレーションを後輩くんに任せ、競プロ同期にはコードの改善に集中してもらう。

自分は改善箇所の調査・策定とミドルウェアのチューニングをしつつ他のメンバーが詰まったら様子を見て手伝う、といった分担。

当日

我々の人生には様々なトラブルが起きる。例えば競技の当日に年間で最大レベルの台風が来るとか、チームメンバーが突然風邪で倒れるとか、競技の開始時間が遅延するとか、SwitchのJoy-Conストラップが外せなくなるとか……。どれもありふれたトラブルだが今回は全てが1日で起きた。トラブルは寂しがりやだ。

問題の公開と無為になった準備

さて、本題だ。今回のISUCON7予選はチャットアプリisubataが題材となった。ログイン機能、ユーザ登録、プロフィール、チャットへの読み書き、チャットルームの作成などの機能を持つベーシックなチャットだ。

最初に戸惑ったのはサーバのインスタンスが3つ用意されていたこと。実は今回のISUCONは過去の予選といくつかの点で異なり、これまでの予選ではイメージファイルが配布されるだけでそれを元にした環境構築は参加者がやっていた(らしい)。

しかしインスタンスが一つだけだと作業時間に待ちが発生しやすいことは事前に予測できたため、イメージファイルが配布されたらVirtualBoxで仮想環境を構築しようと考えていた。途中でイメージファイルは配布されないとFAQに追加されたため、予めnginxやmysqlなどをインストールしたubuntu環境を構築してコードとDBダンプを入れようと準備。

また、スコアを測定するためのベンチマーカーはリモートにしかない。そこで開発環境で各自が効果測定するためにスクリプトを書いておいた。これはnginxでcookieなどを含むHTTPリクエストをログ出力しておくと、それを元に同じHTTPリクエストを指定IPに送信するというもの。これで本番へのベンチマーカーによるアクセスログからゴーストを作ろうというもくろみ。もちろん実際のベンチマークとは挙動が違うが実行にかかる時間で一定の目安にはなる。

ところが競技が始まってみると前述のように3台分のインスタンスが渡され、それらに対して自由にベンチマークを行うことが出来た。そのためこの二つの準備は無駄となった、南無三。

プロファイリング

色々と試したり準備していたが結局3つだけしか使っていない。

  1. htopによる消費リソース監視
  2. Sinatraに仕掛けたloggerによる各URIの処理時間
  3. pt-query-digestによるmysqlスロウクエリの解析

sinatraはRailsログのような処理時間や発行SQLを含むログを出力しないため雑に自分で実装した。具体的にはリクエストの前後に実行されるbefore/afterフィルタを利用する。文末にコードも置いておく。

nginxのログ出力で計測しなかったのは純粋にURIの正規化に手間がかかりそうだったというのが理由。例えば/profile/owlと/profile/catは同じGET /profile/:idだが、URLとしては異なるためログ集計するには正規表現でまとめる必要があるが、この方法だとメソッドの単位で取れる。とはいえリバースプロキシされた静的ファイルへのアクセスなどは集計出来ない欠点もある。

他にrack-lineprofなども事前に検討し導入の練習もしたが本番ではなんやかんやで使わずじまい。

プロファイリングの結果

まずhtopの結果を見るとmysqldのCPU消費がボトルネックになっているようだった。sinatraの結果からわかる通り以下のリクエストが処理時間のほとんどを占有しいる。

URI Total Time Access Count
GET /icons/:file_name 81.054915831 99
GET /message 31.560699566999997 46
GET /fetch 12.588484534 8

コードを追って行くと/messageと/fetchは単純にDBアクセスに改善の余地があった。/icons/:file_nameが曲者でBLOB型でDBに画像ファイルを直接持つ構造になっていた。とりあえず、これは実ファイルに書き出して静的ファイルとしてnginxで処理することに決めた。

mysqlの集計結果も上記のアクションで使われている一部のSQLが大きな負荷となっていることを示している。

方針

最初に着手することを決めたのはこんなところ。

既読機能あたりはRedisに乗せてオンメモリで処理するべきと思ったが、インデックスを付与するだけで速度的にはかなりマシになったため後回しに。

実装

後輩くんにはDBから画像ファイル化するためのスクリプトを書いてもらっていたが、途中でサーバが画像を配信しているのだからファイル名だけをDBから出力させてURLを生成しcurlでダウンロードしてくれば済むことに気づいた。

プロ同期には画像アップロード周りとN+1潰しなどを任せつつ、自分はnginxやmysqlの設定を変更してアイコンの画像ファイルをnginx側で処理するなど改善を積んだ。

ここら辺が一通り終わった時点でスコアは初期の3,000ptから7倍近い20,000ptまでは伸びたが、ボトルネックがDBアクセスから画像ファイルの配信に移りそれが解消できず完全に停滞する。結論から言うと、これはCache-controlヘッダを適切に設定する事で回避可能でありCDNの効果的な利用は今回の問題における主眼の一つだったのだがものの見事につまづいた。

悔しい点はもう1つある、/fetch内に存在していたsleep 1というコードだ。これは目を通した時、レギュレーションに/fetchのレスポンスはスコアとして加算されない、という文言があったのを記憶していたため特に修正を加えなかった。しかし、それは誤りで実際にはこのsleepをタイムアウトにならない程度まで増やすことで受信メッセージ数が増加しスコアが稼ぎやすくなる。

過ちと反省

レギュレーションの読み込み不足

今回の反省はいくつかある。
まずレギュレーションを読み込むのが重要だ。これは過去ISUCONの参加記録でも繰り返し書かれていたし意識もしていたが、実際に競技が始まると内容を把握するために手を動かすのに忙しくてざっと目を通す程度で終わっていた。

しかし、終わってみると今回気が付けずにスコアを損していた箇所はどれもレギュレーションにヒントが書かれている。レギュレーション内でスコアの計算方法は明記されていたのでじっくり読めば/fetchのsleepを弄る必要があることには気づけたはずだ。

またネットワーク帯域についても詳しく記載があった意図を考えれば、問題の主眼がCDNにあることにも考えが行ったはずだし、手を動かして把握した内容の半分くらいはレギュレーションにも記述があった。

複数台構成に対する知見不足

これは事前に予習自体が出来ていなかった。過去のISUCON予選では複数台の構成はなく、また今までで最大規模の参加者と運営側がインスタンスを準備するという事前情報からまさか複数台が用意されているとは思いもしなかったため、正直にいえばそれなりに狼狽した。

また自分が業務で複数台の構成に触れるとき、そのの目的は負荷分散や高速化よりも可用性や冗長化のためであることが多く、高速化が目的のロードバランシングに関する知見が積まれていなかった。事前にやってきたこと以上のことを本番では出来ない。そういうところが自分の今の限界である。

微妙なところ

結局、Redisへの移植を始めとする改善可能な部分をかなり残したまま競技時間を終えてしまった。これはボトルネックになった画像配信の部分を改善するために自分がかかりきりになり、コード改修には着手しなかったため手が足りなくなったのが原因の一つだ。

では、自分も可能な限りコーディングを受け持つべきだったか? と言われると微妙だ。結果は出なかったものの、アプローチとして最低1人がボトルネックの探索と方針策定に集中するやり方は最善手の部類だと考えている。

アホみたいに高かった頂上

自分が画像配信のボトルネックで停滞している中、次々と上位チームが自分たちの20倍を超えるスコアを叩き出していた。このときは一体全体どうやってそんなスコアを出しているのかが全く理解出来なかった。もちろん何らかの方法で画像配信のボトルネックはとっくに解消していて、それに上積みする改善がいくつもあるのだろう。それでも20倍だって!?

とはいえ、この高速化という競技のスコアは複利の性質を持っている。必要な処理を10分の1にする改善を2回考え出すと10の2乗で100倍速くなる。20倍というのは大抵の場合、1.3倍速くなる改善を12回繰り返した結果だ。(1.3^12 = 23.29...)

つまるところ、画像配信がどうのこうの言うより改善箇所の数が圧倒的に違うのだ。引き出しの数が違うということだ。

今回のISUCONでの特に大きな収穫はCache-controlヘッダなど今まで意識しなかった領域の重要性を認識できたことだ。認識さえ出来れば調べて学ぶことが出来る。存在そのものに気が付かなければ何もすることは出来ない。重要なのは目標地点を知る事だ。

さて、そんな得ることが多かったISUCONだが「結果はどうあれ、参加する事で技術力を上げることが出来ればそれは勝ちも同然だ」と後輩くんには説明している。

が、現実にはボコボコに負けている。終わる頃にはズタズタにされたエンジニアの雑魚がいただけだ。もちろん楽しかったし有意義ではあったがそれ以上に行き場のない悔しさと情けなさが頭の中を渦巻いている。来年は予選を抜けて本戦へ参加出来るように今から功夫を積もう。まずはCache-controlヘッダについて調べなおすところからだ。

書き捨てスクリプト

Sinatra Logger

[app.rb]

  before do
    @start_at = Time.now
  end

  after do
    req_time = Time.now - @start_at
    data = {time: req_time.to_s, action: @env['sinatra.route']}.to_json
    @@logger.puts data
  end

[digest.rb]
テーブル出力のgemをわざわざinstallするのが面倒なので愚直に書いた

require 'json'

COL_LENGTH = 40
class SinatraDigest
  def self.execute
    digest = self.new
    digest.load_file
    digest.render_result
  end

  def load_file
    @sum_time, @sum_count = Hash.new(0), Hash.new(0)
    File.open("./req_time.log","r").each do |line|
     log = JSON.parse(line)
     @sum_time[log['action']] += log['time'].to_f
     @sum_count[log['action']] += 1
    end
  end

  def render_result
    data = [['URI', 'Total Time', 'Access Count']]
    data << ['-' * COL_LENGTH] * 3

    @sum_time.sort_by {|k, v| -v }.map do |ele|
      uri, time = ele
      cnt = @sum_count[uri]
      data << [ uri, time, cnt]
    end

    data.each do |line|
      puts line.map { |col| col.to_s.ljust COL_LENGTH }.join(' | ')
    end
  end
end

SinatraDigest.execute

gzip_static用スクリプト

nginxでgzip圧縮をしてから通信しているとCPUリソースが消費されるので、予めgzip圧縮したファイルを用意しておく。そのための再帰的にカレントディレクトリ以下のファイルを元ファイルを残しつつgzip圧縮するスクリプト。

for file in `\find . -type f`; do
  echo $file
  gzip -c $file > "${file}.gz"
done

 このエントリーをはてなブックマークに追加


<< ピザと開発: IT業界のおもしろおかしな就活   同僚エンジニアなるもの >>

[38]