11.7.6 Examples

The following example script displays information for every I/O as it is issued:

#pragma D option quiet

BEGIN
{
  printf("%10s %58s %2s\n", "DEVICE", "FILE", "RW");
}

io:::start
{
  printf("%10s %58s %2s\n", args[1]->dev_statname,
  args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W");
}

The output from this script resembles the following example:

# dtrace -s ./iosnoop.d
    DEVICE                             FILE RW
     dm-00                  /usr/bin/evince  R
     dm-00                  /usr/bin/evince  R
     dm-00                        <unknown>  R
     dm-00                        <unknown>  R
     dm-00                        <unknown>  R
     dm-00                           <none>  R
...

The <none> entries in the output indicate that the I/O request does not correspond to the data in any particular file. Such I/O requests are due to metadata of one form or another. The <unknown> entries in the output indicate that the pathname for the file is not known.

You can make the example script slightly more sophisticated by using an associative array to track the time in milliseconds spent on each I/O, as shown in the following example:

#pragma D option quiet

BEGIN
{
  printf("%10s %58s %2s %7s\n", "DEVICE", "FILE", "RW", "MS");
}

io:::start
{
  start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
}

io:::done
/start[args[0]->b_edev, args[0]->b_blkno]/
{
  this->elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
  printf("%10s %58s %2s %3d.%03d\n", args[1]->dev_statname,
  args[2]->fi_pathname, args[0]->b_flags & B_READ ? "R" : "W",
  this->elapsed / 10000000, (this->elapsed / 1000) % 1000);
  start[args[0]->b_edev, args[0]->b_blkno] = 0;
}

The modified script adds a MS (milliseconds) column to the output.

You can aggregate on device, application, process ID and bytes transferred, as shown in the following example:

#pragma D option quiet

io:::start
{
  @[args[1]->dev_statname, execname, pid] = sum(args[0]->b_bcount);
}

END
{
  printf("%10s %20s %10s %15s\n", "DEVICE", "APP", "PID", "BYTES");
  printa("%10s %20s %10d %15@d\n", @);
}

Running this script for a few seconds results in output similar to the following example:

# dtrace -s whoio.d 
^C
    DEVICE                  APP        PID           BYTES
     dm-00               evince      14759           16384
     dm-00          flush-252:0       1367           45056
     dm-00                 bash      14758          131072
     dm-00       gvfsd-metadata       2787          135168
     dm-00               evince      14758          139264
     dm-00               evince      14338          151552
     dm-00          jbd2/dm-0-8        390          356352

If you are copying data from one device to another, you might want to know if one of the devices acts as a limiter on the copy. To answer this question, you need to know the effective throughput of each device rather than the number of bytes per second that each device is transferring. You can determine throughput with the following example script:

#pragma D option quiet

io:::start
{
  start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
}

io:::done
/start[args[0]->b_edev, args[0]->b_blkno]/
{
  /*
   * We want to get an idea of our throughput to this device in KB/sec.
   * What we have, however, is nanoseconds and bytes. That is we want
   * to calculate:
   *
   * bytes / 1024
   * ------------------------
   * nanoseconds / 1000000000
   *
   * But we cannot calculate this using integer arithmetic without losing
   * precision (the denominator, for one, is between 0 and 1 for nearly
   * all I/Os). So we restate the fraction, and cancel:
   *
   * bytes       1000000000      bytes       976562
   * --------- * ------------- = --------- * -------------
   * 1024        nanoseconds     1           nanoseconds
   *
   * This is easy to calculate using integer arithmetic.
   */
  this->elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
  @[args[1]->dev_statname, args[1]->dev_pathname] =
    quantize((args[0]->b_bcount * 976562) / this->elapsed);
  start[args[0]->b_edev, args[0]->b_blkno] = 0;
}

END
{
  printa(" %s (%s)\n%@d\n", @);
}

Running the example script for several seconds while copying data from a hard disk to a USB drive yields the following output:

 sdc1 (/dev/sdc1)

           value  ------------- Distribution ------------- count    
              32 |                                         0
              64 |                                         3
             128 |                                         1
             256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  2257
             512 |                                         1
            1024 |                                         0       

 dm-00 (/dev/dm-00)

           value  ------------- Distribution ------------- count    
             128 |                                         0
             256 |                                         1
             512 |                                         0
            1024 |                                         2
            2048 |                                         0
            4096 |                                         2
            8192 |@@@@@@@@@@@@@@@@@@                       172
           16384 |@@@@@                                    52
           32768 |@@@@@@@@@@@                              108
           65536 |@@@                                      34
          131072 |                                         0     

The output shows that the USB drive (sdc1) is clearly the limiting device. The throughput of sdc1 is between 256K/sec and 512K/sec, while dm-00 delivered I/O at anywhere from 8 MB/second to over 64 MB/second.