sexta-feira, 2 de dezembro de 2011

Utilizando o tkprof para localizar hotspots de SQL

Finalmente, dando continuidade ao post sobre Metodologia de tuning parte 3, vou falar um pouco mais sobre como funciona a ferramenta tkprof para localizar hotspots de SQL.

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;

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;
/
Agora, para começar, lembre-se de verificar o diretório de destino do trace no sqlplus com o comando:

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/dani

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
Agora temos 2 arquivos de trace, correspondentes a cada uma das execuções. Vamos analisá-los com o tkprof:

$ 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.txt

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.
Primeiro, 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:

$ grep total slow.txt
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
Todas 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:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
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
No 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.

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}}'
0.19
1.37
0.29
0.41
0.20
2.09
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:

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