cddl/contrib/dtracetoolkit/Examples/lockbydist_example.txt

   1 The following is a demonstration of the lockbyproc.d script,
   2
   3    # lockbydist.d
   4    dtrace: description 'lockstat:::adaptive-block ' matched 1 probe
   5    ^C
   6
   7      metadata-manager
   8               value  ------------- Distribution ------------- count
   9              131072 |                                         0
  10              262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  11              524288 |                                         0
  12
  13      sched
  14               value  ------------- Distribution ------------- count
  15               16384 |                                         0
  16               32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9
  17               65536 |                                         0
  18
  19      oracle
  20               value  ------------- Distribution ------------- count
  21               16384 |                                         0
  22               32768 |@@@@@@@@@@@@@@@@@@@                      9
  23               65536 |@@@@@@@@@@@@@@@@@@@@@                    10
  24              131072 |                                         0
  25
  26 In the above output, oracle can be seen to have blocked 10 times from
  27 65 to 131 microseconds, and 9 times from 32 to 65 microseconds. sched,
  28 the kernel, has blocked several times also. metadata-manager only
  29 blocked once, which was at least 262 microseconds.
  30
  31
  32
  33 The following is a longer sample,
  34
  35    # lockbydist.d
  36    dtrace: description 'lockstat:::adaptive-block ' matched 1 probe
  37    ^C
  38
  39      svc.startd
  40               value  ------------- Distribution ------------- count
  41                8192 |                                         0
  42               16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  43               32768 |                                         0
  44
  45      java
  46               value  ------------- Distribution ------------- count
  47               16384 |                                         0
  48               32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  49               65536 |                                         0
  50
  51      oracle
  52               value  ------------- Distribution ------------- count
  53               16384 |                                         0
  54               32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              4
  55               65536 |@@@@@@@@@@@@@                            2
  56              131072 |                                         0
  57
  58      mysql-test-run
  59               value  ------------- Distribution ------------- count
  60               65536 |                                         0
  61              131072 |@@@@@@@@@@@@@@@@@@@@                     1
  62              262144 |@@@@@@@@@@@@@@@@@@@@                     1
  63              524288 |                                         0
  64
  65      pageout
  66               value  ------------- Distribution ------------- count
  67               16384 |                                         0
  68               32768 |@@@@@@@@@@@@@                            1
  69               65536 |                                         0
  70              131072 |                                         0
  71              262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  72              524288 |                                         0
  73
  74      mysqltest
  75               value  ------------- Distribution ------------- count
  76               16384 |                                         0
  77               32768 |@@@@@@                                   1
  78               65536 |@@@@@@@@@@@                              2
  79              131072 |@@@@@@@@@@@                              2
  80              262144 |@@@@@@@@@@@                              2
  81              524288 |                                         0
  82
  83      sched
  84               value  ------------- Distribution ------------- count
  85                8192 |                                         0
  86               16384 |@@@@@@@@@@@                              11
  87               32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@               25
  88               65536 |                                         0
  89              131072 |@                                        1
  90              262144 |@@                                       2
  91              524288 |                                         0
  92
  93      mysqld
  94               value  ------------- Distribution ------------- count
  95               16384 |                                         0
  96               32768 |@@@@@@@@@@@@@@@@@@@@@                    22
  97               65536 |@@@@@@@@@                                9
  98              131072 |                                         0
  99              262144 |@@@@                                     4
 100              524288 |                                         0
 101             1048576 |                                         0
 102             2097152 |                                         0
 103             4194304 |@@                                       2
 104             8388608 |@@@@                                     4
 105            16777216 |                                         0
 106
 107 The length of time threads were blocked, and the number of such blocks
 108 can be easily observed from the above output.
 109
 110 mysqld can be seen to have many short blocks: 22 from 32 -> 65 microseconds,
 111 and a few larger blocks: 4 from 8 -> 16 ms.
 112
 113
 114