Analisando SQL traces em Bancos de Dados Oracle - Parte 1
Fonte:
O objetivo principal deste artigo, é
deixar claro (de um modo resumido) que existem N formas de gerar SQL
trace, o porquê de eu escolher 1 delas, e como analisar os pontos
principais de um trace para analisar o desempenho de uma instrução SQL.
Antes de começar, é importante entender, que existem outros tipos de
trace e que abordaremos aqui apenas o trace de instruções SQL. Para
facilitar a compreensão, sempre que eu citar trace de forma indefinida
dentro do artigo, estarei me referindo à SQL trace, ou seja, trace de
instruções SQL. Analisar um trace é um dos métodos mais utilizados
para entender em detalhes como uma instrução SQL foi executada no BD e
efetuar Debug!
1- Como uma instrução SQL é executada dentro do BD?
Toda instrução SQL pode ser executada em um BD Oracle em até 3 passos:
a) Parse:
Primeira fase da execução. Nesta fase o Otimizador do Oracle
analisa basicamente a sintaxe e a semântica da instrução SQL e monta
um
plano de execução para ela.
b) Execute:
Segunda fase da execução. Esta é a fase em que o Otimizador
realmente executa a instrução SQL, conforme o plano de execução montado
no estágio anterior.
c) Fetch:
Última fase da execução, única que não é obrigatória. Nesta
fase o Otimizador retorna os dados para a sessão de usuário e isso só
ocorre em instruções SELECT.
Toda instrução SQL que é executada em um BD deve ter no mínimo 1
Parse e 1 Execute. O ideal é que ela tenha 1 Parse e N Executes, e isso
só ocorre quando a instrução SQL é executada sempre com a mesma string,
com variáveis bind ou com o recurso de compartilhamento de cursores
habilitado.
.
 |
