Kafka
  1. Kafka
  2. KAFKA-1115

producer performance affected by trace/debug calls

    Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Incomplete
    • Affects Version/s: 0.8.0
    • Fix Version/s: None
    • Component/s: producer
    • Labels:
      None

      Description

      After investigating high CPU usage on some producers in production, we found out that a lot of time was passed in string construction for logging of DEBUG and TRACE level.

      This patch removes most of the logging calls, on our systems it cuts CPU usage down to half of what it used to be.

      Note that this is a significant boost in performance for environment where there are thousands of msg/s.

      1. producer-performance-fix.patch
        12 kB
        Francois Saint-Jacques

        Activity

        Joel Koshy made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Incomplete [ 4 ]
        Hide
        Joel Koshy added a comment -

        So this is a non-issue right? Please re-open if you have any other concerns.

        A lot of the trace/debug messages are often extremely important for live debugging. i.e., we set the level to debug/trace to avoid log flooding but when we do need to trouble-shoot a production issue we can enable those messages using the JMX operations exposed by kafka.utils.Log4jController

        However if you see any log statements that can be improved/cleaned-up please let us know.

        Show
        Joel Koshy added a comment - So this is a non-issue right? Please re-open if you have any other concerns. A lot of the trace/debug messages are often extremely important for live debugging. i.e., we set the level to debug/trace to avoid log flooding but when we do need to trouble-shoot a production issue we can enable those messages using the JMX operations exposed by kafka.utils.Log4jController However if you see any log statements that can be improved/cleaned-up please let us know.
        Hide
        Francois Saint-Jacques added a comment -

        You are right, and by looking at the code the trace/debug logging functions are defined with lazy arguments.

        By debugging a bit further, I did not have any log4.properties in the producer classpath. The library does give me a WARN about missing log4.properties file. After this warning message, the program does not output any more log. Internally I'd assume the logging still we're set to TRACE without any appender to stdout/stderr.

        I'll take WARN more seriously next time. Maybe a put message in the producer documentation that not providing log4j configuration will have a serious impact on performance.

        On another note, I believe trace/debug message shouldn't be committed to production code, but this is only a personal hunch.

        Show
        Francois Saint-Jacques added a comment - You are right, and by looking at the code the trace/debug logging functions are defined with lazy arguments. By debugging a bit further, I did not have any log4.properties in the producer classpath. The library does give me a WARN about missing log4.properties file. After this warning message, the program does not output any more log. Internally I'd assume the logging still we're set to TRACE without any appender to stdout/stderr. I'll take WARN more seriously next time. Maybe a put message in the producer documentation that not providing log4j configuration will have a serious impact on performance. On another note, I believe trace/debug message shouldn't be committed to production code, but this is only a personal hunch.
        Hide
        Jun Rao added a comment -

        Thanks for the patch. Are you sure that scala doesn't do lazy evaluation? I did the following test. It seems that it does?

        scala> import java.util.concurrent.atomic.AtomicInteger
        import java.util.concurrent.atomic.AtomicInteger

        scala> val c = new AtomicInteger(1)
        c: java.util.concurrent.atomic.AtomicInteger = 1

        scala> def a(msg: => String, isRun: Boolean)

        { if (isRun) println(msg) }

        a: (msg: => String,isRun: Boolean)Unit

        scala> a("test %d".format(c.incrementAndGet), false)

        scala> c
        res3: java.util.concurrent.atomic.AtomicInteger = 1

        Show
        Jun Rao added a comment - Thanks for the patch. Are you sure that scala doesn't do lazy evaluation? I did the following test. It seems that it does? scala> import java.util.concurrent.atomic.AtomicInteger import java.util.concurrent.atomic.AtomicInteger scala> val c = new AtomicInteger(1) c: java.util.concurrent.atomic.AtomicInteger = 1 scala> def a(msg: => String, isRun: Boolean) { if (isRun) println(msg) } a: (msg: => String,isRun: Boolean)Unit scala> a("test %d".format(c.incrementAndGet), false) scala> c res3: java.util.concurrent.atomic.AtomicInteger = 1
        Hide
        Guozhang Wang added a comment -

        Ah got it. Good point.

        Show
        Guozhang Wang added a comment - Ah got it. Good point.
        Hide
        Francois Saint-Jacques added a comment -

        This is not the problem. Even if I change the log level, the construction of the string passed to the logging subsystem is the root cause, i.e. all calls of the form "Message %s is... ".format(...) . Scala is not a lazy evaluation language, the only ways to fix this problem are:

        1. Wrap all the trace/debug calls with if (logging.debugEnabled()...) so that it doesn't get evaluated. This is the lazy way.

        or

        2. Remove any debug/trace calls in this critical code path. This is clearly the remnant of `print foo' debugging, it shouldn't be committed to the trunk branch.

        Show
        Francois Saint-Jacques added a comment - This is not the problem. Even if I change the log level, the construction of the string passed to the logging subsystem is the root cause, i.e. all calls of the form "Message %s is... ".format(...) . Scala is not a lazy evaluation language, the only ways to fix this problem are: 1. Wrap all the trace/debug calls with if (logging.debugEnabled()...) so that it doesn't get evaluated. This is the lazy way. or 2. Remove any debug/trace calls in this critical code path. This is clearly the remnant of `print foo' debugging, it shouldn't be committed to the trunk branch.
        Hide
        Guozhang Wang added a comment -

        Hi Francois,

        You can change the logging level in config/log4j.properties to avoid printing DEBUG and TRACE level log entries.

        Show
        Guozhang Wang added a comment - Hi Francois, You can change the logging level in config/log4j.properties to avoid printing DEBUG and TRACE level log entries.
        Francois Saint-Jacques made changes -
        Status Patch Available [ 10002 ] Open [ 1 ]
        Francois Saint-Jacques made changes -
        Attachment producer-performance-fix.patch [ 12611695 ]
        Francois Saint-Jacques made changes -
        Field Original Value New Value
        Status Open [ 1 ] Patch Available [ 10002 ]
        Francois Saint-Jacques created issue -

          People

          • Assignee:
            Francois Saint-Jacques
            Reporter:
            Francois Saint-Jacques
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development