[連載5]どどんとふが重い？

連載3の真面目な対処法をやっても、あまり効果がありませなんでしたので、いくつか追加で思い当たる対応策を実施しました。

追加対策5-1: fastcgiをTCP/IPではなくドメインソケットに変更

効果無しでした。TCPIPのオーバーヘッドってセッション数が200-300程度じゃ誤差にもならなかったです。

追加対策5-2: $refreshIntervalを死ぬほど短くする

これまでの対応でやはりnginxとfastcgi間を散々弄ってみましたが、nginxのreq/secがほぼfastcgiのプロセス数上限で頭打ちになるということから、
buffering云々ではなくDodontoFServer.rbのどっかでCPUやDiskIOに関係なく待っている箇所があると疑い、調べてみたらありました。

    def refreshLoop(saveData)
    now = Time.now
    whileLimitTime = now + $refreshTimeout
    @logger.debug(now, "now")
    @logger.debug(whileLimitTime, "whileLimitTime")

    while( Time.now < whileLimitTime )

      refreshOnce(saveData)

      break unless( saveData.empty? )

      intalval = getRefreshInterval
      @logger.debug(intalval, "saveData is empty, sleep second");
      sleep( intalval ) # ←ここと
      @logger.debug("awake.");
    end
  end

  def getRefreshInterval
    if( $isCommet )
      $refreshInterval
    else
      $refreshIntervalForNotCommet　　　　#←ここ
    end
  end

めっちゃsleepしてます、しかもデフォルトのCommet方式をそのまま使っているので、$refreshTimeout秒もしくは、$refreshInterval秒×saveDataが空になるまでのループ回数分もここでsleepで待っています。
refreshという一番使用頻度の高いリクエストがsleepなんかしちゃってるせいで、fastcgiのサーバープロセスが他のリクエストを処理できない待ち時間が発生してしまっていたわけです。
ただ待っているだけのsleepですからCPUもDiskIOも食うわけありません。
こんなに待たされちゃたまりませんので、refreshIntervalをとりあえず0.1秒にして$refreshTimeoutも0.1秒にしてみました。

結果：リクエスト数が3倍になりました。平日に第壱、第弐だけで試したのが幸いでした。週末に全鯖に設定入れてたら3倍どころの騒ぎじゃなく、1日で2億リクエストぐらいになってしまいログがパンクしていたでしょう。
しかし、nginxのreq/secは1400req/secまで一気に改善していました。設定値に問題はあったもののボトルネックはここで間違いなさそうです。

追加対策5-3: 疑似Commet方式を辞めて、sleepそのものをコメントアウト

そもそも、この処理ってレンタルサーバーなどでrubyプロセスを1つのリクエストがなるべく再利用するためにという思想で作られた擬似Commet方式のためにあるのですが、公式鯖はやたら大量にリクエストが来るので、リクエストはrubyプロセスをさっさと開放して次のリクエストを処理させたほうが良いのでCommet方式をまず辞めちゃいましょう。
この設定に関する箇所は、src_ruby/config.rbにあるこの部分で設定することになります。

#通信方式を擬似Commet方式にするなら true に。
#サーバ応答時に即座にクライアントに返答するには falseに。
$isCommet = true
#擬似Commetを使わない場合のクライアント側での再読み込み待ち時間
$refreshIntervalForNotCommet = 2.0

で、実はこれも過去に試していたんですが、どちらの方式でもあまり挙動に変化がなかったことから、デフォルトのままisCommetをTrueにしていました。
なぜ、効果がなかったのかをよく見てみると、Commetを無効にしていてもrefreshLoopが呼び出されたらサーバー内で2秒もsleepしちゃってたわけです。
そりゃ、有効にしても無効にしても変わらないわけです。これはいけません。改善しましょう。
まずは、諸悪の根源sleepが入っているrefreshLoopを確認してsleepを根絶できないか調べてみます。

refreshLoopの呼び出し元は、「getWebIfChatTextFromTime getWebIfRefresh refresh」の3箇所からです。
このうち、refreshについては、Commetを無効にすれば呼ばれなくなりますので、気にしないとして、
「getWebIfChatTextFromTime getWebIfRefresh」については、Commetを無効にするとサーバー上で2秒も待ってしまうことになります。
むせる鯖のようにwebIfを無効にしちゃえば呼ばれることはなくなりますが、どろいどんとふとかスマホ用chat.htmlとか影響が大きすぎるのでWebIfは無効にはできません。
次は、この処理のsleepを丸ごと削っちゃっていいのかどうか挙動を追ってみます。

むせる鯖の中の人であるくまかば氏によると大丈夫らしいのですが、一応確認しておきましょう。
sleepをコメントアウトすると$refreshTimeoutで設定している間(公式鯖では1秒)は、saveDataが空になるまで全速力でrefreshOnceを呼ぶことになります。
refreshOnceの中身は、saveData.merge!。つまりハッシュをマージしているだけですね。
ハッシュをマージしてsaveDataが空になればループを抜けるので全速力になっても負荷が高くなる理由はないですし、
コメントアウトしても問題なさそうです。というわけでコードを変更したのはこの一カ所(sleepのコメントアウト)だけでcommet方式も無効にしました。

    def refreshLoop(saveData)
    now = Time.now
    whileLimitTime = now + $refreshTimeout
    @logger.debug(now, "now")
    @logger.debug(whileLimitTime, "whileLimitTime")

    while( Time.now < whileLimitTime )

    refreshOnce(saveData)

    break unless( saveData.empty? )

    intalval = getRefreshInterval
    @logger.debug(intalval, "saveData is empty, sleep second");
    #sleep( intalval ) # ←コメントアウト
    @logger.debug("awake.");
    end
  end

というわけで、今回のチューニングは、今まではやらなかったどどんとふ本体のコードにも手をつけてしまいました。
で、結果がどうなったかというと、こうなりました。(見やすくするためにグラフのスケールが近くなるようにリサイズしています)

ログイン人数が620人の状態で、nginxの処理能力が400req/sec以上を叩き出していますし、今まで1鯖あたり100人を超えたあたりから部屋一覧の表示がもっさりするようになっていたのが、150人を超えても一瞬で表示されています。
クライアントからのリクエスト数も増えていないことから、負荷チューニングとしては成功したと思います。

公式鯖は今までどどんとふ本体には手を入れないという基本的ポリシーでしたが、ついに手を出しちゃいました。とはいえ、公式鯖用にForkなんてもってのほかなので、この記事を@torgtaitai氏が見つけてどどんとふ本体にマージされることを生温かく待つことにします。