Analisando SQL traces em Bancos de Dados Oracle - Parte 2

Olá pessoal,

     Dando continuidade ao artigo Analisando traces em Bancos de Dados Oracle - Parte 1, explicarei  hoje como analisar um arquivo trace, gerando-o através do 6º método (package DBMS_MONITOR) apresentado no artigo anterior. Começaremos gerando o trace de uma instrução SQL, e faremos em seguida, uma análise dos pontos principais que demonstram como ela foi executada e o seu desempenho.

     A instrução SQL que iremos executar, irá consultar dados de 2 tabelas do schema HR, obtendo as seguintes informações de empregados: Identificador, nome completo, identificador do departamento e o salário de cada empregado do departamento 10. Antes de executá-la, iremos habilitar trace na sessão do usuário HR, e após executá-la, iremos desabilitar o trace e iniciar a sua análise. Analisar um arquivo trace em seu formato original não é uma tarefa fácil, pois os dados não são gravados em um formato "amigável" (fácil de ler e entender). Para analisá-lo, iremos antes, convertê-lo em um formato amigável, utilizando o famoso utilitário tkprof. Existe outra ferramenta chamada Trace Analyzer, que oferece mais recursos que o tkprof, mas que depende de instalação adicional, motivo pelo qual eu não irei demonstrá-la neste artigo.

     Segue abaixo um roteiro para implementar o que está descrito acima:

 

1- GERANDO UM ARQUIVO DE SQL TRACE

Importante: Todos os passos deste roteiro deverão ser executados no SQL Plus, SQL Developer ou ferramenta similar, conectado com o usuário HR.

Passo 1: Habilitando trace na sessão de usuário:

     Para habilitar trace na sessão do usuário HR (usuário que executará a instrução SQL), iremos utilizar a package DBMS_MONITOR, porque o seu uso faz parte do método atualmente recomendado pela Oracle para tal finalidade (gerenciar sql trace):

    a) Configure um identificador de nome do arquivo trace (sufixo do nome do arquivo):
     SQL> alter session set tracefile_identifier='hr';

    b) Habilite trace na sessão do usuário (conectado como HR):
     SQL> EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(waits=>true, binds=>true);
  
Obs.: Para executar o comando acima, atribua privilégios de execute na package DBMS_MONITOR para o usuário HR (grant execute on dbms_monitor to hr;). Se você é um DBA e precisa habilitar trace na sessão do usuário HR, identifique-o na visão V$SESSION (select sid, serial# from v$session where username = 'HR') e forneça o valor correspondente das colunas sid e serial# para o comando a seguir: EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id => 15, serial_num => 2388, waits => true, binds => true);

Passo 2: Executando a instrução SQL:
    Execute a instrução SQL abaixo 11 vezes para que sejam registradas no arquivo trace as suas estatísticas de execução:

  SQL> SELECT   employee_id,       
                first_name||' '||last_name as complete_name,       
                DEPARTMENT_ID,
                SALARY
       FROM     HR.EMPLOYEES E
       WHERE    DEPARTMENT_ID =20
       ORDER BY SALARY DESC;

Passo 3: Desabilitando trace:

   Agora que já terminamos de executar a instrução SQL, podemos desabilitar a geração de trace executando o comando abaixo:

     SQL> EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE;

Obs.: Se você é um DBA e precisa desabilitar trace na sessão do usuário HR, identifique-o na visão V$SESSION (select sid, serial# from v$session where username = 'HR') e forneça o valor correspondente das colunas sid e serial# para o comando a seguir: EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id => 15, serial_num => 2388);

 

2 - UTILIZANDO O TKPROF

Passo 1: Utilizando o tkprof para gerar um trace "amigável":

     Neste passo precisamos converter o arquivo trace em outro arquivo que contenha os dados em um formato amigável, que a gente consiga ler e interpretar os seus dados.
  
    a) Para descobrir o local onde o arquivo trace foi gerado, execute o comando abaixo, conectado no BD com um usuário que tenha privilégios administrativos e anote o valor do retorno da coluna VALUE. É importante ressaltar que o caminho resultante irá variar, de acordo com a estrutura de pastas em que o software do Oracle Database foi instalado:

     SQL> show parameter background_dump_dest
  
Resultado:

NAME                                    TYPE         VALUE      

-------------------------------- ----------- -----------------------------------------------------------------------------------

background_dump_dest         string        /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace

    b) Abra uma janela de prompt de comandos do Sistema Operacional e entre na pasta resultante do passo anterior, como no exemplo abaixo (ver Imagem 01):
     $ cd /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace         

    c) Localize o arquivo trace que você gerou, pesquisando pelo identificador que foi atribuído no passo a) do roteiro GERANDO UM ARQUIVO DE SQL TRACE, como no exemplo abaixo:
     $ ll *hr* 

    d) Utilize o tkprof para converter o arquivo com a extensão .trc, localizado no passo anterior, em outro arquivo com o nome result.txt, como no exemplo abaixo:
     $ tkprof orcl_ora_3803_hr.trc result.txt sys=no
  
Obs.: O tkprof está sendo executado com 3 parâmetros: nome do arquivo trace, nome do arquivo de saída e um valor para o parâmetro sys. Somente o nome do arquivo trace é um parâmetro obrigatório. O valor no foi fornecido para o parâmetro sys para evitar que sql recursivo seja incluso no arquivo result.txt. O tkprof aceita vários outros parâmetros. Para ver uma lista completa destes parâmetros e os valores possíveis, digite apenas tkprof no prompt de comandos.

Imagem 01 - Utilizando o tkprof

  
3- ANALISANDO O ARQUIVO TRACE

     Chegamos no roteiro final. Agora iremos analisar o arquivo de sql trace "amigável" gerado com o nome result.txt no roteiro anterior. Como o seu conteúdo é grande, extraí dele somente a parte que nos interessa (aquela que contém as estatísticas de execução da instrução SQL). As informações que iremos analisar estão destacadas em vermelho na Listagem 01 e subdivididas em seções, com nomes indicados em azul para facilitar referências nas explicações. Ressalto novamente que não entrarei em todos os detalhes sobre o assunto, comentarei apenas os pontos principais:
   
********************************************************************************
SELECT        employee_id,

                      first_name||' '||last_name as complete_name,
                      DEPARTMENT_ID,
                      SALARY
FROM          HR.EMPLOYEES E
WHERE        DEPARTMENT_ID =20
ORDER BY   SALARY DESC

call         count     cpu    elapsed  disk      query   current  rows                                        ***  Seção 1 ***
----------- --------  -------- ------------ -------- ---------- ----------  ----------

Parse       11         0.02       0.02          0             0            0                0

Execute   11         0.00       0.00          0             0            0                0

Fetch       11         0.00       0.01          2           22            0              22

----------- --------  -------- ------------ -------- ---------- ----------  ----------

total         33         0.02       0.03          2           22            0              22

Misses in library cache during parse: 1

Optimizer mode: FIRST_ROWS                                                                                          ***  Seção 2 ***

Parsing user id: 2821

Number of plan statistics captured: 2

Rows (1st) Rows (avg) Rows (max)  Row Source Operation                                         ***  Seção 3 ***

-------------- ---------------- ---------------  ---------------------------------------------------

         2             2                    2                SORT ORDER BY (cr=2 pr=1 pw=0 time=5728 us cost=9 size=52 card=2)

         2             2                    2                TABLE ACCESS BY INDEX ROWID EMPLOYEES 

                                                                           (cr=2 pr=1 pw=0 time=5703 us cost=8 size=52 card=2)

         2             2                    2                INDEX RANGE SCAN EMP_DEPARTMENT_IX 

                                                                           (cr=1 pr=0 pw=0 time=2740 us cost=4 size=0 card=2)(object id 84939)

Elapsed times include waiting on following events:                                                       ***  Seção 4 ***

Event waited on                             Times     Max. Wait    Total Waited

  ----------------------------------------   Waited  ---------------  ------------------

  SQL*Net message to client           11           0.00               0.00

  db file sequential read                      2           0.00               0.01

  SQL*Net message from client       11           0.00               0.02
********************************************************************************

