Thursday, April 1, 2010

Dynamic Java Log Levels with JMX/LoggingMXBean, JConsole, VisualVM, and Groovy

One of the most popular uses of JMX is to change the logging level of an executing Java application that utilizes Java's built-in logging (java.util.logging). This is made possible by the platform MBean server and the built-in LoggingMXBean. As an example of this, consider the simple Java class below.


The Java Application that Logs

FickleLogging.java

package dustin.examples;

import java.util.logging.Logger;
import static java.lang.System.out;

public class FickleLogging
{
private static Logger LOGGER = Logger.getLogger(FickleLogging.class.getCanonicalName());

public static void main(final String[] arguments)
{
for (int i=0; i < 500; i++)
{
try
{
LOGGER.info("Sleep: " + i);
Thread.sleep(5000);
}
catch (InterruptedException threadException)
{
LOGGER.severe("InterruptedException: " + threadException.toString());
}
}
}
}


The simple class above logs every five seconds at the INFO level. Because INFO-level logging is turned on by default, this simple application will log out the increments in each loop. JMX and the LoggingMXBean make it possible to change the logging level dynamically so that these info-level logs do not get written.


Adjusting the Logging Level via JConsole

The name of the logger in the above code is the class name or "dustin.examples.FickleLogging." If I don't realize this or remember it exactly, I can look it up because LoggingMXBean provides a getLoggerNames() method. This is shown in the next screen snapshot with JConsole.



One can click on "Values" field to have it expanded to see the available logger names. The next image shows this expanded view with the name of the logger from this simple application highlighted.



The highlighted logger name can be copied and pasted into the first String parameter field (p0) in JConsole for the setLoggerLevel method and the new level of logging can be placed in the second field (p1). This is demonstrated in the next screen snapshot.



Because the logging level of the regular logging updates in the simple example was at info level, setting the logging level to SEVERE means the logging in the running application stops. It only starts again if we set the logging level to INFO or more detailed level of logging. This is more dramatic in an actually running environment, but the next screen snapshot attempts to capture this by showing how the count in the log statements stops for a while and then starts up again.



The above image reflects the fact that I changed the log level via JConsole to SEVERE after the sixth logged message and then started it logging again by changing the level back to INFO in time for the tenth loop.

See Using JConsole to Monitor Applications for additional details on using JConsole to set the java.util.logging level of a Java application.


Adjusting the Logging Level via VisualVM

VisualVM is another graphical tool one can use to set the logging level of the simple application that I started this post with. Once the MBeans plug-in for VisualVM has been downloaded and installed (all easily done with its wizard), that tab can be used just like JConsole's MBeans tab was used above. The next two screen snapshots show use of the logger names attribute and the setLoggerNames operation. Note the similarities with JConsole.






Adjusting the Logging Level with Groovy Script

JConsole and VisualVM are easy-to-use graphical interfaces for interacting with a Java application's java.util.logging-based logging level. However, there are times when one would prefer to change the log level of a running application via a command-line script. I demonstrate this next with a Groovy script.

To make the Java application accessible via remote client, I run it with the three system properties com.sun.management.jmxremote.port, com.sun.management.jmxremote.authenticate=false, and
com.sun.management.jmxremote.ssl. These are set as shown in the next screen snapshot.



You may notice in the image above that there is a skipped output between 8 and 12 in the count. This is thanks to the running of a simple Groovy script that uses JMX and is shown next.


#!/usr/bin/env groovy
//
// setLogLevel.groovy
//
// This script allows one to control the logging level of a Java application
// using java.util.logging that exposes its LoggingMXBean for management.
// Java applications using java.util.Logging may provide easily controlled logging
// levels even from remote clients.
//
if (!args)
{
println "Usage: setLogLevel loggerName logLevel host port"
System.exit(-1)
}
import javax.management.JMX
import javax.management.ObjectName
import javax.management.remote.JMXConnectorFactory
import javax.management.remote.JMXServiceURL
import java.util.logging.LoggingMXBean
import java.util.logging.LogManager

def serverUrl = "service:jmx:rmi:///jndi/rmi://${args[2]}:${args[3]}/jmxrmi"
def server = JMXConnectorFactory.connect(new JMXServiceURL(serverUrl)).MBeanServerConnection
def mbeanName = new ObjectName(LogManager.LOGGING_MXBEAN_NAME)
LoggingMXBean mxbeanProxy =
JMX.newMXBeanProxy(server, mbeanName, LoggingMXBean.class);
mxbeanProxy.setLoggerLevel(args[0], args[1].toUpperCase())


I could have made this script more sophisticated with Groovy's built-in CLI support, but I use simply command-line args support here. The four necessary arguments after the script name are the Logger's name ("dustin.examples.FickleLogging"), the logging level to change to (such as SEVERE or INFO), the host of the application that's doing the logging ("localhost"), and the port via which JMX remote management is enabled (9999).

With the proper parameters passed to it, this Groovy script connects to the application started with remote JMX exposure and is able to adjust that application's logging level. More elaborate and sophisticated scripts could be written that could make it just a few keystrokes for a developer to quickly change the logging level of software as necessary.


Conclusion

Selecting the appropriate level of logging can be difficult both in terms of setting the level at which individual messages should be logged and in terms of what level of messages should actually be written out. The ability to adjust the level of logs that are written dynamically provides developers with more options in using logging for debugging and other purposes. In this post, I have attempted to demonstrate how easy it is to adjust the level at which logged messages are written by a particular Java application that logs with the built-in Java logging facilities. I have also demonstrated doing this with JConsole, VisualVM, and a Groovy script.

2 comments:

Anil Samuel said...

Good stuff and thanks.
Is there anyway to change the logLvel of handlers such as ConsoleHandler ?

Dustin said...

Anil,

I don't think you can do this via the standard-provided LoggingMXBean, but you could expose your ConsoleHandler via your own MBeans or MXBeans.