Entendendo arquivo de trace(final)

O que nos diz o restante do trace?

Olá Pessoal! Tudo certo? Vos falo daqui, diretamente da República de Curitiba.rsrsrs

Gente vai aí uma dica muito especial, procure focar suas metas, traçar seus objetivos e corra atrás para que tudo dê certo. Não fique colocando a culpa dos insucessos, neste ou naquele político, nesta ou naquela crise. Eu sei que a situação atual do país influencia nos resultados, mas tenha a visão empreendedora de conseguir vislumbrar acima de tudo as oportunidades e não apenas as dificuldades.

Ouvi uma frase estes dias que dizia mais ou menos assim:
“O pessimista vê na situação uma dificuldade,
   o otimista vislumbra a oportunidade.”

Dica dada então, sejamos otimistas e vida que segue na nossa batalha de DBA.

Hoje vou continuar com um assunto que eu sei já estou devendo. A continuação da interpretação do arquivo de trace.

Como o do post anterior não demonstrava lentidão em banco de dados aparentemente resolvi selecionar outro trace de cliente que provavelmente tinha um problema mais aparente(de fato tinha):

TKPROF: Release 11.2.0.3.0 – Development on Mon Feb 2 16:58:17 2014
Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.
Trace file: ORCL_ora_10144.trc Nome do arquivo do trace gerado no sistema que deu origem ao txt que estamos lendo
Sort options: fchela Formato de ordenação que as instruções SQL vão aparecer dentro do trace. fchela mostra primeiro a query com maior tempo de execução. Normalmente é o que eu uso para detectar problemas deste nível.
********************************************************************************
count    = number of times OCI procedure was executed Número de vezes que executou a query
cpu      = cpu time in seconds executing tempo de CPU na execução
elapsed  = elapsed time in seconds executing tempo total gasto para executar
disk     = number of physical reads of buffers from disk  número de leituras físicas de buffer(memória)
query    = number of buffers gotten for consistent read memória consistente lida
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call Número de linhas processadas pelo comando.
********************************************************************************
SQL ID: 5t75pg76ig3xc  Plan Hash: 4562710901
SELECT PWFGUID, NUM_PROCESSO
FROM
LF_NF_SAIDA_INF_COMPL WHERE COD_HOLDING = :B9 AND COD_MATRIZ = :B8 AND
COD_FILIAL = :B7 AND DT_EMISSAO = :B6 AND SERIE = :B5 AND SUBSERIE = :B4
AND NUM_NF = :B3 AND COD_CFOP_LEGAL = :B2 AND COD_MUNICIPIO = :B1 AND
ROWNUM <= 1
call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        0      0.00       0.00          0          0          0           0
Execute   8259      1.73       3.17          0          0          0           0
Fetch     8258    779.59    1360.35          0  168604489          0        8100
——- ——  ——– ———- ———- ———- ———-  ———-
total    16517    781.32    1363.52          0  168604489          0        8100
********************************************************************************

Ok, do trecho acima podemos fazer algumas análises iniciais, com isso vemos facilmente que houve uma demora de 1360,35 segundos no fetch.
Conforme eu havia falado no outro post, precisaremos ver qual o tempo total de chamadas recursivas e não recursivas.
Primeiramente quem são estas duas?? Hehehe Ok, ok, sei que deve ter feito esta pergunta certo? vamos lá então:
Não recursiva(OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS) são aquelas chamadas, queries que não são da aplicação em si, mas fazem parte da caixa preta do Oracle(rsrsrs) verificações em dicionário de dados, queries internas, etc.

Recursivas(OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS) são as da aplicação, o que normalmente mais nos interessa.

Então vamos ao exemplo acompanhando o trace:

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
——- ——  ——– ———- ———- ———- ———-  ———-
total        0      0.00       0.00          0          0          0           0
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse   308148      2.47       5.47          0          0         76           0
Execute 944049     68.24     142.67         37         29       4415         208
Fetch   2443378    831.65    1511.26      21840  173371413          0     2125586
——- ——  ——– ———- ———- ———- ———-  ———-
total   3695575    902.36    1659.41      21877  173371442       4491     2125794