Imagem 01 - Fases da da execução de uma instrução SQL
Fonte: Oracle Corporation |
2- O que é um arquivo trace?
Trace ou especificamente SQL Trace, é um método de rastreamento de
comandos SQL para verificar o que está sendo executado no BD e pode ser
utilizado para corrigir erros (debug) ou otimizar SQL. No Oracle
Database, o SQL Trace pode ser habilitado no nível de sessão
(identificador do cliente, serviço, módulo ou ação) ou BD. Ao habilitar
SQL Trace na sessão de um usuário, todas as instruções SQL que ele
submeter ao BD serão registradas em um arquivo, comumente conhecido como arquivo trace. As principais informações que um arquivo trace contém são:
- Contadores de parse, fetch e execute;
- Tempo de CPU e o tempo total de execução de instruções SQL;
- Quantidade de leituras físicas e lógicas;
- Quantidade de linhas processadas.
Os arquivos trace possuem um nome composto pelas seguintes partes: nome da instância + "_" + nome do processo de background + "_" + valor numérico + "." + extensão .trc
(Ex.: orcl_mmon_27214.trc). Eles
podem ser gerados em pastas diferentes, conforme a versão do Oracle
Database. Para descobrir facilmente onde eles são gerados, execute no BD
(conectado com um usuário que tenha privilégios de administrador), a
consulta abaixo:
SQL> show parameter background_dump_dest
A pasta retornada no comando acima contém arquivos trace de
processos de usuário e background. Trace de processos de background são
gerados automaticamente pelo Oracle Database, quando ele encontra algum
problema no BD. Para identificar
mais
facilmente os arquivos traces de usuário, pode-se acrescentar prefixos
aos nomes dos arquivos, configurando-se o parâmetro TRACEFILE_IDENTIFIER
(mais adiante veremos isso). Outro ponto importante a ser considerado
antes de gerar traces, é o tamanho máximo de um arquivo trace, que pode
ser configurado através do parâmetro MAX_DUMP_FILE_SIZE (também veremos
isso adiante).
3- Como gerar um arquivo trace?
Atualmente (até a versão 12C do Oracle Database), existem 6 métodos para habilitar SQL Trace no BD:
1- ORADEBUG:
É uma ferramenta de debug muito poderosa, que passou a existir na
versão 8.1 do Oracle Database. Ela não é muito bem documentada e por
questões de segurança, recomenda-se utilizá-la somente quando o suporte
da Oracle indicar. Por existirem outros métodos atuais mais seguros que
substituem esta ferramenta para gerar sql trace, não irei abordá-la.
Para obter mais informações sobre oradebug, consulte o link a seguir:
Oradebug.
2- Parâmetro SQL_TRACE:
Este é o método mais simples de habilitar SQL Trace e pode ser realizado configurando-se o parâmetro SQL_TRACE
no nível da instância (ALTER SYSTEM) ou sessão (ALTER SESSION). Por
questões de performance do BD (trace consome muitos recursos do BD),
jamais habilite este parâmetro no nível da instância em um ambiente de
produção. Execute os comandos do roteiro abaixo na sessão de um usuário
que você deseja habilitar o trace:
a) Configurando um prefixo no nome do arquivo trace:
SQL> alter session set tracefile_identifier='hr_';
b) Configurando o tamanho máximo de um arquivo trace, também conhecido como trace dump:
SQL> alter session set max_dump_file_size=UNLIMITED;
Obs.: O parâmetro
MAX_DUMP_FILE_SIZE tem por padrão o valor UNLIMITED a partir da versão
8.1.6 do Oracle Database, o que significa que podemos gerar traces com
tamanho ilimitado. Quando instruções SQL não estiverem aparecendo em um
arquivo trace, verifique se não é o valor deste parâmetro que está
limitando o tamanho do arquivo, e por este motivo, suprimindo os SQLs
que você está procurando.
c) Iniciando a geração de trace simples:
SQL> alter session set sql_trace=TRUE;
ou:
c) Iniciando a geração de trace de um trace estendido (que nada mais
é do que um trace contendo informações adicionais, que podem incluir
Wait Events e
Bind Variables):
SQL> alter session set events '10046 trace name context forever, level 12';
Depois de habilitar o trace e executar as instruções SQL que você
quer investigar, não esqueça de desabilitar o trace. Para desabilitar o
trace
simples, execute o comando abaixo:
SQL> alter session set sql_trace=FALSE;
ou, para desabilitar o trace estendido, execute:
SQL> alter session set events '10046 trace name context off';
Obs.: Como todo parâmetro configurado em nível de sessão, os valores configurados são descartados ao efetuar logoff.
3- Package DBMS_SUPPORT
Esta package foi introduzida provavelmente no Oracle 8.1.7 e
não vem instalada por padrão no BD. Para instalá-la, é necessário
executar o script $ORACLE_HOME/rdbms/admin/dbmssupp.sql. A package DBMS_SUPPORT permite
habilitar SQL Trace somente no nível da sessão (similar ao ALTER
SESSION SET SQL_TRACE...), portanto, ela é mais limitada que as opções
anteriores (que permitem habilitar trace no nível da instância).
Para habilitar a geração de um trace estendido, execute o comando abaixo:
SQL> BEGIN DBMS_SUPPORT.START_TRACE(true, true); END;
Para desabilitar a geração de trace estendido, execute o comando abaixo:
SQL> BEGIN DBMS_SUPPORT.STOP_TRACE; END;
4- Package DBMS_SESSION
Esta package foi introduzida provavelmente no Oracle 9i e é
mais poderosa que as opções anteriores, pois possui recursos adicionais
para habilitar trace em grupos de sessões, permitindo simplificar, por
exemplo, a geração de traces na conta de um usuário que possui um pool de conexões.
Para gerenciar o trace de múltiplas sessões, é necessário configurar um
identificador de cliente único ao iniciar cada sessão (ver
DBMS_SESSION.SET_IDENTIFIER).
Para habilitar a geração de um trace, execute o comando abaixo:
SQL> BEGIN DBMS_SESSION.SET_SQL_TRACE(true); END;
Para configurar o identificar de cliente (que pode ser o nome da
conta de um pool de conexões), execute o comando abaixo substituindo o
valor da string:
SQL> BEGIN DBMS_SESSION.SET_IDENTIFIER('FABIO'); END;
Para desabilitar a geração de trace extendido, execute o comando abaixo:
SQL> BEGIN DBMS_SESSION.SET_SQL_TRACE(false); END;
5- Package DBMS_SYSTEM
Esta package foi
introduzida provavelmente no Oracle 8i e é similar à DBMS_SESSION.
Difere-se apenas pela possibilidade de poder afetar qualquer sessão do
BD, e não somente a sessão atual ou aquelas que tiveram um identificador
de cliente previamente configuradas.
Para habilitar a geração de trace na sessão de outro usuário, siga o exemplo abaixo substituindo os valores dos parâmetros:
SQL> BEGIN
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(sid => 15, serial# => 2388, true);
END;
Para desabilitar a geração de trace na sessão do mesmo usuário, execute:
SQL> BEGIN
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(sid => 15, serial# => 2388, false);
END;
6- Package DBMS_MONITOR
A package DBMS_MONITOR foi
criada no Oracle Database 10G e é uma evolução da packages DBMS_SYSTEM.
Ela contém todas as funcionalidades da package anterior e permite, por
exemplo, habilitar trace no nível de serviço, módulo ou ação. Essa é a
package atualmente recomendada pela Oracle para gerenciar trace e deve
ser utilizada em conjunto com as packages DBMS_SESSION ou DBMS_APPLICATION_INFO para gerenciar traces em diversos níveis (não somente usuários individuais).
Para habilitar a geração de trace na sessão de outro usuário, siga o exemplo abaixo substituindo os valores das
variáveis:
SQL> BEGIN
DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id => 15, serial_num => 2388, waits => true, binds => true);
END;
Para desabilitar a geração de trace na sessão do mesmo usuário, execute:
SQL> BEGIN
DBMS_MONITOR.SESSION_TRACE_DISABLE(sid => 15, serial_num => 2388);
END;
Existe ainda o AUTOTRACE, que pode ser utilizado no SQL Plus ou
ferramentas similares, e que permite ver estatísticas da instrução SQL
sem gerar arquivo externo, porém com poucas e limitadas informações. É
importante entender que em um arquivo de SQL Trace você não encontrará o
tempo de execução de blocos PL/SQL, mas somente as instruções SQL
executadas dentro destes blocos (ou fora deles). Se você precisa
analisar o desempenho de blocos PL/SQL, consulte a package
DBMS_TRACE.
Para descobrir onde trace está habilitado, conecte-se no BD com privilégios administrativos e consulte a visão DBA_ENABLED_TRACES.
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);
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, pode-se 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!
Resumo comandos:
/**************************/ setup TKPROF/ **************************
1 - checar se há trace habilitado
select * from sys.wri$_tracing_enabled; ou
SELECT *FROM DBA_ENABLED_TRACES;
2 - verificar o caminho de gravação:
SHOW PARAMETER USER_DUMP_DEST;3 - Identificar a sessão do usuário:
select sid, serial#, username from v$session;SID SERIAL# USERNAME
------ -------
136 7854 SCOTT
4 - alterar a nivel de sessão
alter session set user_dump_dest="c:\nome_do_diretorio";
alter session set tracefile_identifier ="nome_do_trace";5 - nomear o trace para identificação
alter session set tracefile_identifier ='Nome_do_trace';como exemplo:
alter session set tracefile_identifier ='Nome_do_user_data_TK';6 - habilitar a estatística da sessão:
alter session set timed_statistics=true;7 - ativar o trace da sessão
EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE;De posse do SID (Session ID) e o serial# da sessão, habilitar o trace:
exec DBMS_MONITOR.session_trace_enable (session_id => 136,serial_num => 7854); -- 136 é o SID e 7854 é o SERIAL# da sessão auditadaou pelo cliente:
exec dbms_monitor.client_id_trace_enable (client_id=>'nome_cliente');/************************** /DISABLE TKPROF/ **************************
1 - desabilitar o trace
exec DBMS_MONITOR.session_trace_disable (session_id => 136,serial_num => 7854); -- 136 é o SID e 7854 é o SERIAL# da sessão auditadaou
exec dbms_monitor.client_id_trace_disable (client_id=>'nome_cliente');2 - para gerar o TKPROF:
tkprof /caminho/nome_do_arquivo /caminho/nome_do_arquivo_de_saida_trace.txt
