かんがるーさんの日記

最近自分が興味をもったものを調べた時の手順等を書いています。今は Spring Boot をいじっています。

Spring Boot + Spring Integration でいろいろ試してみる ( その44 )( Docker Compose でサーバを構築する、Kafka 編11 - kafka-producer-perf-test、kafka-consumer-perf-test コマンドでパフォーマンスを確認する )

概要

記事一覧はこちらです。

パフォーマンスのテストをするために kafka-producer-perf-test、kafka-consumer-perf-test というコマンドが用意されていましたので、それらを利用して今の環境でどれくらいのパフォーマンスを出せるのか確認してみます。

参照したサイト・書籍

  1. ably77/DCOS-Kafka-Performance
    https://github.com/ably77/DCOS-Kafka-Performance

  2. ueokande/benchmark-commands.md
    https://gist.github.com/ueokande/b96eadd798fff852551b80962862bfb3

  3. Benchmarking Kafka!
    https://blog.clairvoyantsoft.com/benchmarking-kafka-e7b7c289257d

  4. Performance testing in Kafka
    https://stackoverflow.com/questions/50753980/performance-testing-in-kafka

  5. Kafka to the Maxka - (Kafka Performance Tuning)
    https://www.slideshare.net/Hadoop_Summit/kafka-to-the-maxka-kafka-performance-tuning

  6. めざせ!Kafkaマスター ~Apache Kafkaで最高の性能を出すには~
    https://www.ospn.jp/osc2017.enterprise/pdf/OSC2017.enterprise_Hitachi_Kafka.pdf

  7. Confluent Platform CLI Tools
    https://docs.confluent.io/current/installation/cli-reference.html

    • 今回の調査中にコマンド一覧を見つけたのでメモしておきます。

目次

  1. パフォーマンスを確認する方針を決める
  2. kafka-producer-perf-test、kafka-consumer-perf-test 実行用のコンテナを起動するための docker-compose.perftest.yml を作成する
  3. 確認手順
  4. partition x 3 の場合 throughput はどこまで指定可能か?
  5. partition x 9 の場合 throughput はどこまで指定可能か?
  6. kafka-consumer-groups コマンドで登録されている offset を削除する
  7. 最後に

手順

パフォーマンスを確認する方針を決める

  • kafka-producer-perf-test でメッセージを送信し、kafka-consumer-perf-test コマンドでメッセージを受信することでパフォーマンスを確認します。
  • kafka-producer-perf-test、kafka-consumer-perf-test コマンドを実行するコンテナはそれぞれ専用のものを Docker Compose で構築します。コンテナのイメージには confluentinc/cp-kafka:5.3.0 を使用します。また zookeeper も cp-zookeeper1~3 とは別に kafka-producer-perf-test、kafka-consumer-perf-test コマンド実行用コンテナ専用のものを構築します。
  • topic は Topic1 という名前のものを作成します。partition 数は確認時の条件に合わせて変更しますが、replication-factor は 3 固定です。
  • kafka-producer-perf-test コマンドのオプションの内、以下のものは固定の値を指定します。
    • --topic Topic1
    • --record-size 250
    • --producer-props acks=1 buffer.memory=67108864 compression.type=none batch.size=8196 bootstrap.servers=cp-kafka1:19092,cp-kafka2:29092,cp-kafka3:39092(buffer.memory、compression.type、batch.size はデフォルト値ですが明示的に指定しています)
  • kafka-consumer-perf-test コマンドのオプションの内、以下のものは固定の値を指定します。
    • --broker-list cp-kafka1:19092,cp-kafka2:29092,cp-kafka3:39092
    • --topic Topic1
    • --group topic1-perftest-group
    • --timeout 300000
  • 可変にするのは以下の値です。
    • topic の partition 数
    • kafka-producer-perf-test コマンドの
      • --throughput オプションの値(秒あたりの送信メッセージ件数がこの値に近くなるよう自動調整されます)
      • --num-records オプションの値は --throughput オプションに指定する値が 1000未満の場合には 100000(10万)、5000未満の場合には 1000000(100万)、それ以上の場合には 5000000(500万)にします。
    • kafka-consumer-perf-test コマンドの
      • --threads オプション(topic の partition 数に合わせます)
      • --messages オプションの値は kafka-producer-perf-test コマンドの --num-records オプションの値に合わせます。

