How would you break down and log the execution times of different parts of your application?

Question

We have built a web application that accepts SOAP messages, does some processing, calls out to another web service, massages the response and sendd it back to the original caller.

We'd like to log, in a single line, the different execution times for these different steps. We use log4j with the JBossWS stack. In other words, we'd like the log output to look something like:

2009-06-10T16:19:31.487 3336/2449/861

where 3336ms is the total time spent serving the request, 2449ms is the time spent waiting for the web service's response, and 861ms is the time spent internally massaging the data.

These different computations happen in different places in our code and we cannot just time each one of them and make a call to the logger at the end of a single method. One of us has suggested using log4j's MDC for this as a poor man's set of global variables to track the different executions times.

So my questions are the following:

1. Is this a horrible abuse of the MDC's primary intent?
2. If yes, how would you do this otherwise?

Answer 1

I'd do the following:

1. create a PerformanceTimer class, which exposes:
   • recordWaitedForWebServerReponse(operationId, time);
   • recordMassagedData(operationId, time);
   • other methods, if needed
2. inject that class where it's needed;
3. have the PerformanceTimer maintain a concurrent map of OperationId -> OperationTimingData;
4. on the method call known to be the last, invoke Log4j with the output you desired.

Answer 2

While it would certainly work, I cringe at the thought, too. My suggestion would be to create a timing class just for that purpose which uses ThreadLocal to create a variable per request.

When the request comes in, you create the variable (a long with the start time). When the variable already exists, you leave it alone. When the result gets sent back to the client, you calculate the duration and log that.

Answer 3

I'd use Spring and aspect-oriented programming to do it. The nice thing is that I'd write the logic once and apply it declaratively everywhere I needed it.

Answer 4

Sounds like a job for Perf4J.

Answer 5

One Simple way is to use System.currentTimeMillis() which returns time in milli seconds. The difference between the millisec at the start of the method and the milli seconds at the end of the method will give the milli sec's taken for executing that particular method. Hope System.currentTimeMillis() will help you.

Answer 6

Please have a look at SLF4J profiler. Interestingly enough. tt was developed to answer the exact same need, that is to measure and improve the performance of SOAP calls.

Answer 7

We just use this in our first request filter:

logger.trace("Init");
long start = System.currentTimeMillis();

//do stuff here 

long stop = System.currentTimeMillis();
String time = Util.getTimeDifferenceInSec(start, stop);
logger.trace("Complete in " + time + " sec");