Verificando I/O com DTrace

Verificando I/O com DTrace

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.