kafka-producer-perf-test、kafka-consumer-perf-test 実行用のコンテナを起動するための docker-compose.perftest.yml を作成する

プロジェクトのルートディレクトリ直下に docker-compose.perftest.yml というファイルを新規作成し、以下の内容を記述します。

# docker-compose -f docker-compose.perftest.yml up -d
# docker-compose -f docker-compose.perftest.yml down
version: '3'

services:
  cp-zookeeper-perf-test:
    image: confluentinc/cp-zookeeper:5.3.0
    container_name: cp-zookeeper-perf-test
    environment:
      ZOOKEEPER_CLIENT_PORT: 2181
      ZOOKEEPER_TICK_TIME: 2000
      ZOOKEEPER_INIT_LIMIT: 5
      ZOOKEEPER_SYNC_LIMIT: 2

  # kafka-producer-perf-test コマンド実行用
  # docker exec -it cp-kafka-producer-perf-test /bin/bash
  cp-kafka-producer-perf-test:
    image: confluentinc/cp-kafka:5.3.0
    container_name: cp-kafka-producer-perf-test
    environment:
      KAFKA_ZOOKEEPER_CONNECT: cp-zookeeper-perf-test:2181
      KAFKA_ADVERTISED_LISTENERS: PLAINTEXT://cp-kafka-producer-perf-test:9092
    depends_on:
      - cp-zookeeper-perf-test

  # kafka-consumer-perf-test コマンド実行用
  # docker exec -it cp-kafka-consumer-perf-test /bin/bash
  cp-kafka-consumer-perf-test:
    image: confluentinc/cp-kafka:5.3.0
    container_name: cp-kafka-consumer-perf-test
    environment:
      KAFKA_ZOOKEEPER_CONNECT: cp-zookeeper-perf-test:2181
      KAFKA_ADVERTISED_LISTENERS: PLAINTEXT://cp-kafka-consumer-perf-test:9092
    depends_on:
      - cp-zookeeper-perf-test

networks:
  default:
    external:
      name: ksbysample-eipapp-kafka_default

確認手順

