fluentd の heartbeat_interval と phi_threshold の関係

以前、「Apache ログを転送するための fluentd 初期設定」というエントリーを書いたのですが、以下のような match 部の設定を紹介しました：

<match apache.access>
  type forward
  send_timeout 60s
  recover_wait 30s
  heartbeat_interval 1s

  <server>
    name （td-agent がログ出力時に利用するサーバ名(任意)）
    host （外部サーバのドメイン or IPアドレス）
    port 24224
  </server>
</match>

普通の forward の設定なのですが、実は私の環境では heartbeat_interval を 10s（10秒）に設定しています。しかしデータ転送はできていましたが、heartbeat_interval をデフォルトの 1s から 10s にすると、データ転送先サーバが死活監視のたびに detach と recover を繰り返してしまいました。気持ちがいいものでもないので、先ほどのエントリーを書いたついでに調べることにしました。

原因を探る

fluentd のログ

heartbeat_interval が 10s の場合

何はともあれ、障害対策の基本のログを見ます。td-agent.log を見ると、以下のようなログが1分間に何度も出力されていました。

2013-06-03 20:59:36 +0900: detached forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224 phi=326.3589023596042
2013-06-03 21:00:06 +0900: recovered forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224
2013-06-03 21:02:36 +0900: detached forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224 phi=182.4831679983974
2013-06-03 21:03:06 +0900: recovered forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224
2013-06-03 21:03:26 +0900: detached forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224 phi=58.48866897474658
2013-06-03 21:03:56 +0900: recovered forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224
2013-06-03 21:05:16 +0900: detached forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224 phi=1767.0235392182283
2013-06-03 21:05:46 +0900: recovered forwarding server 'maple' host="xxx.xxx.xxx.xxx" port=24224

phi= と出力されていることから、この値が問題なのかもしれないと思い、公式ドキュメント forward Output Plugin を見てみました。

phi_threshold: The threshold parameter used to detect server faults. The default value is 8.

説明があっさりしすぎていてよく分かりませんが、デフォルト値が 8 だということと、8を超えると何やら問題だということが分かりました。

ただ、デフォルト値について GitHub でソースコードを見てみると（2013年6月12日現在）、なぜか 16 で設定されています。ソースコードだけでなく、TreasureData 社のリポジトリから落としてきたソースでも 16 になっているので、こちらが正しそうです。

config_param :phi_threshold, :integer, :default => 16

phi の値をログに出力するようにしたところ、heartbeat_interval が 10s の場合の phi の値は4～7でした。上記ログのように、時折 16 を大幅に超えていることから、このタイミングで転送先サーバが detach されてしまうようです。

heartbeat_interval が 1s の場合（デフォルト）

デフォルトの場合の phi の値は 0.4 前後でした。phi_threshold のデフォルト値 16 には及びません。

私の転送先サーバが AWS なのでデフォルトでもたまに遅延が生じてしまうのですが、毎分 detach と recover を繰り返すような状況にはなりませんでした。

out_forward.rb のソースコードを見る

phi_threshold の判定個所を見つける

GitHub から、forward 処理を行っている out_forward.rb のソースコードを見てみました。phi_threshold でひっかけると、次のコードが見つかります（2013年6月12日現在）。

module Fluent
class ForwardOutput < ObjectBufferedOutput
  class Node
    ...
    def tick
      ...
      phi = @failure.phi(now)
      #$log.trace "phi '#{@name}'", :host=>@host, :port=>@port, :phi=>phi
      if phi > @phi_threshold
        $log.info "detached forwarding server '#{@name}'", :host=>@host, :port=>@port, :phi=>phi
        @available = false
        @resolved_host = nil  # expire cached host
        @failure.clear
        return true
      else
        return false
      end
    end
    ...
  end
  ...
end

phi が @phi_threshold の値を超えた場合、そのノードを外してしまうようです。

phi の計算処理を見てみる

次に、変数 phi の値を計算している phi メソッドの中身を見てみます。

module Fluent
class ForwardOutput < ObjectBufferedOutput
  ...
  class FailureDetector
    PHI_FACTOR = 1.0 / Math.log(10.0)
    SAMPLE_SIZE = 1000
    ...
    def phi(now)
      size = @window.size
      return 0.0 if size == 0

      # Calculate weighted moving average
      mean_usec = 0
      fact = 0
      @window.each_with_index {|gap,i|
        mean_usec += gap * (1+i)
        fact += (1+i)
      }
      mean_usec = mean_usec / fact

      # Normalize arrive intervals into 1sec
      mean = (mean_usec.to_f / 1e6) - @heartbeat_interval + 1

      # Calculate phi of the phi accrual failure detector
      t = now - @last
      phi = PHI_FACTOR * t / mean

      return phi
    end
    ...
  end
  ...
end

複雑な計算ですが、@window は以前までの死活監視の結果を保持する配列で、mean はその加重移動平均です。t は現在時刻と前回の死活監視終了時刻の差分ですので、おおよそ今回の死活監視に要した時刻と考えられます。

mean の元になっている @window の gap は、次の式で計算されています：

    def add(now)
      if @window.empty?
        @window << @init_gap
        @last = now
      else
        gap = now - @last
        @window << (gap * 1e6).to_i
        @window.shift if @window.length > SAMPLE_SIZE
        @last = now
      end
    end

6行目を見ると、先ほどの変数 mean や t の計算とかなり似ています。改めて、この3つの変数の定義のされ方を見てみましょう：

# メソッド add 内
gap  = now - @last

# メソッド phi 内
t    = now - @last
mean = (mean_usec.to_f / 1e6) - @heartbeat_interval + 1

mean_usec は gap の平均ですから、mean のみ - @heartbeat_interval + 1 が余分に付与されています。 phi は mean と t の比として計算されていますから、heartbeat_interval を大きな値にすればするほど、メソッド phi が返す値が大きくなります。

係数 PHI_FACTOR はおおよそ 0.43 なので、例えば heartbeat_interval を大幅に増やして 50 秒に設定すると、phi_threshold のデフォルト値 16 を定常的に超える状態となり、死活監視のたびに detach と recover を繰り返します。常に detach 状態とならないのは、死活監視のタイミングで phi の値が phi_threshold を超えていれば detach とし、その直後に TCP ソケットで死活監視を行い、応答があれば recover とするようなアルゴリズムになっているからのようです。（書いていてあんまり自信がない…）

解決策

heartbeat_interval はデフォルト値を使う

phi_threshold も heartbeat_interval も変更するのが億劫であれば、デフォルト値のまま利用するのが安全だと思います。（データのフォワード処理は、データ受信のタイミングで発生するため、積極的に死活監視を行わなくてもよい気もするのですが…）

phi_threshold を heartbeat_interval に合わせて計算する

普段の phi の値をログ等で確認して、phi_threshold を設定することでも解決できます。サーバ間の遅延状況を含めた閾値が設定できますが、heartbeat_interval を変更した際には、phi_threshold も変更する必要があります。

変数 t を mean に合わせて計算する

先ほど、mean のみ - @heartbeat_interval + 1 が余分に付与されています。 と述べました。この処理を変数 t にも加えてやれば、t と mean の尺度が一致するため、heartbeat_interval に引きずられて phi の値が大きくなることがありません。

実はこの処理を GitHub 上で Pull Request したら開発者の方にマージして頂けたので、この解決策が反映されたバージョンがそのうち展開されるかもしれません。

phi の閾値自体が複雑で設定しづらい、というそもそもの問題があるため、detach と recover の判定ロジック自体を根本的に変えたい…と開発者の方が Twitter 上でお話されていましたので、引き続きウォッチしていきたいと思います。