Listagem 01: Informações de estatísticas de SQL Trace

      

     Analisando a Seção 1, podemos verificar que a instrução SQL foi executada 11 vezes e que ela gastou mais tempo na fase de Parse (0.02 de 0.03) do que nas outras fases. Isso normalmente ocorre em instruções SQL que atualizam e/ou acessam e retornam poucos dados. Em instruções com longo processamento ou que atualizam, ou retornam e consultam muitos dados, o ideal é que o tempo de Parse seja muito menor que o tempo de Execute e Fetch. O mais importante é que nesta seção a gente consegue ver estes tempos de forma isolada, ou seja,  por fase. 

     Seguem abaixo as informações de cada coluna apresentada na Seção 1:

          - call: Nome da fase de execução da instrução SQL;

          - count: Quantidade de vezes em que a instrução passou por uma determinada fase;

          - cpu: Tempo total de cpu dedicado à instrução SQL. 

          - elapsed disk: Tempo total de execução dedicado à instrução SQL. Inclui tempo de execução e tempo e espera;

          - disk: Quantidade total de blocos lidos/escritos em disco;

          - query: Quantidade total de blocos lidos em memória (leitura consistente);

          - current: Quantidade total de blocos lidos em memória (dados atuais, lidos normalmente em UPDATEs);

          - rows: Quantidade total de linhas processadas.
        

     Analisando a Seção 2, podemos verificar que a instrução SQL foi executada com o parâmetro OPTIMIZER_MODE configurado como FIRST_ROWS. O valor FIRST_ROWS normalmente força o uso de índices, que podem ser utilizados pela instrução SQL. Essa informação é muito importante para sabermos o porquê de um índice ser utilizado ou não, pois com o valor padrão (ALL_ROWS), existem muitas variantes do sistema que podem influenciar no comportamento do otimizador e fazer com que ele ignore índices e realize um Full Table Scan.

     Na Seção 3, a gente vê detalhes sobre o plano de execução da instrução SQL. Aqui estão as informações mais importantes do trace, onde podemos ver o tempo de execução por operação da instrução SQL. A análise minuciosa desta seção é muito importante para o trabalho de tuning, pois nela podemos identificar a(s) operação(ões) mais cara(s) da execução de uma instrução SQL, para posteriormente concentrar nossos esforços de otimização somente nesta(s) operação(ões), pois elas são as que causam maior impacto na instrução SQL e onde normalmente podemos ter mais sucesso no trabalho de tuning. Analisando esta seção, descobri que a operação mais cara foi aquela necessária para realizar a ordenação pela coluna SALARY, ou seja, a operação SORT ORDER BY, encontrada na primeira linha de informações da seção (SORT ORDER BY (cr=2 pr=1 pw=0 time=5728 us cost=9 size=52 card=2)). Esta operação tem custo 9 e tempo de execução estimado igual à 0.005728s, enquanto que, as demais (TABLE ACCESS... e INDEX RANGE SCAN...) tem custo 8 e 4, e tempo de execução estimado igual à 0.005703s e 0.00247s,  respectivamente. As informações que podemos analisar sobre cada operação aparecem entre parenteses, após o nome delas. São elas:

          - cr (consistent reads): Qtde. de blocos lidos em memória de forma consistente;
          - pr (physical reads): Qtde. de blocos lidos em disco;

          - pw (physical writes): Qtde. de blocos escritos em disco;
          - time (elapsed time): Tempo total gasto em microsegundos pela operação.
          - cost (optimizer cost): Custo da operação.
          - size (estimated size): Tamanho estimado em bytes dos dados processados.

          - card (estimated cardinality): Qtde. estimada de linhas processadas.

     Na Seção 4, encontram-se as informações sobre estatísticas de eventos de espera (wait events). O tempo de execução de uma instrução SQL é igual ao tempo de cpu + tempo de espera. Uma instrução SQL eficiente normalmente tem um baixo tempo de espera, em relação ao tempo de CPU, portanto, quando você identificar que o tempo de um determinado evento de espera está muito alto, investigue o porquê disso estar acontecendo. É importante entender, também, que nem todo evento de espera trata-se de um problema. 

CONCLUSÃO
     Após analisar todas as seções do sql trace, pude concluir que a instrução SQL foi executada de forma eficiente, pois ela teve um tempo total de execução baixo (0.03s ou 0.002s por execução), usou um índice para filtrar os dados do departamento, e fez o acesso aos dados de forma eficiente!

     Bom pessoal, por hoje é só! Apresentei aqui somente os pontos principais da análise de um sql trace, pois o assunto é longo e maiores detalhes exigem muitos conhecimentos adicionais. Para aqueles que desejam se aprofundar no assunto, consulte as referências, ou participe de um treinamento Database Performance Tuning.
   

[]s

     

Referências:

   - SQL trace, 10046, trcsess and tkprof in Oracle

   - TKPROF And Oracle Trace

   - Oracle Database 11G Performance Tuning Recipes, Autores: Sam R. Alapati, Darl Kuhn e Bill Padfield, Editora: Apress