Skip to main content

Kirk Pepperdine on Detecting Logging Performance Issues

Posted by editor on September 3, 2009 at 5:56 AM PDT

One of the things that make software engineering a challenging endeavor is the fact that many problems seem to have an almost innate ability to hide themselves from the view of any number of developers. "Why doesn't this work?" or "Why is this so slow?" are questions that have been asked as I have stared at code that I'm working on, or stared at code that another developer has asked me to look at. All seems fine as you gaze through the listing. But, in fact, all is not fine.

Java performance tuning expert Kirk Pepperdine is well aware of difficulty of tracking down performance issues. Yesterday he posted a Simple logging tip that can help developers detect a typically difficult to find performance issue that arises due to object creation.

Included in the list of latest places where I've seen object creation become a hinderance to performance was the Scala compiler and a few applications that have been aggressively logging activity. In the former case the problem was due to frequent resizing of the main symbol table. Hopefully the next version of the Scala compiler will fix that problem. The later case had to do with premature construction of debug messages.

Taking the second case: Kirk is saying that the attempt to provide the operations team (which is often the development team) with a rich set of diagnostic messages can itself cause performance problems. I've seen an example of logging causing problems in my own work at a data center recently. In this case, we have an Oracle database that is at the center of a complex system consisting of more than a dozen multiprocessor servers (mostly Solaris, some Fedora Linux). The interactions with the database at each step of the processing are so numerous that if we don't monitor things closely it's possible for a disk where Oracle outputs its logs to fill up. And we're not even asking Oracle to do an incredible amount of logging. The problem simply arises because so many steps along the processing chain interact with the database, and we need to be able to go to those logs if something goes wrong, because we'd need to manually re-do the processing if something failed along the way, and the Oracle logs are our best view into where in the processing something failed.

That's not a performance issue, per se, but it's an example of logging itself having the potential to create issues within an operational environment.

Kirk goes on to show how a particular, common style of logging can create performance problems:

Most logging looks something like...

log.debug( "Some tag " + variable.toString() + ", " + someMoreInformation);

The problem is that log.debug(String msg) causes all of the stuff in the brackets to be executed. Not only can this coding style create a significant number of object, it is very hard to detect and very time consuming to fix in an application of significant enough size.

He then goes on to provide a "simple trick and certainly not a new one" but one that he considers "worth mentioning again":

In the case of log messages there is an easy solution, wrap each call in an if statement that checks the current log level. If the log message will never get logged, there isn't any point in creating all of those extra objects. The overall improvements may vary but I've never found them to insignificant.

It's a useful technique that improves performance based on the fact that object creation is a relatively heavy task compared with the computational effort to check if the current message is of sufficient importance that it will in fact be output into the log.

In Java Today, Pavel Rozenblioum reviews the new book "Beginning Java EE 6 Platform with GlassFish 3":

Recently I had an opportunity to read Beginning Java EE 6 Platform with Glassfish 3 by Antonio Goncalves. The book has the subtitle "From Novice to Professional" and that's a pretty accurate description of the book. After reading it a person not familiar with Java EE, but familiar with Java SE should feel comfortable developing a small Java EE application...

Paul Ponec announces a "New high performance ORM for Java: Ujorm":

Let me to introduce a new open source ORM framework for Java called Ujorm. I have created the ORM solution especially for a rapid development of persistent layer, however the first performance tests show that some types of SELECT query are very fast in comparison to its competitors. Next features are: the type safe parameters in the query, small memory footprint and the minimum size of the entire solution...

Java Champion Kirk Pepperdine provides a Simple Logging Tip:

Each time I go into a round of preparing for course delivery I try to drop in information about any recurrent problem that I've run into. This time round the recurrent problem is object creation.

Included in the list of latest places where I've seen object creation become a hinderance to performance was the Scala compiler and a few applications that have been aggressively logging activity...

In today's Weblogs, Carla Mott informs us about the Latest functionality in GlassFish v3 logging: "This blog highlights some of the changes that are part of GlassFish v3 logging. Since Prelude I have added 3 asadmin commands related to logging. The new commands are..."

John Ferguson Smart writes about Automated Deployment with Maven - going the whole nine yards : "Last week I gave a talk at the Agile 2009 conference about automating the deployment process with tools such as Maven, Nexus Cargo, Liquibase and Hudson. Here is a brief description of the talk..."

And Ed Burns provides instruction on JSF2 Composite Component Metadata: "This ultra-quick blog entry shows how to use the JSF runtime to access metadata for a composite component. Note that most of the metadata is optional when creating a composite component, therefore, this entry will be of interest to tool vendors and those wishing to write composite components that stand a chance of showing up nicely in tools..."

In the Forums, suneelkumar85 responds Re: Sending/Receiving SMS to SMPPSim: "m also doing same task wat u have done.. modify the code.. here they r using 0020 specific destination address but i want to more destination nmbers then the reply from the G-talk can be go to that mobile numbers.. so..."

suneelkumar85 also continues the conversation in Re: Mobicents Diameter v1.0.1.GA Released!: "Mendon

Related Topics >>