fluentd forwarder を daemon service として登録することで fluentd logging driver 起因の fluentd の負荷を分散させる

2021-03-22

Docker の logging driver として fluentd logging driver を使うと、DNS や NLB で複数の fluentd プロセスに負荷を分散させようとしても特定のプロセスに負荷が集中することがあります。それを回避するのに FireLens が使えるという話を次の記事に書きました。

FireLens を使って fluentd logging driver 起因の fluentd の負荷を分散させる

ところが、既に fluentd が動いていると、FireLens を使うおうと思うと、既存の fluentd のポート番号の変更か、設定の統合を余儀なくされます。これを避けるために、daemon service (daemon scheduling strategy の service) の fluentd を設置することで同様のことを実現しようという話です。
なお、Fargate は非対応なので、Fargate でログを柔軟に処理しようと思うと FireLens 一択です。

リポジトリ

今回検証に使ったコードは次のリポジトリにまとめてあります。

https://github.com/abicky/fluentd-daemon-service-example

実験

logging driver の設定として NLB のエンドポイントを指定するタスクと、daemon service の fluentd の unix domain socket を指定するタスクを用意し、それぞれのタスクでログを流した時に fluentd aggregator に流れるログがどの程度偏るかを見てみます。

前者の logging driver の設定は次のとおりです。

"logConfiguration": {
  "logDriver": "fluentd",
  "options": {
    "tag": "docker.application-using-aggregator",
    "fluentd-address": "${aws_lb.fluentd_aggregator.dns_name}:24224",
    "fluentd-sub-second-precision": "true"
  }
}

cf. application.tf#L17-L24

後者の設定は次のとおりです。

"logConfiguration": {
  "logDriver": "fluentd",
  "options": {
    "tag": "docker.application-using-forwarder",
    "fluentd-address": "unix:///var/run/fluentd/unix.sock",
    "fluentd-sub-second-precision": "true"
  }
}

cf. application.tf#L39-L46

ログは次のように 1 ms 間隔で 180,000 回流し、10 タスク起動することにします。

require 'logger'

$stdout.sync = true
logger = Logger.new($stdout)

msg = "0123456789" * 10

logger.info "Started"
180_000.times do |i|
  logger.info "#{i}: #{msg}"
  sleep 0.001
end
logger.info "Finished"

cf. main.rb

実験結果

log driver に NLB のエンドポイントを直接指定した場合

次のコマンドでログを流しました。

./run.sh aggregator

fluentd aggregator の flowcount のログは次のとおりです。

fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:22:29.399876193 +0000 flowcount: {"count":83738,"count_rate":1384.09,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:22:29.689232469 +0000 flowcount: {"count":168222,"count_rate":2780.54,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:22:30.681630124 +0000 flowcount: {"count":128522,"count_rate":2124.34,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:22:31.994476770 +0000 flowcount: {"count":44181,"count_rate":730.26,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:23:29.899642102 +0000 flowcount: {"count":110185,"count_rate":1821.25,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:23:30.188844442 +0000 flowcount: {"count":220289,"count_rate":3641.18,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:23:31.181282460 +0000 flowcount: {"count":165269,"count_rate":2731.75,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:23:32.493979323 +0000 flowcount: {"count":55082,"count_rate":910.45,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:24:30.400072680 +0000 flowcount: {"count":110176,"count_rate":1821.08,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:24:30.688910751 +0000 flowcount: {"count":220303,"count_rate":3641.39,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:24:31.681876567 +0000 flowcount: {"count":165261,"count_rate":2731.57,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:24:32.993879277 +0000 flowcount: {"count":55062,"count_rate":910.12,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:25:30.899980807 +0000 flowcount: {"count":55905,"count_rate":924.05,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:25:31.188816896 +0000 flowcount: {"count":111194,"count_rate":1837.93,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:25:32.182087198 +0000 flowcount: {"count":80954,"count_rate":1338.08,"tag":"docker.application-using-aggregator"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:25:33.494263738 +0000 flowcount: {"count":25677,"count_rate":424.41,"tag":"docker.application-using-aggregator"}

タスクごとにログの数をまとめると次のようになります。

Task ID	Count
117809ec4164485db0c6c9859ed32e1b	360,004
46fbf162762b4555846904ad81dcfbc0	540,006
7db063d050df49f78d0aaf385b6586c7	720,008
ca804b3ee5764cf5a35e522a7c993134	180,002

ログの数にかなりの偏りが出ていることがわかります。

また、fluentd aggregator のコンテナの CPU 使用率を見ても、最も負荷の低いものと高いものでは 3 倍程度の差があります。

log driver に fluentd forwarder を指定した場合

次のコマンドでログを流しました。

./run.sh forwarder

fluentd aggregator の flowcount のログは次のとおりです。

fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:11:25.400127668 +0000 flowcount: {"count":12645,"count_rate":209.0,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:11:27.993792733 +0000 flowcount: {"count":9080,"count_rate":150.08,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:12:25.899463285 +0000 flowcount: {"count":117589,"count_rate":1943.65,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:12:26.188982726 +0000 flowcount: {"count":207846,"count_rate":3435.46,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:12:27.181862278 +0000 flowcount: {"count":117742,"count_rate":1946.16,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:12:28.493703609 +0000 flowcount: {"count":108880,"count_rate":1799.68,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:13:25.899981475 +0000 flowcount: {"count":126532,"count_rate":2108.86,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:13:26.688544172 +0000 flowcount: {"count":153804,"count_rate":2542.24,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:13:27.682246139 +0000 flowcount: {"count":153755,"count_rate":2541.4,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:13:28.994500244 +0000 flowcount: {"count":99695,"count_rate":1647.84,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:14:26.399402862 +0000 flowcount: {"count":153904,"count_rate":2543.9,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:14:26.688952640 +0000 flowcount: {"count":117573,"count_rate":1959.54,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:14:28.181709911 +0000 flowcount: {"count":145080,"count_rate":2398.05,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:14:29.493614957 +0000 flowcount: {"count":126420,"count_rate":2089.63,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/117809ec4164485db0c6c9859ed32e1b 2021-03-22 01:15:26.399921994 +0000 flowcount: {"count":59273,"count_rate":987.88,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/7db063d050df49f78d0aaf385b6586c7 2021-03-22 01:15:27.188492122 +0000 flowcount: {"count":27135,"count_rate":448.51,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/46fbf162762b4555846904ad81dcfbc0 2021-03-22 01:15:28.681455491 +0000 flowcount: {"count":27152,"count_rate":448.79,"tag":"docker.application-using-forwarder"}
fluentd/fluentd/ca804b3ee5764cf5a35e522a7c993134 2021-03-22 01:15:29.494035912 +0000 flowcount: {"count":35915,"count_rate":598.58,"tag":"docker.application-using-forwarder"}

タスクごとにログの数をまとめると次のようになります。

Task ID	Count
117809ec4164485db0c6c9859ed32e1b	469,943
46fbf162762b4555846904ad81dcfbc0	443,729
7db063d050df49f78d0aaf385b6586c7	506,358
ca804b3ee5764cf5a35e522a7c993134	379,990

先ほどと比べると偏りがかなり解消されていることがわかります。

一方で、fluentd forwarder の CPU 使用率は 70% 程度になっており、4 コアのうちほぼ 1 コアを使うぐらいの負荷がかかっています。この点に関しては fluent bit にすることで解消するかもしれません。

注意点

ログの偏りが解消することはわかりきっていたことなので、ハマりどころや運用する際に考慮した方が良さそうな点について触れます。

Unix domain socket を作成するディレクトリの権限

Docker の bind mount を利用する場合、mount したディレクトリは host の権限と同じになります。一方、fluentd の公式 Docker イメージではデフォルトで fluent ユーザで実行されるようになっています。よって、fluent ユーザのまま実行すると、mount したディレクトリによっては socket を作成することができません。

この問題を回避する典型的な方法としては次の 4 つが挙げられると思います。

/tmp 等 sticky bit の設定されたディレクトリを mount する
mount するディレクトリの ownership を予め fluent ユーザの UID のものにしておく
- 逆に mount するディレクトリの UID で実行するというアプローチもある
fluentd を root ユーザで動かす
fluentd を起動する直前の処理を root で動かして ownership を fluent ユーザに変更した上で fluent ユーザで fluentd を実行する

/tmp を使うのが一番無難な気がするし、今回の用途であれば /tmp を使うので問題ないはずですが、何となく抵抗があったので、4 を採用しました。つまり、task definition の user で root を指定し、次のように entrypoint.sh で ownership を変えた上で、fluent ユーザで fluentd を実行するようにしています。

if [ $(id -u) -eq 0 ]; then
    # We assume that /var/run/fluentd on the host is mounted into /fluentd/var/run
    # and the ECS agent creates the directory with root:root ownership,
    # so the ownership must be changed to create a unix domain socket.
    chown -R fluent /fluentd/var/run
    set -- su-exec fluent "$@"
fi

cf. entrypoint.sh#L29-L35

なお、回避方法としては次の issue の議論が参考になるかもしれません。

Add ability to mount volume as user other than root · Issue #2259 · moby/moby

Datadog による fluentd forwarder の監視

ログとはいえ、fluentd の queue が溜まりがちになっていたら worker を 2 つにするなどの対策を講じなければならないので監視は重要です。

Datadog には fluentd の integration が用意されているので、 auto discovery と組み合わせることで、monitor agent から取得できるメトリクスを簡単に送ることができます。
異常を察知するには次のメトリクスが使えるんじゃないかと思います。

fluentd.buffer_available_buffer_space_ratios
- total_limit_size に対する fluentd.buffer_total_queued_size の割合 cf. buffer.rb#L768-L777
fluentd.retry_count

まず、メトリクスを収集できるようにするには fluentd の設定に次の内容を追加します。

# cf. https://docs.datadoghq.com/integrations/fluentd/
<source>
  @id monitor-agent
  @type monitor_agent
  bind 0.0.0.0
  port 24220
</source>

cf. fluent.conf.erb#L7-L13

auto discovery を有効にするには、メトリクスを収集したい container の task definition で次のように label を指定すれば良いです。

"dockerLabels": {
  "com.datadoghq.ad.check_names": "[\"fluentd\"]",
  "com.datadoghq.ad.init_configs": "[{}]",
  "com.datadoghq.ad.instances": "[{\"monitor_agent_url\": \"http://%%host%%:24220/api/plugins.json\"}]"
}

cf. fluentd_forwarder.tf#L30-L34

これだけで datadog agent がよしなにメトリクスを収集してくれるんだから便利ですよね。auto discovery の設定方法についてはドキュメントを参照してください。
なお、datadog agent を awsvpc newtork mode で動かすと対象コンテナの 24220 番ポートにアクセスできなくてエラーになるようです。収集対象のタスクが awsvpc network mode で動いていても収集できないかもしれません。

fluentd forwarder のデプロイによるログの欠損

ログを流している途中で fluentd forwarder を force new deployment するとどの程度ログが欠損し、アプリケーションにもどのような影響があるか見てみます。

実験の時と同様 ./run.sh forwarder を実行し、1 分程経過したタイミングで forwarder service を force new deployment しました。

Task ID	Count
117809ec4164485db0c6c9859ed32e1b	421,013
46fbf162762b4555846904ad81dcfbc0	473,347
7db063d050df49f78d0aaf385b6586c7	518,518
ca804b3ee5764cf5a35e522a7c993134	385,437

合計 1,800,020 にならないといけないところが 1,798,315 になっているので、0.1% 程度ログが欠損していることになりますね。
たいていの場合、デプロイによってコンテナのログが 0.1% 程度欠損するのは許容できる気がしますが、もし許容できないのであれば、Docker 20.10.0 から fluentd-request-ack log option を指定できるようになっているので、ECS の Docker のバージョンが上がったら試してみると良いかもしれません。

cf. https://github.com/moby/moby/commit/008fc679742b1f6dc386b728887573987ac09feb

アプリケーションの影響については、Started のログが出てから Finished のログが出るまでの時間を見てみます。

まずこちらが force new deployment しなかった時のログです。3 分 20 秒程度ですね。

5032ea5b8c1b I, [2021-03-22T01:11:22.935291 #1]  INFO -- : Started
c3ecdd255020 I, [2021-03-22T01:11:23.254936 #1]  INFO -- : Started
43df4c4e1099 I, [2021-03-22T01:11:23.259080 #1]  INFO -- : Started
0a70717c1e6d I, [2021-03-22T01:11:23.268763 #1]  INFO -- : Started
c23d480bab7f I, [2021-03-22T01:11:23.366176 #1]  INFO -- : Started
cea2937c67d2 I, [2021-03-22T01:11:23.501495 #1]  INFO -- : Started
949ea1421645 I, [2021-03-22T01:11:23.509615 #1]  INFO -- : Started
5dbab423c5c7 I, [2021-03-22T01:11:23.564029 #1]  INFO -- : Started
e5aa23c34243 I, [2021-03-22T01:11:23.654518 #1]  INFO -- : Started
0da5702567e0 I, [2021-03-22T01:11:23.653471 #1]  INFO -- : Started
5032ea5b8c1b I, [2021-03-22T01:14:42.196975 #1]  INFO -- : Finished
c3ecdd255020 I, [2021-03-22T01:14:42.329838 #1]  INFO -- : Finished
0a70717c1e6d I, [2021-03-22T01:14:42.374640 #1]  INFO -- : Finished
43df4c4e1099 I, [2021-03-22T01:14:42.415482 #1]  INFO -- : Finished
c23d480bab7f I, [2021-03-22T01:14:42.519610 #1]  INFO -- : Finished
5dbab423c5c7 I, [2021-03-22T01:14:42.573078 #1]  INFO -- : Finished
949ea1421645 I, [2021-03-22T01:14:42.605540 #1]  INFO -- : Finished
cea2937c67d2 I, [2021-03-22T01:14:42.613742 #1]  INFO -- : Finished
0da5702567e0 I, [2021-03-22T01:14:42.618751 #1]  INFO -- : Finished
e5aa23c34243 I, [2021-03-22T01:14:42.670983 #1]  INFO -- : Finished

続いてこちらが force new deployment した時のログです。3 分 20 秒程度ですね。数秒程度遅くなっている気もしますが、あれだけ大量にログを吐いてこの程度の影響であれば、よほど頻繁にデプロイしない限り問題ないでしょう。

c0dcc062dd56 I, [2021-03-22T01:51:58.866743 #1]  INFO -- : Started
dcf70765a896 I, [2021-03-22T01:51:58.961938 #1]  INFO -- : Started
83cefa1beb95 I, [2021-03-22T01:51:59.027976 #1]  INFO -- : Started
8d21969cdd1c I, [2021-03-22T01:51:59.065431 #1]  INFO -- : Started
9ae9428183f8 I, [2021-03-22T01:51:59.429690 #1]  INFO -- : Started
634067e72fd5 I, [2021-03-22T01:51:59.440353 #1]  INFO -- : Started
70a19a8a2d21 I, [2021-03-22T01:51:59.482598 #1]  INFO -- : Started
c32ab2f625be I, [2021-03-22T01:51:59.495628 #1]  INFO -- : Started
3aef45741e12 I, [2021-03-22T01:51:59.498435 #1]  INFO -- : Started
545ce5061c10 I, [2021-03-22T01:51:59.567398 #1]  INFO -- : Started
c0dcc062dd56 I, [2021-03-22T01:55:22.440351 #1]  INFO -- : Finished
83cefa1beb95 I, [2021-03-22T01:55:22.497421 #1]  INFO -- : Finished
8d21969cdd1c I, [2021-03-22T01:55:22.557508 #1]  INFO -- : Finished
dcf70765a896 I, [2021-03-22T01:55:22.584022 #1]  INFO -- : Finished
70a19a8a2d21 I, [2021-03-22T01:55:22.788653 #1]  INFO -- : Finished
634067e72fd5 I, [2021-03-22T01:55:22.808537 #1]  INFO -- : Finished
3aef45741e12 I, [2021-03-22T01:55:22.868724 #1]  INFO -- : Finished
9ae9428183f8 I, [2021-03-22T01:55:22.881587 #1]  INFO -- : Finished
c32ab2f625be I, [2021-03-22T01:55:22.897849 #1]  INFO -- : Finished
545ce5061c10 I, [2021-03-22T01:55:22.976546 #1]  INFO -- : Finished

コンテナインスタンスの Draining 時の挙動

FireLens を使って fluentd logging driver 起因の fluentd の負荷を分散させるでも言及したように、以前はコンテナインスタンスを draining すると daemon service のタスクは即座に終了するようになっていました。

ECS agent に手が入った気配がないので AWS 内部のどこかで手が入ったんじゃないかと予想しますが、とりあえず ECS agent 1.50.3 では次のような挙動を示すようです。

service に属さないタスクが running であっても終了する
service に属するタスクが 1 つでもインスタンス上で動いていれば待ち続ける

つまり、spot instance の interruption warning で draining にした場合、2 分以内に終了しないタスクがあると正常終了しない可能性があります。
今回のような用途では 1 秒間隔でログを転送しているので大した影響はないでしょうが、重要なデータを扱う場合は注意が必要です。

以上、これで安心して負荷を分散させられますね！