1The 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 26In the above output, oracle can be seen to have blocked 10 times from 2765 to 131 microseconds, and 9 times from 32 to 65 microseconds. sched, 28the kernel, has blocked several times also. metadata-manager only 29blocked once, which was at least 262 microseconds. 30 31 32 33The 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 107The length of time threads were blocked, and the number of such blocks 108can be easily observed from the above output. 109 110mysqld can be seen to have many short blocks: 22 from 32 -> 65 microseconds, 111and a few larger blocks: 4 from 8 -> 16 ms. 112 113 114 115