La siguiente secuencia de comandos de ejemplo muestra información pertinente de cada E/S según se emite:
#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"); }
La salida del ejemplo al iniciar en frío Acrobat Reader en un sistema portátil x86 se parece al siguiente ejemplo:
# 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 ... |
Las entradas <none> en la salida indican que la E/S no corresponde a los datos en ningún archivo particular: estas E/S se deben a los metadatos de una forma u otra. Las entradas <unknown> en la salida indican que el nombre de ruta del archivo es desconocido. La situación es relativamente rara.
La secuencia de comandos de ejemplo se podría hacer un poco más sofisticada, utilizando una matriz asociativa para realizar un seguimiento del tiempo empleado en cada E/S, como se muestra en el siguiente ejemplo:
#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; }
La salida del ejemplo anterior mientras se conecta en marcha un dispositivo de almacenamiento USB en un sistema portátil x86 inactivo se muestra en el siguiente ejemplo:
# 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 ... |
Se podrían realizar algunas observaciones en relación al mecanismo del sistema en base a esta salida. Primero, observe el gran periodo de tiempo empleado para realizar las primeras E/S, que fue alrededor de 25 milisegundos cada una. Este tiempo se puede deber al dispositivo cmdk0 cuya alimentación se ha administrado en el portátil. En segundo lugar, observe la E/S provocada por la carga del controlador scsa2usb(7D) para manejar el dispositivo de almacenamiento masivo USB. Tercero, observe las escrituras en /var/adm/messages conforme se informa del dispositivo. Y, por último, observe la lectura de los generadores de vínculos del dispositivo (los archivos que terminan en link.so), que, en teoría, manejan el nuevo dispositivo.
El proveedor io permite entender en profundidad la salida de iostat(1M). Supongamos que se observa una salida iostat similar a la del siguiente ejemplo:
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 |
Se puede utilizar la secuencia de comandos iotime.d para ver estas E/S conforme se producen, tal y como se muestra en el siguiente ejemplo:
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 |
Esta salida parece mostrar que el archivo archives.tar se está leyendo desde cmdk0 (en /export/archives), y se está escribiendo en el dispositivo sd2 (en /mnt). La existencia de dos archivos denominados archives.tar que se estén utilizando de forma independiente en paralelo parece poco probable. Si desea investigar aún más, puede agregar dispositivo, aplicación, Id. de proceso y bytes transferidos, como se muestra en el siguiente ejemplo:
#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", @); }
Si se ejecuta esta secuencia de comandos durante unos segundos, la salida será similar a la del siguiente ejemplo:
# dtrace -s ./whoio.d ^C DEVICE APP PID BYTES cmdk0 cp 790 1515520 sd2 cp 790 1527808 |
Esta salida muestra que esta actividad es una copia del archivo archives.tar de un dispositivo a otro. Esta conclusión conduce a otra pregunta lógica: ¿Uno de estos dispositivos es más rápido que el otro? ¿Qué dispositivo actúa como limitador en la copia? Para responder a estas preguntas, necesitará conocer el rendimiento efectivo de cada dispositivo, en lugar del número de bytes por segundo que transfiere cada dispositivo. Se puede determinar el rendimiento con la siguiente secuencia de comandos de ejemplo:
#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", @); }
Si se ejecuta la secuencia de comandos de ejemplo durante unos segundos, se producirá la siguiente salida:
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 |
La salida muestra que sd2es claramente el dispositivo que limita. El rendimiento de sd2se encuentra entre los 256 K/s y los 512 K/s, mientras que cmdk0 ofrece una E/S en todas partes desde 8 MB/s a más de 64 MB/s. La secuencia de comandos imprime ambos nombres tal y como aparecen en iostat, y la ruta completa del dispositivo. Para obtener más información sobre el dispositivo, puede especificar la ruta del dispositivo a prtconf, tal y como se muestra en el siguiente ejemplo:
# 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 |
Como indican los términos resaltados, este dispositivo es un dispositivo USB de almacenamiento extraíble.
Los ejemplos de esta sección han explorado todas las solicitudes de E/S. Sin embargo, es posible que sólo esté interesado en un tipo de solicitud. El siguiente ejemplo realiza un seguimiento de los directorios en los que se producen escrituras, junto con las aplicaciones que realizan las escrituras:
#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", @); }
Al ejecutar esta secuencia de comandos de ejemplo en una carga de trabajo de escritorio durante un periodo de tiempo, se producen algunos resultados interesantes, tal y como se muestra en la salida de ejemplo siguiente:
# 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 |
Como indica la salida, casi todas las escrituras se asocian a la antememoria de Mozilla Firebird. Las escrituras con etiqueta <none> es probable que se deban a escrituras asociadas al registro UFS, escrituras que son inducidas por otras escrituras del sistema de archivos. Consulte ufs(7FS) para obtener detalles sobre el registro. Este ejemplo muestra la utilización del proveedor io para descubrir un problema a un nivel mucho más alto de software. En este caso, la secuencia de comandos ha revelado un problema de configuración: el navegador Web provoca mucha menos E/S (y con bastante probabilidad, ninguna) si su antememoria se encontraba en un directorio de un sistema de archivos tmpfs(7FS).
Los ejemplos anteriores han utilizado únicamente los sondeos start y done. Es posible utilizar los sondeos wait-start y wait-done para entender por qué las aplicaciones bloquean E/S – y durante cuánto tiempo. La siguiente secuencia de comandos de ejemplo utiliza los sondeos io y sched (consulte el Capítulo 26Proveedor sched) para derivar el tiempo de CPU comparado con el tiempo de espera de E/S para el software de StarOffice:
#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); }
Al ejecutar la secuencia de comandos durante un inicio en frío del software StarOffice, se produce la siguiente salida:
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 |
Como muestra esta salida, gran parte del tiempo de inicio de StarOffice en frío se debe a la espera de E/S. (13,1 segundos a la espera de E/S en contraposición a 3,6 segundos para la CPU). La ejecución de la secuencia de comandos en un inicio en caliente del software StarOffice, revela que la antememoria de paginación ha eliminado el tiempo de E/S, tal y como se muestra en el siguiente ejemplo de salida:
Time breakdown (milliseconds): <I/O wait> 0 <on cpu> 2860 I/O wait breakdown (milliseconds): temp 0 soffice.tmp 0 <unknown> 0 Office 0 |
La salida de inicio en frío muestra que el archivo applicat.rdb presenta más tiempo de espera de E/S que ningún otro archivo. Probablemente, este resultado se deba a un alto número de E/S al archivo. Para explorar las E/S realizadas en este archivo, puede utilizar la siguiente secuencia de comandos 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); }
Esta secuencia de comandos utiliza el campo fi_offset de la estructura fileinfo_t para comprender a qué partes del archivo se está accediendo, en la granularidad de un megabyte. Al iniciar esta secuencia de comandos durante un inicio en frío del software StarOffice, se produce una salida similar al siguiente ejemplo:
# 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 |
Esta salida indica que sólo se accede a los seis primeros megabytes del archivo, quizá porque el archivo tiene seis megabytes de tamaño. La salida también indica que no se accede a todo el archivo. Si desea mejorar el tiempo de inicio en frío de StarOffice, es posible que desee entender el patrón de acceso del archivo. Si las secciones necesarias del archivo pudieran ser contiguas en gran parte, una forma de mejorar el tiempo de inicio en frío de StarOffice podría ser tener un subproceso explorador que ejecutara antes la aplicación, provocando la E/S al archivo antes de que sea necesaria (este enfoque es especialmente directo si se accede al archivo mediante mmap(2)). Sin embargo, los aproximadamente 1,6 segundos que esta estrategia haría ganar en el tiempo de inicio en frío, no merecerían la pena, dada la complejidad y el mantenimiento adicionales que suponen para la aplicación. De todas formas, los datos recopilados con el proveedor io permite una compresión precisa del beneficio que podría suponer este trabajo.