[jboss-jira] [JBoss JIRA] Commented: (JBCACHE-1301) Checking debug level can improve performance under heavy load

[Adrian Brock (JIRA)]

    [ http://jira.jboss.com/jira/browse/JBCACHE-1301?page=comments#action_12400965 ] 
            
Adrian Brock commented on JBCACHE-1301:
---------------------------------------

NOT DOING HIGH VOLUME LOGGING AT DEBUG LEVEL also improves performance ;-)

isDebugEnabled() should be redundant. The amount of logging at DEBUG should be minimal
(deployment time and accompanying resource intensive operations like opening channels in cache's case).

While you are at it move those useless INFO logs (a sysadmin has no idea what it means and it just
obscures other useful information) to DEBUG.

The example above also shows two or three common logging mistakes:

* This is redundant use of isXEnabled() since there is not StringBuffer construction in the log statement.
if (log.isDebugEnabled()) log.debug("children all initialized");

* It is also useless since there is no context (whose children? :-)

* Logging inside a synchronized block should be reduced to a minimum to avoid contention.
Think about it, it is accessing the disk inside a synchronized block!

> Checking debug level can improve performance under heavy load
> -------------------------------------------------------------
>
>                 Key: JBCACHE-1301
>                 URL: http://jira.jboss.com/jira/browse/JBCACHE-1301
>             Project: JBoss Cache
>          Issue Type: Quality Risk
>      Security Level: Public(Everyone can see) 
>    Affects Versions: 1.4.1.SP8
>         Environment: Any
>            Reporter: Martin Landua
>         Assigned To: Manik Surtani
>
> In the source file ActivationInterceptor.java we experienced severe performance downgrade due to the fact that the debug level is not being checked. The two log statements in lines 152 and 156 result in a call to toString() for the DataNode object. Worst case this can create a huge string which is obsolete if debug is turned off in log4j. Since this occurs in a synchronized block, performance slows down in a multithreaded environment.
> Please consider the following change (checking for debug level):
>       synchronized(this) {
>          if (fqn != null && nodeRemoved)
>             // If the node is being removed, just remove it and don't perform
>             // activation processing
>             loader.remove(fqn);
>          else if (fqn != null && cache.exists(fqn) && loader.exists(fqn)) {
>             // Remove the node from the cache loader if it exists in memory,
>             // its attributes have been initialized, its children have been loaded,
>             // AND it was found in the cache loader (nodeLoaded = true). 
>             // Then notify the listeners that the node has been activated.
>             DataNode n = getNode(fqn); // don't load
>             // node not null and attributes have been loaded?
>             if (n != null && !n.containsKey(TreeCache.UNINITIALIZED)) {
>                if (n.hasChildren()) {
>                   if (allInitialized(n)) {
>                 	  if (log.isDebugEnabled()) log.debug("children all initialized");
>                      remove(fqn);
>                   }
>                } else if (loaderNoChildren(fqn)) {
>                   if (log.isDebugEnabled()) log.debug("no children " + n);
>                   remove(fqn);
>                }
>             }
>          }

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira