1This is an example of j_cpudist.d showing the elapsed times for different 2types of Java operations. 3 4This traces activity from all Java processes on the system with hotspot 5provider support (1.6.0), and produces the output in graphical format, showing 6a histogram of the amount of time taken by each call. Method calls are only 7visible when using the flag "+ExtendedDTraceProbes". eg, 8java -XX:+ExtendedDTraceProbes classfile 9 10Because of the extensive results returned otherwise, this script will show you 11a configurable number of results in each section. The default (as in this 12example) is ten. 13 14Here we see it tracing the activity of Code/Java/Func_abc. 15 16# j_cpudist.d 17Tracing... Hit Ctrl-C to end. 18^C 19 20Top 10 on-CPU times (us), 21 22Top 10 exclusive method on-CPU times (us), 23 PID=311364, method, java/lang/AbstractStringBuilder.append 24 value ------------- Distribution ------------- count 25 0 | 0 26 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 382 27 2 |@@@@@@@@@@@ 151 28 4 |@ 13 29 8 | 1 30 16 | 1 31 32 | 1 32 64 | 0 33 34 PID=311364, method, java/util/Arrays.copyOf 35 value ------------- Distribution ------------- count 36 1 | 0 37 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 68 38 4 |@@@@@@@ 15 39 8 | 0 40 16 | 0 41 32 | 1 42 64 | 1 43 128 | 0 44 256 |@ 2 45 512 | 0 46 47 PID=311364, method, java/io/UnixFileSystem.normalize 48 value ------------- Distribution ------------- count 49 1 | 0 50 2 |@ 1 51 4 | 0 52 8 |@@@@@@@@@@@ 9 53 16 |@@@@@@@@@@@@@@ 12 54 32 |@@@@@@ 5 55 64 |@@@@@@@ 6 56 128 |@ 1 57 256 | 0 58 59 PID=311364, method, java/io/File.<clinit> 60 value ------------- Distribution ------------- count 61 512 | 0 62 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 63 2048 | 0 64 65 PID=311364, method, sun/misc/URLClassPath$JarLoader.getJarFile 66 value ------------- Distribution ------------- count 67 512 | 0 68 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 69 2048 | 0 70 71 PID=311364, method, java/io/FilePermission$1.run 72 value ------------- Distribution ------------- count 73 1 | 0 74 2 |@@@@@@@@@@@@@@@@@@@@ 2 75 4 |@@@@@@@@@@ 1 76 8 | 0 77 16 | 0 78 32 | 0 79 64 | 0 80 128 | 0 81 256 | 0 82 512 | 0 83 1024 |@@@@@@@@@@ 1 84 2048 | 0 85 86 PID=311364, method, java/lang/StringBuilder.append 87 value ------------- Distribution ------------- count 88 1 | 0 89 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 526 90 4 | 2 91 8 | 0 92 16 | 4 93 32 | 1 94 64 | 0 95 96 PID=311364, method, java/lang/String.<init> 97 value ------------- Distribution ------------- count 98 1 | 0 99 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 162 100 4 |@@ 10 101 8 | 0 102 16 | 0 103 32 | 0 104 64 | 1 105 128 | 0 106 256 | 1 107 512 | 0 108 1024 | 1 109 2048 | 0 110 111 PID=311364, method, java/lang/String.charAt 112 value ------------- Distribution ------------- count 113 0 | 0 114 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1953 115 2 | 3 116 4 | 1 117 8 | 1 118 16 | 2 119 32 | 0 120 121 PID=311364, method, java/lang/System.initializeSystemClass 122 value ------------- Distribution ------------- count 123 1024 | 0 124 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 125 4096 | 0 126 127 128Top 10 inclusive method on-CPU times (us), 129 PID=311364, method, sun/misc/Launcher$ExtClassLoader.<init> 130 value ------------- Distribution ------------- count 131 8192 | 0 132 16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 133 32768 | 0 134 135 PID=311364, method, sun/misc/Launcher$ExtClassLoader.getExtClassLoader 136 value ------------- Distribution ------------- count 137 8192 | 0 138 16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 139 32768 | 0 140 141 PID=311364, method, sun/misc/Launcher$ExtClassLoader.getExtURLs 142 value ------------- Distribution ------------- count 143 8192 | 0 144 16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 145 32768 | 0 146 147 PID=311364, method, sun/misc/Launcher.<clinit> 148 value ------------- Distribution ------------- count 149 8192 | 0 150 16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 151 32768 | 0 152 153 PID=311364, method, sun/misc/Launcher.<init> 154 value ------------- Distribution ------------- count 155 8192 | 0 156 16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 157 32768 | 0 158 159 PID=311364, method, java/lang/ClassLoader.loadClassInternal 160 value ------------- Distribution ------------- count 161 32 | 0 162 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6 163 128 |@@@@@@@@@ 2 164 256 | 0 165 512 | 0 166 1024 | 0 167 2048 | 0 168 4096 | 0 169 8192 | 0 170 16384 |@@@@ 1 171 32768 | 0 172 173 PID=311364, method, sun/misc/Launcher$AppClassLoader.loadClass 174 value ------------- Distribution ------------- count 175 32 | 0 176 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6 177 128 |@@@@@@@@@ 2 178 256 | 0 179 512 | 0 180 1024 | 0 181 2048 | 0 182 4096 | 0 183 8192 | 0 184 16384 |@@@@ 1 185 32768 | 0 186 187 PID=311364, method, sun/misc/URLClassPath.getLoader 188 value ------------- Distribution ------------- count 189 2 | 0 190 4 |@@@ 1 191 8 | 0 192 16 | 0 193 32 | 0 194 64 | 0 195 128 | 0 196 256 |@@@ 1 197 512 |@@@@@@@@@@@@@@@@@@@@@@ 7 198 1024 |@@@@@@ 2 199 2048 | 0 200 4096 |@@@ 1 201 8192 |@@@ 1 202 16384 | 0 203 204 PID=311364, method, java/lang/ClassLoader.loadClass 205 value ------------- Distribution ------------- count 206 16 | 0 207 32 |@@@@@@@@@ 6 208 64 |@@@@@@@@@@@@@@@@@@@@@ 14 209 128 |@@@@@@ 4 210 256 | 0 211 512 | 0 212 1024 | 0 213 2048 | 0 214 4096 | 0 215 8192 |@ 1 216 16384 |@@@ 2 217 32768 | 0 218 219 PID=311364, method, java/security/AccessController.doPrivileged 220 value ------------- Distribution ------------- count 221 2 | 0 222 4 |@ 1 223 8 |@@@@ 4 224 16 |@@@@@@@@@@ 11 225 32 |@@@@@@@@@@ 11 226 64 | 0 227 128 |@@@ 3 228 256 |@ 1 229 512 |@@@@@ 5 230 1024 |@@ 2 231 2048 |@ 1 232 4096 |@ 1 233 8192 |@@ 2 234 16384 |@ 1 235 32768 | 0 236 237The elapsed times section is empty. It would show us anything that is not a 238Java method - garbage collection for example. However there was nothing of 239the kind in this example. 240 241The exclusive method elapsed times show us the time spent on-CPU by the most 242time consuming methods, not including time spent in subroutines called by 243those methods. 244 245The inclusive method elapsed times show us the time spent on-CPU by the top 246ten most time consuming methods including time spent in subroutines called by 247those methods. 248 249It is important to pay close attention to the third column, "count" as this 250will indicate if there were any instances in a particular timeframe, even if 251the number is too small to show up on the histogram clearly. 252 253