Useful Eclipse Code Templates

The issue comes in if ${Message} is a build up string, using something like String.format(...) or MessageFormat.format(..), since that will get called before the parameter gets passed to logger.debug(...), thus doing something that might not be necessary to execute if debug logging is not enabled.

And in a lot of applications, every millisecond counts. 

I wrote a decorator for commons Log that allows you to call all its methods as if you were calling MessageFormat.format(). The advantage lies in the implementation which I chose where it actually wraps the message in an Object whose toString() calls MessageFormat.format(). This means that the only overhead of logging to a disabled log level is an Object allocation rather than a complete formatting of a potentially complete MessageFormat.

A call such as decoratedLog.info("Iteration {0} of {1}", 15, 100) calls underlyingLog.info(getMessage("Iteration {0} of {1}", 15, 100)).

Log#getMessage(String, Object...) and Log#info(String, Object...) are implemented as follows:

private static Object message(final String pattern, final Object... arguments)
{
    return new Object()
    {
        public String toString()
        {
            return MessageFormat.format(pattern, arguments);
        }
    };
}

public void info(String pattern, Object... arguments)
{
    log.info(message(pattern, arguments));
}

This allows you to write elegant logging code without worrying about a heavy performance impact. It does mean that you have to decorate LogFactory as well, but that is pretty trivial and only affects the imports of client code. What do you guys think of this approach?

Can someone explain to me why we want to go thru all the fuss to avoid checking logger.isDebugEnabled() before calling debug? Even if that is in fact an unnecessary double check, it should not affect the performance of production because you are supposed to disabled DEBUG in production. So the isDebugEnabled() will be checked only once in production whether it's being checked explicitly using if (logger.isDebugEnabled()) {  } or implictly by the logger internally by examing the log level.

Another fairly useful template for iterating over the entries in a map:

for(Map.Entry<${key:argType(map,0)},${value:argType(map,1)}> entry : ${map:var(java.util.Map)}.entrySet()) {
    ${key} key = entry.getKey();
    ${value} value = entry.getValue();

    ${cursor}
} 

A few qns:

(1) Where are these templates documented?

(2) Is there a repository/web site of useful templates somewhere?

(3) Is there a similar way to create such templates for Ruby in the RDT?

Thanks

Charles

Alain:  You're code would be no benefit to performance, if you do not check for isInfoEnabled before executing message(String, Object...). I think it would slow it down, because the formatting is nice, but expensive. Also The JVM builds an Array for the vararg-argument. If you are interessted in very good performance. You should offer some overloaded methods, with one, two, three, or more arguments, so no Array must be build, especially if the logging is not done.

But it's a very elegant solution. Doesn't offer plain log4j something similar?

BTW: Logging was only a performance issues to me, when really logging heavily for debbuging or when performing costly operations to build up the message, like using commons langs ToStringBuilder.reflectionToString.

Hi Kisito,

 I definitely agree with you. In despite of integrated the logger templates suggested in this post for the needed logger points, like debugging message or  some transaction information, my base method logging information relies in a Logging Advice, configurated with Spring AOP.