#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"); }
在 x86 膝上型计算机系统上冷启动 Acrobat Reader 时的示例输出与以下示例类似:
# dtrace -s ./iosnoop.d DEVICE FILE RW cmdk0 /opt/Acrobat4/bin/acroread R cmdk0 /opt/Acrobat4/bin/acroread R cmdk0 <unknown> R cmdk0 /opt/Acrobat4/Reader/AcroVersion R cmdk0 <unknown> R cmdk0 <unknown> R cmdk0 <none> R cmdk0 <unknown> R cmdk0 <none> R cmdk0 /usr/lib/locale/iso_8859_1/iso_8859_1.so.3 R cmdk0 /usr/lib/locale/iso_8859_1/iso_8859_1.so.3 R cmdk0 /usr/lib/locale/iso_8859_1/iso_8859_1.so.3 R cmdk0 <none> R cmdk0 <unknown> R cmdk0 <unknown> R cmdk0 <unknown> R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 <none> R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 <unknown> R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 <none> R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libreadcore.so.4.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 /opt/Acrobat4/Reader/intelsolaris/bin/acroread R cmdk0 <unknown> R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libAGM.so.3.0 R cmdk0 <none> R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libAGM.so.3.0 R cmdk0 /opt/Acrobat4/Reader/intelsolaris/lib/libAGM.so.3.0 R ... |
输出中的 <none> 条目指示 I/O 与任何特定文件中的数据都不对应:这些 I/O 是由于元数据的形式不同造成的。输出中的 <unknown> 条目指示该文件的路径名未知。此情况相对较少。
可通过使用关联数组跟踪每个 I/O 所花费的时间来使示例脚本更加完善,如下例所示:
#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; }
在将 USB 存储设备热插拔到空闲的 x86 膝上型计算机系统中时,上述示例的输出将如下例所示:
# dtrace -s ./iotime.d DEVICE FILE RW MS cmdk0 /kernel/drv/scsa2usb R 24.781 cmdk0 /kernel/drv/scsa2usb R 25.208 cmdk0 /var/adm/messages W 25.981 cmdk0 /kernel/drv/scsa2usb R 5.448 cmdk0 <none> W 4.172 cmdk0 /kernel/drv/scsa2usb R 2.620 cmdk0 /var/adm/messages W 0.252 cmdk0 <unknown> R 3.213 cmdk0 <none> W 3.011 cmdk0 <unknown> R 2.197 cmdk0 /var/adm/messages W 2.680 cmdk0 <none> W 0.436 cmdk0 /var/adm/messages W 0.542 cmdk0 <none> W 0.339 cmdk0 /var/adm/messages W 0.414 cmdk0 <none> W 0.344 cmdk0 /var/adm/messages W 0.361 cmdk0 <none> W 0.315 cmdk0 /var/adm/messages W 0.421 cmdk0 <none> W 0.349 cmdk0 <none> R 1.524 cmdk0 <unknown> R 3.648 cmdk0 /usr/lib/librcm.so.1 R 2.553 cmdk0 /usr/lib/librcm.so.1 R 1.332 cmdk0 /usr/lib/librcm.so.1 R 0.222 cmdk0 /usr/lib/librcm.so.1 R 0.228 cmdk0 /usr/lib/librcm.so.1 R 0.927 cmdk0 <none> R 1.189 ... cmdk0 /usr/lib/devfsadm/linkmod R 1.110 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_audio_link.so R 1.763 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_audio_link.so R 0.161 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_cfg_link.so R 0.819 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_cfg_link.so R 0.168 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_disk_link.so R 0.886 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_disk_link.so R 0.185 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_fssnap_link.so R 0.778 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_fssnap_link.so R 0.166 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_lofi_link.so R 1.634 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_lofi_link.so R 0.163 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_md_link.so R 0.477 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_md_link.so R 0.161 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link.so R 0.198 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link.so R 0.168 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link.so R 0.247 cmdk0 /usr/lib/devfsadm/linkmod/SUNW_misc_link_i386.so R 1.735 ... |
可以根据此输出从多方面观察该系统的结构。首先,应注意到前几个 I/O 操作的执行时间很长,每个操作所花费的时间大概是 25 毫秒。此执行时间可能是由于膝上型计算机上的 cmdk0 设备的电源管理造成的。其次,应观察到由于要处理 USB 海量存储设备而装入 scsa2usb(7D) 驱动程序时产生的 I/O。第三,应注意到在报告设备时将写入 /var/adm/messages。最后,应观察到对设备链接生成器(文件名以 link.so 结尾)的读取,它们可能用于处理新设备。
通过 io 提供器可以深入了解 iostat(1M) 输出。假定您观察到类似以下示例的 iostat 输出:
extended device statistics device r/s w/s kr/s kw/s wait actv svc_t %w %b cmdk0 8.0 0.0 399.8 0.0 0.0 0.0 0.8 0 1 sd0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 sd2 0.0 109.0 0.0 435.9 0.0 1.0 8.9 0 97 nfs1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 nfs2 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 |
可使用 iotime.d 脚本来查看所发生的 I/O,如下例所示:
DEVICE FILE RW MS sd2 /mnt/archives.tar W 0.856 sd2 /mnt/archives.tar W 0.729 sd2 /mnt/archives.tar W 0.890 sd2 /mnt/archives.tar W 0.759 sd2 /mnt/archives.tar W 0.884 sd2 /mnt/archives.tar W 0.746 sd2 /mnt/archives.tar W 0.891 sd2 /mnt/archives.tar W 0.760 sd2 /mnt/archives.tar W 0.889 cmdk0 /export/archives/archives.tar R 0.827 sd2 /mnt/archives.tar W 0.537 sd2 /mnt/archives.tar W 0.887 sd2 /mnt/archives.tar W 0.763 sd2 /mnt/archives.tar W 0.878 sd2 /mnt/archives.tar W 0.751 sd2 /mnt/archives.tar W 0.884 sd2 /mnt/archives.tar W 0.760 sd2 /mnt/archives.tar W 3.994 sd2 /mnt/archives.tar W 0.653 sd2 /mnt/archives.tar W 0.896 sd2 /mnt/archives.tar W 0.975 sd2 /mnt/archives.tar W 1.405 sd2 /mnt/archives.tar W 0.724 sd2 /mnt/archives.tar W 1.841 cmdk0 /export/archives/archives.tar R 0.549 sd2 /mnt/archives.tar W 0.543 sd2 /mnt/archives.tar W 0.863 sd2 /mnt/archives.tar W 0.734 sd2 /mnt/archives.tar W 0.859 sd2 /mnt/archives.tar W 0.754 sd2 /mnt/archives.tar W 0.914 sd2 /mnt/archives.tar W 0.751 sd2 /mnt/archives.tar W 0.902 sd2 /mnt/archives.tar W 0.735 sd2 /mnt/archives.tar W 0.908 sd2 /mnt/archives.tar W 0.753 |
此输出似乎说明正在从 cmdk0(在 /export/archives 中)读取文件 archives.tar,且正在将该文件写入到设备 sd2(在 /mnt 中)。这种并行地对名为 archives.tar 的两个文件进行独立处理的情况似乎不可能存在。为了进一步地深入了解,可对设备、应用程序、进程 ID 和所传送的字节数进行聚集,如下例所示:
#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", @); }
运行此脚本几秒钟后将生成与以下示例类似的输出:
# dtrace -s ./whoio.d ^C DEVICE APP PID BYTES cmdk0 cp 790 1515520 sd2 cp 790 1527808 |
此输出说明此活动是将文件 archives.tar 从一个设备复制到另一个设备。此结论会很自然地引出另一个问题:这些设备中是否有一个设备的运行速度比另一个设备的运行速度更快?哪个设备限制了复制操作?要回答这些问题,您需要知道每个设备的有效吞吐量而不是每个设备每秒传送的字节数。可以使用以下示例脚本来确定吞吐量:
#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 can't calculate this using integer arithmetic without losing * precision (the denomenator, 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 is what * we do below. */ 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", @); }
运行示例脚本几秒钟后会产生以下输出:
sd2 (/devices/pci@0,0/pci1179,1@1d/storage@2/disk@0,0:r) value ------------- Distribution ------------- count 32 | 0 64 | 3 128 | 1 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2257 512 | 1 1024 | 0 cmdk0 (/devices/pci@0,0/pci-ide@1f,1/ide@0/cmdk@0,0:a) 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 |
该输出说明 sd2 很明显是限制设备。sd2 的吞吐量介于 256K/秒和 512K/秒之间,而cmdk0 在任何位置传送 I/O 的速率都是 8 MB/秒到超过 64 MB/秒。该脚本列显了设备的名称(可在 iostat 中看到)和完整路径。要了解有关设备的更多信息,可向 prtconf 指定设备路径,如下例所示:
# prtconf -v /devices/pci@0,0/pci1179,1@1d/storage@2/disk@0,0 disk, instance #2 (driver name: sd) Driver properties: name='lba-access-ok' type=boolean dev=(29,128) name='removable-media' type=boolean dev=none name='pm-components' type=string items=3 dev=none value='NAME=spindle-motor' + '0=off' + '1=on' name='pm-hardware-state' type=string items=1 dev=none value='needs-suspend-resume' name='ddi-failfast-supported' type=boolean dev=none name='ddi-kernel-ioctl' type=boolean dev=none Hardware properties: name='inquiry-revision-id' type=string items=1 value='1.04' name='inquiry-product-id' type=string items=1 value='STORAGE DEVICE' name='inquiry-vendor-id' type=string items=1 value='Generic' name='inquiry-device-type' type=int items=1 value=00000000 name='usb' type=boolean name='compatible' type=string items=1 value='sd' name='lun' type=int items=1 value=00000000 name='target' type=int items=1 value=00000000 |
如强调项中所指示的那样,此设备是可移除的 USB 存储设备。
本节中的示例已经研究了所有 I/O 请求。但是,您可能只关注一种请求类型。以下示例将跟踪要进行写操作的目录以及执行写操作的应用程序:
#pragma D option quiet io:::start /args[0]->b_flags & B_WRITE/ { @[execname, args[2]->fi_dirname] = count(); } END { printf("%20s %51s %5s\n", "WHO", "WHERE", "COUNT"); printa("%20s %51s %5@d\n", @); }
在台式机上运行此示例脚本一段时间会生成一些值得关注的结果,如以下示例输出所示:
# dtrace -s ./whowrite.d ^C WHO WHERE COUNT su /var/adm 1 fsflush /etc 1 fsflush / 1 fsflush /var/log 1 fsflush /export/bmc/lisa 1 esd /export/bmc/.phoenix/default/78cxczuy.slt/Cache 1 fsflush /export/bmc/.phoenix 1 esd /export/bmc/.phoenix/default/78cxczuy.slt 1 vi /var/tmp 2 vi /etc 2 cat <none> 2 bash / 2 vi <none> 3 xterm /var/adm 3 fsflush /export/bmc 7 MozillaFirebird <none> 8 vim /export/bmc 9 MozillaFirebird /export/bmc 10 fsflush /var/adm 11 devfsadm /dev 14 ksh <none> 71 ksh /export/bmc 71 fsflush /export/bmc/.phoenix/default/78cxczuy.slt 119 MozillaFirebird /export/bmc/.phoenix/default/78cxczuy.slt 119 fsflush <none> 211 MozillaFirebird /export/bmc/.phoenix/default/78cxczuy.slt/Cache 591 fsflush /export/bmc/.phoenix/default/78cxczuy.slt/Cache 666 sched <none> 2385 |
如以上输出所示,所有写操作实际上都与 Mozilla Firebird 高速缓存关联。标有 <none> 的写操作可能是由文件系统中的其他与 UFS 日志关联的写操作而引发的。有关日志记录的详细信息,请参见 ufs(7FS)。此示例说明如何使用 io 提供器来发现更高层次的软件问题。在此情况下,脚本显示存在配置问题:如果 Web 浏览器的高速缓存位于 tmpfs(7FS) 文件系统的某个目录中,则它引起的 I/O 会少得多(并且很可能根本没有任何 I/O)。
前面的示例中仅使用了 start 和 done 探测器。可使用 wait-start 和 wait-done 探测器来了解为什么应用程序会因为 I/O 阻塞以及阻塞多长时间。以下示例脚本同时使用 io 探测器和 sched 探测器(请参见第 26 章)来获取 CPU 时间(相对于 StarSuite 软件的 I/O 等待时间):
#pragma D option quiet sched:::on-cpu /execname == "soffice.bin"/ { self->on = vtimestamp; } sched:::off-cpu /self->on/ { @time["<on cpu>"] = sum(vtimestamp - self->on); self->on = 0; } io:::wait-start /execname == "soffice.bin"/ { self->wait = timestamp; } io:::wait-done /self->wait/ { @io[args[2]->fi_name] = sum(timestamp - self->wait); @time["<I/O wait>"] = sum(timestamp - self->wait); self->wait = 0; } END { printf("Time breakdown (milliseconds):\n"); normalize(@time, 1000000); printa(" %-50s %15@d\n", @time); printf("\nI/O wait breakdown (milliseconds):\n"); normalize(@io, 1000000); printa(" %-50s %15@d\n", @io); }
在 StarSuite 软件冷启动期间运行示例脚本将产生以下输出:
Time breakdown (milliseconds): <on cpu> 3634 <I/O wait> 13114 I/O wait breakdown (milliseconds): soffice.tmp 0 Office 0 unorc 0 sbasic.cfg 0 en 0 smath.cfg 0 toolboxlayout.xml 0 sdraw.cfg 0 swriter.cfg 0 Linguistic.dat 0 scalc.cfg 0 Views.dat 0 Store.dat 0 META-INF 0 Common.xml.tmp 0 afm 0 libsimreg.so 1 xiiimp.so.2 3 outline 4 Inet.dat 6 fontmetric 6 ... libucb1.so 44 libj641si_g.so 46 libX11.so.4 46 liblng641si.so 48 swriter.db 53 libwrp641si.so 53 liblocaledata_ascii.so 56 libi18npool641si.so 65 libdbtools2.so 69 ofa64101.res 74 libxcr641si.so 82 libucpchelp1.so 83 libsot641si.so 86 libcppuhelper3C52.so 98 libfwl641si.so 100 libsb641si.so 104 libcomphelp2.so 105 libxo641si.so 106 libucpfile1.so 110 libcppu.so.3 111 sw64101.res 114 libdb-3.2.so 119 libtk641si.so 126 libdtransX11641si.so 127 libgo641si.so 132 libfwe641si.so 150 libi18n641si.so 152 libfwi641si.so 154 libso641si.so 173 libpsp641si.so 186 libtl641si.so 189 <unknown> 189 libucbhelper1C52.so 195 libutl641si.so 213 libofa641si.so 216 libfwk641si.so 229 libsvl641si.so 261 libcfgmgr2.so 368 libsvt641si.so 373 libvcl641si.so 741 libsvx641si.so 885 libsfx641si.so 993 <none> 1096 libsw641si.so 1365 applicat.rdb 1580 |
如此输出所示,大部分 StarSuite 冷启动时间是由于等待 I/O 造成的。(等待 I/O 花费 13.1 秒,启动 CPU 花费 3.6 秒。)在热启动 StarSuite 软件时,运行该脚本显示出页面高速缓存已经消除了 I/O 时间,如以下示例输出所示:
Time breakdown (milliseconds): <I/O wait> 0 <on cpu> 2860 I/O wait breakdown (milliseconds): temp 0 soffice.tmp 0 <unknown> 0 Office 0 |
冷启动输出显示,与任何其他文件相比,文件 applicat.rdb 引起的 I/O 等待时间最长。此结果可能是由于对文件执行了许多 I/O 操作造成的。要研究对此文件执行的 I/O 操作,可使用以下 D 脚本:
io:::start /execname == "soffice.bin" && args[2]->fi_name == "applicat.rdb"/ { @ = lquantize(args[2]->fi_offset != -1 ? args[2]->fi_offset / (1000 * 1024) : -1, 0, 1000); }
此脚本使用 fileinfo_t 结构的 fi_offset 字段来了解要访问文件的哪些部分(以兆字节为单位)。在 StarSuite 软件冷启动期间运行此脚本将产生与以下示例类似的输出:
# dtrace -s ./applicat.d dtrace: script './applicat.d' matched 4 probes ^C value ------------- Distribution ------------ count < 0 | 0 0 |@@@ 28 1 |@@ 17 2 |@@@@ 35 3 |@@@@@@@@@ 72 4 |@@@@@@@@@@ 78 5 |@@@@@@@@ 65 6 | 0 |
此输出指示仅访问文件的前六兆字节,这可能是因为文件的大小为六兆字节。输出还指示未访问整个文件。如果要缩短 StarSuite 的冷启动时间,则可能需要了解文件的访问模式。如果文件的各个必需部分大多数是相连的,则可能缩短 StarSuite 冷启动时间的一个方法是在运行应用程序之前先运行侦察线程,从而提前执行文件所需的 I/O 操作。(如果通过使用 mmap(2) 来访问文件,则此方法最简单。)此策略可使冷启动时间缩短大约 1.6 秒,但会额外增加应用程序的复杂程度和维护负担。通过任一方法,使用 io 提供器收集的数据有助于更好地了解此类工作最终带来的好处。