Redo Log Analysis: 2. A “log file sync” case

por Vinicius Hoffmann

Saudações galera!Este é o primeiro artigo de análise da utilização dos Redo Log Files pelo Banco de Dados. O case abaixo se baseia em um problema real de servidor de produção.

Vamos começar?

Segue abaixo a configuração do servidor:

Database: Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 – 64bits (Single Instance com ASM)
OS: HP-UX xxxxxxxx B.11.11 U 9000/800 3743309575 unlimited-user license
Hardware: 16 Processors PA8900 plus 32gb of Ram Memory
System Global Area:
Total System Global Area 11.173.625.856 bytes
Fixed Size ……………… 2.087.872 bytes
Variable Size ……….. 1.426.064.448 bytes
Database Buffers …….. 9.730.785.280 bytes
Redo Buffers …………… 14.688.256 bytes

Versão do Mandela utilizada: 4.2.2.6

Agora que já temos as configurações básicas do servidor o primeiro passo, como em qualquer análise de uma base de dados Oracle, é extrair um gráfico de Wait Events na linha do tempo:
Analisando o gráfico, podemos observar um aumento dos eventos de “log file sync” e “log buffer space” a partir do dia 29/06, ambos eventos estão relacionados à utilização dos Redo Log Files.
Click image for larger version    Name:	Wait Events.jpg  Views:	285  Size:	101.7 KB  ID:	51

“Oracle Database” > “Wait Events” > “Stacked Area Graph”

Para entender melhor os eventos:

  • O “log file sync” pode ser descrito como o estado atual da sessão de usuário que efetuou o commit. É um Wait Event, pois esta é uma espera pelo processo LogWriter (LGWR) retornar que a sincronização do Log Buffer com os Redo Logs foi completada com sucesso.
  • Já o “log buffer space” é o estado da sessão que aguarda por espaço no Log Buffer para escrever suas entradas de Redo proveniente de seus DMLs.

Quando visualisamos um aumento do “log file sync” como o exposto no gráfico acima, este aumento pode estar relacionado com 3 fatores principais e alguns sub-fatores:

  1. O volume individual de cada transação (INSERTs, UPDATEs, DELETEs) de dados aumentou
  2. O número de transações aumentou
    1. Devido à diminuição do volume individual das transações, ou seja, o volume total de dados continua o mesmo, porém as transações estão mais curtas
    2. Ou devido ao aumento absoluto do número de transações, ou seja, o volume de dados total também aumentou com o aumento do número de transações
  3. Houve uma degradação na velocidade que o LGWR faz a etapa de sincronismo do Log Buffer para os Redo Logs, ou seja, o tempo total de escrita nos logs aumentou
    1. Devido a uma má distribuição lógica das partes de disco que o storage entraga para os Filesystems do SO (no caso de não utlizar ASM)
    2. Devido a problemas de infra-estrutura na comunicação com o Storage: HBA, Fibra, Switch, Fibra, FA, Storage Frond/Back End, Controladoras, Discos lentos ou slices de discos lentos misturados com discos rápidos

Este conceito acima pode ser abstraído para qualquer outra análise em qualquer outra tecnologia onde você possui métricas do ambiente em situação normal e métricas do ambiente com o problema instaurado.
Consulte o blog post para entender melhor:
Troubleshooting Methodology – 1. Picking a Peak!

Agora vamos às evidências…
OBS: No caso da análise de Redo Log, todas evidências podem ser obtidas através da ferramenta. Abaixo de cada gráfico você pode aprender a sequência de botões para gerar o gráfico.

A primeira evidência da degradação do tempo de resposta é o gráfico de Wait Events que visualizamos anteriormente, com ele fica possível afirmar que o problema se iniciou no dia 29/06.

O próximo passo é responder à pergunta “O tempo total da operação aumentou?”. O gráfico de eventos de espera nos dá uma indicação e o gráfico abaixo com a métrica correta nos confirma isso:

Click image for larger version    Name:	Redo Write Time.jpg  Views:	268  Size:	99.0 KB  ID:	52

“Oracle Database” > “Redo Statistics” > “Customize” > “Statistic: redo write time” | “Metric Unit: Number of Times” | “Convert: Do not Convert” | “Compute delta = CHECKED” > “Click on Close”

Vemos que realmente, a partir do dia 29/06, o tempo total de escrita no redo aumentou. Imediatamente nos surge a segunda pergunta na mente “O volume total de dados aumentou?”. Vamos verificar:

Click image for larger version    Name:	Redo Blocks Written.jpg  Views:	262  Size:	98.7 KB  ID:	53

“Oracle Database” > “Redo Statistics” > “Customize” > “Statistic: redo blocks writen” | “Metric Unit: Number of Blocks” | “Convert: Do not Convert” | “Compute delta = CHECKED” > “Click on Close”

Descobrimos que o volume total de dados (blocos) escritos no redo não aumentou, portanto a hipótese de ter acontecido um aumento de carga ou de volumetria das tabelas do ambiente não é sustentável a princípio.
Isto nos remete à terceira pergunta “O número total de interações aumentou?”. Vamos ver:

Click image for larger version    Name:	Redo Writes.jpg  Views:	261  Size:	98.9 KB  ID:	56

“Oracle Database” > “Redo Statistics” > “Customize” > “Statistic: redo writes” | “Metric Unit: Number of Times” | “Convert: Do not Convert” | “Compute delta = CHECKED” > “Click on Close”

Como nem o volume e nem o número total de interações aumentaram, podemos afirmar que não há indícios de alteração no comportamento do ambiente, portanto a análise recairá agora na infra-estrutura de comunicação entre o servidor de banco de dados e o sistema de storage.

Neste caso posso adiantar a vocês que o problema estava na comunicação Servidor -> Storage, mais especificamente na Fibra Ótica que ligava a HBA do servidor com o Switch de Storage.

Como a análise possuia evidências gráficas e uma linha de raciocínio lógica até a causa raiz do problema, o pessoal do suporte atuou prontamente na identificação da causa raiz e resolveu o problema de forma rápida, restaurando a qualidade de serviço para o usuário.

Isto prova como é importante nas entregas a montagem das evidências visuais para seguir uma linha de raciocínio que direcione o próprio leitor à mesma conclusão que você apresenta, desta forma fica clara a causa raiz e os próximos passos da análise.

Leituras complementares:

Deixe um comentário