Como havia dito anteriormente, infelizmente eu tive problemas com o HD da minha máquina e perdi a versão anterior deste artigo. Então, para poder publicá-lo no menor tempo possível resolvi ao invés de utilizar o exemplo complexo que eu havia elaborado, reaproveitar o código de exemplo do post Caso de Performance 2 - Tabelas Temporárias, com algumas pequenas adaptações. Na realidade, o código que utilizarei neste post pouco importa, o que vale é a técnica de utilização da ferramenta.
Dito isto, as adaptações realizadas no código original foram as seguintes: primeiro, eu transformei os blocos anônimos em duas stored procedures. A primeira, slow_proc, é o método lento, utilizando tabelas temporárias. A segunda, fast_proc, é o método rápido, utilizando arrays. Além disso, para simplificar o trabalho, coloquei as etapas de criação do ambiente em um arquivo texto chamado prepara_trace.sql que eu irei invocar para zerar o ambiente em cada etapa do tutorial. Segue seu conteúdo na íntegra:
drop table heap_table;Agora, para começar, lembre-se de verificar o diretório de destino do trace no sqlplus com o comando:
create table heap_table(x number);
drop table temp_table;
create global temporary table temp_table(x number);
create or replace procedure slow_proc as
t number := dbms_utility.get_time;
procedure lp_dummy is
begin
insert into heap_table
select * from temp_table;
end;
begin
for r in (select rownum from dual connect by level <= 1000)
loop
delete temp_table;
insert into temp_table
select rownum from dual connect by level <= 100;
lp_dummy;
end loop;
dbms_output.put_line('hsecs=' || (dbms_utility.get_time - t));
end;
/
create or replace procedure fast_proc as
t number := dbms_utility.get_time;
type typ_heap is table of heap_table%rowtype index by pls_integer;
a_heap typ_heap;
procedure lp_dummy is
begin
forall i in a_heap.first .. a_heap.last
insert into heap_table values a_heap(i);
end;
begin
for r in (select rownum from dual connect by level <= 1000)
loop
select rownum bulk collect into a_heap
from dual connect by level <= 100;
lp_dummy;
end loop;
dbms_output.put_line('hsecs=' || (dbms_utility.get_time - t));
end;
/
show parameter user_dump_dest
Além disso, você vai precisar se conectar com o usuário oracle ou um usuário que pertence ao grupo dba para poder ler o arquivo do trace.
Feito estes preparativos vamos ao processo:
$ sqlplus dani/daniAgora temos 2 arquivos de trace, correspondentes a cada uma das execuções. Vamos analisá-los com o tkprof:
SQL*Plus: Release 10.2.0.1.0 - Production on Sun Dec 4 21:52:11 2011
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Connected to:
Oracle Database 10g Express Edition Release 10.2.0.1.0 - Production
SQL> set serveroutput on
SQL> @/tmp/prepara_trace
Table dropped.
Table created.
Table dropped.
Table created.
Procedure created.
Procedure created.
SQL> alter session set tracefile_identifier = 'slow';
Session altered.
SQL> alter session set sql_trace = true;
Session altered.
SQL> call slow_proc();
hsecs=235
Call completed.
SQL> alter session set sql_trace = false;
Session altered.
SQL> alter session set tracefile_identifier = 'fast';
Session altered.
SQL> alter session set sql_trace = true;
Session altered.
SQL> call fast_proc();
hsecs=38
Call completed.
SQL> alter session set sql_trace = false;
Session altered.
SQL> exit
$ ls -ltrh | tail -n 2
-rw-r----- 1 oracle dba 283K 2011-12-04 21:53 xe_ora_2946_slow.trc
-rw-r----- 1 oracle dba 236K 2011-12-04 21:54 xe_ora_2946_fast.trc
$ tkprof xe_ora_2946_slow.trc slow.txtPrimeiro, vamos analisar o arquivo slow.txt. Uma maneira bem tranquila para se localizar os comandos SQL que estão tomando mais tempo é observar as linhas de sumário para total - elapsed, ou seja, o tempo real decorrido de execução do comando. Com o comando grep do Linux/Unix podemos listar rapidamente as linhas de totais:
TKPROF: Release 10.2.0.1.0 - Production on Sun Dec 4 21:57:26 2011
Copyright (c) 1982, 2005, Oracle. All rights reserved.
$ tkprof xe_ora_2946_fast.trc fast.txt
TKPROF: Release 10.2.0.1.0 - Production on Sun Dec 4 21:57:39 2011
Copyright (c) 1982, 2005, Oracle. All rights reserved.
$ grep total slow.txtTodas as linhas mostradas representam o sumário de um comando SQL contido no arquivo, com exceção das duas últimas que representam os sumários do tkprof. Agora, eu falei que era importante olhar para as colunas elapsed, certo? Para recordar, estas linhas "total" que mostramos com o comando anterior fazem parte de tabelas como esta aqui:
total 1 0.00 0.00 0 0 0 0
total 4 0.00 0.00 0 0 0 2
total 2 0.14 0.19 0 0 0 0
total 4 0.00 0.00 0 4 0 1
total 3 0.00 0.00 0 2 0 0
total 3 0.00 0.00 0 2 0 1
total 3 0.00 0.00 0 2 0 1
total 3 0.00 0.00 0 1 0 1
total 3 0.00 0.00 0 2 0 0
total 4 0.00 0.00 0 4 0 1
total 3 0.00 0.00 0 1 0 0
total 1 0.00 0.00 0 0 0 0
total 13 0.00 0.00 0 0 0 1000
total 6 0.00 0.00 0 2 0 0
total 1001 1.08 1.37 0 31947 103235 99900
total 5 0.00 0.00 0 4 0 0
total 1001 0.33 0.29 0 1183 3018 100000
total 3 0.00 0.00 0 3 0 1
total 1001 0.46 0.41 0 32384 2869 100000
total 108 0.00 0.00 0 92 0 27
total 32 0.00 0.00 0 50 16 16
total 32 0.00 0.00 0 80 16 16
total 2 0.00 0.00 0 0 0 0
total 9 0.15 0.20 0 0 0 2
total 3229 1.90 2.09 0 65763 109154 300965
call count cpu elapsed disk query current rowsNo caso, destaquei em negrito a linha "total" na tabela acima e na lista anterior para você se situar melhor onde quero chegar. A coluna 4 da lista de resultado do grep corresponde exatamente ao tempo elapsed. Então ao olhar esta coluna sabemos exatamente quais são os comandos SQL que devemos buscar no arquivo do trace baseado nos seus tempos. Se você abrir o arquivo slow.txt e buscar pelo tempo 1.37 vai cair nesta tabela e vai descobrir que ela corresponde à linha delete temp_table da procedure slow_proc.
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1000 1.08 1.36 0 31947 103235 99900
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1001 1.08 1.37 0 31947 103235 99900
Agora repare que interessante: com exceção da última linha, que corresponde ao sumário, esta é a linha que mais consome tempo, ou seja: perdemos mais tempo limpando nossa tabela de trabalho do que fazendo qualquer processamento útil para nossa "regra de negócio". Sei que é um exemplo artificial, mas na vida real já vi acontecerem situações similares.
E para você que teve paciência de ler até aqui vai um macete de presente. Primeiro, observe que este é um trace pequeno e mesmo assim tem 25 linhas total para serem avaliadas. Imagine uma procedure "de verdade", com dezenas de linhas e de chamadas a outras procedures... vai ser um caos localizar manualmente estas querys, certo? Então fique de olho no comando a seguir:
$ grep total slow.txt | awk '{if($4>0.1) {print $4}}'Qual é a mágica? Utilizando o comando awk, adicionei um filtro na coluna 4 (variável $4) para mostrar apenas os valores que forem maiores que 0,1 . Assim eu estabeleço um critério sobre quais SQL eu quero avaliar - apenas aqueles que gastaram mais que um tempo x. Se você quiser mostrar a linha inteira, pode substituir o print $4 por print $0:
0.19
1.37
0.29
0.41
0.20
2.09
$ grep total slow.txt | awk '{if($4>0.1) {print $0}}'
total 2 0.14 0.19 0 0 0 0
total 1001 1.08 1.37 0 31947 103235 99900
total 1001 0.33 0.29 0 1183 3018 100000
total 1001 0.46 0.41 0 32384 2869 100000
total 9 0.15 0.20 0 0 0 2
total 3229 1.90 2.09 0 65763 109154 300965
Aí, tendo em mãos esta lista de valores, você pode facilmente pegar seu editor de texto favorito e fazer uma busca textual pelo valor da coluna 4 que encontrará a tabela de sumário. Logo acima desta tabela estará a query responsável por aquele tempo.
Enfim, esta é a técnica que eu gostaria de mostrar para identificar hotspots de SQL em um arquivo de trace. É de certa forma bastante rudimentar mas já me quebrou o galho muitas vezes. Apenas gostaria de acrescentar mais uma informação para aqueles que utilizam RedHat ou derivados, adicione a função strtonum() na coluna $4 ao fazer a comparação com o valor de limite:
$ grep total slow.txt | awk '{if(strtonum($4)>0.1) {print $0}}'E para finalizar, vou mostrar o resultado do grep no arquivo fast.txt:
$ grep total fast.txt | awk '{if($4>0.1) {print $0}}'
total 2001 0.18 0.18 0 0 0 100000
total 3054 0.27 0.26 0 210 2240 201009
Apenas 2 ocorrências, sendo que uma delas é o sumário... definitivamente, remover o overhead do tratamento das temporárias deixou o código muito mais level e eficiente!
Aconselho você a executar este exemplo em casa e conferir os resultados. Tem muita informação nos arquivos de trace e tkprof que eu não consigo cobrir em um único post, então aproveite para tirar dúvidas na seção de comentários abaixo. Até a próxima!
Nenhum comentário:
Postar um comentário