Performance Analysis for Enterprise Java Applications

Users come to you and shout "Why Trades page is taking too much time to load?" Now you may say because I call Trade Service so it might be taking time to return the response in timely fashion. You approach developer of the Service and ask - Can you please tell how much time is being taken for getTrades(userId) to return trades from database for XYZ user? Developer will say Yes I can - let me check you in the logs as I have put System.currentTimeMillis(); statements in my code as shown below:

public static List<Trade> getTrades(String userId)
            throws TradeServiceException {
        long start = System.currentTimeMillis();
        // common component across Services 
        authenticate(userId);
        // common component across Services
        authorize(userId);
 
        List<Trade> trades = TradeDao.getTrades(userId);
        long end = System.currentTimeMillis();
        System.out.println("Method took " + ((end - start) / 1000) + " seconds");
        return trades;
 
    }

As you can see in the code snippet that this method relies on external components (common to all services) for actual task. So answering the question "Why Trades page is slow?" requires investigating multiple components and execution paths, and it requires detailed performance data from all of the application components used. It may be due to poor performance of component that perform authorization for user.

The developer here forgot that the total time printed in logs is basically sum of time taken for authentication, authorization and actual database call. So he may change the code to add few more System.currentTimeMillis(); statements around authenticate and authorize methods to come up with the individual timings for each component (He feels happy and relaxed).

Later on, though, architects find they want more information, such as aggregated performance statistics like mean, minimum, maximum, standard deviation and transactions per second over a set time span. They would like graphs of these values in real time to detect problems on a running server, or they would like to expose performance metrics through JMX so that monitors can be set up to alert when performance degrades. In addition, they want their timing statements to work with the common logging frameworks like log4j (so that they can be enabled and disabled at run time).

Can someone save this developer from pain? The answer is YES - It's Perf4J.

"Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()"

Perf4J provides above features and more:

• A simple stop watch mechanism for succinct timing statements.
• A command line tool for parsing log files that generates aggregated statistics and performance graphs.
• Easy integration with the most common logging frameworks and facades: log4j, java.util.logging, Apache Commons Logging and SLF4J.
• Custom log4j appenders to generate statistics and graphs in a running application (custom java.util.logging handlers coming soon).
• The ability to expose performance statistics as JMX attributes, and to send notifications when statistics exceed specified thresholds.
• A servlet for exposing performance graphs in a web application. Note: that Graphs for average execution time and transactions per second are generated as URLs to the Google Chart Server.

Let's change our code to use Per4J configured along with log4j

public static List<Trade> getTrades(String userId)
        throws TradeServiceException {
    StopWatch stopWatch = new Log4JStopWatch();
    stopWatch.start("TradeService.getTrades");
    authenticate(userId);
    authorize(userId);
    List<Trade> trades = TradeDao.getTrades(userId);
    stopWatch.stop("TradeService.getTrades");
    return trades;
 
}

As seen above the code is more clean and maintainable. The logs now will be written to log file (e.g. server.log) automatically as shown below:

INFO  TimingLogger - start[1315017679678] time[1000] tag[getTrades_authenticate]
INFO  TimingLogger - start[1315017680679] time[1001] tag[getTrades_authorize]
INFO  TimingLogger - start[1315017681681] time[2000] tag[getTrades_db]
INFO  TimingLogger - start[1315017679678] time[4003] tag[TradeService.getTrades]
Note: The logs are self explanatory.

The Performance statistics can be obtained as:java -jar perf4j-0.9.13.jar server.log
I hope and wish some of us can adapt Per4J sooner or Later !!!

Thanks - http://www.gognamunish.blogspot.com/