パフォーマンスは以下の手順で確認します(1度書いた後に手順追加しているため画像に一貫性はありません)。

  1. docekr-compose up -d コマンドでコンテナを起動します。

    f:id:ksby:20190922114612p:plain

  2. docker-compose -f docker-compose.perftest.yml up -d コマンドで perf-test コマンド実行用のコンテナを起動します。

    f:id:ksby:20190922114736p:plain

  3. http://localhost:1936/haproxy-cp-schema-registry?stats にアクセスして cp-schema-registry のステータスが全て緑になるまで待機します。

    f:id:ksby:20190922114855p:plain

  4. cp-kafka1 コンテナに接続し、topic を作成します。この時 partition 数を指定します。

    • kafka-topics --zookeeper cp-zookeeper1:12181 --create --topic Topic1 --partitions <パーティション数> --replication-factor 3 --if-not-exists

    f:id:ksby:20190922115017p:plain

  5. 以下のコマンドを実行して cp-kafka-producer-perf-test、cp-kafka-consumer-perf-test コンテナに接続した後、実行用のコマンドを入力します(ただしまだ実行はしません)。

    • kafka-producer-perf-test コマンド用
      • docker exec -it cp-kafka-producer-perf-test /bin/bash
      • kafka-producer-perf-test --topic Topic1 --num-records <送受信するレコード数(例:1000000)> --record-size 250 --throughput <ここに秒あたりの送信レコード数を指定する(例:100)> --producer-props acks=1 buffer.memory=67108864 compression.type=none batch.size=8196 bootstrap.servers=cp-kafka1:19092,cp-kafka2:29092,cp-kafka3:39092
    • kafka-consumer-perf-test コマンド用
      • docker exec -it cp-kafka-consumer-perf-test /bin/bash
      • kafka-consumer-perf-test --threads <スレッド数、topic の partition 数と同じ値を指定する> --broker-list cp-kafka1:19092,cp-kafka2:29092,cp-kafka3:39092 --messages <送受信するレコード数(例:1000000)> --topic Topic1 --group topic1-perftest-group --timeout 300000

    f:id:ksby:20190922115631p:plain

  6. まず kafka-consumer-perf-test コマンドを実行します。topic の partition に対する group の offset を登録します。

    kafka-consumer-perf-test コマンド実行前は topic の partition に対する group の offset は登録されていませんが、

    f:id:ksby:20190922120249p:plain

    kafka-consumer-perf-test コマンドを実行すると、

    f:id:ksby:20190922120024p:plain

    topic の partition に対する group の offset が登録されます。この時点ではメッセージの送受信が行われていないので CURRENT-OFFSET、LOG-END-OFFSET、LAG は全て 0 です。

    f:id:ksby:20190922120351p:plain

  7. kafka-producer-perf-test コマンドを実行します。

    f:id:ksby:20190922121626p:plain

  8. メッセージ送受信中の lag の確認は kafka-consumer-groups コマンドか Grafana の Kafka Lag Exporter で確認します。

    kafka-consumer-groups --bootstrap-server cp-kafka1:19092,cp-kafka2:29092,cp-kafka3:39092 --describe --group topic1-perftest-group --timeout 300000 コマンドを実行するとその時の lag が表示されます。ただしこのコマンドは応答が返ってくるまで少し時間がかかります。

    f:id:ksby:20190922131355p:plain

    Grafana の Kafka Lag Exporter では「Consumer Group Max Lag Offsets」「Consumer Group Lag Partition Offsets」と「Consumer Group Lag In Time Per Group Over Offset Lag」の上のグラフの黄色の線の方を見ます。

    f:id:ksby:20190922130945p:plain

  9. 10万レコードを送信し終わると kafka-producer-perf-test、kafka-consumer-perf-test コマンドがほぼ同時に終わります。

    f:id:ksby:20190922122000p:plain

    kafka-producer-perf-test コマンドからは以下の情報が出力されます(最後の4つが何かよく分かりませんでした)。--print-metrics オプションを指定すればより詳細な metrics が出力されます。

    100000 records sent
    999.440313 records/sec (0.24 MB/sec)
    88.55 ms avg latency
    653.00 ms max latency
    68 ms 50th
    235 ms 95th
    367 ms 99th
    536 ms 99.9th

    kafka-consumer-perf-test コマンドからは以下の情報が出力されます。

    start.time 2019-09-22 03:11:23:490
    end.time 2019-09-22 03:13:06:721
    data.consumed.in.MB 23.8419
    MB.sec 0.2310
    data.consumed.in.nMsg 100000
    nMsg.sec 968.7013
    rebalance.time.ms 3159
    fetch.time.ms 100072
    fetch.MB.sec 0.2382
    fetch.nMsg.sec 999.2805

    コマンド終了後の offset を確認すると CURRENT-OFFSET と LOG-END-OFFSET が同じ値になっており、LAG も 0 になっています。

    f:id:ksby:20190922123915p:plain

  10. docker-compose -f docker-compose.perftest.yml downdocekr-compose down コマンドでコンテナを停止します。

  11. メッセージを大量に送受信した結果ディスクを消費していますので docker volume prune コマンドで削除します。この作業は毎回ではなくしばらくやった後でも構いません。

    f:id:ksby:20190922131637p:plain

  12. 大量にメッセージを送受信すると Docker 自体が不安定になるかもしれません。不安定になっていると感じたら Docker 本体を再起動してください。

partition x 3 の場合 throughput はどこまで指定可能か?

kafka-producer-perf-test コマンドの出力結果は以下の通りでした。

