14. Logging and Profiling settings

The library uses Apache Log4j logging library. See http://logging.apache.org/log4j/docs/ for more details how to configure it.

The default logging level for BeanKeeper should be INFO. On this level, no messages should be visible when in use. On DEBUG level, the logging is very verbose, you should not use this level unless you are tracking a bug in the library and want to see everything that happens.

There is however two services, which you may find useful to enable. The first is the profile logging. This is a service, which in given intervals gives different profiling data from the BeanKeeper internals. Useful for tracking memory, or connection pool problems. To enable it, include this in the log4j.properties file:

log4j.logger.hu.netmind.beankeeper.ProfileLogger=DEBUG

This will cause the logger to regularly (5 seconds by default) output a peak of the current profile status. There are multiple possible profile outputs into the log file:

 ...
 [connectionpool:300] Connection used/pool/wrappers: 1/4/4
 ...
 [weakmap:161] Current map sizes: 0,0
 ...
 [sharedmap:22] Shared data size is: 1
 ...

The first one is the status of the connection pool. The number '300' means, the profile logger received this many pool profile data events since the last output. The message contains the status of the pool according to the last event. It indicates, that there are 4 connections available, one is used.

The second and third entries are just internal memory sizes of currently tracked objects. The more objects, the more memory is used. This used memory should always scale back when the garbage collector is run.

The second service which can be useful is the performance logger. This logger works similarly as the profile logger, because this one displays the log messages in regular intervals too. But instead of showing the last event's message, it actually averages the values of the events. To enable this logger, write the following in the log4j.properties file:

log4j.logger.hu.netmind.beankeeper.PerformanceLogger=DEBUG

The following messages will be generated:

 ...
 Update statement execution: 18 times, values: 5-1/59
 ...
 Query statement execution: 20 times, values: 3-1/8
 ...

These lines indicate how many times the specified event occured since the last display of the same event. And it also contains the statistics of the supplied value of the event (which usually is the completion time in milliseconds). The statistics is in the form of: avg-min/max. So the first line says, that there was 18 update statement executions since the last display, and it cost 5 milliseconds on average. There was however at least one that cost 1 millisecond, and one that cost 59 milliseconds.

This document was generated by Robert Brautigam on November, 21 2009 using texi2html 1.78.