Guía de seguimiento dinámico de Solaris

Ejemplos

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.