A ferramenta DTrace veio como mais uma arma contra o “TroubleChuting”, e aqui demonstro como utiliza-la para identificar qual o maior consumidor de I/O.
Os comandos mais complexos de DTrace geralmente são englobados em um scipt, mas eles também podem ser executados diretamente na linha de comando, para uma análise mais rápida.
Identificando via sar que há um gargalo de I/O em um Solaris 10 dedicado a uma Instance Oracle Database 11.2.0.2, imediatamente acusaríamos o banco de dados, e investigaríamos dentro deste onde está o consumo de I/O.
Não é bem assim.
Após o sar, confirmo via iostat o gargalo de I/O, vendo que se trata do device c0d0, que entre outras coisas abriga os DATAFILEs do Oracle Database.
Oracle Corporation SunOS 5.10 Generic Patch January 2005 # bash bash-3.00# uname -a SunOS nerv03 5.10 Generic_142910-17 i86pc i386 i86pc bash-3.00# cat /etc/release Oracle Solaris 10 9/10 s10x_u9wos_14a X86 Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved. Assembled 11 August 2010 bash-3.00# iostat -xnz 2 10 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 30.4 140.3 530.4 2209.7 3.6 0.5 20.9 3.0 14 33 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 22.7 117.3 215.5 858.0 0.0 0.4 0.1 2.7 1 29 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 17.0 23.5 164.0 134.0 0.0 0.2 0.7 5.0 3 16 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 15.5 121.5 278.0 884.0 0.1 0.3 0.5 2.0 4 20 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 17.5 162.0 204.0 1200.0 0.1 0.4 0.5 2.4 7 31 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 16.0 28.0 168.0 144.0 0.0 0.3 0.6 6.5 2 24 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 20.5 174.0 228.0 1248.0 0.1 0.4 0.6 2.2 6 31 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 16.0 155.5 240.0 1076.0 0.2 0.3 1.2 1.9 3 25 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 24.0 48.5 236.0 218.0 0.2 0.3 2.8 4.7 3 28 c0d0 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device 17.0 128.5 168.0 852.0 0.1 0.3 0.7 2.3 4 24 c0d0
Para verificar quais são os processos e arquivos que estão fazendo mais leituras no Sistema Operacional via DTrace, utilizo o comando abaixo. Este comando coleta os dados mas não fornece nenhum retorno, até que seja cancelado via Crtl+C. Portanto, eu espero cerca de 10 minutos, cancelo o comando, e verifico o resultado.
bash-3.00# dtrace -n 'syscall::*read:entry {@f[execname, fds[arg0].fi_pathname] = count();}'
dtrace: description 'syscall::*read:entry ' matched 2 probes
^C
automountd 1
oradism 1
sshd 1
utmpd /proc/1769/psinfo 1
utmpd /proc/845/psinfo 1
utmpd /proc/985/psinfo 1
gnome-terminal 2
metacity 2
nautilus 2
nscd /etc/inet/hosts 2
oracle /proc/1259/psinfo 2
oracle /proc/1263/psinfo 2
oracle /proc/1275/psinfo 2
oracle /proc/1277/psinfo 2
oracle /proc/1279/psinfo 2
oracle /proc/1281/psinfo 2
oracle /proc/1283/psinfo 2
oracle /proc/1309/psinfo 2
oracle /proc/1324/psinfo 2
oracle /proc/1326/psinfo 2
oracle /proc/1459/psinfo 2
oracle /proc/1662/psinfo 2
oracle /proc/1664/psinfo 2
oracle /proc/1666/psinfo 2
oracle /proc/1668/psinfo 2
oracle /proc/1670/psinfo 2
oracle /proc/1672/psinfo 2
oracle /proc/1674/psinfo 2
oracle /proc/1676/psinfo 2
oracle /proc/1678/psinfo 2
oracle /proc/1680/psinfo 2
oracle /proc/1682/psinfo 2
oracle /proc/1684/psinfo 2
oracle /proc/1686/psinfo 2
oracle /proc/1688/psinfo 2
oracle /proc/1690/psinfo 2
oracle /proc/1780/psinfo 2
oracle /proc/1875/psinfo 2
oracle /proc/1977/psinfo 2
oracle /proc/1981/psinfo 2
oracle /proc/1983/psinfo 2
utmpd /var/adm/utmpx 2
utmpd /var/adm/wtmpx 2
wnck-applet 2
clock-applet 4
gnome-smproxy 5
oracle /u01/app/oracle/fast_recovery_area/ORCL/controlfile/o1_mf_76kvsvb3_.ctl 5
oracle /proc/1298/psinfo 8
oracle /proc/1301/psinfo 8
oracle /proc/1303/psinfo 8
oracle /proc/1305/psinfo 8
oracle /proc/1246/psinfo 26
oracle /proc/1248/psinfo 42
oracle /proc/1253/psinfo 42
oracle /proc/1257/psinfo 42
oracle /proc/1261/psinfo 42
oracle /proc/1265/psinfo 42
oracle /proc/1267/psinfo 42
oracle /proc/1269/psinfo 42
oracle /proc/1271/psinfo 42
oracle /proc/1273/psinfo 42
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_system_76kvqzkd_.dbf 55
xscreensaver 56
oracle /u01/app/oracle/oradata/ORCL/controlfile/o1_mf_76kvsv4s_.ctl 185
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw2cvf_.dbf 428
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw1rlr_.dbf 485
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw2gnf_.dbf 494
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw2kvn_.dbf 527
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw25xf_.dbf 590
oracle 1574
Xorg 2206
java 3098
bash-3.00#
Como vimos acima, na verdade o maior gerador de leituras é o java, e não o Oracle Database. Até o Xorg, que não devia estar em uso, causa mais leituras do que o Oracle Database.
Vamos verificar agora as gravações, com um comando parecido.
bash-3.00# dtrace -n 'syscall::*write:entry {@f[execname, fds[arg0].fi_pathname] = count();}'
dtrace: description 'syscall::*write:entry ' matched 2 probes
^C
dtrace /devices/pseudo/pts@0:3 1
sshd /devices/pseudo/clone@0:ptm 1
sshd 1
init /etc/svc/volatile/init-next.state 2
gnome-netstatus- 7
xscreensaver 21
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_undotbs1_76kvqzmm_.dbf 27
oracle /u01/app/oracle/fast_recovery_area/ORCL/controlfile/o1_mf_76kvsvb3_.ctl 28
oracle /u01/app/oracle/oradata/ORCL/controlfile/o1_mf_76kvsv4s_.ctl 28
clock-applet 62
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw2cvf_.dbf 269
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw2gnf_.dbf 269
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw1rlr_.dbf 280
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw25xf_.dbf 337
oracle /u01/app/oracle/oradata/ORCL/datafile/o1_mf_soe_76kw2kvn_.dbf 367
java 538
oracle 754
oracle /u01/app/oracle/fast_recovery_area/ORCL/onlinelog/o1_mf_5_76kml2r4_.log 1122
oracle /u01/app/oracle/oradata/ORCL/onlinelog/o1_mf_5_76kmk8bs_.log 1122
bash-3.00#
As gravações sim são mais executadas no Oracle Database, mas lá está o java ajudando na lentidão.
Esta é uma análise superficial, pois considerou apenas a quantidade de gravações, e não o seu tamanho, mas já demonstra como encontrar informações detalhadas sobre o comportamento do Sistema Operacional via DTrace.