Kafka
  1. Kafka
  2. KAFKA-535

Significant difference in time taken to produce messages between 1, -1 for request-num-acks

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None

      Description

      There is a significant difference in time taken for ProducerPerformance to produce messages between 1 & -1 for request-num-acks.

      The following are the log4j messages from ProducerPerformance with consequent calls from the system test script.

        • Please note the time elapsed in consequent timestamps of calling ProducerPerformance.

      The overall test scenarios:
      1. This test is set up to have 1 zookeeper, 1 broker cluster of 6 nodes (distributed systems, non-local), replica factor 6, 1 topic, 1 partition
      2. The script will wait for ProducerPerformance to complete sending all messages (500 each call in this case) before calling the producer again.

      1. request-num-acks = -1. The rate is about 10 messages per second. The timestamp indicates that it takes 60+ seconds for ProducerPerformance to completely sending 500 messages and exit by itself.

      2012-09-26 21:20:56,102 - INFO - #### [producer thread] status of stopBackgroundProducer : [False] => producing [500] messages with starting message id : [0] (kafka_system_test_utils)
      2012-09-26 21:20:56,102 - DEBUG - executing command: [ssh host0996.mydomain 'JAVA_HOME=/export/apps/jdk/JDK-1_6_0_21 JMX_PORT=9997 /kafka_pst_wip/bin/kafka-run-class.sh kafka.perf.ProducerPerformance --broker-list host0997.mydomain:9091,host0998.mydomain:9092,host0999.mydomain:9093,host1000.mydomain:9094,host1001.mydomain:9095,host1002.mydomain:9096 --initial-message-id 0 --messages 500 --topic test_1 --threads 5 --compression-codec 0 --message-size 500 --request-num-acks -1   >> /kafka_pst_wip/system_test/replication_testsuite/testcase_0001/logs/producer_performance-7/producer_performance.log  & echo pid:$! > /kafka_pst_wip/system_test/replication_testsuite/testcase_0001/logs/producer_performance-7/entity_7_pid'] (kafka_system_test_utils)
      . . .
      2012-09-26 21:22:00,162 - INFO - #### [producer thread] status of stopBackgroundProducer : [False] => producing [500] messages with starting message id : [500] (kafka_system_test_utils)
      2012-09-26 21:22:00,162 - DEBUG - executing command: [ssh host0996.mydomain 'JAVA_HOME=/export/apps/jdk/JDK-1_6_0_21 JMX_PORT=9997 /kafka_pst_wip/bin/kafka-run-class.sh kafka.perf.ProducerPerformance --broker-list host0997.mydomain:9091,host0998.mydomain:9092,host0999.mydomain:9093,host1000.mydomain:9094,host1001.mydomain:9095,host1002.mydomain:9096 --initial-message-id 500 --messages 500 --topic test_1 --threads 5 --compression-codec 0 --message-size 500 --request-num-acks -1   >> /kafka_pst_wip/system_test/replication_testsuite/testcase_0001/logs/producer_performance-7/producer_performance.log  & echo pid:$! > /kafka_pst_wip/system_test/replication_testsuite/testcase_0001/logs/producer_performance-7/entity_7_pid'] (kafka_system_test_utils)

      2. request-num-acks = 1. The rate is about 150 ~ 200 messages per second. The timestamp indicates that it takes < 3 seconds for ProducerPerformance to completely sending 500 messages.

      2012-09-26 21:29:23,698 - INFO - #### [producer thread] status of stopBackgroundProducer : [False] => producing [500] messages with starting message id : [500] (kafka_system_test_utils)
      2012-09-26 21:29:23,698 - DEBUG - executing command: [ssh host0996.mydomain 'JAVA_HOME=/export/apps/jdk/JDK-1_6_0_21 JMX_PORT=9997 /kafka_pst_wip/bin/kafka-run-class.sh kafka.perf.ProducerPerformance --broker-list host0997.mydomain:9091,host0998.mydomain:9092,host0999.mydomain:9093,host1000.mydomain:9094,host1001.mydomain:9095,host1002.mydomain:9096 --initial-message-id 500 --messages 500 --topic test_1 --threads 5 --compression-codec 0 --message-size 500 --request-num-acks 1   >> /kafka_pst_wip/system_test/replication_testsuite/testcase_0002/logs/producer_performance-7/producer_performance.log  & echo pid:$! > /kafka_pst_wip/system_test/replication_testsuite/testcase_0002/logs/producer_performance-7/entity_7_pid'] (kafka_system_test_utils)
      . . .
      2012-09-26 21:29:26,576 - INFO - #### [producer thread] status of stopBackgroundProducer : [False] => producing [500] messages with starting message id : [1000] (kafka_system_test_utils)
      2012-09-26 21:29:26,577 - DEBUG - executing command: [ssh host0996.mydomain 'JAVA_HOME=/export/apps/jdk/JDK-1_6_0_21 JMX_PORT=9997 /kafka_pst_wip/bin/kafka-run-class.sh kafka.perf.ProducerPerformance --broker-list host0997.mydomain:9091,host0998.mydomain:9092,host0999.mydomain:9093,host1000.mydomain:9094,host1001.mydomain:9095,host1002.mydomain:9096 --initial-message-id 1000 --messages 500 --topic test_1 --threads 5 --compression-codec 0 --message-size 500 --request-num-acks 1   >> /kafka_pst_wip/system_test/replication_testsuite/testcase_0002/logs/producer_performance-7/producer_performance.log  & echo pid:$! > /kafka_pst_wip/system_test/replication_testsuite/testcase_0002/logs/producer_performance-7/entity_7_pid'] (kafka_system_test_utils)

        Activity

        Hide
        Jay Kreps added a comment -

        I don't think this is a bug and is in any way fixed in the new producer.

        Show
        Jay Kreps added a comment - I don't think this is a bug and is in any way fixed in the new producer.

          People

          • Assignee:
            Unassigned
            Reporter:
            John Fung
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development