A ferramenta primordial para localizar estes pontos é o SQL Trace. Este é um recurso do banco de dados Oracle que habilita a gravação de um arquivo de log com todas as operações realizadas dentro de uma determinada sessão (ou de várias sessões, no caso de uma conexão MTS). O arquivo de log gerado pelo SQL trace fica sempre armazenado no sistema de arquivos do servidor, dentro da pasta apontada pelo parâmetro user_dump_dest. Abaixo mostro duas formas de recuperar o valor deste parâmetro:
paulo@hitomi:~$ sqlplus paulo/paulo
SQL*Plus: Release 11.2.0.2.0 Beta on Sat Nov 26 21:23:12 2011
Copyright (c) 1982, 2010, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Express Edition Release 11.2.0.2.0 - 64bit Beta
SQL> show parameter user_dump_dest
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string /u01/app/oracle/diag/rdbms/xe/
XE/trace
SQL> select value from v$parameter where name = 'user_dump_dest';
VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/xe/XE/trace
SQL>
E, para habilitar o SQL trace da sessão atual, basta executar:
SQL> alter session set sql_trace = true;
Session altered.
SQL> select 1 from dual;
1
----------
1
SQL> alter session set sql_trace = false;
Session altered.
SQL>
Um arquivo .trc será gerado no diretório de user_dump_dest com o resultado do trace desta sessão. Se você for neste diretório e tentar localizar o arquivo pode abri-lo com um editor de textos comum, como o vi ou o nano. Pode a principio ser um pouco complicado localizar o arquivo, pois é comum que o banco armazene traces automáticos para seus processos internos, então é um bom costume criar um identificador para o arquivo para facilitar sua busca.
Fazemos isso usando outra variável de sessão, o tracefile_identifier. Exemplo de uso:
SQL> alter session set tracefile_identifier = 'paulo';
Session altered.
SQL> alter session set sql_trace = true;
Session altered.
SQL> select 1 from dual;
1
----------
1
SQL> alter session set sql_trace = false;
Session altered.
SQL>
Agora, basta procurar por todos os arquivos com este identificador no diretório dos arquivos de trace:
oracle@hitomi:/u01/app/oracle/diag/rdbms/xe/XE/trace$ ll *paulo*
-rw-r----- 1 oracle dba 2351 2011-11-26 21:34 XE_ora_25084_paulo.trc
-rw-r----- 1 oracle dba 82 2011-11-26 21:34 XE_ora_25084_paulo.trm
No caso, o arquivo XE_ora_25084_paulo.trc é o trace gerado para a sessão acima.
Ok, agora que temos o trace como utilizá-lo? Uma rápida vista neste arquivo mostrará que mesmo uma sessão tão simples quanto a que apresentei neste exemplo vai popular o arquivo com uma infinidade de comandos que a princípio vão parecer praticamente "criptografados". A verdade é que este arquivo possui uma estrutura bastante lógica, e é possível sim ler ele diretamente para buscar informações. No entanto, não é o nosso neste momento aprender a interpretá-lo, por isso vou passar direto para mostrar a próxima ferramenta que vai simplificar bastante este trabalho. Trata-se do tkprof.
O tkprof é um utilitário que faz a conversão do arquivo de trace em um relatório mais "legível" para os seres humanos. Estaremos utilizando ele bastante sempre que houver a necessidade de localizar hotspots de SQL em nossos procedimentos. No caso, isto se deve ao fato de que o trace por si só coleta informação de querys, e não de PL/SQL, o que pode ser uma limitação aparentemente inconveniente, mas existem outras formas de obter esta informação. De qualquer forma, o tkprof é uma ferramenta fundamental para localizar querys problemáticas dentro de hierarquias de procedimentos e funções. Vamos ao seu uso:
oracle@hitomi:/u01/app/oracle/diag/rdbms/xe/XE/trace$ tkprof XE_ora_25084_paulo.trc paulo.txt
TKPROF: Release 11.2.0.2.0 - Development on Sat Nov 26 21:45:40 2011
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
oracle@hitomi:/u01/app/oracle/diag/rdbms/xe/XE/trace$
Simples assim! Passamos o arquivo de trace como entrada e um arquivo txt como saída. A resposta é o arquivo txt apresentando um relatório muito mais legível do que o trace puro. Abaixo, coloco na íntegra o relatório do trace que gerei nos passos acima:
oracle@hitomi:/u01/app/oracle/diag/rdbms/xe/XE/trace$ cat paulo.txt
TKPROF: Release 11.2.0.2.0 - Development on Sat Nov 26 21:45:40 2011
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: XE_ora_25084_paulo.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
SQL ID: 1hgzr5xxpmt7h Plan Hash: 0
alter session set sql_trace = true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 48
********************************************************************************
SQL ID: 520mkxqpf15q8 Plan Hash: 1388734953
select 1
from
dual
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 48
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=8 us cost=2 size=0 card=1)
********************************************************************************
SQL ID: 988n7wn97ptgf Plan Hash: 0
alter session set sql_trace = false
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 48
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL 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
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: XE_ora_25084_paulo.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
47 lines in trace file.
17 elapsed seconds in trace file.
oracle@hitomi:/u01/app/oracle/diag/rdbms/xe/XE/trace$
Como você pode ver, no relatório do tkprof estão todos os comandos SQL executados a partir do início do trace. Num procedimento real, as tabelas de resumo apresentadas (com as contagens de parse, execute e fetch) vão acumular os dados das n-vezes que a determinada query for executada. Por exemplo, se eu executasse 100 vezes a query 'select 1 from dual', todas as 100 estariam agregadas na mesma tabela de sumário.
Isto é muito útil para localizar quais querys estão consumindo mais tempo de execução, baseado no seu tempo total decorrido (coluna elapsed do relatório). Uma maneira fácil de analisar este arquivo é executar uma busca por todas as linhas contendo a palavra 'total':
oracle@hitomi:/u01/app/oracle/diag/rdbms/xe/XE/trace$ grep total paulo.txt
total 1 0.00 0.00 0 0 0 0
total 4 0.00 0.00 0 0 0 1
total 2 0.00 0.00 0 0 0 0
total 7 0.00 0.00 0 0 0 1
total 0 0.00 0.00 0 0 0 0
oracle@hitomi:/u01/app/oracle/diag/rdbms/xe/XE/trace$
No caso, este arquivo não é um bom exemplo porque todas as querys foram instantâneas, mas num procedimento mais complexo você poderia localizar exatamente quais são as querys mais pesadas com este comando. No próximo post trarei um exemplo melhor para mostrar como funciona esta técnica.
Nenhum comentário:
Postar um comentário