Tuning the JBoss AS Part 4

Logging for performance

In JBoss AS log4j is used as framework for logging. If you are not familiar with the log4j package and would like to use it in your applications, you can read more about it at the Jakarta website (http://jakarta.apache.org/log4j/).

Logging is controlled from a central conf/jboss-log4j.xml file. This file defines a set of appenders specifying the log files, what categories of messages should go there, the message format, and the level of filtering. By default, JBoss AS produces output to two appenders: the Console and a log File (located in <server>/log/ server.log).

There are six basic log levels used: TRACE, DEBUG, INFO, WARN, ERROR, and FATAL. The logging threshold on the console is INFO, that means that you will see informational messages, warning messages, and error messages on the console but not general debug and trace messages. In contrast, there is no threshold set for the server.log file, so all generated logging messages will be logged there.

Choosing the best logging strategy

Logging information is an indispensable activity both in development and in production. However you should choose carefully what information is needed for debugging (development phase) and what information is needed for routine maintenance (production phase). Decide carefully about where to log information and about the formatting of the log messages so that the information can be processed and analyzed in the future by other applications.

Avoid logging unnecessary information. This will convolute the logging trace and affects badly the performance of your application. As a matter of fact, if you don’t define any specific category for your classes, they will inherit the default logging level of JBoss AS, which is set to INFO. You should, as a general rule, stick to a higher level of logging for your classes, like WARN, for example.

If you don’t want to modify the default logging level on the log4j file, you can pass the -Djboss.server.log.threshold parameter while starting the server. For example:

./run.sh -Djboss.server.log.threshold=WARN

In the following sections, we will uncover what are the best practices for logging your data with the minimum overhead for your application performance.

Which is the fastest appender?

As we said, JBoss AS defines two appenders for logging its activities: the Console appender and the File appender. The Console appender prints log information on the application server console. The File appender writes a log file which rotates every day or when it reaches a fixed size.

One of the biggest mistakes you could make is to roll your application in production with the server logs running on the console terminal. As a matter of fact, printing text to screen involves a lot of work for the OS in drawing the letters, scrolling, and a large amount of Java-native transitions which happen on every line break or flush.

Furthermore, on Windows OS, writing to the console is a blocking unbuffered operation, so writing lots of data to the console slows down (or blocks) your application.

The following Jmeter aggregate report documents the different throughput for a Servlet logging an 80 characters long text, on a test repeated 1000 times. The first test was executed against the Console appender, and the second with the File appender:

As you can see, the throughput is more than double when the File appender is used. So as a golden rule, disable Console logging in production and use only the File appender for better logging performance.

You can further tune your File appender by setting the immediateFlush attribute to false:

By default, the File appender performs a flush operation after writing each event, ensuring that the message is immediately written to disk. Setting the ImmediateFlush option to false can drastically reduce I/O activity since the Output-StreamWriter will buffer logs in memory before writing them to disk.

The performance gain is particularly important for shorter messages where throughput gains are in the range of 100% or even more. For longer messages it can account for somewhat less, and range between 40% and 60%.

This is the same test executed with the option ImmediateFlush set to false:

Another performance gain can be achieved by enabling the Bufferedio option. If set to true, the File will be kept open and the resulting Writer wrapped around a BufferedWriter. This leads to an increase in performance by an additional 10% to 40% compared to only disk I/O buffering (lmmediateFlush=false). The following image shows evidence of it, with a new throughput record for our Servlet:

Performance of Bufferedio anyway varies somewhat depending on the host machine, and can be significantly higher on systems which are heavily I/O loaded.

Should I use the AsyncAppender to improve my log throughput?

The AsyncAppender can be used to log events asynchronously.

Behind the scenes, this appender uses a bounded queue to store events. Every time a log is emitted, the AsyncAppender.append() method immediately returns after placing events in the bounded queue. An internal thread called the Dispatcher thread serves the events accumulated in the bounded queue

The AsyncAppender is included (but commented by default) in JBoss’s log4j configuration. When you include it in your configuration, you should take care that the appender references any other appender. As a matter of fact, the AsyncAppender is a composite appender, which attaches to other appenders to produce asynchronous logging events. Here’s an example of how to configure asynchronous logging for your File appender:

Many developers wrongly believe that AsyncAppender is the fastest appender. This is true only in certain circumstances. The AsyncAppender does not improve logging throughput. On the contrary, a non-negligible number of CPU cycles is spent managing the bounded queue and synchronizing the dispatcher thread with various client threads.

Thus logging each event will take a little longer to complete, appending those events will hopefully take place at times where other threads are idle either waiting for new input to process or blocked on I/O intensive operations. In short, if you are running I/O bound applications, then you will benefit from asynchronous logging. On the contrary, CPU bound applications will not.

The following image documents how our optimized File appender throughput is reduced significantly when used in conjunction with AsyncAppender:

You can try to increase the default BufferSize option (which is 128) so that you can raise the maximum number of logging events that can be buffered in the internal queue.

However, as we said, AsyncAppender does not always increase performance. Do not include it blindly in your code, but just after a benchmark. If you don’t want to experiment too much with your configuration, our advice is to stay with the plain File appender, which is a safe bet.

Which layout should I choose for my logs?

The JBoss AS log configuration by default includes the PatternLayout for formatting log messages. PatternLayout provides a flexible layout configurable, which is encoded by means of a pattern string.

For example, the File appender uses the following layout pattern:

This means that the current format date is first printed (%d), then the priority of the logging event should be left justified to a width of five characters (%-5p). The %c string is used to output the category of the logging event. Finally the %m identifier outputs the application-supplied message with the carriage return (%n).

You should choose carefully the identifiers which are fed to the layout pattern. For example, the default File appender pattern formats the date (%d) using the ISO8601 standard, thus relying on the pattern string of the java.text. simpleDateFormat. Although part of the standard JDK, the performance of SimpleDateFormat is quite poor.

For better results it is recommended to use the log4j date formatters. These can be specified using one of these strings: absolute, date.

For example, with a few characters changes:

You can get an astonishing 10% performance boost, as shown by the following picture:

Besides the date pattern, other conversion characters that can badly influence your performance are as follows:

• c: Generates the caller class information. Slow.

• l: Used to output the line number from where the logging request was issued. Slow.

• m: Used to output the method name where the logging request was issued. Very slow.

• f: Used to output the file name where the logging request was issued. Very slow.

Is it enough to increase the log threshold to get rid of log charge?

The short answer is: it depends. When logging is turned off entirely or for a level below the threshold, the cost of a log request consists of a method invocation plus an integer comparison. On the same test hardware (Pentium 4 Dual Core 2.80 Ghz) this cost is typically in the 5 to 50 nanosecond range.

However, any logging instruction might involve the "hidden" cost of parameter construction. For example, for some logger writing:

This incurs in the cost of constructing the message parameter, that is, converting both integer i and entry[i] to a string, and concatenating intermediate strings, regardless of whether the message will be logged or not.

The cost of parameter construction can be quite high and depends on the size of the parameters involved. So, as a rule of thumb, avoid using parameter construction within the logging request.

If you want to get rid of any logging penalty, you should wrap the call to the logger, for example:

You could conveniently set the debug variable to false in production. Some compilers will not even add the logger call to the class’s byte code, because it is guaranteed never to occur.

How does logging hierarchy influence performance?

When deciding your logging strategy, consider that in log4j the loggers are organized in a parent-child relationship. For example, a logger named com is the parent logger of the child logger com.sample.

In the logger hierarchy, the child logger inherits the properties and the logger components from its immediate parent. In short, this means that all the logging events captured by the child logger com.sample will be processed by the child logger itself and also by its parent logger com.

In log4j, by setting the additivity of the logger to false, you can circumvent ancestor loggers, thus improving the performance significantly.

This can be done by configuring the attribute additivity on the logger:

Or programmatically with the method: logger.setAdditivity(false);

So, by setting the additivity to false for the logger com.sample, it will not be necessary for the logger to traverse the unused com logger but it will be directly linked to the root category, thereby increasing the performance significantly.

Summary

In this topic, we have covered the basic structure of the application server and some of the core services like the thread pool, the connection pool, and the logging system. The basic rules of thumb we have learnt can be resumed as follows:

• The new release 5.x of the application server is the state-of-art as it concerns modular and extensible services. The system requirements for this release are higher than with 4.x. In order to get the most from this release you can conveniently remove the services not used by your applications.

• You can cut down by nearly 50% the application server basic requirements by removing the admin_console, the scheduler service, EJB2 support, the Hypersonic DB, and a set of minor services.

• JBoss AS generally dispatches its services by means of a pool of resources.

• The System thread pool is used to serve JNDI clients and can be configured by means of <server>/conf/jboss-service.xml. The default settings are usually good for most applications.

• The connection pool is used to cache database connections in order to avoid the burden of opening and closing new connections.

° In order to find the optimal minimum and maximum pool size you should check the Max Connections In Use Count attribute of your Managed Connection Pool after a consistent benchmark. Allow 15-20% additional resources to keep a safety margin.

° The PreparedStatement cache is a performance booster as it allows sharing Statements across requests. An excessive sized cache can anyway exhaust the amount of available db cursors.

° Detect database leaks in the development stage by means of the CachedConnectionManager Mbean and <track-statements> element in your DataSource configuration.

• The JBoss AS default logging framework is log4j. Choose carefully the amount of information which needs to be logged. Limit your logging just to warning and error messages in production.

° Appending your logs on a File usually has the best throughput. Setting the parameter ImmediateFlush = false and BufferedIO = true generally results in much better performance.

° Asynchronous appender does not always provide the best performance, especially for CPU bound applications. You can try it for applications with high I/O demands.

° Choose carefully the layout of your logs. Stay away from c, l, M, and F character conversions. Replace the default date (%d ) with the log4j pattern (%d{ABsoLUTE}).

° Wrap your logging statements with a conditional statement if the message is built with string manipulation arguments.

° Always set the additivity to false in your loggers if you don’t need to inherit any attribute from parent loggers, besides the root logger.