cddl/contrib/dtracetoolkit/Examples/iopending_example.txt


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
115
116
117
118
119
120
121
122
123
124
125
126

The following is a demonstration of the iopending tool,

Here we run it with a sample interval of 1 second,

   # iopending 1
   Tracing... Please wait.
   2006 Jan  6 20:21:59,  load: 0.02,  disk_r:      0 KB,  disk_w:      0 KB
   
              value  ------------- Distribution ------------- count
                < 0 |                                         0
                  0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1010
                  1 |                                         0
   
   2006 Jan  6 20:22:00,  load: 0.03,  disk_r:      0 KB,  disk_w:      0 KB
   
              value  ------------- Distribution ------------- count
                < 0 |                                         0
                  0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1000
                  1 |                                         0
   
   2006 Jan  6 20:22:01,  load: 0.03,  disk_r:      0 KB,  disk_w:      0 KB
   
              value  ------------- Distribution ------------- count
                < 0 |                                         0
                  0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1000
                  1 |                                         0
   
   ^C

The iopending tool samples at 1000 Hz, and prints a distribution of how many
disk events were "pending" completion. In the above example the disks are
quiet - for all the samples there are zero disk events pending.


Now iopending is run with no arguments. It will default to an interval of 5
seconds,

   # iopending
   Tracing... Please wait.
   2006 Jan  6 19:15:41,  load: 0.03,  disk_r:   3599 KB,  disk_w:      0 KB
   
              value  ------------- Distribution ------------- count
                < 0 |                                         0
                  0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     4450
                  1 |@@@                                      390
                  2 |@                                        80
                  3 |                                         40
                  4 |                                         20
                  5 |                                         30
                  6 |                                         0
   
   ^C

In the above output there was a little disk activity. For 390 samples there
was 1 I/O event pending; for 80 samples there was 2, and so on. 


In the following example iopending is run during heavy disk activity. We
print output every 10 seconds,

   # iopending 10
   Tracing... Please wait.
   2006 Jan  6 20:58:07,  load: 0.03,  disk_r:  25172 KB,  disk_w:  33321 KB
   
              value  ------------- Distribution ------------- count
                < 0 |                                         0
                  0 |@@@@@@@@@                                2160
                  1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              6720
                  2 |@@@@                                     1000
                  3 |                                         50
                  4 |                                         30
                  5 |                                         20
                  6 |                                         10
                  7 |                                         10
                  8 |                                         10
                  9 |                                         0
   
   2006 Jan  6 20:58:17,  load: 0.05,  disk_r:   8409 KB,  disk_w:  12449 KB
   
              value  ------------- Distribution ------------- count
                < 0 |                                         0
                  0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@            7260
                  1 |@@@@@@@                                  1700
                  2 |@                                        300
                  3 |                                         0
                  4 |                                         10
                  5 |                                         10
                  6 |                                         10
                  7 |                                         20
                  8 |                                         0
                  9 |                                         0
                 10 |                                         0
                 11 |                                         0
                 12 |                                         0
                 13 |                                         0
                 14 |                                         0
                 15 |                                         0
                 16 |                                         0
                 17 |                                         10
                 18 |                                         20
                 19 |                                         0
                 20 |                                         0
                 21 |                                         0
                 22 |                                         0
                 23 |                                         0
                 24 |                                         0
                 25 |                                         0
                 26 |                                         0
                 27 |                                         0
                 28 |                                         0
                 29 |                                         0
                 30 |                                         0
                 31 |                                         10
              >= 32 |@@@                                      650
   
   ^C

In the first output, most of the time (67%) there was 1 event pending, 
and for a short time there were 8 events pending. In the second output we
see many samples were off the scale - 650 samples at 32 or more pending
events. For this sample I had typed "sync" in another window, which 
queued many disk events immediately which were eventually completed.