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