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