Using Groovy MOP and Closure to prevent expression evaluation in logger.debug()
Generally in our code, we have lots of debug statements that prints the intricate details of the state of the program. Infact, the debug statements are meant for doing this. Sometimes, these debug statements may contain a call to some other method to evaluate what is to be logged.
[java]
//Logging statement calling some function to get what is to be logged
logger.debug myVeryBigFunc()
def myVeryBigFunc()
{
//Do something big…
// Take lot of time and resources
//
return “SUCCESSFUL IN THE BIG TASK”
}
[/java]
If the logger level is set to DEBUG. The above code would log "SUCCESSFUL IN THE BIG TASK“.
Once our application graduates to production we might not really care to see those debug statements. We just need to see something of priority WARN or higher. We would set logger level to WARN. Now, the above code would not print anything. But, still it will execute the myVeryBigFunc() in order to pass the result as an argument to logger.debug().
The decision to log the message or not is taken inside the logger.debug() method only after getting its arguments. This is clearly an overhead to evaluate the arguments which are to be ignored later.
Can we really do something to avoid this???
In old java days, we used to fix this by using logger.isDebugEnabled() method.
[java]
if(logger.isDebugEnabled())
{
logger.debug myVeryBigFunc()
}
[/java]
Now, the myVeryBigFunc() would not be called at all because our ‘if’ statement is making sure that logger.debug() is called only when the logging level is atleast DEBUG. This seems to be a pretty cool fix at the moment. But this becomes very dirty as the log statements increase.
So, how can we achieve this without being at the risk of looking dirty.
The solution is with the Closure and MOP feature of Groovy which enables us to create an overloaded function for debug which takes a Closure as an argument. This Closure is evaluated only after checking for logging level.
The following piece of code does just the same.
We have overloaded the Logger’s debug(), info(), error(),warn() and fatal() methods to accept Closure as an argument.
In the overloaded versions we first check for logging levels and if the logging level permits the current method to log, only then the closure is evaluated.
[java]
class Log4jEnhancerMOP
{
static void addClosureOverloadsToLoggerDynamically()
{
[‘debug’, ‘info’, ‘warn’, ‘error’, ‘fatal’].each{ logLevel ->
println "Defining metaclass method for logging level $logLevel"
Logger.metaClass."${logLevel}" = {Closure clos ->
if (delegate.invokeMethod("isEnabledFor", Level."${logLevel.toUpperCase()}"))
{
println "logging is enabled for $logLevel"
delegate.invokeMethod("$logLevel", clos.call())
}
else
{
println "logging is not enabled for $logLevel"
}
}
}
}
public static void main(String[] args)
{
addClosureOverloadsToLoggerDynamically()
Logger logger = Logger.getRootLogger()
//setting the logger level to WARN
logger.level = Level.WARN
logger.addAppender(new ConsoleAppender(new PatternLayout("%-5p [%t]: %m%n ")))
//calling the regular debug() method myVeryBigFunc() would get called even if the logger level is set to WARN
logger.debug(myVeryBigFunc("DEBUG MESSAGE"))
//calling the overloaded debug() method. myVeryBigFunc() would not be called as is present in a closure. The closure
//is executed by the overloaded method only if the logger level has debug enabled.
logger.debug {myVeryBigFunc("DEBUG MESSAGE")}
logger.error {myVeryBigFunc("ERROR MESSAGE")}
logger.fatal {myVeryBigFunc("FATAL MESSAGE")}
logger.info {myVeryBigFunc("INFO MESSAGE")}
}
static String myVeryBigFunc(String msg)
{
println "invoked myVeryBigFunc… $msg"
return ‘SUCCESSFUL IN THE BIG TASK’
}
}
[/java]
Hope this helps!!!
Any suggestions or corrections are most welcome.
Thanks & Regards
Mohd Farid
Intelligrape Software
Looks like an elegant solution but keep in mind that every closure is implemented with an anonymous inner class. If like you say you have tons of these debug statements then you may run into trouble with your permgen.