cddl/contrib/dtracetoolkit/Examples/iopending_example.txt

   1 The following is a demonstration of the iopending tool,
   2
   3 Here we run it with a sample interval of 1 second,
   4
   5    # iopending 1
   6    Tracing... Please wait.
   7    2006 Jan  6 20:21:59,  load: 0.02,  disk_r:      0 KB,  disk_w:      0 KB
   8
   9               value  ------------- Distribution ------------- count
  10                 < 0 |                                         0
  11                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1010
  12                   1 |                                         0
  13
  14    2006 Jan  6 20:22:00,  load: 0.03,  disk_r:      0 KB,  disk_w:      0 KB
  15
  16               value  ------------- Distribution ------------- count
  17                 < 0 |                                         0
  18                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1000
  19                   1 |                                         0
  20
  21    2006 Jan  6 20:22:01,  load: 0.03,  disk_r:      0 KB,  disk_w:      0 KB
  22
  23               value  ------------- Distribution ------------- count
  24                 < 0 |                                         0
  25                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1000
  26                   1 |                                         0
  27
  28    ^C
  29
  30 The iopending tool samples at 1000 Hz, and prints a distribution of how many
  31 disk events were "pending" completion. In the above example the disks are
  32 quiet - for all the samples there are zero disk events pending.
  33
  34
  35
  36 Now iopending is run with no arguments. It will default to an interval of 5
  37 seconds,
  38
  39    # iopending
  40    Tracing... Please wait.
  41    2006 Jan  6 19:15:41,  load: 0.03,  disk_r:   3599 KB,  disk_w:      0 KB
  42
  43               value  ------------- Distribution ------------- count
  44                 < 0 |                                         0
  45                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     4450
  46                   1 |@@@                                      390
  47                   2 |@                                        80
  48                   3 |                                         40
  49                   4 |                                         20
  50                   5 |                                         30
  51                   6 |                                         0
  52
  53    ^C
  54
  55 In the above output there was a little disk activity. For 390 samples there
  56 was 1 I/O event pending; for 80 samples there was 2, and so on.
  57
  58
  59
  60
  61 In the following example iopending is run during heavy disk activity. We
  62 print output every 10 seconds,
  63
  64    # iopending 10
  65    Tracing... Please wait.
  66    2006 Jan  6 20:58:07,  load: 0.03,  disk_r:  25172 KB,  disk_w:  33321 KB
  67
  68               value  ------------- Distribution ------------- count
  69                 < 0 |                                         0
  70                   0 |@@@@@@@@@                                2160
  71                   1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              6720
  72                   2 |@@@@                                     1000
  73                   3 |                                         50
  74                   4 |                                         30
  75                   5 |                                         20
  76                   6 |                                         10
  77                   7 |                                         10
  78                   8 |                                         10
  79                   9 |                                         0
  80
  81    2006 Jan  6 20:58:17,  load: 0.05,  disk_r:   8409 KB,  disk_w:  12449 KB
  82
  83               value  ------------- Distribution ------------- count
  84                 < 0 |                                         0
  85                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@            7260
  86                   1 |@@@@@@@                                  1700
  87                   2 |@                                        300
  88                   3 |                                         0
  89                   4 |                                         10
  90                   5 |                                         10
  91                   6 |                                         10
  92                   7 |                                         20
  93                   8 |                                         0
  94                   9 |                                         0
  95                  10 |                                         0
  96                  11 |                                         0
  97                  12 |                                         0
  98                  13 |                                         0
  99                  14 |                                         0
 100                  15 |                                         0
 101                  16 |                                         0
 102                  17 |                                         10
 103                  18 |                                         20
 104                  19 |                                         0
 105                  20 |                                         0
 106                  21 |                                         0
 107                  22 |                                         0
 108                  23 |                                         0
 109                  24 |                                         0
 110                  25 |                                         0
 111                  26 |                                         0
 112                  27 |                                         0
 113                  28 |                                         0
 114                  29 |                                         0
 115                  30 |                                         0
 116                  31 |                                         10
 117               >= 32 |@@@                                      650
 118
 119    ^C
 120
 121 In the first output, most of the time (67%) there was 1 event pending,
 122 and for a short time there were 8 events pending. In the second output we
 123 see many samples were off the scale - 650 samples at 32 or more pending
 124 events. For this sample I had typed "sync" in another window, which
 125 queued many disk events immediately which were eventually completed.
 126