Uploaded image for project: 'Kafka'
  1. Kafka
  2. KAFKA-5781

Frequent long produce latency periods that result in reduced produce rate.

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Major
    • Resolution: Unresolved
    • 0.11.0.0
    • None
    • core
    • None
    • CentOS Linux release 7.3.1611 , Kernel 3.10, java version "1.8.0_121"

    Description

      When we upgraded from Kafka 0.10,2 to 0.11.0 , I started to see frequent throughput drops with a predictable pattern (attached file shows the pattern in a 14 hour period). This resulted in an a degradation of up to 30% in our overall produce throughput.

      The drops can be correlated to the significant increase in 99th percentile latency (up to 4 seconds). We have a cluster of 6 brokers and a single topic. The problem happens both with/without consumers running so I only included a case without consumers.

      There is no specific message in the broker logs when the latency surge happens. However, I found a correlation between the log rotation messages in the log and the the longer cycles in the pattern (details shown in the attached graph:frequent_latency_increase.png)

      Each increased latency period takes 5 to 20 minutes to finish (shown in the zoomed graph in the attached files).

      The broker cpu utilization goes down during this time and some read disk activity is observed (see attached graph)

      This pattern started to appear in our environment exactly at the time when we switched to kafka 0.11.0. We kept the idempotence as false and didn`t make any configuration change as we switched. So I was wondering if it could be a bug or configuration that needs to be changed after upgrade?

      Attachments

        1. controler.log
          1.36 MB
          Raoufeh Hashemian
        2. frequent_latency_increase_diskactivity.png
          139 kB
          Raoufeh Hashemian
        3. frequent_latency_increase_zoomed.png
          61 kB
          Raoufeh Hashemian
        4. frequent_latency_increase.png
          272 kB
          Raoufeh Hashemian
        5. gc0.log
          4.56 MB
          Raoufeh Hashemian
        6. GC time.png
          21 kB
          Raoufeh Hashemian
        7. produce_delay.png
          57 kB
          Raoufeh Hashemian
        8. server.log
          0.8 kB
          Raoufeh Hashemian
        9. state-change.log.zip
          4.50 MB
          Raoufeh Hashemian

        Activity

          People

            Unassigned Unassigned
            RSH2000 Raoufeh Hashemian
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated: