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.
- © 2010, Oracle Corporation and/or its affiliates