Social Icons

30 de set. de 2013

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 completoidentificador 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 => 15serial_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 serial# para o comando a seguir: EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id => 15serial_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.txtO 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 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
   - Oracle Database 11G Performance Tuning Recipes, Autores: Sam R. Alapati, Darl Kuhn e Bill Padfield, Editora: Apress
  

10 comments:

  1. Muito bom mesmo Fabio! Obrigado por sanar minhas dúvidas.

    ResponderExcluir
  2. Muito bom artigo Fabio, seu blog esta contribuindo muito para meu aprendizado.

    Uma duvida, se eu encerrar uma sessão com o comando ALTER SYSTEM KILL SESSION, o arquivo de trace desta sessão será deletado?

    ResponderExcluir
    Respostas
    1. Matinha, obrigado pelo comentário!

      Não, o trace não será apagado!

      []s

      Excluir
  3. Fábio, boa tarde.

    Muito bom o artigo. Eu tenho as seguintes dúvidas:

    1 - Para alterar o parâmetro tracefile_identifier seria necessário reiniciar a instância?
    2 - O uso da instrução EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id => 15, serial_num => 2388, waits => true, binds => true); depende da instrução EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE que habilita o trace na sessão do usuário?

    Obrigado!! Parabéns pelo "blogão".

    ResponderExcluir
    Respostas
    1. Alan, obrigado pelos comentários. Seguem abaixo as respostas:

      1- O parâmetro tracefile_identifier pode ser alterado tanto no nível da instância quanto nível da sessão. Se for alterar no nível da instância é necessário sim reiniciar o BD, porém veja no artigo que eu recomendo alterar somente no nível da sessão, ok?

      2- Não entendi a sua pergunta. Me parece que tem algum erro nela, revise-a e faça-a de novo da forma correta, ok?

      []s

      Excluir
  4. Excelente artigo !!! Parabéns pela ideia !!!

    ResponderExcluir
  5. Bom dia Fabio, como vai?

    Eu tenho uma dúvida aqui, estou gerando um trace e nele contém diversos "bind variables".
    No arquivo de trace os valores dos "binds" aparecem corretamente, entretanto quando executo o tkprof para "embelezar" o trace os valores dos "binds" não são mais apresentados.
    Há algo que possa ser feito para apresenta-los?

    Muito obrigado e excelente artivo, até mais!

    ResponderExcluir
    Respostas
    1. Olá Daniel, primeiramente obrigado pelos comentários. Infelizmente o arquivo gerado pelo tkprof não inclui o valor das variáveis bind. Neste caso, se quiser vê-las, sugiro uma das alternativas abaixo:

      1- Consultar a visão v$sql_bind_capture como indicado no artigo http://www.dba-oracle.com/t_trace_bind_variable_values.htm;

      2- Executar o sql abaixo informado o sqlid da instrução desejada:
      SELECT * FROM
      Table(DBMS_XPLAN.DISPLAY_CURSOR('5af7q8n22sux7',
      NULL,'ADVANCED'));

      3- Usando a ferramenta TRCANLZR (TRCA): https://carlos-sierra.net/category/trcanlzr-trca/. Em breve publicarei um artigo sobre ela.

      []s

      Excluir

 

LINKS ÚTEIS

Total de visualizações de página

Seguidores

Meu One Drive (antigo Sky Drive)