cddl/contrib/dtracetoolkit/Examples/j_calldist_example.txt

   1 This is an example of j_calldist.d showing the elapsed times for different
   2 types of Java operations.
   3
   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
   9
  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
  12 example) is ten.
  13
  14 Here we see it tracing the activity of Code/Java/Func_abc.
  15
  16 # j_calldist.d
  17 Tracing... Hit Ctrl-C to end.
  18 ^C
  19
  20 Top 10 elapsed times (us),
  21
  22 Top 10 exclusive method elapsed times (us),
  23    PID=311342, method, sun/net/www/ParseUtil.decode
  24            value  ------------- Distribution ------------- count
  25              128 |                                         0
  26              256 |@@@@@@@@@@@@@                            3
  27              512 |                                         0
  28             1024 |@@@@@@@@@@@@@@@@@@@@@@                   5
  29             2048 |@@@@                                     1
  30             4096 |                                         0
  31
  32    PID=311342, method, java/net/URLClassLoader.<clinit>
  33            value  ------------- Distribution ------------- count
  34             4096 |                                         0
  35             8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  36            16384 |                                         0
  37
  38    PID=311342, method, java/util/jar/JarFile.hasClassPathAttribute
  39            value  ------------- Distribution ------------- count
  40             4096 |                                         0
  41             8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  42            16384 |                                         0
  43
  44    PID=311342, method, java/util/zip/ZipFile.read
  45            value  ------------- Distribution ------------- count
  46             4096 |                                         0
  47             8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  48            16384 |                                         0
  49
  50    PID=311342, method, sun/nio/cs/US_ASCII.newEncoder
  51            value  ------------- Distribution ------------- count
  52                4 |                                         0
  53                8 |@@@@@@@@@@@@@@@@@@@@                     1
  54               16 |                                         0
  55               32 |                                         0
  56               64 |                                         0
  57              128 |                                         0
  58              256 |                                         0
  59              512 |                                         0
  60             1024 |                                         0
  61             2048 |                                         0
  62             4096 |                                         0
  63             8192 |@@@@@@@@@@@@@@@@@@@@                     1
  64            16384 |                                         0
  65
  66    PID=311342, method, java/util/zip/ZipFile.getInputStream
  67            value  ------------- Distribution ------------- count
  68                8 |                                         0
  69               16 |@@@@@@@@@@@@@@@@@@@@                     1
  70               32 |                                         0
  71               64 |                                         0
  72              128 |                                         0
  73              256 |                                         0
  74              512 |                                         0
  75             1024 |                                         0
  76             2048 |                                         0
  77             4096 |                                         0
  78             8192 |@@@@@@@@@@@@@@@@@@@@                     1
  79            16384 |                                         0
  80
  81    PID=311342, method, sun/nio/cs/US_ASCII.newDecoder
  82            value  ------------- Distribution ------------- count
  83                4 |                                         0
  84                8 |@@@@@@@@@@                               1
  85               16 |@@@@@@@@@@@@@@@@@@@@                     2
  86               32 |                                         0
  87               64 |                                         0
  88              128 |                                         0
  89              256 |                                         0
  90              512 |                                         0
  91             1024 |                                         0
  92             2048 |                                         0
  93             4096 |                                         0
  94             8192 |@@@@@@@@@@                               1
  95            16384 |                                         0
  96
  97    PID=311342, method, java/util/HashMap.<init>
  98            value  ------------- Distribution ------------- count
  99                4 |                                         0
 100                8 |@@@@@@@@@@@@@@                           8
 101               16 |@@@@@@@@@@@@@@@@                         9
 102               32 |@@@@@@@@@                                5
 103               64 |                                         0
 104              128 |                                         0
 105              256 |                                         0
 106              512 |                                         0
 107             1024 |                                         0
 108             2048 |                                         0
 109             4096 |                                         0
 110             8192 |@@                                       1
 111            16384 |                                         0
 112
 113    PID=311342, method, java/io/UnixFileSystem.normalize
 114            value  ------------- Distribution ------------- count
 115                4 |                                         0
 116                8 |@                                        1
 117               16 |                                         0
 118               32 |                                         0
 119               64 |@@@@@@@@@                                8
 120              128 |@@@@@@@@@@@@@                            11
 121              256 |@@@@@@                                   5
 122              512 |@@@@@@@@@                                8
 123             1024 |                                         0
 124             2048 |                                         0
 125             4096 |@                                        1
 126             8192 |                                         0
 127
 128    PID=311342, method, java/lang/Thread.sleep
 129            value  ------------- Distribution ------------- count
 130           262144 |                                         0
 131           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
 132          1048576 |                                         0
 133
 134
 135 Top 10 inclusive method elapsed times (us),
 136    PID=311342, method, java/net/URLClassLoader$1.run
 137            value  ------------- Distribution ------------- count
 138             8192 |                                         0
 139            16384 |@@@@@@@@@@@@@@@@@@@@                     1
 140            32768 |                                         0
 141            65536 |@@@@@@@@@@@@@@@@@@@@                     1
 142           131072 |                                         0
 143
 144    PID=311342, method, java/net/URLClassLoader.findClass
 145            value  ------------- Distribution ------------- count
 146             8192 |                                         0
 147            16384 |@@@@@@@@@@@@@@@@@@@@                     1
 148            32768 |                                         0
 149            65536 |@@@@@@@@@@@@@@@@@@@@                     1
 150           131072 |                                         0
 151
 152    PID=311342, method, sun/misc/URLClassPath.getLoader
 153            value  ------------- Distribution ------------- count
 154                8 |                                         0
 155               16 |@@@                                      1
 156               32 |                                         0
 157               64 |                                         0
 158              128 |                                         0
 159              256 |                                         0
 160              512 |                                         0
 161             1024 |                                         0
 162             2048 |@@@@@@                                   2
 163             4096 |@@@@@@@@@@@@@@@@@@@@@@@@@                8
 164             8192 |                                         0
 165            16384 |@@@                                      1
 166            32768 |                                         0
 167            65536 |@@@                                      1
 168           131072 |                                         0
 169
 170    PID=311342, method, java/lang/ClassLoader.loadClass
 171            value  ------------- Distribution ------------- count
 172               64 |                                         0
 173              128 |@@@@@@@@@                                6
 174              256 |@@@@@@@@@@@@@@@@@@@@@@                   15
 175              512 |@@@@                                     3
 176             1024 |                                         0
 177             2048 |                                         0
 178             4096 |                                         0
 179             8192 |                                         0
 180            16384 |                                         0
 181            32768 |                                         0
 182            65536 |@@@@                                     3
 183           131072 |                                         0
 184
 185    PID=311342, method, java/security/AccessController.doPrivileged
 186            value  ------------- Distribution ------------- count
 187                8 |                                         0
 188               16 |@@                                       2
 189               32 |@                                        1
 190               64 |@@@@                                     4
 191              128 |@@@@@@@@@@@@@@@@                         17
 192              256 |@                                        1
 193              512 |@@@@                                     4
 194             1024 |@@                                       2
 195             2048 |@                                        1
 196             4096 |@@@@@@                                   6
 197             8192 |@                                        1
 198            16384 |@@                                       2
 199            32768 |                                         0
 200            65536 |@@                                       2
 201           131072 |                                         0
 202
 203    PID=311342, method, Func_abc.func_c
 204            value  ------------- Distribution ------------- count
 205           262144 |                                         0
 206           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 207          1048576 |                                         0
 208
 209    PID=311342, method, Func_abc.func_b
 210            value  ------------- Distribution ------------- count
 211           524288 |                                         0
 212          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 213          2097152 |                                         0
 214
 215    PID=311342, method, java/lang/Thread.sleep
 216            value  ------------- Distribution ------------- count
 217           262144 |                                         0
 218           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
 219          1048576 |                                         0
 220
 221    PID=311342, method, Func_abc.func_a
 222            value  ------------- Distribution ------------- count
 223          1048576 |                                         0
 224          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 225          4194304 |                                         0
 226
 227    PID=311342, method, Func_abc.main
 228            value  ------------- Distribution ------------- count
 229          1048576 |                                         0
 230          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 231          4194304 |                                         0
 232
 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.
 236
 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
 239 those methods.
 240
 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
 243 methods.
 244
 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.