--throughput 50 --throughput 100 --throughput 150
100000 records sent 100000 records sent 100000 records sent
49.998700 records/sec (0.01 MB/sec) 99.999200 records/sec (0.02 MB/sec) 149.985751 records/sec (0.04 MB/sec)
3.39 ms avg latency 7.73 ms avg latency 18.07 ms avg latency
592.00 ms max latency 887.00 ms max latency 1096.00 ms max latency
2 ms 50th 2 ms 50th 2 ms 50th
8 ms 95th 30 ms 95th 106 ms 95th
27 ms 99th 94 ms 99th 245 ms 99th
115 ms 99.9th 393 ms 99.9th 500 ms 99.9th
--throughput 200 --throughput 500 --throughput 1000
100000 records sent 100000 records sent 1000000 records sent
199.990800 records/sec (0.05 MB/sec) 499.640259 records/sec (0.12 MB/sec) 999.835027 records/sec (0.24 MB/sec)
24.33 ms avg latency 70.29 ms avg latency 64.27 ms avg latency
607.00 ms max latency 1068.00 ms max latency 967.00 ms max latency
4 ms 50th 54 ms 50th 44 ms 50th
124 ms 95th 199 ms 95th 200 ms 95th
242 ms 99th 333 ms 99th 357 ms 99th
420 ms 99.9th 522 ms 99.9th 595 ms 99.9th
--throughput 5000 --throughput 10000 --throughput 20000
5000000 records sent 5000000 records sent 5000000 records sent
4998.520438 records/sec (1.19 MB/sec) 8417.465905 records/sec (2.01 MB/sec) 7975.550153 records/sec (1.90 MB/sec)
80.29 ms avg latency 28588.07 ms avg latency 30396.65 ms avg latency
3520.00 ms max latency 68596.00 ms max latency 104988.00 ms max latency
31 ms 50th 29904 ms 50th 15809 ms 50th
200 ms 95th 52302 ms 95th 95187 ms 95th
1809 ms 99th 61605 ms 99th 102926 ms 99th
3103 ms 99.9th 67960 ms 99.9th 104409 ms 99.9th

kafka-consumer-perf-test コマンドの出力結果は以下の通りでした。

--throughput 50 --throughput 100 --throughput 150
start.time 2019-09-22 10:03:49:071 2019-09-22 12:46:33:432 2019-09-23 00:08:07:191
end.time 2019-09-22 10:37:10:303 2019-09-22 13:03:14:996 2019-09-23 00:19:15:541
data.consumed.in.MB 23.8419 23.8419 23.8419
MB.sec 0.0119 0.0238 0.0357
data.consumed.in.nMsg 100000 100000 100000
nMsg.sec 49.9692 99.8438 149.6222
rebalance.time.ms 3309 3416 3871
fetch.time.ms 1997923 998148 664479
fetch.MB.sec 0.0119 0.0239 0.0359
fetch.nMsg.sec 50.0520 100.1855 150.4938
--throughput 200 --throughput 500 --throughput 1000
start.time 2019-09-23 02:39:14:142 2019-09-23 03:03:18:495 2019-09-23 03:19:35:384
end.time 2019-09-23 02:47:35:920 2019-09-23 03:06:43:725 2019-09-23 03:36:18:194
data.consumed.in.MB 23.8419 23.8419 238.4186
MB.sec 0.0475 0.1162 0.2378
data.consumed.in.nMsg 100000 100000 1000000
nMsg.sec 199.2913 487.2582 997.1979
rebalance.time.ms 4296 4172 9785
fetch.time.ms 497482 201058 993025
fetch.MB.sec 0.0479 0.1186 0.2401
fetch.nMsg.sec 201.0123 497.3689 1007.0240
--throughput 5000 --throughput 10000 --throughput 20000
start.time 2019-09-23 04:03:53:545 2019-09-23 04:31:34:424 2019-09-23 04:51:40:650
end.time 2019-09-23 04:20:35:428 2019-09-23 04:41:31:001 2019-09-23 05:02:09:149
data.consumed.in.MB 1192.0929 1192.0929 1192.0929
MB.sec 1.1899 1.9982 1.8967
data.consumed.in.nMsg 5000000 5000000 5000000
nMsg.sec 4990.6027 8381.1478 7955.4621
rebalance.time.ms 3930 5931 3694
fetch.time.ms 997953 590646 624805
fetch.MB.sec 1.1945 2.0183 1.9079
fetch.nMsg.sec 5010.2560 8465.3075 8002.4968

