Guia de rastreamento dinâmico Solaris

Exemplos

O script de exemplo a seguir exibe informações pertinentes a cada E/S conforme é emitida:

#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");
}

O resultado da partida a frio do Acrobat Reader em um sistema de laptop x86 lembra o seguinte exemplo:


# 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
       ...

As entradas <none> no resultado indicam que a E/S não corresponde aos dados em nenhum arquivo em particular: essas E/Ss são devido a metadados de um formato ou outro. As entradas <unknown> no resultado indicam que o nome de caminho do arquivo não é conhecido. Essa situação é relativamente rara.

Você poderia tornar o script de exemplo um pouco mais sofisticado usando uma matriz de associação para controlar o tempo gasto em cada E/S, conforme mostrado no exemplo a seguir:

#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;
}

O resultado do exemplo acima durante a conexão automática de um dispositivo de armazenamento USB em um sistema de laptop x86 inativo é mostrado no exemplo a seguir:


# 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
       ... 

Você pode fazer várias observações sobre o mecanismo do sistema com base neste resultado. Primeiro, observe que o tempo de realização das primeiras E/Ss foi longo: aproximadamente 25 milissegundos cada. A causa dessa demora pode ter sido que o dispositivo cmdk0 teve a energia gerenciada no laptop. Segundo, observe a E/S devido ao driver scsa2usb(7D) que está sendo carregado para lidar com o dispositivo de armazenamento em massa USB. Terceiro, observe as gravações em /var/adm/messages à medida que o dispositivo é informado. Finalmente, observe a leitura dos geradores de link do dispositivo (os arquivos que terminam em link.so) , que supostamente lidam com o novo dispositivo.

O provedor io possibilita uma compreensão abrangente do resultado de iostat(1M). Suponha que você observe o resultado de iostat de forma similar ao exemplo a seguir:


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

Você pode usar o script iotime.d para ver estas E/Ss à medida que acontecem, conforme mostrado no exemplo a seguir:


    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

Este resultado parece mostrar que o arquivo archives.tar está sendo lido a partir de cmdk0 (em /export/archives ) e sendo gravado no dispositivo sd2 (em /mnt). Essa existência de dois arquivos chamados archives.tar operados separadamente em paralelo parece pouco provável. Para investigar melhor, você pode agregar dispositivo, aplicativo, ID de processo e bytes transferidos, conforme mostrado no exemplo a seguir:

#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", @);
}

A execução deste script por alguns segundos produz um resultado similar ao exemplo a seguir:


# dtrace -s ./whoio.d
^C
    DEVICE                  APP        PID           BYTES
     cmdk0                   cp        790         1515520
       sd2                   cp        790         1527808

Este resultado mostra que esta atividade é uma cópia do arquivo archives.tar de um dispositivo para outro. Essa conclusão leva a uma outra pergunta natural: um desses dispositivos é mais rápido que o outro? Qual dispositivo atua como limitador na cópia? Para responder a estas perguntas, você precisa conhecer o throughput efetivo de cada dispositivo em vez do número de bytes por segundo que cada dispositivo está transferindo. Você pode determinar o throughput com o seguinte script de exemplo:

#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", @);
}

A execução do script de exemplo por vários segundos produz o seguinte resultado:


  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        

O resultado mostra que sd2 é claramente o dispositivo limitador. O throughput sd2 está entre 256K/seg. e 512K/seg., enquanto cmdk0 está entregando E/S em qualquer ponto de 8 MB/segundo a mais de 64 MB/segundo. O script imprime o nome conforme visto em iostat e o caminho completo do dispositivo. Para descobrir mais sobre o dispositivo, você pode especificar o caminho do dispositivo para prtconf, conforme mostrado no exemplo a seguir:


# 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

Conforme os termos enfatizados indicam, este dispositivo é um dispositivo de armazenamento USB removível.

Os exemplos nesta seção exploraram todas as solicitações de E/S. Entretanto, você pode estar interessado em somente um tipo de solicitação. O exemplo a seguir controla os diretórios nos quais as gravações estão ocorrendo, junto com os aplicativos que estão realizando as gravações:

#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", @);
}

A execução deste script de exemplo em uma carga de área de trabalho por um período de tempo produz alguns resultados interessantes, conforme mostrado no seguinte resultado de exemplo:


# 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 o resultado indica, virtualmente todas as gravações são associadas ao cache do Mozilla Firebird. As gravações rotuladas <none> são provavelmente devido a gravações associadas ao log UFS, gravações que são, elas mesmas, induzidas por outras gravações no sistema de arquivos. Consulte ufs(7FS) para obter detalhes sobre log. Este exemplo mostra como usar o provedor io para descobrir um problema em uma camada mais elevada de software. Neste caso, o script revelou um problema de configuração: o navegador da Web induziria muito menos E/S (e provavelmente nenhuma) se o seu cache estivesse em um diretório em um sistema de arquivos tmpfs(7FS).

Os exemplos anteriores usaram somente os testes start e done. Você pode usar os testes wait-start e wait-done para compreender por que os aplicativos são bloqueados para E/S e por quanto tempo. O seguinte script de exemplo usa os testes de io e de sched (consulte o Capítulo 26Provedor sched) para derivar tempo de CPU em comparação ao tempo de espera de E/S do software 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);
}

A execução do script de exemplo durante uma partida a frio do software StarOffice produz o seguinte resultado:


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 este resultado mostra, grande parte do tempo de partida a frio do StarOffice é devido à espera por E/S. (13,1 segundos de espera por E/S em comparação a 3,6 segundos na CPU.) A execução do script em uma partida a quente do software StarOffice revela que o armazenamento em cache da página eliminou o tempo de E/S, conforme mostrado no seguinte resultado de exemplo:


Time breakdown (milliseconds):
  <I/O wait>                                                       0
  <on cpu>                                                      2860

I/O wait breakdown (milliseconds):
  temp                                                             0
  soffice.tmp                                                      0
  <unknown>                                                        0
  Office                                                           0

O resultado da partida a frio mostra que o arquivo applicat.rdb contabiliza mais tempo de espera por E/S que qualquer outro arquivo. Esse resultado provavelmente é devido à grande quantidade de E/Ss no arquivo. Para explorar as E/Ss realizadas nesse arquivo, você pode usar o seguinte script de 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);
}

Este script usa o campo fi_offset da estrutura fileinfo_t para compreender quais partes do arquivo estão sendo acessadas, na granularidade de um megabyte. A execução desse script durante uma partida a frio do software StarOffice produz um resultado similar ao seguinte exemplo:


# 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

Este resultado indica que somente os primeiros seis megabytes do arquivo são acessados, talvez porque o tamanho do arquivo seja de seis megabytes. O resultado também indica que o arquivo completo não é acessado. Se você desejasse aumentar o tempo da partida a frio do StarOffice, talvez desejasse compreender o padrão de acesso do arquivo. Se as seções necessárias do arquivo pudessem ser totalmente contíguas, uma forma de aumentar o tempo de partida a frio do StarOffice seria executar um segmento verificador antes do aplicativo, induzindo a E/S no arquivo antes do necessário. (Essa abordagem é particularmente fácil se o arquivo for acessado usando-se mmap(2).) Entretanto, o tempo de aproximadamente 1,6 segundos que essa estratégia ganharia na partida a frio não compensa a complexidade adicional e o aumento de manutenção no aplicativo. De qualquer forma, os dados coletados com o provedor io permitem uma compreensão precisa do benefício que tal trabalho poderia oferecer.