1 This is an example of j_calldist.d showing the elapsed times for different
2 types of Java operations.
4 This traces activity from all Java processes on the system with hotspot
5 provider support (1.6.0), and produces the output in graphical format, showing
6 a histogram of the amount of time taken by each call. Method calls are only
7 visible when using the flag "+ExtendedDTraceProbes". eg,
8 java -XX:+ExtendedDTraceProbes classfile
10 Because of the extensive results returned otherwise, this script will show you
11 a configurable number of results in each section. The default (as in this
14 Here we see it tracing the activity of Code/Java/Func_abc.
17 Tracing... Hit Ctrl-C to end.
20 Top 10 elapsed times (us),
22 Top 10 exclusive method elapsed times (us),
23 PID=311342, method, sun/net/www/ParseUtil.decode
24 value ------------- Distribution ------------- count
28 1024 |@@@@@@@@@@@@@@@@@@@@@@ 5
32 PID=311342, method, java/net/URLClassLoader.<clinit>
33 value ------------- Distribution ------------- count
35 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
38 PID=311342, method, java/util/jar/JarFile.hasClassPathAttribute
39 value ------------- Distribution ------------- count
41 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
44 PID=311342, method, java/util/zip/ZipFile.read
45 value ------------- Distribution ------------- count
47 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
50 PID=311342, method, sun/nio/cs/US_ASCII.newEncoder
51 value ------------- Distribution ------------- count
53 8 |@@@@@@@@@@@@@@@@@@@@ 1
63 8192 |@@@@@@@@@@@@@@@@@@@@ 1
66 PID=311342, method, java/util/zip/ZipFile.getInputStream
67 value ------------- Distribution ------------- count
69 16 |@@@@@@@@@@@@@@@@@@@@ 1
78 8192 |@@@@@@@@@@@@@@@@@@@@ 1
81 PID=311342, method, sun/nio/cs/US_ASCII.newDecoder
82 value ------------- Distribution ------------- count
85 16 |@@@@@@@@@@@@@@@@@@@@ 2
97 PID=311342, method, java/util/HashMap.<init>
98 value ------------- Distribution ------------- count
101 16 |@@@@@@@@@@@@@@@@ 9
113 PID=311342, method, java/io/UnixFileSystem.normalize
114 value ------------- Distribution ------------- count
120 128 |@@@@@@@@@@@@@ 11
128 PID=311342, method, java/lang/Thread.sleep
129 value ------------- Distribution ------------- count
131 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
135 Top 10 inclusive method elapsed times (us),
136 PID=311342, method, java/net/URLClassLoader$1.run
137 value ------------- Distribution ------------- count
139 16384 |@@@@@@@@@@@@@@@@@@@@ 1
141 65536 |@@@@@@@@@@@@@@@@@@@@ 1
144 PID=311342, method, java/net/URLClassLoader.findClass
145 value ------------- Distribution ------------- count
147 16384 |@@@@@@@@@@@@@@@@@@@@ 1
149 65536 |@@@@@@@@@@@@@@@@@@@@ 1
152 PID=311342, method, sun/misc/URLClassPath.getLoader
153 value ------------- Distribution ------------- count
163 4096 |@@@@@@@@@@@@@@@@@@@@@@@@@ 8
170 PID=311342, method, java/lang/ClassLoader.loadClass
171 value ------------- Distribution ------------- count
174 256 |@@@@@@@@@@@@@@@@@@@@@@ 15
185 PID=311342, method, java/security/AccessController.doPrivileged
186 value ------------- Distribution ------------- count
191 128 |@@@@@@@@@@@@@@@@ 17
203 PID=311342, method, Func_abc.func_c
204 value ------------- Distribution ------------- count
206 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
209 PID=311342, method, Func_abc.func_b
210 value ------------- Distribution ------------- count
212 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
215 PID=311342, method, java/lang/Thread.sleep
216 value ------------- Distribution ------------- count
218 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
221 PID=311342, method, Func_abc.func_a
222 value ------------- Distribution ------------- count
224 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
227 PID=311342, method, Func_abc.main
228 value ------------- Distribution ------------- count
230 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
233 The elapsed times section is empty. It would show us anything that is not a
234 Java method - garbage collection for example. However there was nothing of
235 the kind in this example.
237 The exclusive method elapsed times show us the time spent in the top ten most
238 time consuming methods, not including time spent in subroutines called by
241 The inclusive method elapsed times show us the time spent in the top ten most
242 time consuming methods including time spent in subroutines called by those
245 It is important to pay close attention to the third column, "count" as this
246 will indicate if there were any instances in a particular timeframe, even if
247 the number is too small to show up on the histogram clearly.