--throughput 50 の時の Grafana の Kafka Lag Exporter のグラグです(時間がかかったのでこれだけ Last 1 hour に変更しています)。

f:id:ksby:20190922193807p:plain

--throughput 100 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190922220642p:plain

--throughput 150 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923092005p:plain

--throughput 200 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923115118p:plain

--throughput 500 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923120729p:plain

--throughput 1000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923123706p:plain

--throughput 5000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923132113p:plain

--throughput 10000 の時の Grafana の Kafka Lag Exporter のグラグです。今回 --throughput オプションで指定した値のスループットが出たのは下のグラフの黄色の線が急に落ちたところからでした(それまでは 6,000~9,000 records/sec 程度)。

f:id:ksby:20190923134215p:plain

--throughput 20000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923140253p:plain

ここまでやってみて思ったことを以下に記載します。

  • --throughput 5000 までは指定したスループットが出ているが、--throughput 10000 以上だと出ていない。kafka-producer-perf-test コマンドが 5秒おきに出力する records/sec を見ていると 6,000~7,000程度が限界のような気がする。
  • --throughput 10000 以上は kafka-producer-perf-test コマンドが出力する avg latency の値も 30秒以上と急に悪化していた。
  • kafka-producer-perf-test コマンドで指定した --throughput オプションの値と kafka-consumer-perf-test コマンドが終了時に出力する nMsg.sec、fetch.nMsg.sec の件数が同じならば指定したスループットは出ていると思われる。
  • 例えば --throughput 5000 を指定して実際に 5,000 records/sec のメッセージを送信していて、Grafana の Kafka Lag Exporter に lag が 5,000 程度表示されるのは当然なのかもしれない(心配することではないのかもしれない)。最初は lag は 0 に近い方がよいと思っていたが、何度もやっているうちにそんな感じがした。
  • Grafana の Kafka Lag Exporter を見ていると突然 lag in offsets の値が落ちる時があるが、なぜこうなるのか不明。
  • partition 数 = 3 だと、kafka-consumer-perf-test コマンドの方で [2019-09-23 04:14:48,147] WARN [Consumer clientId=consumer-1, groupId=topic1-perftest-group] Offset commit failed on partition Topic1-0 at offset 1079272: The request timed out. (org.apache.kafka.clients.consumer.internals.ConsumerCoordinator) というログが 1~2件程度出力されることがあった。
  • kafka-consumer-groups コマンドが出力する lag の数も確認したいと思い途中で何度か実行してみたが kafka-producer-perf-test コマンドの --throughput オプションの値が大きくなる程応答が遅くなった(正直かなり遅い)。また Grafana の Kafka Lag Exporter のグラフに表示されている lag 数と一致しない(kafka-consumer-groups コマンドが出力する値の方が大きい)。応答が遅い影響だろうか?

partition x 9 の場合 throughput はどこまで指定可能か?

kafka-producer-perf-test コマンドの出力結果は以下の通りでした。

--throughput 10000 --throughput 12000 --throughput 14000
5000000 records sent 5000000 records sent 5000000 records sent
9987.575456 records/sec (2.38 MB/sec) 11993.571446 records/sec (2.86 MB/sec) 13965.193153 records/sec (3.33 MB/sec)
99.84 ms avg latency 188.95 ms avg latency 8180.31 ms avg latency
1451.00 ms max latency 4328.00 ms max latency 30732.00 ms max latency
57 ms 50th 57 ms 50th 3453 ms 50th
325 ms 95th 852 ms 95th 26020 ms 95th
770 ms 99th 3241 ms 99th 29981 ms 99th
1291 ms 99.9th 4164 ms 99.9th 30537 ms 99.9th
--throughput 16000 --throughput 18000 --throughput 20000
5000000 records sent 5000000 records sent 5000000 records sent
15766.454660 records/sec (3.76 MB/sec) 16550.646634 records/sec (3.95 MB/sec) 15266.056839 records/sec (3.64 MB/sec)
12374.64 ms avg latency 13948.77 ms avg latency 15236.51 ms avg latency
33281.00 ms max latency 29037.00 ms max latency 38270.00 ms max latency
12813 ms 50th 13504 ms 50th 11244 ms 50th
27468 ms 95th 27285 ms 95th 35753 ms 95th
32314 ms 99th 28354 ms 99th 37608 ms 99th
32968 ms 99.9th 28914 ms 99.9th 38143 ms 99.9th

