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!!!