Simple logging tip

FYI - slf4j helps a bit here. It uses parameter substitution to format log messages for you, and skips the formatting if the message won't be getting output. e.g.:

logger.trace("Adding update to batch: {}", sql);

Of course it doesn't solve the problem completely, and you still need to use the if block from time to time. For example, here I definitely don't want to go through the trouble of calling record.toString() in a tight loop if the message is just going to get thrown away:

if (logger.isTraceEnabled()) { logger.trace("Importing data record: {}", record.toString()); }

DR

It's sort of funny to see the "anti-if campaign" badge on this page.

I am familiar with the logging paradigm you advocate, but every time I see it it leaves me thinking "there has to be a better way than this".

I almost wish that the compiler was smart enough to notice at runtime: "log.trace() always discards its parameters, which means that I don't have to execute any of its arguments in the first place"

Michael, your comment just cracked me up.

It does suggest that Gill is correct in that there must be a better solution. David's solution? var args maybe? Serious overloading of the log methods? The last two are sort of ugly but then performance sometimes (but not always) dictates ugly solutions.

Hi Kirk, We had exactly the same rule, until we switched to the printf style mentioned in the comment :) BTW closures would help here again, to remove the if statement. Regards, Markus

Is it not so obvious that the solution is not to log in the first place and most certainly not to write the actual statement in the code itself.

By the way detecting object creation is not difficult at all. We have counters and meters for this.

We need to replace logging with an Events API with a dynamic but typed event model that can be augmented with complex event processing agents (diagnostics, health checkers, event aggregators) rather than having to do this after the fact and via post processing of strings in a log file. We lose so much execution & environment context with a log string or log record.

At my job I wrote wrappers for Log and LogFactory such that developers can write complex MessageFormat style log statements without performance penalties. It creates an anonymous Object (closure) for each formatted log call with a toString() that creates and runs the MessageFormat. The only space cost if the log level is off is the Object array the developer sends. The big benefit at runtime is avoiding the quadratic order time cost of string concatenation.

If only we had closures we could factor the if-statement away nicely.

>More over object creation involves updating shared structures

Extremely rarely (i.e. if a thread's local heap is exhausted). The above sentence can be misleading if left unquantified. If someone would want to see what would really happen to a multithreaded app if there really was synchronization associated with object creation, then just add a volatile-write in the constructor of java.lang.Object (hint: it wouldn't be pretty).

Dimitris I believe Kirk was referring to the actual object construction (executing code) and not the memory allocation.

Casper can you quantify the actual savings made with a closure (number of keystrokes? bytecode ops executed,....). How does this compare to actually not writing log statements all over the code.

It surely doesn't solve the problem neither, but it allows sparring a function call and makes the code "less unreadable": you can always declare a static variable together with the Logger, like:

• boolean debug = logger.isDebugEnabled();

and use this variable in your code instead:

• if (debug) {

• }

BTW, I like darose's slf4j proposition and will give a try soon!

Dimitris, I won't say that I fully understand what is going on but there is clearly a benefit to reducing object allocation (aside from GC benefits) that goes beyond fast path allocations. It gives me the feeling of some lock contention which is why used implies instead of a more definitive word. Clearly the effect of thread local allocation is significant. Try running with -XX:-UseTLAB and you'll see the difference.

StablioBoss, I'd hate to have that evaluated once and then have someone use JMX to reset the logging level.... ;-). I'm not sure that I like varargs over the more verbose form of method overloading. But then, that is still a win over lo4j or jdk logging.

Kirk

But there are some possibilities to overcome the object creation thing. Look at the logback project of the(or one of them dunno) founder of log4j. There he uses a printf like possibility to parse arguments without parsing the String. Ok it will create an array, because of the varargs and it will execute all you parse to it. But it's one possibility to partly remove the double check if no real execution is taken place.

Couldn't we use some AOP here using aspects to guard the calls with if statements?