Database Reference
In-Depth Information
if (logger.isInfoEnabled())
{
long endTimeMillis = System.currentTimeMillis();
logger.info("Signon(" + username + ") response time " +
(endTimeMillis-beginTimeMillis) + " ms");
}
return ret;
}
Simply put, the instrumentation code, which is highlighted in bold, gets a timestamp when the method begins,
gets a timestamp when the method ends, and then logs a message providing the name of the user and the time
it took to do it. At the beginning, it also checks whether the logger has already been initialized. Notice that the
Log4jLoggingHelper
class is specific to Oracle WebLogic Server, not to log4j. This was used during the test. Even if the
code snippet is straightforward, there are some important points to note:
•
Start measuring the time, in this case by calling the
currentTimeMillis
method, at the very
beginning of the instrumented method. You never know what situations could cause even
simple initialization code to consume time.
•
The logging framework should support different levels of messages. In the case of log4j,
the following levels are available (in increasing order of verbosity):
fatal
,
error
,
warning
,
information
, and
debug
. You set the level by calling one of the following methods:
fatal
,
error
,
warn
,
info
, and
debug
. In other words, each level has its own method. By putting
messages in different levels, you're able to explicitly choose the verbosity of the logging by
enabling or disabling specific levels. This could be useful if you want to enable part of the
instrumentation only while investigating a specific problem.
•
Even if the logging facility is aware of which levels the logging is enabled for, it's better to not
call the logging method, in the example
info
, if the logging for that specific level isn't enabled,
especially to avoid the message construction overhead (and subsequent call to the garbage
collector). It's usually much faster to check whether the logging for a specific level is enabled
by calling a method like
isInfoEnabled
and then call the logging method only if necessary.
That can make a huge difference. For example, on my test server, calling
isInfoEnabled
takes about 7 nanoseconds, while calling
info
and providing the parameters as shown
in the previous code snippet takes about 265 nanoseconds (I used the class defined in
LoggingPerf.java
to measure these statistics). Another technique for reducing the overhead
of instrumentation would be to remove the logging code at compile time. This is, however, not
the preferred technique because it's usually not possible to dynamically recompile the code
in case the instrumentation is needed. Further, as you have just seen, the overhead of a line of
instrumentation that doesn't generate any message is really very small.
•
In this example, the generated message would be something like “Signon(JPS1907) response
time 24 ms.” This is good for a human being, but if, for example, you plan on parsing the
message with another program in order to check a service level agreement, a more structured
form, such as XML or JSON, would be more appropriate.
Database Calls
This section describes how to instrument database calls properly in order to give information to the database engine
about the application context in which they'll be executed. Be aware that this type of instrumentation is very different
from what you saw in the previous section. In fact, not only should database calls be instrumented like any other part
