Question about profiling

[Vincent Foley]

I was trying to make an application go faster today when I found out
that a Java program that does pretty much the same task was 8 times
faster. I used the -Xrunhprof:cpu=times profiling flag to know where
I should look, and the results are a little puzzling:

CPU TIME (ms) BEGIN (total = 3334005) Mon Mar 16 15:26:26 2009
rank self accum count trace method
1 33.09% 33.09% 6 302294 java.lang.ref.ReferenceQueue.remove
2 33.09% 66.17% 3 302283 java.lang.Object.wait
3 1.11% 67.28% 4681282 304233
java.util.concurrent.atomic.AtomicInteger.get
4 1.05% 68.34% 1273366 326814 clojure.lang.Var.deref
5 0.82% 69.15% 162675 326831 starcraft.replay.parse
$parse_buffer__65$fn__68.invoke
6 0.75% 69.90% 162710 326175
clojure.lang.APersistentVector.doEquals
7 0.67% 70.58% 1273672 325764 clojure.lang.Var.getThreadBinding
8 0.67% 71.24% 1273366 326815 clojure.lang.Var.get
9 0.54% 71.79% 650700 326818 clojure.core$nth__3505.invoke
10 0.50% 72.29% 650700 326817 clojure.lang.RT.nth
11 0.38% 72.67% 462044 326102 clojure.lang.Var.deref
12 0.37% 73.04% 162718 325793
clojure.lang.APersistentVector.hashCode
13 0.37% 73.40% 153954 326133 starcraft.replay.parse
$read_field_aux__32.invoke
14 0.35% 73.75% 659541 312088 clojure.lang.Var.getThreadBinding
15 0.34% 74.09% 650840 326173 clojure.lang.APersistentVector
$2.next
16 0.32% 74.41% 385545 312090 clojure.lang.Var.deref
17 0.30% 74.71% 1273672 325765 clojure.lang.Var.hasRoot
18 0.30% 75.01% 19608 327262 starcraft.replay.unpack
$decode_command_block__93.invoke
19 0.27% 75.28% 517194 326100 clojure.lang.Var.getThreadBinding
20 0.26% 75.54% 488130 326171 clojure.lang.APersistentVector
$2.hasNext

Can anyone explain how 9 method calls can be responsible for 66% of my
runtime and how I could avoid this overhead? The AtomicInteger.get
also intrigues me.

My code is available at the following address if you need to see it:
http://bitbucket.org/gnuvince/clj-starcraft/src/

Thank you,

Vincent.

[Vincent Foley]

I found that the problem is caused by the version of Sun's JVM on
Ubunty Hardy Heron. On my Ibex machine at home, the first two lines
(Object.wait and ReferenceQueue.remove) are not even there and the
costliest method if AtomicInteger.get.

Vincent.

[Jeffrey Straszheim]

Are they both Java 6?  I know it fixed a lot of performance issue over 5.

[Vincent Foley]

Java 1.6.0_07 for Hardy vs Java 1.6.0_10 for Ibex.

However, with this newer package, the Java program is now more than
13x faster than my Clojure program. Looks like I got a lot of work
ahead of me.

Vincent.

On Mar 16, 9:31 pm, Jeffrey Straszheim <straszheimjeff...@gmail.com>
wrote:

[Vincent Foley]

Some numbers:

Clojure:

]% time java -server -cp clj-starcraft.jar:$HOME/src/clojure/
clojure.jar clojure.main dump.clj misc/replays/*.rep
1047
"Elapsed time: 159605.6084 msecs"
java -server -cp clj-starcraft.jar:$HOME/src/clojure/clojure.jar
clojure.main 163.84s user 1.11s system 102% cpu 2:41.10 total

Java:

% time java -server -cp . hu.belicza.andras.bwhf.control.BinRepParser
~/prog/clojure/clj-starcraft/misc/replays/*.rep
1047
java -server -cp . hu.belicza.andras.bwhf.control.BinRepParser
12.92s user 0.31s system 110% cpu 11.923 total