【遅い】Fluentd→Kinesis Stream→Lambdaの構成だと、LambdaのCloudWatchのログがはかれるのに10秒~12秒かかってしまう

Question

課題

タイトルの通りですが、実際ログ（CloudWatch）に出力されるのに10秒〜12秒かかってしまい、困っています。
私が知りたいのは「これぐらいかかるもん」なのか、「Fluend設定ファイルやKinesisの設定等を変えれば、早くなるよ」なのかです。
FluentdとかKinesisに詳しい方の、意見を頂きたく質問致しました。
Fluentdの環境はローカルPCで構築されたDockerコンテナを立ち上げています

ソース

FROM fluent/fluentd:v1.10

USER root

# install plugin
RUN apk add --update-cache --virtual .build-deps sudo build-base ruby-dev \
  && gem install fluent-plugin-kinesis -v 3.0.0 --no-document \
  && gem sources --clear-all \
  && apk del .build-deps \
  && rm -rf /var/cache/apk/* \
  /home/fluent/.gem/ruby/*/cache/*.gem

# set timezone (Alpine)
RUN apk --update-cache add tzdata && \
  cp /usr/share/zoneinfo/Asia/Tokyo /etc/localtime && \
  apk del tzdata && \
  rm -rf /var/cache/apk/*

WORKDIR /fluentd
COPY ./fluent.conf /fluentd/etc/fluent.conf

USER fluent

<source>
  @type  forward
  @label @mainstream
  port   24224
</source>

<filter **>
  @type stdout
</filter>

<label @mainstream>
  <match kinesis.**>
    @type kinesis_streams
    stream_name sample-kinesis-stream
    aws_key_id "#{ENV['AWS_ACCESS_KEY_ID#']}"
    aws_sec_key "#{ENV['AWS_SECRET_ACCESS_KEY']}"
    region ap-northeast-1

    <buffer>
      @type file
      path /fluentd/log/kinesis
      timekey 5
      timekey_wait 5
      timekey_use_utc true
      flush_interval 1
      chunk_limit_size 1m
      flush_thread_interval 0.1
      flush_thread_burst_interval 0.01
      flush_thread_count 15
    </buffer>

    <format>
      @type json
    </format>
  </match>
</label>

Kinesis Stream側の設定

試したこと・調べたこと

• fluentd公式：bufferタグのプロパティの種類やデフォルト値を参考にしました
• Qiita：ここではKinesis Firehoseを使用した例
• github：aws-fluent-plugin-kinesisプラグインのREADME参考

その他、ネットで「Kinesis Lambda　遅い」などと検索しまたが、有効な情報が見つかりませんでした。

その他

今はFluentd→Kinesis Stream→Lambdaの構成ですが、Fluentd→DynamoDB→LambdaやFluentd→S3→Lambdaも試そうかなと思います。
いずれにせよ、速度は大事にしていきたいと思うので、その他「速度ならこの構成の方がおすすめだよ」というのがあれば、ご教授頂けると幸いです。

Answer 1

timekey 5
timekey_wait 5

なので、Lambdaの動作時間等々を考えたらまあまあ妥当な時間のような気がします。
参考
Config: Buffer Section

Comments

[Umeeeh]

time が設定されてないので、timekey、timekey_wait の設定は無効な気がします。

Answer 2

私の方でもいろいろ試しましたが、原因わかりました！
CloudWatchにはかれるのに10秒ぐらいかかるだけで、実際処理はすぐに走っていました。
テストとしてやってみたのですが、Lambdaソースで適当なconsole.logを実行してCloudWatchに反映されるまでが10秒かかりました。結果的にFluentdもKinesis側に問題があったわけではなく、CloudWachにログが反映されるまで時間がかかるだけでした

マイナス評価をする場合は必ず理由を書いてください。

Comments

[isacRu]

何がマイナスなのか、記載頂けると嬉しいですね。

[Umeeeh]

回答が書かれてない？ようですが、可能でしたら、どのように解決したか書いていただけるとうれしいです。（マイナス票は私ではありません。念の為…。）

[isacRu]

どうやら誰かマイナス評価すると、強制的に回答が非表示になる仕様みたいです。
追記をして、更新しました。

Answer 3

ちょっと違いますが、Githubに類似のIssueがありました。
https://github.com/fluent/fluentd/issues/2766

バッファーの設定を次のようにすると変化はありますか？

    <buffer>
      @type file
      path /fluentd/log/kinesis
      flush_mode interval
      flush_interval 1
      chunk_limit_size 1m
      flush_thread_interval 0.1
      flush_thread_burst_interval 0.01
      flush_thread_count 15
    </buffer>

あと、インスタンスの性能を測定して、CPU負荷、ローカルストレージのIOPSなど、性能が不足してないか確認してみると良いかもしれません。

Comments

[isacRu]

回答ありがとうございます。
バッファー設定の件、ちょっと試しましたがダメでした????

＞あと、インスタンスの性能を測定して、CPU負荷、ローカルストレージのIOPSなど、性能が不足してないか確認してみると良いかもしれません。

すみません、インスタンスとはKinesisのインスタンスでしょうか？

[Umeeeh]

fluentdが動いているEC2インスタンスのことです。

CPU→短いインターバルで かつ 15個のスレッドで処理してるので CPU負荷が気になります。十分なコア数があって負荷が低ければ問題ないと思います。

ストレージ→バッファーがFileなので、データ量や速度に応じて ストレージのIO負荷が発生します。ディスクのIOPS性能がボトルネックになっていないか 確認してみると良いかもしれません。

[isacRu]

＞fluentdが動いているEC2インスタンスのことです。

すみません、説明が足りなかったみたいです。EC2ではなくローカルPCで、Fluentdの環境構築されたDockerコンテナを立ち上げています。質問内容に追記します。

[Umeeeh]

なるほど承知しました。EC2だと思いこんでました…。

Answer 4

※Fluentd については明るくないので、AWS側の話をします

Kinesis DataStream がリアルタイム性に欠けるという話はあまり聞いたことがありません。なので、「設定でなんとかなる」なのではないかと思っています。

気になるのはログのボリューム、そしてKinesisのシャード数とバッチサイズです。（スクショにもあるように）1本のシャードで処理できるスループットには限度があります。

ログの '件数' が多いのであれば、シャード数を増やすことを検証してみてはいかがでしょうか。合わせて、適切にシャード分散が図れるようにパーティションキーを設定するよう必要があります（このへんがFluentdからうまく設定できるかは、すみませんが存じ上げません）。

また、バッチサイズの設定も確認した方が良いかもしれません。バッチサイズが極端に小さいとその分lambdaの起動オーバヘッドで CloudWatch logs への配送が遅延することが予想されますし、大きすぎればlambdaの実行時間が伸びてこれもまた遅延する可能性があります。そのへんのチューニングについての良いアイデアはありませんが、Kinesisやlambdaのメトリックを見ながら試行錯誤で調整していくことになるんじゃないかと思います。

Comments

[isacRu]

早々の回答ありがとうございます。

>ログの '件数' が多いのであれば、シャード数を増やすことを検証してみてはいかがでしょうか
件数は一件で試しておりますので、シャード数は影響ないかもしれませんね？
念のため変えてみましょうか

>バッチサイズの設定も確認した方が良いかもしれません。
バッチ＝fluent.confのことでしょうか？

[hassaku_63]

バッチサイズは Kinesis を受ける lambda の設定を指しています。1回あたりに lambda が最大何個のレコードを処理できるかをそこでコントロールできます。
...とはいえ、ログ1件で試しているのであれば、あまり関係はないかもしれませんね...

1件ずつで試されているのであれば、lambda のコールドスタートに引っかかっているとかも一応可能性はあると思います（薄い気はしますが）。確か今はだいぶ改善していたと思いますが、例えばJavaあたりはコールドスタート時のオーバヘッドが結構重たいです。

[isacRu]

＞確か今はだいぶ改善していたと思いますが、例えばJavaあたりはコールドスタート時のオーバヘッドが結構重たいです。

そうなんですね！
今はJSで試しているので、関係なさそうですかね・・

[hassaku_63]

js であればコールドスタート時でも10-12秒にはまず至らないですね。根本原因にはなりえなさそうです。

fluentd がログを flush するタイミングの影響を受けているのでは？というのは割とありそうな線かなという感じはしてました（詳しくなかったので言及できませんでしたが）。で、 yu_1985 様の回答で指摘されている内容がまさしくそれに該当するのではないかと思います。ざっと見た感じ、私もこの方の指摘が正しいように見えます。

※私自身も後学のため少々調べてみたので少しだけ補足しておきます。細かいパラメータの意味はご自身で確認いただくとして（私には正確に回答できない領域なので）...。

今の fluentd の設定では5秒間のチャンクでログをバッファして、さらに5秒待ってからKinesisに送っているのではないでしょうか？

となると、lambdaのコールドスタートも含めたら10-12秒はyu_1985様の指摘通り、妥当だと思います。（コールドスタートがどのくらいかかるかは、lambdaのデプロイパッケージのサイズとか、中のコードの実装にも依存するので一概に言えませんが、多くてもせいぜい数秒程度だと思います）

[isacRu]

調べて頂きありがとうございます。

＞今の fluentd の設定では5秒間のチャンクでログをバッファして、さらに5秒待ってからKinesisに送ってい＞るのではないでしょうか？
ここは関係ないみたいです。ログの送り元から削除する時間のことを指しているかと思います。

私の方でもいろいろ試しましたが、原因わかりました！
CloudWatchにはかれるのに10秒ぐらいかかるだけで、実際処理はすぐに走っていました。
実際にLambdaソースで適当なconsole.logを実行して、CloudWatchに反映されるまでが10秒かかるみたいです。結果的にFluentdもKinesis側に問題があったわけではなく、CloudWachにログが反映されるまで時間がかかるだけでした????