Friday, June 22, 2007

Using Groovy to profile .class vs. getClass()

In Log4j template code in Eclipse, I mentioned two different ways of constructing a Logger instance:

Logger.getLogger(getClass());
and
Logger.getLogger(Foo.class);
and mentioned that the latter is supposed to be faster. Wondering how much faster led to an impulse to start creating a new Eclipse project and...

Then I thought "why write a new Java file? This is a perfect time to try Groovy." (If my goal was not to produce something persistent, I've failed because now we have this post.)

I recently installed Groovy, the dynamic scripting language with Java-like syntax and doubtful name, and fired up the Groovy console, a simple Swing application that functions as a kind of read-eval-print loop environment with one very useful feature, an object field and method explorer.

Bottom line: .class vs. getClass()

The bottom line is that accessing the static .class object was faster by about 20 times, at least in my tests using Java 1.4 in Windows:
Operation Average time
getClass() 1281 ns
.class 62 ns
x++ for int x 1859 ns
loop overhead
(not counted in other numbers)
78 ns
I would surely like to find some explanation for this gap. I'm sure all it would take is knowledge of how these two calls translate in the JVM, but that alas lies outside my knowledge.

Groovy code for profiling

I follow a standard pattern for profiling a block of code where you simply repeat the block some large number of times, sampling a timer before and after the loop, and then subtracting the loop overhead by timing the same looping construct with an empty body:
limit=1000*1000
import java.util.Date
t0 = new Date().time
for(i in 0..<limit)
{
;
}
t1 = new Date().time
loopoverhead = t1-t0
println "loopoverhead=${loopoverhead/limit} ms"

s = "foo"

t0 = new Date().time
for(i in 0..<limit)
{
c = s.getClass()
}
t1 = new Date().time
tgetclass = (t1-t0)-loopoverhead
println "getClass()=${tgetclass/limit} ms"
The Groovy feature I liked here was the ability to write an expression inside the string literals. Also note the automatic getter translation of the phrase new Date().time, where the Java getTime() getter method call is available as a field reference time. One thing I wanted to do was to call System.currentTimeMillis() instead of constructing a Date object, but actually couldn't find in the docs how to invoke a static method.

Appendix: Groovy source code


limit=1000*1000
import java.util.Date
t0 = new Date().time
for(i in 0..<limit)
{
;
}
t1 = new Date().time
loopoverhead = t1-t0
println "loopoverhead=${loopoverhead/limit} ms"

acc=0
t0 = new Date().time
for(i in 0..<limit)
{
acc++
}
t1 = new Date().time
intincr = t1-t0
println "integer increment=${intincr/limit} ms"

s = "foo"

t0 = new Date().time
for(i in 0..<limit)
{
c = s.getClass()
}
t1 = new Date().time
tgetclass = (t1-t0)-loopoverhead
println "getClass()=${tgetclass/limit} ms"

t0 = new Date().time
for(i in 0..<limit)
{
c = java.lang.String.class
}
t1 = new Date().time
tstaticclass = (t1-t0)-loopoverhead
println "String.class=${tstaticclass/limit} ms"

// Try with a non-system class

class Bob
{
}
testbob = new Bob()

t0 = new Date().time
for(i in 0..<limit)
{
c = testbob.getClass()
}
t1 = new Date().time
tbobgetclass = (t1-t0)-loopoverhead
println "getClass() on non-system class=${tbobgetclass/limit} ms"

t0 = new Date().time
for(i in 0..<limit)
{
c = Bob.class
}
t1 = new Date().time
tbobstaticclass = (t1-t0)-loopoverhead
println "Bob.class=${tbobstaticclass/limit} ms"

No comments: