Metodologia para Tuning de Procedimentos - Parte 3

Dando continuidade a série de posts sobre metodologia de tuning hoje vou falar sobre as estratégias que dispomos para identificar os hotspots, ou seja, os pontos que estão gastando mais tempo do nosso processo e que portanto necessitam de ajustes.

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.

Metodologia para Tuning de Procedimentos - Parte 2

No post anterior eu falei sobre o primeiro requisito para uma tarefa de tuning: a reprodutibilidade. Dando continuidade ao assunto, hoje vou abordar o segundo requisito: o objetivo. Toda tarefa de tuning necessita ter muito bem estabelecido o seu objetivo logo no início do processo. Eu sempre pergunto para as pessoas "Qual é a meta para este procedimento?", ou seja, qual é o tempo de resposta esperado como resultado da tarefa de tuning?

Estabelecer este tempo logo no início evita que seja gasto um esforço muito grande para otimizar o processo além do necessário e, digo isso principalmente porque, considerando que estamos falando de um processo complexo, sempre é possível extrair mais performance. O grande problema é o nível de esforço que vai ser gasto para obter as melhorias sucessivas, pois a cada nível de melhoria a tendência é que o processo para obter melhora seja mais complexo e mais demorado. Fundamentalmente, encontrar um equilibro entre objetivo de tuning e esforço é o segredo do tuning bem sucedido.

Algumas vezes o objetivo não está bem definido quando nós recebemos a tarefa, e é aí que ter feito todo o preparo que eu comentei sobre a reprodutibilidade vai entrar no jogo. Primeiro executamos o processo sem nenhuma intervenção para obter uma baseline na qual iremos nos basear durante todo o trabalho. Em alguns casos isso não é possível, como por exemplo, eu já recebi algumas tarefas onde a especificação dizia algo parecido com "este processo não roda mais... leva horas e não termina". Neste tipo de situação a baseline pode ser estabelecida em um processo parcial. Existem várias formas para fazer isto e tratarei de comentar sobre isso adiante.

Se você conseguir estabelecer a baseline no processo completo melhor, porém em processos muito grandes, ou mesmo, "infinitos", podemos utilizar as seguintes abordagens: 1) gerar um volume de dados de entrada menor para o processo (assumindo que estes dados são estatisticamente relevantes); 2) dividir o processo em etapas e analisando cada uma delas de forma independente ou; 3) utilizar o recurso de amostragem do Oracle (e ele se preocupa em reduzir o volume de dados por você).

Sobre o recurso de amostragem, talvez um recurso que poucos conheçam, trata-se da clausula SAMPLE do SELECT. Observe:


oracle@hitomi:~$ sqlplus paulo/paulo

SQL*Plus: Release 11.2.0.2.0 Beta on Sat Nov 26 13:45:03 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> create table t as select rownum x from dual connect by level <= 100;

Table created.

SQL> select count(*) from t;

  COUNT(*)
----------
       100

SQL> select count(*) from t sample(10);

  COUNT(*)
----------
12

SQL> /

  COUNT(*)
----------
7

SQL> /

  COUNT(*)
----------
4

SQL> /

  COUNT(*)
----------
11

SQL> select * from t sample(10);

X
----------
8
15
22
30
76
94

6 rows selected.

SQL>

Neste exemplo, foi criada uma tabela t com 100 linhas. Em seguida, demonstro o uso da cláusula sample com uma amostragem de 10%. Note que, por ser um conjunto de dados pequenos, existe uma grande variação no número de linhas retornadas. Para conjuntos de dados maiores esta cláusula tende a representar subconjuntos bastante significativos.

A grande vantagem do seu uso, também, é o fato de que você não precisa modificar a sua massa de dados de origem e consegue reduzir o tempo de execução necessário para cada teste de alteração no procedimento em que se está fazendo o tuning.

Uma vez estabelecidos os critérios de reprodutibilidade, o objetivo do tuning e a baseline de referência, seja esta para a massa de dados completa ou parcial, podemos então partir efetivamente para a tarefa de tuning.

Nesta próxima etapa precisamos tomar o cuidado de manter um controle rigoroso das alterações que fazemos, alterando de preferência uma coisa de cada vez. As vezes é muito tentador fazer várias modificações ao mesmo tempo, porém corremos sempre o risco de perder a referência e ter que voltar atrás várias vezes até descobrir qual alteração melhorou e qual piorou a performance do processo.

Eu recomendo o uso de uma planilha do Excel como controle de execuções, alterações, efeitos esperados e efeitos obtidos. Para não tornar este post demasiadamente extenso, continuarei a falar sobre isso na parte 3 desta série... fiquem ligados!

Metodologia para Tuning de Procedimentos - Parte 1

É comum no meu dia-a-dia receber chamados para a otimização de um determinado procedimento ou query que está demasiado lento. Para realizar uma tarefa como esta, o banco nos oferece diversas ferramentas que facilitam bastante a nossa vida, porém sem uma metodologia adequada elas podem não só se mostrarem ineficientes como também prejudicar o processo como um todo.

É por este motivo que eu gostaria de iniciar hoje uma discussão sobre uma metodologia para otimização, focando principalmente em código PL/SQL, mas também comentando alguns aspectos sobre o tuning de querys. Esta é a parte 1 de uma série de artigos que virão na sequencia para comentar sobre este tema.

O primeiro critério para um tuning bem sucedido é a reprodutibilidade. De modo geral eu costumo gastar um bom tempo na preparação do ambiente para que eu possa reproduzir a situação-problema inúmeras vezes. Dependendo do processo isso vai envolver apagar dados de tabelas chave, salvar valores de colunas numa tabela de backup, truncar tabelas inteiras... enfim, é importante mapear todas as condições para um restart limpo e deixar elas a mão em um script de limpeza (pode ser o próprio script de execução da rotina), pois a cada modificação do cenário é necessário recomeçar do zero ou corremos o risco de obter uma falsa sensação de objetivo cumprido e o processo voltar a dar problema nas mãos do usuário.

Uma ressalva importante na questão da reprodutibilidade é que você não pode ignorar as características do banco, ou seja, não se trata apenas de código pois algumas features fundamentais que fazem o banco Oracle ter uma performance excelente podem atrapalhar você na hora do tuning.

Vai ficar mais claro com um exemplo: suponha que o problema da sua query está diretamente relacionada a um excesso de I/O físico (physical reads). No caso, ao executar ela pela primeira vez ela estará bastante lenta... aí você modifica um ou outro código e bota ela para rodar de novo. Para sua surpresa a query executa quase instantâneamente! "Problema resolvido!" você pensa, mas pode estar muito enganado! Acontece que ao executar a primeira vez a query os blocos das tabelas estavam no disco e não na memória... um cache miss no db block cache então solicita a carga das tabelas para memória (este é um processo lento). Ao executar a segunda query, independente dela ser diferente ou não, seu tempo de acesso vai ser mais rápido porque o cache miss agora é um cache hit, ou seja, o banco vai acessar diretamente o dado das tabelas em memória e o gargalo do I/O físico vai aparentemente desaparecer, para voltar apenas quando os blocos em cache forem aged out (removidos).

Uma forma de se ver livre deste viés é fazer um flush do buffer cache:

Alter System Flush buffer_cache;

Porém jamais faça isso em produção, pois este comando não é nada seletivo e todos os blocos em memória são descarregados para o disco. Seus usuários agradecem!

Outro fator que pode impactar é o parsing da query. No Oracle existem duas formas de parse: o hard parse e o soft parse. No hard parse é feita a completa validação e avaliação da query, desde a elaboração do melhor plano de execução até a construção do result set. Este parse é bastante demorado em função de que diversos algoritmos são aplicados para escolher o plano ótimo. Por outro lado, o soft parse se baseia num plano de execução pronto e após uma validação mais rápida da query parte direto para a fase de execução (execute) e aquisição (fetch) dos dados. Por este motivo o soft parse é muito mais rápido e é sempre desejável.

Agora, sempre que uma query não está em memória o Oracle necessita fazer um hard parse, mas uma vez carregada ele vai fazer o soft parse sempre que possível. Portanto, ao executar pela segunda vez uma query a tendência é que ela seja mais rápida por não necessitar mais do parse completo. Mais uma vez existe um comando para eliminar este viés, que é:

Alter system flush shared_pool;

Estes dois comandos são um tanto radicais, pois ambos destroem completamente os dados carregados em memória. Por isto, não recomendo o seu uso exceto em ocasiões muito especiais. Além disto, existem algumas formas de contornar estas otimizações do Oracle de forma menos agressiva, como por exemplo, no caso do parsing, executar um gather stats da tabela alvo com o parametro no_invalidade=>false. Este parâmetro força a reavaliação dos planos de todas as querys que dependem da tabela. Ou ainda, se o parâmetro cursor_sharing da instância estiver setado para exact, basta fazer uma modificação simples da query como inserir um espaço em branco ou modificar a caixa de uma letra que a query será tratada como uma query totalmente nova (a comparação das querys no Oracle é textual/binária).

No caso do db block cache, eu procuro nivelar o terreno para o tuning desconsiderando a primeira execução e utilizando como métrica sempre a segunda em diante. Existem algumas outras técnicas, mas para não me estender muito vou deixar para comentar sobre isso num post futuro.

Sumarizando então o tópico da reprodutibilidade, é importante garantir uma metodologia para executar o procedimento sempre nas mesmas condições, tanto em termos de dados como de infraestrutura de banco. Esta preocupação é necessária para termos uma baseline para trabalhar com a qual poderemos medir as influências das nossas alterações e identificar resultados positivos e negativos das intervenções. Existem alguns fatores externos que também devemos sempre procurar minimizar, como por exemplo, a concorrência, mas nem sempre temos poder sobre isso... neste caso o importante é lembrar que ela existe e que o seu resultado nem sempre estará "puro".