quinta-feira, 1 de março de 2012

Caso de Performance 3: Bind variables

Olá pessoal. Hoje vou continuar com a demonstração do efeito de usar (e não usar) bind variables no Oracle. Começo ressaltando que embora eu esteja usando um exemplo em PL/SQL pela praticidade, isto é válido para qualquer linguagem que se comunica com o banco, incluindo java, C++ e outras. De modo geral, vou provar para vocês que montar uma query com valores concatenados sempre é uma má idéia, pois força o hard parsing aumentando intensamente o consumo de recursos pelo banco e simplesmente destrói a shared pool no curto prazo.

O código de exemplo é bastante simples: vamos montar uma tabela T com duas colunas, X e Y, ambas numéricas e com valores de 1 a 1000. Em seguida, vamos fazer um bloco anônimo em PL/SQL que lê esta tabela passando o valor de X e retornando Y para uma variável em memória. Faremos este bloco repetir este processamento 100 vezes (portanto, executamos 100.000 vezes a query de recuperação de valor) e tomamos o tempo gasto nesta operação.

O bloco anônimo primeiramente vai ser implementado usando a concatenação de valores e, num segundo momento, vai ser reescrito para utilizar bind variables. A nossa prova será a diferença de tempo entre as execuções e também as estatisticas de parsing da sessão.

Vamos passo a passo:

/tmp$ sqlplus paulo/paulo

SQL*Plus: Release 10.2.0.1.0 - Production on Thu Mar 1 01:02:01 2012

Copyright (c) 1982, 2005, Oracle.  All rights reserved.
 
Connected to:
Oracle Database 10g Express Edition Release 10.2.0.1.0 - Production
 
SQL> drop table t;
 
Table dropped.
 
SQL> create table t(x number, y number);

Table created.
 
SQL> insert into t
  2  select rownum, rownum from dual connect by level <= 1000;
 
1000 rows created.
 
SQL> commit;

Commit complete.

Ok, com a tabela criada vamos primeiro tomar a medida da quantidade de parses executadas até o momento para termos como base. Isto é feito com a query abaixo:

SQL> select sn.name, vm.value
  2    from v$mystat   vm,
  3          v$statname sn
  4   where vm.statistic# = sn.statistic#
  5      and sn.name like '%parse%';

NAME                                      VALUE
---------------------------------------------------------------- ----------
parse time cpu                                 16
parse time elapsed                             19
parse count (total)                           445
parse count (hard)                             95
parse count (failures)                          0


Esta query resume as principais estatísticas da sessão com relação ao parse. Estamos mais interessados, no entanto, no parse count (total) e no parse count (hard). Tenha em mente o seguinte: o parse count (total) é a soma de todos os parses executados, sejam eles hard ou soft. A diferença entre um parse hard e um soft é que no hard parse o banco precisa validar a query e estabelecer o plano de execução, um processo bastante demorado e consumidor de recursos. Já no soft parse, o banco apenas verifica se a query já existe na shared pool e reaproveita o plano existente, economizando aí um tempo bastante significativo. Pelas estatisticas acima, para saber a quantidade de soft parses basta subtrair a quantidade de hard parses do total.

Vamos então executar o bloco anônimo com o código que utiliza concatenação de valores para gerar as diversas querys.

SQL> declare
  2    v_num number;
  3    t0    number := dbms_utility.get_time;
  4 
  5  begin
  6    for r1 in (select rownum from dual connect by level <= 100)
  7    loop
  8       for r2 in (select rownum from dual connect by level <= 1000)
  9       loop
 10         execute immediate 'select y from t where x = ' || r2.rownum into v_num;
 11       end loop;
 12    end loop;
 13    dbms_output.put_line('hsecs=' || (dbms_utility.get_time - t0));
 14  end;
 15  /
hsecs=11859

PL/SQL procedure successfully completed.


Como vocês podem ver, esta operação tomou um tempo significativo do banco: 11859 centésimos de segundo, ou 118.59 segundos. Acompanhe a estatistica de parses:

SQL> select sn.name, vm.value
  2    from v$mystat   vm,
  3          v$statname sn
  4   where vm.statistic# = sn.statistic#
  5      and sn.name like '%parse%';

NAME                                      VALUE
---------------------------------------------------------------- ----------
parse time cpu                                  10881
parse time elapsed                              10980
parse count (total)                            200494
parse count (hard)                             100113
parse count (failures)                              0

Agora, temos duas coisas interessantes para observar: primeiro, a contagem de hard parses foi lá em cima, como esperado, mas por que ainda sim tivemos quase 50% de soft parses? A resposta está no fato de que sempre existem querys recursivas, ou internas do banco, que são executadas quando enviamos qualquer comando para o banco, e certamente elas foram escritas para serem reaproveitadas. Isso explica também porque a quantidade de hard parses foi um pouco acima do esperado (100.000). Enfim, vamos ao segundo teste:

SQL> declare
  2    v_num number;
  3    t0    number := dbms_utility.get_time;
  4 
  5  begin
  6    for r1 in (select rownum from dual connect by level <= 100)
  7    loop
  8       for r2 in (select rownum from dual connect by level <= 1000)
  9       loop
 10         execute immediate 'select y from t where x = :1' into v_num using r2.rownum;
 11       end loop;
 12    end loop;
 13    dbms_output.put_line('hsecs=' || (dbms_utility.get_time - t0));
 14  end;
 15  /
hsecs=798

PL/SQL procedure successfully completed.

Desta vez fizemos do jeito certo: com bind variables. E o resultado é surpreendente: de 118.59 segundos agora a mesma query executou em apenas 7.98 segundos! Vejamos como ficou a estatística da sessão:

SQL> select sn.name, vm.value
  2    from v$mystat   vm,
  3          v$statname sn
  4   where vm.statistic# = sn.statistic#
  5      and sn.name like '%parse%';

NAME                                      VALUE
---------------------------------------------------------------- ----------
parse time cpu                                  10883
parse time elapsed                              10983
parse count (total)                            200537
parse count (hard)                             100127
parse count (failures)                              0

Lembre-se que estamos na mesma sessão do bloco anterior, ou seja, 200.537 - 200.494 = 43 parses a mais, sendo que destes apenas 14 são do tipo hard! Isso quer dizer que a nossa query com bind variables foi 100% reaproveitada em todas as passadas. Acredito que ficou nítida a diferença de performance que isso proporciona.

Para encerrar, deixo uma pergunta no ar: era esperado que todas as querys recursivas e as querys dos cursores r1 e r2 fossem reaproveitadas já que estamos na mesma sessão, e portanto seriam feitos apenas soft parses das mesmas. Agora, se você parar para pensar, a query do cursor r2 é executada 100 vezes mas temos muito menos de 100 soft parses. Qual seria a explicação para isso? Infelizmente eu não tenho a resposta, mas se alguém tiver fique a vontade para postar nos comentários.

E por hoje é só pessoal! :)