Home | History | Annotate | Line # | Download | only in Examples
      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 
    130