Saiba como um erro simples de aplicação pode detonar um banco de dados

maio 1, 2016 V. J.A. Parse

O problema tratado neste artigo ocorreu em um de nossos clientes com uma aplicação de um terceiro, esse problema causou um grande impacto no banco de dados pois fez o banco aumentar o consumo de CPU e atingir um LOAD 30 nos dois nodes do RAC. Para simular o problema vamos utilizar uma base Oracle 11.2.0.4 instalada num servidor virtual com 1 processador, essa configuração é muito diferente da configuração de produção onde o problema ocorreu mas serve para ilustrar e facilitar o entendimento do problema.

Visão geral do problema

Cenário:

Banco de dados Oracle RAC 11.2.0.4 com servidor Oracle Linux el6 x86_64;

Aplicação WEB com milhares de usuários que num determinado dia do mês tem uma volume muito grande de acessos;

O problema ocorre nesse dia de pico de acesso;

Sintomas:

O Consumo de CPU dos 2 nodes do RAC aumenta e atinge um LOAD de 30;

Não foi identificada qualquer instrução SQL que estivesse com auto consumo de CPU;

Relatório AWR indica os eventos “library cache lock” e “library cache: mutex X” entre os três maiores eventos de WAIT;

Na seção Time Model do AWR verificamos que a estatística “failed parse elapse time” atigiu 22% do DBTime da base;

Causa:

Foi identificada uma consulta de uma tabela que não existia na base e era executada por quase todas as sessões que estavam acessando a aplicação;

Contorno:

Criação da tabela inexistente;

Title of the document

Ajudo DBAs e analistas de sistema a se destacarem em suas empresas

e obter um crescimento mais acelerado em suas carreiras, quer saber mais click no link abaixo:

https://dbtimewizard.com.br/mentoria

Solução:

Solicitar ao fornecedor da aplicação para alterar o código e excluir a consulta que esta causando o problema, já que aparentemente ela não afeta a funcionalidade da aplicação.

Simulação do problema

Para simular o problema utilizamos uma base Oracle 11.2.0.4 num servidor Linux virtual com 1 processador e realizamos os seguintes passos:

1. Criamos um programa Java para simular a aplicação enviando 500 vezes por segundo uma consulta que acessa uma tabela inexistente;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71

import java.sql.*;

public class OracleJDBC {

public static void main(String[] argv) {

System.out.println("-------- Oracle JDBC Query Test ------------");

try {

Class.forName("oracle.jdbc.driver.OracleDriver");

} catch (ClassNotFoundException e) {

System.out.println("Where is your Oracle JDBC Driver?");
e.printStackTrace();
return;

}

System.out.println("Oracle JDBC Driver Registered!");

try {

Connection connection = DriverManager.getConnection("jdbc:oracle:thin:@192.168.57.111:1521:lab11","dbtw","oracle");

Statement stmt = connection.createStatement();

int count = 1;
while (count < 100000) {

try {

ResultSet rset = stmt.executeQuery("select * from dbtw_users where cont=2");
rset.next();
System.out.println ("Line number: " + rset.getInt(1));
rset.close();

} catch (SQLException e) {

System.out.println("Query Failed! ("+count+")" );
System.out.println(e);

}

count++;
try {
Thread.sleep(2); //1000 milliseconds is one second.
} catch(InterruptedException ex) {
Thread.currentThread().interrupt();
}

}

stmt.close();
connection.close();

} catch (SQLException e) {

System.out.println("Connection Failed! Check output console");
e.printStackTrace();
return;

}

System.out.println("End of program");

}

}

2. Abrimos 10 sessões CMD num desktop Windows e acionando o programa Java acima;

3. Aguardamos alguns segundos e o servidor de banco atingiu um Load 8;

4. Emitimos um relatório AWR da base e verificamos os eventos “library cache lock” e “library cache: mutex X” aparecem na seção “Top 10 Foreground Events By Total Wait Time”;

5. No site de suporte da Oracle existe um documento que mostra que a estatística “failed parse elapsed time” causa contenção “library cache lock” e “library cache: Mutex X”: “ID 1566018.1 : High Waits for ‘library cache lock’ and ‘library cache: mutex X’ Due to Parse Failures When Using JDBC ResultSet .TYPE_SCROLL_SENSITIVE”

6. Verificamos na seção “Time Model Statistics” que “failed parse elapse time” representa 52% do DBTime da base;

7. No site de suporte da Oracle existe um documento “ID 1353015.1 : How to Identify Hard Parse Failures”, a partir desse documento pudemos identificar a instrução SQL que estava apresentado erro. O procedimento consiste em habilitar o evento 10035, aguardar que alguma sessão execute a instrução SQL com erro, desabilitar o evento 10035 e verificar o arquivo Log Alert;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

SQL > ALTER SESSION SET EVENTS '10035 trace name context forever, level 1';

Session altered.

SQL > select * from dbtw_users where cont=2;
select * from dbtw_users where cont=2
*
ERROR at line 1:
ORA-00942: table or view does not exist

SQL > ALTER SESSION SET EVENTS '10035 trace name context off';

Session altered.

SQL >

Abaixo parte do arquivo Log Alert com o erro de PARSE da consulta:

8. Para contornar o problema criamos a tabela referenciada na consulta;

1
2
3
4
5
6
7
8
9

SQL > create table dbtw_users (cont number(5,2));

Table created.

SQL > exec dbms_stats.gather_table_stats(ownname=> USER, tabname=> 'DBTW_USERS', cascade=> true, estimate_percent=> null, method_opt=> 'FOR ALL COLUMNS SIZE 254');

PL/SQL procedure successfully completed.

SQL >

9. Abrimos 10 sessões CMD num desktop Windows e acionamos a aplicação Java novamente;

10. Aguardamos alguns segundos e o servidor de banco atingiu um Load 4.2;

11. Emitimos um relatório AWR da base e verificamos que os eventos “library cache lock” e “library cache: mutex X” não aparecem na seção “Top 10 Foreground Events By Total Wait Time”;

12.Verificamos na seção “Time Model Statistics” que “failed parse elapse time” não aparece nessa seção;

Conclusão

Existem problemas cujos sintomas não impactam o banco de dados quando o Workload da base é pequeno, porem quando esse Workload cresce o impacto pode ser extremamente prejudicial para o tempo de resposta do banco, esse tipo de problema pode ser detectado quando submetemos uma nova aplicação a um processo de “Stress Test”, porem mesmo assim ainda estamos sujeitos a enfrentar esse problema introduzido por um simples plano de mudança na aplicação, onde na maioria das vezes é inviável a realização de “Stress Test”.

Referências

ID 1566018.1 : High Waits for ‘library cache lock’ and ‘library cache: mutex X’ Due to Parse Failures When Using JDBC ResultSet .TYPE_SCROLL_SENSITIVE

ID 1353015.1 : How to Identify Hard Parse Failures