Profiling Just Got Easier With Perf4j
When you start to think about profiling Java applications, many tools come to mind - but did you think profiling could be as easy as adding logging statements? This is the goal of the Perf4j project:
Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()
With this goal in mind, Perf4J provides an impressive feature list of:
- 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.
- A @Profiled annotation and a set of custom aspects that allow unobstrusive timing statements when coupled with an AOP framework such as AspectJ or Spring AOP.
- An extensible architecture.
InfoQ caught up with Alex Devine, a project lead on the Perf4j project, who explained how Perf4j came about:
Realizing that the problem of performance tracking and management would affect pretty much every project at our company (and, indeed, almost all server-based, distributed applications), we decided to build and productize a standard performance library, which eventually became Perf4J.
"Are there any particularly tricky performance issues that Perf4j can help solve":
Perf4J is especially well-suited for tracking down performance problems in widely distributed services-oriented applications. For example, at Homeaway a single hit on one of our search pages results in a call to the front end webserver, which makes database calls in addition to calling the search service and an ad server over HTTP. And the search service itself aggregates results from several search nodes. If performance degrades in a live production environment, it is much easier to quickly pinpoint the component at fault using Perf4j.
This lead to the next question of "can Perf4j be used in a production environment?"
Perf4J is definitely designed to be used in production environments. Indeed, often times everything looks great in staging only to crater miserably in production; having monitoring turned BEFORE a big performance hit is often crucial to tracking down the problem.
For performance overhead, Alex added:
The overhead is similar to logging, as starting and stopping a StopWatch essentially breaks down to the same thing you would do if you called System.currentTimeMillis() before and after the code to be timed and then logged it. Thus, similar to logging, the overhead ultimately depends on the appenders you have attached. The design of the AsyncCoalescingStatisticsAppender is that it just pushes the log message on a queue that is drained by downstread appenders in a separate thread, so when those downstream appenders end up doing a lot of work it won't affect the execution time of the main thread. In addition, if you are using the @Profiled annotation with load-time weaving, you can determine which methods you want to be profiled at runtime, in which case there is absolutely zero overhead for the methods that you do NOT profile.
And for what's coming next:
We want to enable runtime profiling even if the code to be profiled has no StopWatches or @Profiled annotations. That is, I want to enable developers to specify particular methods to be profiled in an aop.xml file or in a Spring application config. This would allow you, for example, to profile third party libraries that had no knowledge of Perf4J, and it completely removes all profiling statements from the source code.
Perf4j can be downloaded from http://perf4j.org.
I don't know
Erik van Oosten
Copied from my blog:
I find Perf4J a bit weird as it uses Log4j as measurement distribution framework. This brings two important disadvantages. Firstly, performance wise I don’t think it will ever be able to compete with Jamon or Simon. Secondly it ties you in with Log4j. Log4j is fine but it is showing its age.
Secondly Perf4j focuses on logging measurements. This is IMHO not suitable for production environments where you easily have hundreds of monitoring points all continuously collecting data. Putting that data in a log file is a sure way to make it inaccessible. A regular database is much more suitable.
Re: I don't know
Thanks for taking a look at Perf4J. Let me clear up some misconceptions. First, Perf4J absolutely does NOT tie you in with log4j. In fact, in addition to log4j, right now Perf4J comes with StopWatch and TimingAspect implementations for java.util.logging, Jakarta Commons Logging, and SLF4J. Currently, yes, Perf4J only has custom log4j appenders (which add a lot of useful functionality), but more fully supporting other logging frameworks is definitely on my roadmap. In fact, a major reason we open sourced Perf4J is to hopefully build a community where developers of other logging frameworks would be interested in porting some of the custom appenders/handlers to those frameworks.
On your second point, which is a more common misconception, is that LOGGING DOES NOT MEAN LOG FILES! One of the biggest architectural benefits of log4j and all the other logging frameworks is that they separate the act of making a log statement from what you DO with that statement - file appenders are just one option. Perf4J takes advantage of this separation. For example, here at Homeaway, we DON'T append performance data to log files in all our apps. Instead, we expose our performance data as a JMX MBean using the JMX appender that comes with Perf4J, and then our IT group uses their standard tools (nagios and cacti) to monitor those MBeans. If you look at the "What's Next" section on the Perf4J homepage you'll see the first bullet point is to add a JDBC appender to save this performance info to a database. I want to emphasize that one big benefit of Perf4J is that, similar to logging frameworks, as we create new appenders client code will be able to take advantage of this functionality with NO code changes; the appenders can be added as desired in the config.
Finally, with respect to performance, if Perf4J is having a measurable impact with respect to application speed, you are using it wrong. Yes, you shouldn't be creating StopWatches in a tight loop, but this isn't what it's designed for. That is, the types of operations that you are going to want to profile in an enterprise app (like remote calls, DB operations, disk IO, heavy computational operations) all take many orders of magnitude more time than starting and stopping a StopWatch and sending it to a logger. And again, be careful not to confuse the time it takes to send something to a logger (which is mainly dependent on the appenders in use, many of which only do operations in memory or do things asynchronously) with the time it takes to write to a log file.
Re: I don't know
Erik van Oosten
As I understand from your reply a perf4j user is not tied to log4j, but a logging framework is needed nonetheless.
I am afraid I have used logging frameworks only for, eh.. logging. It seems unnatural to use them for other kinds of tasks. But that could of course also just be narrow mindedness.
Anyway, my main resistance against the idea of using a logging framework comes from my failure to see the advantages that a logging framework brings. Can you shed some light on this aspect?
How to stop making TPS graph
java -jar perf4j-0.9.12.jar --graph perfGraphs.out test.log on command line.
This command makes the file named test.log which shows Execution graph as well as TPS graph i.e. Transaction Per Second. I dont need TPS graph. How this graph can be avoided so that only Execution graph is made.