Performance testing is an interesting subject and can be quite subtle. I recommend using a micro-benchmark framework like Caliper or JMH for this, it is very easy to make a mistake and end up measuring something other than what you intended. I've made mistakes myself and I've read people much more experienced than me write about their mistakes.
If you really have to hand-roll your own micro-benchmark test, here are a few rules of thumb: * run an empty test to create a baseline (and just to make this extra fun, the JVM will optimize away a loop when it can prove that the loop doesn't do anything, so you need to return a result. Do something fast like binary XOR or something in the loop, and keep that operation when adding the real test back in.) * The JVM starts inlining and compiling methods to native code after 40,000 calls by default (-XX:CompileThreshold=.). Assuming that the code you want to test is hot enough that it is worthwhile optimizing, you will want to measure *after* compilation to native code. * So you need to warm up the JVM. Note that the JVM actually also doesn't start many hotspot optimizations until some time has passed since startup, so your warmup should take at least 10 seconds. * How to warm up: essentially you want to run the same test but throw away the measurement results. If your test calls a method 10,000 times, then execute your test at least 4 times (maybe go for 10 times _and_ at least 10 seconds passed since startup). I have been told by people in the JVM know that this is better than having just one loop with 40,000 iterations. Looking at your test in particular (testPerformanceOfAppenderWith10000Events/...UsingBasicEntity): * Your test has a mod (%) operation. This is slow and may impact the result. I suggest using ((i && 31) == 31), bit operations are almost free. (Don't believe me, read this: http://gmplib.org/~tege/x86-timing.pdf . 3 cycles for an AND operation, vs 25-80(!) cycles for a DIV.) * Logging an exception will have very different performance characteristics than a simple message. As it stands the test may just be measuring how long it takes to walk the stack trace. I would recommend testing the exception logging separately (see also next point). * Your test has two code paths. Branching causes the CPU to speculatively execute both code paths. The intention is to only execute the log(exception) once every 25 calls, but in fact both branches may get executed every call and the results of one branch are discarded. Is this what you want to test? So overall I'd hesitate to draw any conclusions from the numbers you got. I'm not a big fan of running performance tests inside JUnit tests. A proper performance test will take 10 seconds *just to warm up*. And you are correct that you'd want to execute each test 5 times or more and average the results. So that's like a minute per test... I'd like the JUnit tests to run fast because they are part of the build. It should be possible to do our build much faster. My main work project has 20,000+ JUnit tests and they finish within 2 minutes. (They don't use Surefire). We have a few hundred log4j tests and the build takes 10+ minutes. If we had a continuous integration server we could make performance tests part of the CI cycle, I'd like that. ________________________________ From: Nick Williams <[email protected]> To: Log4J Developers List <[email protected]> Sent: Sunday, July 21, 2013 2:15 PM Subject: Interesting Performance Stats for JDBC/JPA Appenders I've performed some performance tests for the JDBC and JPA Appenders. The results are interesting and somewhat confusing, so I wanted to share them. All of these tests were run on Java 1.6.0_51 on a MacBook Pro 15" 2.5 GHz Intel Core i7 8GB 1333 MHz DDR3 running Mac OS X 10.7.5. The abstract test classes for the JDBC and JPA Appenders each have a performance test method. It starts up the LoggerContext, logs a single event (to make sure everything is generally initialized), then starts a timer. It then logs 10,000 events (every 25th event includes an exception whose stack trace is logged) and then stops the timer. Finally, it selects all of the log events from the database table and ensures that 10,001 events appear. For each combination of JDBC+HyperSQL, JDBC+H2, JPA+HyperSQL, and JPA+H2, I ran the test 10 times and took the average of the 10. The spread was very minor and there were zero outliers. First, I tested the JDBCAppender: H2 consumed 738 milliseconds for 10,000 events (74 microseconds per event). I was rather impressed with this. HyperSQL consumed 3,507 milliseconds for 10,000 events (351 microseconds per event). I chalked this up to HyperSQL not performing as well as H2. Next, I tested the JPAAppender: H2 consumed 3,391 milliseconds for 10,000 events (339 microseconds per event). I expected JPA not to perform as well, but I was shocked at how much worse it was. HyperSQL consumed 4,105 milliseconds for 10,000 events (410 microseconds per event). Wait, what? So the performance difference between JDBC and JPA for H2 is huge, but the performance difference between JDBC and JPA for HyperSQL is minimal. This doesn't make a whole lot of sense to me. Thinking maybe JPA just needs a long time to warm up, I decided to double the events to 20,000: JDBC+H2 increased 49% to 1096 milliseconds (per event decreased 35% to 55 microseconds). JDBC+HyperSQL increased 70% to 5960 milliseconds (per event decreased 18% to 295 microseconds). JPA+H2 increased 52% to 5153 milliseconds (per event decreased 32% to 258 microseconds). JPA+HyperSQL increased 49% to 6119 milliseconds (per event decreased 35% to 306 microseconds). I'm not super sure what this means. I suppose it could be the fact that there are more columns it the database table for JPA events than the database table for JDBC events. I wouldn't think that would make that much difference, but it's possible. Either way, I'm not disappointed in the performance. It certainly isn't terrible, and it will be acceptable for most users I imagine. But I wonder if any of you might have any insights about what the deal could be here, or possibly you might look at the code and see that I've missed something. --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