kafka-consumer-perf-test コマンドの出力結果は以下の通りでした。

--throughput 10000 --throughput 12000 --throughput 14000
start.time 2019-09-23 13:12:22:034 2019-09-23 14:27:28:905 2019-09-23 14:44:20:245
end.time 2019-09-23 13:20:43:969 2019-09-23 14:34:28:852 2019-09-23 14:50:19:972
data.consumed.in.MB 1192.0929 1192.0929 1192.0929
MB.sec 2.3750 2.8387 3.3139
data.consumed.in.nMsg 5000000 5000000 5000000
nMsg.sec 9961.4492 11906.2644 13899.4293
rebalance.time.ms 4203 3526 4455
fetch.time.ms 497732 416421 355272
fetch.MB.sec 2.3950 2.8627 3.3554
fetch.nMsg.sec 10045.5667 12007.0794 14073.7238
--throughput 16000 --throughput 18000 --throughput 20000
start.time 2019-09-23 15:15:57:943 2019-09-23 15:31:05:693 2019-09-23 15:45:44:630
end.time 2019-09-23 15:21:16:930 2019-09-23 15:36:09:433 2019-09-23 15:51:16:616
data.consumed.in.MB 1192.0929 1192.0929 1192.0929
MB.sec 3.7371 3.9247 3.5908
data.consumed.in.nMsg 5000000 5000000 5000000
nMsg.sec 15674.6200 16461.4473 15060.8761
rebalance.time.ms 4074 4020 4339
fetch.time.ms 314913 299720 327647
fetch.MB.sec 3.7855 3.9774 3.6383
fetch.nMsg.sec 15877.4011 16682.2368 15260.3259

--throughput 10000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923222124p:plain

--throughput 12000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923233515p:plain

--throughput 14000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190923235111p:plain

--throughput 16000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190924002213p:plain

--throughput 18000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190924003653p:plain

--throughput 20000 の時の Grafana の Kafka Lag Exporter のグラグです。

f:id:ksby:20190924005156p:plain

ここまでやってみて思ったことを以下に記載します。

  • --throughput 16000 までオプションに指定した値と実際に送受信される records/sec のメッセージ件数はほぼ一致しているが、avg latency がまともなのは --throughput 12000 まで。kafka-consumer-perf-test コマンドの方も nMsg.sec が --throughput オプションと同じなのは --throughput 16000 までだった。
  • kafka-producer-perf-test、kafka-consumer-perf-test コマンドでパフォーマンスを見る場合には throughput(records/sec あるいは nMsg.sec)や avg latency、max latency のような気がする。lag を見る必要は感じなかったかな。。。

kafka-consumer-groups コマンドで登録されている offset を削除する

メッセージを送受信すると offset が登録されますが、

f:id:ksby:20190925010020p:plain

kafka-consumer-groups --bootstrap-server cp-kafka1:19092,cp-kafka2:29092,cp-kafka3:39092 --delete --group topic1-perftest-group --timeout 300000 コマンドを実行すれば削除できます。

f:id:ksby:20190925010140p:plain

最後に

kafka-producer-perf-test、kafka-consumer-perf-test コマンドは、構築した kafka の環境で求める throughput と latency が出るのかを確認するには便利なコマンドだと思いました。

次は Kafka Streams、KSQL あたりをやってみるつもりです。

履歴

2019/09/29
初版発行。