[jira] [Updated] (ZOOKEEPER-1767) DEBUG log statements use SLF4j {} format to improve performance

["Patrick Hunt (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/ZOOKEEPER-1767?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Patrick Hunt updated ZOOKEEPER-1767:
------------------------------------

    Assignee: Jackie Chang

> DEBUG log statements use SLF4j {} format to improve performance
> ---------------------------------------------------------------
>
>                 Key: ZOOKEEPER-1767
>                 URL: https://issues.apache.org/jira/browse/ZOOKEEPER-1767
>             Project: ZooKeeper
>          Issue Type: Improvement
>    Affects Versions: 3.4.5
>            Reporter: Jackie Chang
>            Assignee: Jackie Chang
>            Priority: Minor
>         Attachments: ZOOKEEPER-1767-correct-indents.patch, ZOOKEEPER-1767-slf4j.patch
>
>
> As a coordination service, ZooKeeper is meant to be high performant. DEBUG logs are not normally viewed (see Doug Cutting's comment in HADOOP-953). I propose to add a conditional check to each DEBUG log stmt to improve performance. 
> Firstly, previous issues added a condition check before a DEBUG log stmt. For example, in ZOOKEEPER-558:
> {code}
> - LOG.debug("Got notification sessionid:0x" 
> - 	+ Long.toHexString(sessionId)); 
> + if (LOG.isDebugEnabled()) { 
> + 	LOG.debug("Got notification sessionid:0x" + 
> + 	Long.toHexString(sessionId)); 
> + }
> {code} 
> And in ZOOKEEPER-259:
> {code}
> -                LOG
> -                    .debug("Got ping sessionid:0x"
> -                    + Long.toHexString(sessionId));
> +                if (LOG.isDebugEnabled()) {
> +                    LOG.debug("Got ping response for sessionid:0x"
> +                            + Long.toHexString(sessionId)
> +                            + " after " 
> +                            + ((System.nanoTime() - lastPingSentNs) / 1000000)
> +                            + "ms");
> +                }
> {code}
> Secondly, its underlying cause is that: 
> * *If a DEBUG log stmt is unguarded, the string operations (most likely concatenations) are actually conducted even though the log event doesn't happen b/c a level less verbose than DEBUG is configured.*
> * Adding the conditional check creates another basic block in Java bytecode. And instructions inside that basicblock is executed only when execution path goes into it. But this only happens when the path passes the test. Detailed explanations are in a StackOverflow thread: http://stackoverflow.com/questions/10428447/log-debug-enabled-check-in-java
> An alternative solution is to move from log4j to slf4j and use the "{}" format. A workaround now is to add all conditional checks. The additional overhead is marginal (possibly compare-and-jump instruction(s) in Java bytecode) compared to saved computation of expensive string creations and concatenations.  
> Its counterpart in Hadoop has been accepted: HADOOP-6884.



--
This message was sent by Atlassian JIRA
(v6.1#6144)