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

Parse Overload

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;

 

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;

Linux TOP

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”;

AWR Top Wait

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;

AWR Top Model

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:

log alert

 
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;

Linux TOP

 

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”;

AWR TOP Wait

 

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

AWR Top Wait

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

 
 
Promo-D75L

video-02
 
 
 
 
 
 
 
 
 
 
 
 
 
 

Deixe uma resposta

O seu endereço de email não será publicado. Campos obrigatórios são marcados com *