Dos itens acima conseguimos ver que não tivemos chamadas não recursivas impactantes e que do total do tempo (elapsed) das chamadas recursivas temos um tempo de 1659,41 segundos. Agora se analisarmos em relação ao início do nosso trace temos que este tempo é praticamente todo a query citada acima.
Se ainda continuarmos vendo pelo final do trace teremos alguns itens interessantes:

Na primeira sessão fala dos WAITS, eles são os itens mais temidos pela performance, wait=espera.
Sendo:
Tempo Total = Tempo processamento + Espera
Logo quanto menos espera tiver melhor. E sendo assim elas serão foco de análise principal

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total Waited
  —————————————-   Waited  ———-  ————
  db file sequential read                     21877        0.49         82.61
  buffer busy waits                               9        0.00          0.00
  latch: In memory undo latch                     2        0.00          0.00
  latch: cache buffers chains                     1        0.00          0.00
  latch: shared pool                              3        0.00          0.02

307915  user  SQL statements in session.
  310  internal SQL statements in session.
308225  SQL statements in session.
  378  statements EXPLAINed in this session.
********************************************************************************
Trace file: satp_ora_39715532.trc
Trace file compatibility: 10.01.00
Sort options: prsela  exeela  fchela  
       1  session in tracefile.
  307915  user  SQL statements in trace file.
     310  internal SQL statements in trace file.
  308225  SQL statements in trace file.
     388  unique SQL statements in trace file.
     378  SQL statements EXPLAINed using schema:
           LF.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
 21706892  lines in trace file.
    1821  elapsed seconds in trace file.

Pela análise final do trace conseguimos ver que ele foi feito, ou seja, foi mantido trace rodando por um período de 1821 segundos. Isso não significa que a operação, o processo durou este tempo, pois nós podemos iniciar um trace em um processo que já esteja rodando e terminar o trace antes do processo acabar. Portanto este tempo significa o tempo que mantivemos a monitoração.
Se me perguntar qual o tempo ideal para manter um trace rodando, eu diria que: Depende!! Porém, eu nunca deixaria um tempo inferior a 10 minutos, ou até término do processo (o que acabar antes).
Voltando ao nosso tempo de 1821 segundos contra os 1360,35 apenas de uma das queries, eu poderia com certeza afirmar que teremos que dar atenção ao SQL escrito, tentar ver com a equipe de desenvolvimento uma forma melhor de escrever a instrução.
Como DBA poderia ainda buscar auxílio com advisors, fazer testes com índices, analisar as tabelas em questão…
Enfim, quando descobrimos que infelizmente SIM, o problema pode estar em casa(banco de dados) temos que abrir um leque enorme de opções que nos ajudarão a traçar resultados

Sendo assim, aproveitarei este vasto leque de opções para colocar em outros posts como proceder quando realmente somos o culpado. O trace é apenas a nossa porta de entrada para análise.

É meu amigo! Você está vendo que ser DBA é muitas vezes atuar como promotor, advogado de defesa, dentre outros.

Por hoje, acredito que é só, vou deixar espaço para responder emails, solicitações, etc que tem chegado. Aproveitando, agradeço a participação de todos, e mais uma vez peço que ajudem a divulgar: o Blog rauldba.com.br, a fanpage (facebook.com/raulfdba).

Grand abraço a todos e mantenham apesar que qualquer coisa, crise, situação, o FOCO na META!!!

 

 

Sobre raul andrade

DBA e Instrutor Oracle, apaixonado pela minha família e por ensinar.
Esta entrada foi publicada em Talento quando Tá lento. Adicione o link permanente aos seus favoritos.

Deixe uma resposta