Oracle Performance Diagnostics & Tuning Sem Dor – Acelerando INSERTs

Oracle Performance Diagnostics & Tuning Sem Dor – Acelerando INSERTs

Antes de executar um ajuste no RDBMS Oracle, em resposta a um problema de desempenho, devemos ter um diagnóstico correto.

Sem um correto diagnóstico, não faz sentido prosseguir.
O desempenho de processos computacionais é medido por velocidade. Quanto mais rápido, melhor o desempenho.
E quando se trata de velocidade, o desempenho só pode ser medido pelo tempo.

Portanto, para um correto diagnóstico de um problema de desempenho, deve-se saber onde o tempo é gasto.
Finalmente, para saber-se onde o tempo é gasto no RDBMS Oracle, não há uma forma mais direta que observar as WAITs.

As WAITs são eventos de espera por recursos computacionais, físicos (Hard Disk, RAM, Network, etc.) ou lógicos (Latches, Enqueues, etc.). Estes recursos são limitados, e são os únicos limitadores do desempenho de um comando SQL. Se não houvesse espera por recursos computacionais, todos comandos SQLs seriam finalizados instantaneamente.

Vejam esta simples tabela:

C:\Users\Ricardo>set ORACLE_SID=TEST11GR1

C:\Users\Ricardo>set ORACLE_HOME=c:\oracle\product\11.1.0\db_1

C:\Users\Ricardo>sqlplus SCOTT/TIGER

SQL*Plus: Release 11.1.0.7.0 - Production on Seg Ago 31 08:32:51 2009

Copyright (c) 1982, 2008, Oracle. All rights reserved.

Conectado a:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing option

SQL> CREATE TABLE PESSOAS (NOM_PESSOA VARCHAR2(255));

Tabela criada.

SQL> EXIT;

Após criar a tabela, irei inserir nomes de pessoas fictícias, extraídos de um arquivo texto, com cerca de 900.000 linhas.
Abaixo está o script Perl que faz estes INSERTs. Ele abre o arquivo texto, lê linha a linha, separando os campos (que estão limitados por tabulações), e usa o primeiro campo na instrução de INSERT.

use strict;
use warnings;
use DBD::Oracle;

system("time /T");
my $dbh = DBI->connect("dbi:Oracle:host=localhost;sid=TEST11GR1;port=1523", 'SCOTT', 'TIGER', {RaiseError => 1, AutoCommit => 0});
my $sth;
open(PESSOAS, '<person.tsv');
while ()
{
my $linha = $_;
chomp $linha;
my @pessoa = split(/\t/, $linha);
if ($pessoa[0] eq 'name') {next;};
$pessoa[1] =~ s/\/guid\///;
$pessoa[0] =~ s/\'//g;
my $sql = "INSERT INTO pessoas (nom_pessoa) VALUES ('$pessoa[0]')";
$sth = $dbh->prepare($sql);
$sth->execute();
}
$dbh->commit();
$sth->finish();
close PESSOAS;
system("time /T");

print 'INSERTs finalizados. Pressione ENTER.\n';
my $go = ;

$dbh->disconnect();
exit;

Esta é a saída da execução deste script:

C:\temp>perl Insert_Oracle.pl
10:34
10:44
INSERTs finalizados. Pressione ENTER.\n

C:\temp>

Com o script finalizado, irei verificar onde ele gastou mais tempo.

C:\Users\Ricardo>sqlplus / AS SYSDBA

SQL*Plus: Release 11.1.0.7.0 - Production on Seg Ago 31 10:24:48 2009

Copyright (c) 1982, 2008, Oracle. All rights reserved.

Conectado a:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> SET PAGESIZE 1000
SQL> SET LINESIZE 210
SQL> SELECT SID FROM V$SESSION WHERE USERNAME = 'SCOTT';

SID
----------
137

SQL> SELECT EVENT, AVERAGE_WAIT, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE SID = 137 ORDER BY AVERAGE_WAIT;

EVENT AVERAGE_WAIT TOTAL_TIMEOUTS
---------------------------------------------------------------- ------------ --------------
latch: row cache objects 0 0
SQL*Net message to client 0 0
SQL*Net message from client ,02 0
latch: shared pool ,02 0
db file single write ,03 0
events in waitclass Other ,04 0
control file sequential read ,09 0
control file parallel write ,1 0
log file sync ,38 0
Data file init write ,39 0
db file sequential read ,5 0
db file scattered read 2,49 0
log file switch completion 4,84 0

13 linhas selecionadas.

SQL>

Não há segredo: o maior tempo médio deste caso é o log file switch completion. Consultando a documentação de WAITs do RDBMS Oracle, vemos que este
evento ocorre quando o Oracle já utilizou todos os REDO LOGs, da forma circular de sempre, e precisou usar o primeiro novamente, mas as informações que
estavam nele ainda não foram gravadas nos DATAFILEs (pelo DBWR), portanto, não podem ser sobrescristas, pois seriam necessárias em um eventual RECOVER.

Finalizado o diagnóstico, vamos ao ajuste. Para reduzir a ocorrência deste problema, já que o Oracle RDBMS quer mais REDO LOGs, dê mais REDO LOGs a ele.

SQL> COL MEMBER FORMAT A70
SQL> SELECT * FROM V$LOGFILE;

GROUP# STATUS TYPE MEMBER IS_
---------- ------- ------- ---------------------------------------------------------------------- ---
3 ONLINE C:\ORACLE\ORADATA\TEST11GR1\REDO03.LOG NO
2 ONLINE C:\ORACLE\ORADATA\TEST11GR1\REDO02.LOG NO
1 ONLINE C:\ORACLE\ORADATA\TEST11GR1\REDO01.LOG NO

SQL> ALTER DATABASE ADD LOGFILE 'C:\ORACLE\ORADATA\TEST11GR1\REDO04.LOG' SIZE 1G;

Banco de dados alterado.

SQL> ALTER DATABASE ADD LOGFILE 'C:\ORACLE\ORADATA\TEST11GR1\REDO05.LOG' SIZE 1G;

Banco de dados alterado.

SQL> ALTER DATABASE ADD LOGFILE 'C:\ORACLE\ORADATA\TEST11GR1\REDO06.LOG' SIZE 1G;

Banco de dados alterado.

SQL>

Agora podemos executar o script novamente.

C:\temp>perl Insert_Oracle.pl
11:13
11:23
INSERTs finalizados. Pressione ENTER.\n

Ué, o tempo continuou mesmo, mesmo reduzindo a maior WAIT.

SQL> SELECT EVENT, AVERAGE_WAIT, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE SID = 142 ORDER BY AVERAGE_WAIT;

EVENT AVERAGE_WAIT TOTAL_TIMEOUTS
---------------------------------------------------------------- ------------ --------------
latch: cache buffers chains 0 0
latch: row cache objects 0 0
SQL*Net message to client 0 0
events in waitclass Other 0 0
latch: shared pool ,02 0
SQL*Net message from client ,02 0
db file sequential read ,57 0
log file sync ,92 0

8 linhas selecionadas.

SQL>

A armadilha deste caso é que os grandes tempos médios das WAITs físicas (log file sync, db file sequential read, SQL*Net message from client) esconde o péssimo tempo médio de uma WAITs lógica: latch: shared pool. Coisas lógicas devem ser mais rápidas que coisas físicas ! 20 milissegundos para acessar uma estrutura de memória é muito tempo, muito mais grave do que 900 milissegundos para completar um switch.

Novamente consultando a documentação de WAITs do RDBMS Oracle, vemos que este evento é causado por compilações excessivas de comandos SQL. Bom, vamos alterar o script para utilizar SQLs reutilizáveis, na versão Perl para as variáveis BIND.

use strict;
use warnings;
use DBD::Oracle;

system("time /T");
my $dbh = DBI->connect("dbi:Oracle:host=localhost;sid=TEST11GR1;port=1523", 'SCOTT', 'TIGER', {RaiseError => 1, AutoCommit => 0});
my $sth;
open(PESSOAS, '<person.tsv');
while ()
{
my $linha = $_;
chomp $linha;
my @pessoa = split(/\t/, $linha);
if ($pessoa[0] eq 'name') {next;};
$pessoa[1] =~ s/\/guid\///;
$pessoa[0] =~ s/\'//g;
my $sql = "INSERT INTO pessoas (nom_pessoa) VALUES (?)";
$sth = $dbh->prepare($sql);
$sth->execute($pessoa[0]);
}
$dbh->commit();
$sth->finish();
close PESSOAS;
system("time /T");

print 'INSERTs finalizados. Pressione ENTER.\n';
my $go = ;

$dbh->disconnect();
exit;

E então podemos verificar o tempo resultante desta alteração.

C:\temp>perl Insert_Oracle.pl
11:30
11:34
INSERTs finalizados. Pressione ENTER.\n

C:\temp>

O tempo caiu de 10 para 4 minutos, mais de 100% de melhora. Vamos ver como ficaram as WAITs desta execução:

SQL> SELECT EVENT, AVERAGE_WAIT, TOTAL_TIMEOUTS FROM V$SESSION_EVENT WHERE SID = 142 ORDER BY AVERAGE_WAIT;

EVENT AVERAGE_WAIT TOTAL_TIMEOUTS
---------------------------------------------------------------- ------------ --------------
latch: cache buffers chains 0 0
SQL*Net message to client 0 0
events in waitclass Other ,01 0
SQL*Net message from client ,02 0
log file sync ,64 0

SQL>

Mais uma lição importante: após o ajuste de desempenho, se o tempo do comando SQL ficou satisfatório, o processo de diagnóstico deve ser encerrado. Não caia na tentação de eliminar todas as WAITs simplesmente porque você pode elimina-las. Você não conseguirá eliminar todas as WAITs, aceite isso. Faça o que for necessário para que o tempo de execução fique satisfatório para o cliente, e siga em frente.