.comment-link {margin-left:.6em;}

Monday, December 18, 2006

Problema de Performance.

Algumas vezes na carreira de DBA, é preciso ir além do banco de dados para solucionar um problema de performance. Há três semanas, houve uma manutenção na infra-estrutura e os usuários de uma de nossas bases, começaram a perceber um aumento no tempo de resposta de suas aplicações diárias. Assim começa esse curioso problema de performance.

Quando fomos alertados, nossa equipe fez a primeira investigação e encontrou espera na gravação dos redos, resolvemos migrar os redologs para uma área exclusiva, já que esta atividade estava pendende havia algum tempo. Mesmo após a mudança, os usuários ainda reclamavam sobre desempenho levando um colega a reorganizar a base, porque notara linhas migradas. O tempo de export/import normal para a base de dados dos aplicativos era de no máximo 6 horas, qual a surpresa tomou 22 horas. Durante o procedimento de import, ele investigou as máquinas e estavam ociosas deixando a rede como óbvia ofensora nesse processo.

Noss ambiente está protegido por Dataguard com proteção Max Availability, onde é assegurado que não haverá perda de dados, portanto quando há commits, a gravação da redolog buffer é confirmada nos dois redos log files, tanto no primário quando no secundário. Portanto a rede é fundamental para esse processo. Além disso, o nó primário é composto por dois servidores em cluster (não RAC), em cluster do fabricante (HP).

Com o problema identificado, a questão agora era envolver a equipe de infra-estrutura na força-tarefa que havia sido criada para solucionar o issue, que até então era culpa exclusiva do banco de dados. A partir deste ponto, comecei a investigar a rede no sentido de provar o que realmente estava impactando o desempenho do banco. Buscamos as alterações em nosso sistema de Change Control para saber quais componentes havia sido alterados à época do início da ocorrência. vimos uma instalação de uma placa de rede no Switch do Servidor principal, portanto já era suficiente para envolver os engenheiros de rede, mas não, eles não vieram. O suporte nível um nos informou que não havia problema nas rotas e os gráficos não constatavam nenhuma mudança de comportamento na entrega dos pacotes. Voltaram-se os olhos novamente ao banco.

Quando surgiu a idéia de comparar velocidade nas rotas entre os nós primários e secundários dos outros ambientes que também estão usando Dataguard e não apresentávam problema. Voila - o RTT (Round-Trip Time) do pior era do 15ms (Milisegundos) e o box com problema era de 86ms.




$ ping -I 5 xxxx26 10240 3


PING xxxx26: 10240 byte packets
10240 bytes from 999.188.124.999: icmp_seq=0. time=87. ms
10240 bytes from 999.188.124.999: icmp_seq=1. time=87. ms
10240 bytes from 999.188.124.999: icmp_seq=2. time=86. ms

----xxxx26 PING Statistics----
3 packets transmitted, 3 packets received, 0% packet loss
round-trip (ms) min/avg/max = 86/87/87

Buscamos, com o comando traceroute verificar por onde o pacote viajava e finalmente o problema saltou aos olhos do pessoal de rede. O custo da entrega dos pacotes estava errada no switch e portanto forçava os pacotes irem até o meio do país e voltarem para o DataCenter correto. Uma vez resolvido o problema, vejamos a diferença nos statspacks (antes/depois).

ANTES


Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 358,551.08 936,950.59
Logical reads: 21,765.45 56,876.54
Block changes: 532.12 1,390.50
Physical reads: 258.55 675.64
Physical writes: 65.15 170.25
User calls: 89.23 233.16
Parses: 37.68 98.46
Hard parses: 3.10 8.11
Sorts: 15.03 39.28
Logons: 0.15 0.39
Executes: 108.45 283.39
Transactions: 0.38

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
log file sync 13,355 13,008 69.20
enqueue 353 1,001 5.33
library cache pin 330 970 5.16
LNS wait on SENDREQ 379 960 5.11
LGWR wait on LNS 484,141 958 5.10
-------------------------------------------------------------
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file sync 13,355 13,044 13,008 974 35.1
enqueue 353 330 1,001 2837 0.9
library cache pin 330 330 970 2939 0.9
LNS wait on SENDREQ 379 0 960 2533 1.0
LGWR wait on LNS 484,141 44,820 958 2 1,274.1
LGWR-LNS wait on channel 241,880 44,820 958 4 636.5
log file switch completion 283 261 266 938 0.7
buffer busy waits 26 13 38 1478 0.1
local write wait 35 34 34 968 0.1
db file sequential read 6,250 0 13 2 16.4
db file scattered read 24,772 0 11 0 65.2



