cddl/contrib/dtracetoolkit/Examples/fsrw_example.txt

   1 The following are demonstrations of the fsrw.d script.
   2
   3
   4 Here the fsrw.d script was running while a 50 Kbyte file was read,
   5
   6    # ./fsrw.d
   7    Event            Device RW     Size Offset Path
   8    sc-read               .  R     8192      0 /extra1/50k
   9      fop_read            .  R     8192      0 /extra1/50k
  10        disk_io       cmdk0  R     8192      0 /extra1/50k
  11        disk_ra       cmdk0  R     8192      8 /extra1/50k
  12    sc-read               .  R     8192      8 /extra1/50k
  13      fop_read            .  R     8192      8 /extra1/50k
  14        disk_ra       cmdk0  R    34816     16 /extra1/50k
  15    sc-read               .  R     8192     16 /extra1/50k
  16      fop_read            .  R     8192     16 /extra1/50k
  17    sc-read               .  R     8192     24 /extra1/50k
  18      fop_read            .  R     8192     24 /extra1/50k
  19    sc-read               .  R     8192     32 /extra1/50k
  20      fop_read            .  R     8192     32 /extra1/50k
  21    sc-read               .  R     8192     40 /extra1/50k
  22      fop_read            .  R     8192     40 /extra1/50k
  23    sc-read               .  R     8192     48 /extra1/50k
  24      fop_read            .  R     8192     48 /extra1/50k
  25    sc-read               .  R     8192     50 /extra1/50k
  26      fop_read            .  R     8192     50 /extra1/50k
  27    ^C
  28
  29 By looking closely at the Offset (Kbytes) and Size of each transaction, we
  30 can see how the read() system calls (sc-read) were satisfied by the file
  31 system. There were 8 read() system calls, and 3 disk events - 2 of which were
  32 UFS read-ahead (disk_ra). The final read-ahead was for 34 Kbytes and began
  33 with an offset of 16 Kbytes, which read the remaining file data (34 + 16 = 50
  34 Kbytes). The subsequent read() system calls and corresponding fop_read() calls
  35 returned from the page cache.
  36
  37
  38
  39 The following demonstrates how a logical I/O is broken up into multiple
  40 physical I/O events. Here a dd command was used to read 1 Mbytes from the
  41 /var/sadm/install/contents file while fsrw.d was tracing.
  42
  43    # ./fsrw.d
  44    Event            Device RW     Size Offset Path
  45    sc-read               .  R  1048576      0 /var/sadm/install/contents
  46      fop_read            .  R  1048576      0 /var/sadm/install/contents
  47        disk_ra       cmdk0  R     4096     72 /var/sadm/install/contents
  48        disk_ra       cmdk0  R     8192     96 <none>
  49        disk_ra       cmdk0  R    57344     96 /var/sadm/install/contents
  50        disk_ra       cmdk0  R    57344    152 /var/sadm/install/contents
  51        disk_ra       cmdk0  R    57344    208 /var/sadm/install/contents
  52        disk_ra       cmdk0  R    49152    264 /var/sadm/install/contents
  53        disk_ra       cmdk0  R    57344    312 /var/sadm/install/contents
  54        disk_ra       cmdk0  R    57344    368 /var/sadm/install/contents
  55        disk_ra       cmdk0  R    57344    424 /var/sadm/install/contents
  56        disk_ra       cmdk0  R    57344    480 /var/sadm/install/contents
  57        disk_ra       cmdk0  R    57344    536 /var/sadm/install/contents
  58        disk_ra       cmdk0  R    57344    592 /var/sadm/install/contents
  59        disk_ra       cmdk0  R    57344    648 /var/sadm/install/contents
  60        disk_ra       cmdk0  R    57344    704 /var/sadm/install/contents
  61        disk_ra       cmdk0  R    57344    760 /var/sadm/install/contents
  62        disk_ra       cmdk0  R    57344    816 /var/sadm/install/contents
  63        disk_ra       cmdk0  R    57344    872 /var/sadm/install/contents
  64        disk_ra       cmdk0  R    57344    928 /var/sadm/install/contents
  65        disk_ra       cmdk0  R    57344    984 /var/sadm/install/contents
  66        disk_ra       cmdk0  R    57344   1040 /var/sadm/install/contents
  67    ^C
  68
  69 Both the read() syscall (sc-read) and the fop_read() call asked the file system
  70 for 1048576 bytes, which was then broken into numerous disk I/O events of up to
  71 56 Kbytes in size. The 8192 byte read with a path of "<none>" is likely to be
  72 the file system reading the indirect block pointers for the
  73 /var/sadm/install/contents file (something DTrace could confirm in detail).
  74
  75
  76
  77
  78 The following traces activity as a cp command copies a 50 Kbyte file.
  79
  80    # ./fsrw.d
  81    Event            Device RW     Size Offset Path
  82        disk_io        dad1  R     1024      0 /extra1
  83        disk_io        dad1  R     8192      0 <none>
  84        disk_io        dad1  R     8192      0 <none>
  85        disk_io        dad1  R     2048      0 <none>
  86        disk_io        dad1  R     2048      0 <none>
  87    sc-write              .  W    51200      0 /extra1/outfile
  88      fop_write           .  W    51200      0 /extra1/outfile
  89        disk_io        dad1  R     8192      0 /extra1/50k
  90        disk_ra        dad1  R     8192      8 /extra1/50k
  91        disk_ra        dad1  R    34816     16 /extra1/50k
  92        disk_io        dad1  R     2048      0 <none>
  93        disk_io        dad1  W    49152      0 /extra1/outfile
  94    ^C
  95
  96 Reads including UFS read-ahead can be seen as the file is read.
  97 The output finishes with disk writes as the new file is flushed to disk.
  98 The syscall write() and fop_write() can be seen to the /extra1/outfile,
  99 however there is no syscall read() or fop_read() to /extra1/50k - which
 100 we may have expected to occur before the writes. This is due to the way
 101 the cp command now works, it uses mmap() to map files in for reading.
 102 This activity can be seen if we also trace fop_getpage() and fop_putpage(),
 103 as the fspaging.d dtrace script does.
 104
 105    # ./fspaging.d
 106    Event             Device RW     Size Offset Path
 107        disk_io         dad1  R     1024      0 /extra1
 108        disk_io         dad1  R     8192      0 <none>
 109        disk_io         dad1  R     2048      0 <none>
 110    sc-write               .  W    51200      0 /extra1/outfile
 111      fop_write            .  W    51200      0 /extra1/outfile
 112      fop_getpage          .  R     8192      0 /extra1/50k
 113        disk_io         dad1  R     8192      0 /extra1/50k
 114        disk_ra         dad1  R     8192      8 /extra1/50k
 115      fop_getpage          .  R     8192      8 /extra1/50k
 116        disk_ra         dad1  R    34816     16 /extra1/50k
 117      fop_getpage          .  R     8192     16 /extra1/50k
 118      fop_getpage          .  R     8192     24 /extra1/50k
 119      fop_getpage          .  R     8192     32 /extra1/50k
 120      fop_getpage          .  R     8192     40 /extra1/50k
 121      fop_getpage          .  R     8192     48 /extra1/50k
 122      fop_putpage          .  W     8192      0 /extra1/outfile
 123      fop_putpage          .  W     8192      8 /extra1/outfile
 124      fop_putpage          .  W     8192     16 /extra1/outfile
 125      fop_putpage          .  W     8192     24 /extra1/outfile
 126      fop_putpage          .  W     8192     32 /extra1/outfile
 127      fop_putpage          .  W     8192     40 /extra1/outfile
 128        disk_io         dad1  W    51200      0 /extra1/outfile
 129