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.
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
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: Performance