DEPOIS





Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 8,662.55 64,046.10
Logical reads: 3,298.27 24,385.57
Block changes: 23.56 174.21
Physical reads: 0.88 6.53
Physical writes: 0.00 0.00
User calls: 26.41 195.25
Parses: 9.25 68.40
Hard parses: 0.88 6.53
Sorts: 1.11 8.21
Logons: 0.05 0.35
Executes: 13.57 100.30
Transactions: 0.14

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
PL/SQL lock timer 2,804 1,670 97.42
CPU time 22 1.28
LGWR wait on LNS 1,098 5 .27
LGWR-LNS wait on channel 483 5 .27
LNS wait on SENDREQ 132 5 .27
-------------------------------------------------------------
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
PL/SQL lock timer 2,804 2,804 1,670 596 23.0
LGWR wait on LNS 1,098 169 5 4 9.0
LGWR-LNS wait on channel 483 169 5 10 4.0
LNS wait on SENDREQ 132 0 5 35 1.1
db file sequential read 799 0 4 5 6.5
log file sync 108 0 4 33 0.9
process startup 6 0 0 57 0.0
log file parallel write 129 0 0 2 1.1



Algumas diferenças:

Geração de redos, com a liberação da rede, os redos não acumulam mais.

Tempo de espera no evento "log file sync" de 13000 segundos para 33. Entendendo o evento: a janela do statspacks foi de 900 segundos em 60 sessões, portanto 13000/60 = 216 segundos em média de espera para sincronizar os redos em 900 segundos/sessão. Depois: 33/60 = 0.55 segudos em 900 segundos/sessão.

Nem sempre o problema está no banco e quase sempre o ônus da prova é do DBA.

Labels:


Sunday, December 10, 2006

Missão Cumprida

Me sinto realizado, nossa turma foi um sucesso. Missão cumprida!

Aprendemos sobre a velha senhora, o funcionário que só carimba, a faxineira, o garçom, o cozinheiro e todos os que fazem parte da estrutura do banco de dados - em analogia é claro. Estranho para que lê, familiar para minha turma ;-)

O mercado tem nove novos padawans prontos para usarem a força. Fernando (da terra do chopp), Volnei, Eduardo, Douglas, Geisel, João, Edson, Luiz e Fernando (da Pro). Que turma! O que dizer? Eles participaram, criativos, tornaram nossa semana muito agradável.

Entenderam, não entenderam, brincaram, estudaram, perguntaram, questionaram acima de tudo. Cada um à sua maneira, deixou marcas - Fernando, o da terra do chopp, ensinou como devemos confiar na força e não nos palpites (perdemos uma base e eu, o almoço ;-), Volnei com idéias brilhantes de como ganhar mais dinheiro, depois de uma aula incentivadora sobre o tema, Edu - esse é figura! O Horácio (eu posso chamá-lo assim) o mais animado, embora tenha traumatizado criancinhas, foi o destaque, muito bem humorado, era responsável pelas lucesss e também pelo nosso pequeno happy hour (No Cais-Cais há uma placa: Turmas de Oracle Não São Bem-Vindas!). Douglas vai tomar de volta umas senhas que ele emprestou, Geisel nos proporcionou segurança na infra-estrutura (1 computador por aluno e nenhuma falha), Fernando o da Pro me ajudou com o Luiz que bebeu muuuuuito mas nem se compara ao João que ainda identificou vários xaropes na cerveja, dentre eles o de milho, framboesa e cassis. Para finalizar Edson, o mineiro, quietinho ele fez de suas anotações uma apostila melhor que a oficial.

Essa foi a espetacular turma da semana de 4 a 8 de dezembro de 2006. Um verdadeiro presente de Natal.

Parabéns senhores!

Márcio Portes.

Labels:


Saturday, December 02, 2006

Curso Oracle

Na próxima semana, de 4 a 8 de dezembro/2006 das 9h00 as 14h30, vou ministrar curso oficial da Oracle (Work Shop I) na Ensof, quem quiser tomar um café após as 16h30, me avise. ;-)

abraços,
Marcio Portes.

Labels:


This page is powered by Blogger. Isn't yours?