Reading JDK profiler output (was: JDK adventures

[Paul E Johnson]

I kept pointing and clicking in sun's site until I figured out their
vague policy about which release actually contains the bug fix.  Sun's
JDK1.3 did not have the profiling fix, some versions of Blackdown and
IBM did work. While I was there, I found JDK1.3.1 beta (released
2-15-2001, which I unpacked, moved JDK1.3 out of the way, then symlinked
1.3.1 to 1.3, with ln -sf JDK1.3.1 JDK1.3.

Outcome: Profiling works!

-prof gives an output file with the old-style profile information,
whereas Xprof and Xrunhprof are the more modern styles. (You get the
same output from -Xrunhprof:cpu=old, but I think neither is fully
functional in JDK1.3.1. Evidence is at the end of this note.)

I will share now some profiling results, so people who did not do it
before can see what it looks like and people who do know can see how the
new output differs from the old.  I've been retracing Marcus Daniel's
steps in his paper on making java Swarm models that are fast:
http://www.santafe.edu/~mgd/swarmfest2000/x106.html

And I get roughly the same indications from the new swarm and
jdk1.3.1beta.  (Some of you might recall that I achieved a dramatic
speedup in Objective-C heatbugs by streamlining calculations in the
HeatSpace.m (plug in this to see:
http://lark.cc.ukans.edu/~pauljohn/Swarm/MySwarmCode/HeatSpace.m). The
jheatbugs profile does not point in that same direction, at least at
first cut, but I bet we would get there if I dropped in a pure java
implementation of the grid2d...

The output here points to a major concern over getValueAtX$Y$

$ javaswarm -Xprof StartHeatbugs -b
You typed `heatbugs -b' or  `heatbugs --batch' so we're running without
graphics.
Heatbugs is running for 300 timesteps
It is logging data every 1 timesteps to: unhappiness.output
quitting at 300
Flat profile of 85.34 secs (1422 total ticks): main
  Interpreted + native   Method
 15.8%     0  +   225    swarm.activity.SwarmActivityImpl.run
  1.5%    15  +     6    java.lang.Object.hashCode
  0.3%     0  +     4    java.lang.ClassLoader$NativeLibrary.load
  0.3%     0  +     4    swarm.space.Grid2dImpl.getObjectAtX$Y
  0.2%     0  +     3    java.lang.Throwable.fillInStackTrace
  0.2%     0  +     3    swarm.space.Diffuse2dImpl.getValueAtX$Y
  0.2%     0  +     3    java.lang.ClassLoader.defineClass0
  0.1%     0  +     2   
swarm.random.UniformIntegerDistImpl.getIntegerWithMin$withMax
  0.1%     0  +     2    swarm.space.Diffuse2dImpl.putValue$atX$Y
  0.1%     0  +     2    swarm.SwarmEnvironmentImpl.initSwarm
  0.1%     0  +     1    swarm.space.Grid2dImpl.getSizeY
  0.1%     0  +     1    swarm.objectbase.SwarmImpl.drop
  0.1%     0  +     1    java.lang.ClassLoader.findBootstrapClass
  0.1%     0  +     1   
swarm.activity.ScheduleCImpl.create$setRepeatInterval
  0.1%     0  +     1    java.util.zip.Inflater.inflateBytes
  0.1%     0  +     1   
swarm.random.UniformDoubleDistImpl.getDoubleWithMin$withMax
  0.1%     1  +     0    java.lang.String.getBytes
  0.1%     1  +     0   
java.util.LinkedList$ListItr.checkForComodification
  0.1%     0  +     1    java.net.URLClassLoader.findClass
  0.1%     0  +     1    java.io.FilePermission$1.run
 19.6%    17  +   262    Total interpreted
     Compiled + native   Method
  0.8%    11  +     0    HeatSpace.findExtremeType$X$Y
  0.3%     3  +     1    Heatbug.heatbugStep
  0.2%     3  +     0    java.lang.Object.equals
  0.1%     1  +     0    Heatbug.getUnhappiness
  0.1%     1  +     0    java.util.LinkedList$ListItr.hasNext
  1.4%    19  +     1    Total compiled
         Stub + native   Method
 43.6%     2  +   618    swarm.space.Diffuse2dImpl.getValueAtX$Y
 11.3%     0  +   160    swarm.space.Grid2dImpl.putObject$atX$Y
  4.1%     0  +    59   
swarm.random.UniformIntegerDistImpl.getIntegerWithMin$withMax
  4.0%     0  +    57    swarm.space.Grid2dImpl.getObjectAtX$Y
  3.9%     1  +    54    swarm.space.Diffuse2dImpl.putValue$atX$Y
  3.5%     1  +    49   
swarm.random.UniformDoubleDistImpl.getDoubleWithMin$withMax
 70.4%     4  +   997    Total stub
  Runtime stub + native  Method
  0.1%     1  +     0    interpreter_entries
  0.1%     1  +     0    Total runtime stubs
  Thread-local ticks:
  0.1%     1             Class loader
  1.1%    16             Interpreter
  6.5%    93             Unknown: running frame
  0.8%    11             Unknown: thread_state
Global summary of 85.52 seconds:
100.0%  1425             Received ticks
  0.1%     1             Received GC ticks
  0.1%     1             Class loader
  1.1%    16             Interpreter
  7.3%   104             Unknown code


One lesson I learned is that, if you run a program in GUI mode, you have
to let it run a long time, or else java's going to say all the time is
used by the GUI waiting for you to click. Here's such an example:  

$ javaswarm -Xrunhprof:cpu=times StartHeatbugs

and at the end of the printout in java.hprof.txt I see this:
CPU TIME (ms) BEGIN (total = 38) Thu Feb 22 04:56:32 2001
rank   self  accum   count trace method
   1 36.84% 36.84%       1   104 java.lang.Object.wait
   2 36.84% 73.68%       1   105 java.lang.Object.wait
   3 10.53% 84.21%   69300   101 swarm.space.Diffuse2dImpl.getValueAtX$Y
   4  5.26% 89.47%       1   103 swarm.simtoolsgui.GUISwarmImpl.go
   5  2.63% 92.11%      63   100 swarm.analysis.EZGraphImpl.step
   6  2.63% 94.74%   12600   102 swarm.space.Grid2dImpl.putObject$atX$Y
   7  2.63% 97.37%       1    99 swarm.SwarmEnvironmentImpl.initSwarm
   8  2.63% 100.00%       1    98
swarm.simtoolsgui.ControlPanelImpl.setStateStopped

On the other hand, if you let it run 500 timesteps, the problem appears
the way Marcus found it in his paper.

rank   self  accum   count trace method
   1 23.78% 23.78%  576400   104 swarm.space.Diffuse2dImpl.getValueAtX$Y
   2 11.89% 35.66%       2   118 java.lang.Object.wait
   3  9.09% 44.76%     524   106 swarm.analysis.EZGraphImpl.step
   4  9.09% 53.85%       1   119 java.lang.Object.wait
   5  6.29% 60.14%       1   100 swarm.simtoolsgui.GUISwarmImpl.go
   6  6.29% 66.43%  104788   109 swarm.space.Grid2dImpl.putObject$atX$Y
   7  4.90% 71.33%     524   103 swarm.space.Value2dDisplayImpl.display
   8  4.90% 76.22%   52400   101 HeatSpace.findExtremeType$X$Y
   9  2.80% 79.02%     524   116 swarm.space.Object2dDisplayImpl.display
  10  2.10% 81.12%   62121   115 swarm.space.Grid2dImpl.getObjectAtX$Y



The output of the -prof option is a file java.prof which looks a bit
more to me like profiler output from Objective-C. .  It has this at the
top.  I'm totally puzzled that the "time" variable is 0, I figure it is
some bug in the java kit?.


count callee caller time
71500 java.lang.Object.hashCode()I
swarm.space.Diffuse2dImpl.getValueAtX$Y(II)I 0
71500 java.lang.Object.equals(Ljava/lang/Object;)Z
swarm.space.Diffuse2dImpl.getValueAtX$Y(II)I 0
60500 swarm.space.Diffuse2dImpl.getValueAtX$Y(II)I
HeatSpace.findExtremeType$X$Y(ILHeatCell;)I 4
16800 java.lang.Object.hashCode()I
swarm.space.Grid2dImpl.putObject$atX$Y(Ljava/lang/Object;II)Ljava/lang/Object;
0
16655 java.lang.Object.equals(Ljava/lang/Object;)Z
swarm.space.Grid2dImpl.putObject$atX$Y(Ljava/lang/Object;II)Ljava/lang/Object;
0
13200 java.util.ArrayList.clear()V
HeatSpace.findExtremeType$X$Y(ILHeatCell;)I 0
11574 java.lang.String.charAt(I)C
java.io.UnixFileSystem.normalize(Ljava/lang/String;)Ljava/lang/String; 0
11000
swarm.space.Grid2dImpl.putObject$atX$Y(Ljava/lang/Object;II)Ljava/lang/Object;
Heatbug.heatbugStep()V 1
10898 java.util.ArrayList.ensureCapacity(I)V
java.util.ArrayList.add(Ljava/lang/Object;)Z 0
10895 java.util.ArrayList.add(Ljava/lang/Object;)Z
HeatSpace.findExtremeType$X$Y(ILHeatCell;)I 0
10895 HeatCell.<init>(II)V HeatSpace.findExtremeType$X$Y(ILHeatCell;)I 0



"Marcus G. Daniels" wrote:
> 
> Tom Wainwright made this useful observation, but it didn't make
> it through majordomo because the message was mistakenly identified as an
> admin request..  I reworded the message to avoid that. ;)
> 
> TW> Looking at the Java man page, -prof is not documented.  There is an
> TW> option -Xprof, which works.  There is a note that all the -X options
> TW> are not stable, and under development, but Xprof works for now, at least
> TW> on the Blackdown release.
> 
>                   ==================================

-- 
Paul E. Johnson                       email: address@hidden
Dept. of Political Science            http://lark.cc.ukans.edu/~pauljohn
University of Kansas                  Office: (785) 864-9086
Lawrence, Kansas 66045                FAX: (785) 864-5700

                  ==================================
   Swarm-Support is for discussion of the technical details of the day
   to day usage of Swarm.  For list administration needs (esp.
   [un]subscribing), please send a message to <address@hidden>
   with "help" in the body of the message.