[
https://issues.apache.org/jira/browse/KAFKA-3565?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15243840#comment-15243840
]
Jiangjie Qin commented on KAFKA-3565:
-------------------------------------
[~ijuma] What is your other settings? e.g. max.in.flight.requests, number of
partitions, batch size, etc.
I happen to be conducting some performance tuning for the producers. The
results I noticed are different from what you saw:
{noformat}
Producer before KIP31/32
./kafka-run-class.sh org.apache.kafka.tools.ProducerPerformance --topic
test_3_replica_1_partition --num-records 100000 --record-size 10000
--throughput 10000 --valueBound 50000 --producer-props
bootstrap.servers=CLUSTER_WIHT_KIP31/32 acks=1
max.in.flight.requests.per.connection=1 batch.size=50000 compression.type=gzip
client.id=becket_gzip
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/core/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/tools/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/api/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/runtime/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/file/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/json/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
5370 records sent, 1074.0 records/sec (10.24 MB/sec), 14.3 ms avg latency,
165.0 max latency.
5875 records sent, 1175.0 records/sec (11.21 MB/sec), 13.1 ms avg latency, 34.0
max latency.
5977 records sent, 1195.2 records/sec (11.40 MB/sec), 12.7 ms avg latency, 96.0
max latency.
6000 records sent, 1199.8 records/sec (11.44 MB/sec), 12.7 ms avg latency, 79.0
max latency.
6115 records sent, 1223.0 records/sec (11.66 MB/sec), 12.0 ms avg latency, 34.0
max latency.
5967 records sent, 1193.4 records/sec (11.38 MB/sec), 12.5 ms avg latency, 32.0
max latency.
5948 records sent, 1189.6 records/sec (11.34 MB/sec), 12.7 ms avg latency, 35.0
max latency.
5939 records sent, 1187.8 records/sec (11.33 MB/sec), 12.9 ms avg latency, 78.0
max latency.
5941 records sent, 1188.2 records/sec (11.33 MB/sec), 12.7 ms avg latency, 32.0
max latency.
5947 records sent, 1188.9 records/sec (11.34 MB/sec), 12.7 ms avg latency, 31.0
max latency.
6016 records sent, 1203.2 records/sec (11.47 MB/sec), 12.5 ms avg latency, 44.0
max latency.
6049 records sent, 1209.6 records/sec (11.54 MB/sec), 12.3 ms avg latency, 32.0
max latency.
6042 records sent, 1208.4 records/sec (11.52 MB/sec), 12.3 ms avg latency, 33.0
max latency.
5961 records sent, 1191.5 records/sec (11.36 MB/sec), 12.6 ms avg latency, 32.0
max latency.
5875 records sent, 1174.5 records/sec (11.20 MB/sec), 12.9 ms avg latency, 94.0
max latency.
5730 records sent, 1145.5 records/sec (10.92 MB/sec), 13.0 ms avg latency,
111.0 max latency.
100000 records sent, 1181.851489 records/sec (11.27 MB/sec), 12.76 ms avg
latency, 165.00 ms max latency, 12 ms 50th, 21 ms 95th, 27 ms 99th, 47 ms
99.9th.
./kafka-run-class.sh org.apache.kafka.tools.ProducerPerformance --topic
test_3_replica_1_partition --num-records 100000 --record-size 10000
--throughput 10000 --valueBound 50000 --producer-props
bootstrap.servers=CLUSTER_BEFORE_KIP31/32 acks=1
max.in.flight.requests.per.connection=1 batch.size=50000 compression.type=gzip
client.id=becket_gzip
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/core/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/tools/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/api/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/runtime/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/file/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/json/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
5390 records sent, 1078.0 records/sec (10.28 MB/sec), 13.6 ms avg latency,
192.0 max latency.
5970 records sent, 1194.0 records/sec (11.39 MB/sec), 12.8 ms avg latency, 31.0
max latency.
6067 records sent, 1213.2 records/sec (11.57 MB/sec), 12.2 ms avg latency, 32.0
max latency.
6151 records sent, 1230.0 records/sec (11.73 MB/sec), 12.0 ms avg latency, 53.0
max latency.
6143 records sent, 1228.1 records/sec (11.71 MB/sec), 12.0 ms avg latency, 32.0
max latency.
6045 records sent, 1209.0 records/sec (11.53 MB/sec), 12.4 ms avg latency, 66.0
max latency.
6104 records sent, 1220.6 records/sec (11.64 MB/sec), 11.9 ms avg latency, 31.0
max latency.
6057 records sent, 1210.9 records/sec (11.55 MB/sec), 11.9 ms avg latency, 30.0
max latency.
6053 records sent, 1210.6 records/sec (11.55 MB/sec), 11.7 ms avg latency, 31.0
max latency.
6102 records sent, 1220.2 records/sec (11.64 MB/sec), 11.9 ms avg latency, 30.0
max latency.
6144 records sent, 1228.8 records/sec (11.72 MB/sec), 11.8 ms avg latency, 30.0
max latency.
6135 records sent, 1227.0 records/sec (11.70 MB/sec), 11.5 ms avg latency, 28.0
max latency.
6141 records sent, 1228.0 records/sec (11.71 MB/sec), 11.8 ms avg latency, 31.0
max latency.
6138 records sent, 1227.6 records/sec (11.71 MB/sec), 11.6 ms avg latency, 32.0
max latency.
6102 records sent, 1219.9 records/sec (11.63 MB/sec), 12.0 ms avg latency, 33.0
max latency.
6024 records sent, 1204.6 records/sec (11.49 MB/sec), 11.7 ms avg latency, 84.0
max latency.
100000 records sent, 1208.955946 records/sec (11.53 MB/sec), 12.02 ms avg
latency, 192.00 ms max latency, 11 ms 50th, 20 ms 95th, 25 ms 99th, 31 ms
99.9th.
{noformat}
When I use the producer with KIP31/32
{noformat}
Producer with KIP31/32
./kafka-run-class.sh org.apache.kafka.tools.ProducerPerformance --topic
test_3_replica_1_partition --num-records 100000 --record-size 10000
--throughput 10000 --valueBound 50000 --producer-props
bootstrap.servers=CLUSTER_WITH_KIP31/32 acks=1
max.in.flight.requests.per.connection=1 batch.size=50000 compression.type=gzip
client.id=becket_gzip
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/core/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/tools/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/api/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/runtime/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/file/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/json/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
5444 records sent, 1088.8 records/sec (10.38 MB/sec), 9.5 ms avg latency, 158.0
max latency.
6254 records sent, 1250.8 records/sec (11.93 MB/sec), 7.2 ms avg latency, 54.0
max latency.
6448 records sent, 1289.3 records/sec (12.30 MB/sec), 6.9 ms avg latency, 24.0
max latency.
6429 records sent, 1285.8 records/sec (12.26 MB/sec), 6.9 ms avg latency, 14.0
max latency.
6456 records sent, 1291.2 records/sec (12.31 MB/sec), 6.9 ms avg latency, 31.0
max latency.
6382 records sent, 1276.4 records/sec (12.17 MB/sec), 7.0 ms avg latency, 47.0
max latency.
6365 records sent, 1272.7 records/sec (12.14 MB/sec), 6.9 ms avg latency, 12.0
max latency.
6454 records sent, 1290.8 records/sec (12.31 MB/sec), 6.9 ms avg latency, 27.0
max latency.
6457 records sent, 1291.4 records/sec (12.32 MB/sec), 6.8 ms avg latency, 12.0
max latency.
6301 records sent, 1259.7 records/sec (12.01 MB/sec), 6.9 ms avg latency, 19.0
max latency.
6492 records sent, 1298.4 records/sec (12.38 MB/sec), 6.9 ms avg latency, 12.0
max latency.
6426 records sent, 1284.9 records/sec (12.25 MB/sec), 6.9 ms avg latency, 13.0
max latency.
6419 records sent, 1283.5 records/sec (12.24 MB/sec), 6.9 ms avg latency, 37.0
max latency.
6370 records sent, 1273.7 records/sec (12.15 MB/sec), 7.0 ms avg latency, 50.0
max latency.
6431 records sent, 1286.2 records/sec (12.27 MB/sec), 6.8 ms avg latency, 12.0
max latency.
100000 records sent, 1269.051638 records/sec (12.10 MB/sec), 7.07 ms avg
latency, 158.00 ms max latency, 7 ms 50th, 9 ms 95th, 12 ms 99th, 26 ms 99.9th.
{noformat}
It seems both throughput and latency is improved. Similar results for message
size 100B
{noformat}
Producer with KIP31/32
./kafka-run-class.sh org.apache.kafka.tools.ProducerPerformance --topic
test_3_replica_1_partition --num-records 10000000 --record-size 100
--throughput 100000 --valueBound 50000 --producer-props
bootstrap.servers=CLUSTER_WITH_KIP31/32 acks=1
max.in.flight.requests.per.connection=1 batch.size=50000 compression.type=gzip
client.id=becket_gzip
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/core/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/tools/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/api/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/runtime/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/file/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/gitlikafka/connect/json/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
236641 records sent, 47328.2 records/sec (4.51 MB/sec), 4.5 ms avg latency,
170.0 max latency.
241964 records sent, 48383.1 records/sec (4.61 MB/sec), 4.3 ms avg latency,
16.0 max latency.
233744 records sent, 46748.8 records/sec (4.46 MB/sec), 4.3 ms avg latency,
23.0 max latency.
243816 records sent, 48763.2 records/sec (4.65 MB/sec), 4.3 ms avg latency,
15.0 max latency.
249216 records sent, 49843.2 records/sec (4.75 MB/sec), 4.4 ms avg latency,
43.0 max latency.
247266 records sent, 49453.2 records/sec (4.72 MB/sec), 4.3 ms avg latency,
32.0 max latency.
238498 records sent, 47699.6 records/sec (4.55 MB/sec), 4.3 ms avg latency,
31.0 max latency.
244814 records sent, 48962.8 records/sec (4.67 MB/sec), 4.3 ms avg latency,
27.0 max latency.
243154 records sent, 48630.8 records/sec (4.64 MB/sec), 4.4 ms avg latency,
51.0 max latency.
246016 records sent, 49203.2 records/sec (4.69 MB/sec), 4.3 ms avg latency,
55.0 max latency.
237093 records sent, 47418.6 records/sec (4.52 MB/sec), 4.3 ms avg latency,
25.0 max latency.
238039 records sent, 47607.8 records/sec (4.54 MB/sec), 4.4 ms avg latency,
43.0 max latency.
215768 records sent, 43153.6 records/sec (4.12 MB/sec), 4.3 ms avg latency,
15.0 max latency.
226158 records sent, 45231.6 records/sec (4.31 MB/sec), 4.3 ms avg latency,
15.0 max latency.
Producer before KIP31/32
./kafka-run-class.sh org.apache.kafka.tools.ProducerPerformance --topic
test_3_replica_1_partition --num-records 10000000 --record-size 100
--throughput 100000 --valuound 50000 --producer-props
bootstrap.servers=CLUSTER_BEFORE_KIP31/32 acks=1
max.in.flight.requests.per.connection=1 batch.size=50000 compression.type=gzip
client.id=becket_gzip
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/core/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/tools/build/dependant-libs-2.10.6/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/api/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/runtime/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/file/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/home/jqin/workspace/temp/gitlikafka/connect/json/build/dependant-libs/slf4j-log4j12-1.7.15.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
210949 records sent, 42189.8 records/sec (4.02 MB/sec), 7.2 ms avg latency,
243.0 max latency.
220946 records sent, 44189.2 records/sec (4.21 MB/sec), 6.5 ms avg latency,
19.0 max latency.
213472 records sent, 42694.4 records/sec (4.07 MB/sec), 6.7 ms avg latency,
100.0 max latency.
215634 records sent, 43126.8 records/sec (4.11 MB/sec), 6.7 ms avg latency,
107.0 max latency.
197060 records sent, 39404.1 records/sec (3.76 MB/sec), 6.4 ms avg latency,
20.0 max latency.
207942 records sent, 41588.4 records/sec (3.97 MB/sec), 6.7 ms avg latency,
76.0 max latency.
{noformat}
> Producer's throughput lower with compressed data after KIP-31/32
> ----------------------------------------------------------------
>
> Key: KAFKA-3565
> URL: https://issues.apache.org/jira/browse/KAFKA-3565
> Project: Kafka
> Issue Type: Bug
> Reporter: Ismael Juma
> Priority: Critical
> Fix For: 0.10.0.0
>
>
> Relative offsets were introduced by KIP-31 so that the broker does not have
> to recompress data (this was previously required after offsets were
> assigned). The implicit assumption is that reducing CPU usage required by
> recompression would mean that producer throughput for compressed data would
> increase.
> However, this doesn't seem to be the case:
> {code}
> Commit: eee95228fabe1643baa016a2d49fb0a9fe2c66bd (one before KIP-31/32)
> test_id:
> 2016-04-15--012.kafkatest.tests.benchmark_test.Benchmark.test_producer_throughput.topic=topic-replication-factor-three.security_protocol=PLAINTEXT.acks=1.message_size=100.compression_type=snappy
> status: PASS
> run time: 59.030 seconds
> {"records_per_sec": 519418.343653, "mb_per_sec": 49.54}
> {code}
> Full results: https://gist.github.com/ijuma/0afada4ff51ad6a5ac2125714d748292
> {code}
> Commit: fa594c811e4e329b6e7b897bce910c6772c46c0f (KIP-31/32)
> test_id:
> 2016-04-15--013.kafkatest.tests.benchmark_test.Benchmark.test_producer_throughput.topic=topic-replication-factor-three.security_protocol=PLAINTEXT.acks=1.message_size=100.compression_type=snappy
> status: PASS
> run time: 1 minute 0.243 seconds
> {"records_per_sec": 427308.818848, "mb_per_sec": 40.75}
> {code}
> Full results: https://gist.github.com/ijuma/e49430f0548c4de5691ad47696f5c87d
> The difference for the uncompressed case is smaller (and within what one
> would expect given the additional size overhead caused by the timestamp
> field):
> {code}
> Commit: eee95228fabe1643baa016a2d49fb0a9fe2c66bd (one before KIP-31/32)
> test_id:
> 2016-04-15--010.kafkatest.tests.benchmark_test.Benchmark.test_producer_throughput.topic=topic-replication-factor-three.security_protocol=PLAINTEXT.acks=1.message_size=100
> status: PASS
> run time: 1 minute 4.176 seconds
> {"records_per_sec": 321018.17747, "mb_per_sec": 30.61}
> {code}
> Full results: https://gist.github.com/ijuma/5fec369d686751a2d84debae8f324d4f
> {code}
> Commit: fa594c811e4e329b6e7b897bce910c6772c46c0f (KIP-31/32)
> test_id:
> 2016-04-15--014.kafkatest.tests.benchmark_test.Benchmark.test_producer_throughput.topic=topic-replication-factor-three.security_protocol=PLAINTEXT.acks=1.message_size=100
> status: PASS
> run time: 1 minute 5.079 seconds
> {"records_per_sec": 291777.608696, "mb_per_sec": 27.83}
> {code}
> Full results: https://gist.github.com/ijuma/1d35bd831ff9931448b0294bd9b787ed
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
