Caso 1: tempo entre chamadas e SQL linha a linha

O caso 1 é uma sessão de 50,8 s em que 73,6% do tempo fica entre as chamadas, sem espera registrada, e dois comandos recursivos rodam 89.112 vezes cada. Esta página percorre o relatório do caso 1 na ordem das seções, do resumo aos objetos: o que cada número mostra, que hipótese ele sustenta ou descarta e o que conferir em seguida, até a causa provável e o que fazer.

Passo 1: resumo e aviso

Antes do Resumo, o relatório mostra o aviso 718792 chamadas recursivas sem chamada de nível 0 correspondente (trace iniciado ou cortado no meio de uma chamada). O Resumo traz:

• Tempo total: 50,833 s;
• Chamadas ao banco: 719.114, só 6 de nível 0;
• Esperas: 20.320, com 0,166 s entre chamadas;
• Comandos distintos: 1.977, com 2 commits.

Quase todas as chamadas são SQL recursivo, o SQL que roda dentro de PL/SQL, e não pedidos diretos da aplicação (SQL recursivo). As 20.320 esperas mostram que o trace gravou as esperas: o tempo não contabilizado deste caso não vem de trace sem esperas. O aviso diz que alguma chamada de nível 0 começou antes do arquivo ou termina depois dele.

Para saber qual, abra Chamadas de nível 0 mais longas: são só 6 chamadas, e a mais longa leva 0,070 s. Ela é o PARSE do comando #4, o bloco BEGIN ROT_0001('***',*** ); END;, que começa a 0,068 s do início. Em Comandos SQL, o #4 tem Exec 0. A linha de uma chamada só vai para o trace quando a chamada termina (linhas do trace): o EXEC do bloco ainda rodava quando o recorte acaba. Depois do PARSE, quase todo o tempo do caso, cerca de 50,7 s, passa dentro desse bloco.

Veja no relatório: Resumo do caso 1. Para ler cada número: Resumo e Chamadas de nível 0 mais longas.

Passo 2: diagnóstico

O Diagnóstico traz nove achados, em ordem de severidade. Os que se repetem para o #1 e o #2 estão numa linha só:

Os achados são pistas, não conclusões (Diagnóstico). Os dois primeiros falam do mesmo tempo, 37,419 s. O texto das lacunas sugere trace ligado e desligado no meio da sessão, ou processo parado fora do banco. O passo 1 explica por que esse tempo aparece entre chamadas: sem o EXEC do bloco no arquivo, o tempo que o bloco passa fora dos comandos SQL não cai em nenhuma chamada. O tempo em si é real: a sessão passou esses 37,419 s dentro da rotina, entre um SQL e o próximo. Os outros achados apontam para os comandos que ela executa: dois SELECT uma vez por linha, cada um com um PARSE por execução, e INSERTs com literais.

Veja no relatório: Diagnóstico do caso 1.

Passo 3: perfil

O Perfil do tempo de resposta divide os 50,833 s em componentes. Os maiores:

Por classe de espera, Não contabilizado soma 73,7%, CPU 23,8% e User I/O 2,4%. O perfil descarta três hipóteses:

• Tempo na aplicação. Quando a aplicação demora entre um pedido e outro, a sessão grava SQL*Net message from client. Aqui são 2 esperas e 0,001 s: enquanto o bloco roda, a aplicação espera por ele, e não o contrário (sessão esperando a aplicação).
• Trace sem esperas. O trace tem 20.320 esperas (passo 1).
• Disco lento. Toda a classe User I/O soma 2,4%: mesmo que fosse a zero, o tempo total cairia no máximo isso.

Sobra o tempo dentro do bloco, entre um comando SQL e o próximo: o código PL/SQL da rotina trabalhando, ou o processo esperando a vez na CPU num servidor ocupado. Dividido pelas 180.269 execuções, dá cerca de 0,2 ms entre um SQL e o seguinte. O trace não separa as duas coisas, porque a linha EXEC do bloco, com a CPU dele, ficou fora do recorte. O próximo passo mostra o que a rotina executa, e quantas vezes.

Veja no relatório: Perfil do caso 1 e a linha tempo não contabilizado entre chamadas, cujo nome abre o cartão com Onde olhar. Para ler: Perfil do tempo de resposta e Classes de espera e SQL recursivo.

Passo 4: principais comandos

Em Principais comandos por componente e por classe, os grupos de CPU mostram quem gastou o tempo que o banco mediu:

• CPU: PARSE dbcalls: #2 com 31,7%, #1 com 30,4% e #3 com 25,7%;
• CPU: FETCH dbcalls: #2 com 50,3% e #1 com 49,2%;
• CPU: EXEC dbcalls: #1 com 41,3% e #2 com 39,5%.

Em Comandos SQL por contribuição, o #1 e o #2 são SELECT de profundidade 1, com 89.112 execuções, 89.112 linhas e 445.560 leituras lógicas cada: uma linha e 5 leituras lógicas por execução, sem leitura de disco (PIO 0). Cada execução custa pouco; o custo está na quantidade. Os três INSERT com literais em TAB_0001 (#3, #8 e #9) somam 1.217, 350 e 251 execuções, ou 1.818, e 89.112 dividido por 1.818 dá 49: a conta sugere que, para cada linha gravada em TAB_0001, a rotina executa o #1 e o #2 49 vezes cada.

Veja no relatório: Comandos por componente do caso 1 e Comandos SQL do caso 1. Para ler: Comandos por componente e Comandos SQL por contribuição.

Passo 5: detalhe do comando

Abra o comando #1 pelo número na lista ou pelo link Ver comando #1 do Diagnóstico. O título traz o selo 49 variantes: o comando é uma forma, que soma 49 textos que só diferem nos literais. O texto da forma é:

SELECT (SELECT COL_0073 FROM TAB_0005 WHERE COL_0074 = :n AND ROWNUM <=:n) AS COL_0073 FROM DUAL

O :n marca o lugar de um número escrito no texto. O detalhe mostra:

• Variantes que mais gastaram: as variantes listadas têm 7.276 ou 7.272 chamadas, ou seja, 1.819 ou 1.818 execuções de quatro chamadas cada (PARSE, EXEC, FETCH e CLOSE). Bate com os 1.818 INSERT em TAB_0001: cada valor é consultado uma vez por linha gravada. Os literais aparecem como *** por causa da máscara (variantes que mais gastaram).
• Chamadas: 89.112 PARSE para 89.112 EXEC, com 49 Misses: só 49 PARSE foram hard parse. Os outros acharam o cursor na library cache, mas custaram uma chamada e CPU assim mesmo.
• Perfil do comando: CPU de FETCH com 45,3%, de PARSE com 31,5% e de EXEC com 18,3%, sem espera.

Valores no texto, um texto por valor e um PARSE a cada execução: o mais provável é SQL dinâmico montado por concatenação dentro de um laço, com EXECUTE IMMEDIATE ou equivalente. Confirme no código de ROT_0001. O #3 segue o mesmo desenho: 1.217 INSERT e 1.217 hard parses, e a CPU de PARSE é 90,6% do tempo dele. A seção Textos compartilháveis junta essas formas, com os SQL IDs ocultos pela máscara (Textos compartilháveis).

Falta saber o que é TAB_0005. O #10 é TRUNCATE TABLE TAB_0005, e o #16 grava nela 50 linhas: é uma tabela de trabalho, que a rotina esvazia, enche e depois consulta 178.224 vezes. O detalhe do bloco #4 confirma o passo 1: o quadro Chamadas só tem o PARSE.

Veja no relatório: detalhe do comando #1. Para ler: Detalhe do comando.

Passo 6: plano

No Plano de execução do #1, a nota diz plano gravado 89115 vezes, mostrando o da gravação mais demorada. O plano vem das linhas STAT, que o trace traz quando o cursor fecha (guia de tracing do 19c): o plano gravado cerca de uma vez por execução é mais um sinal de que o cursor fecha e abre de novo a cada uso.

O quadro Onde o plano gasta destaca a operação 2, TABLE ACCESS FULL TAB_0005, com 86,5% do tempo e 100,0% das leituras lógicas do plano, e o cartão sugere conferir se o filtro é seletivo e se há índice para ele. Leia a linha antes de seguir a sugestão: a operação devolve 1 linha com 5 leituras lógicas, em 0,000032 s. Ler inteira uma tabela de 50 linhas custa pouco. Um índice em COL_0074 economizaria parte dessas 5 leituras, mas não as 178.224 execuções nem os PARSE: aqui, o plano não é a causa (operação que concentra o plano).

O plano do #7, DELETE FROM TAB_0001, mostra um ponto menor: INDEX FULL SCAN IDX_0001 leu 1.870 blocos do índice, e o comando não apagou nenhuma linha. A tabela estava vazia, mas o índice ainda ocupa esses blocos. O #7 soma 1,023 s, 2,0% do tempo total.

Veja no relatório: operação 2 do plano do #1. Para ler: Plano de execução.

Passo 7: esperas e latência

A Distribuição de latência confirma que o disco fica fora da causa. O db file sequential read tem 1.962 leituras e soma 1,048 s: 87,3% delas levam menos de 100 µs, e as 111 que levam de 1 a 100 ms somam 92,0% do tempo do evento. Em Leituras, a tabela Primeira leitura e releitura do mesmo bloco mostra 1.956 blocos distintos e 6 releituras: o cache não obriga a ler o mesmo bloco de novo. Das 1.962 leituras, 1.870 são do DELETE #7 (passo 6).

Em Tipos de chamada, a linha PARSE tem 180.117 chamadas e 1.920 Misses: quase todos os PARSE são soft parse, e os hard parses vêm quase todos dos textos com literais (muitos hard parses). O peso não está no hard parse, e sim na quantidade de chamadas: 180.117 PARSE, 180.269 EXEC e 178.460 FETCH em 50 s.

Veja no relatório: latência do db file sequential read, Leituras e Tipos de chamada. Para ler: Distribuição de latência, Leituras e Tipos de chamada.

Passo 8: objetos

Objetos com mais tempo de espera começa por IDX_0001, com 0,931 s em 1.877 esperas, quase todas leituras do DELETE #7. Depois vêm o objeto 187750, sem nome, com 0,165 s em 18.336 esperas de direct path read, e TAB_0005, com 0,023 s. Nenhum objeto chega a 2% do tempo total: o tempo do caso não está em espera por um objeto, e esta seção só confirma o ponto menor do passo 6.

O nome vem das linhas STAT do próprio trace, e o objeto sem nome não aparece em nenhum plano. Na console, o obj# abre a página do objeto, com as consultas para identificá-lo no banco (Objetos com mais espera).

Veja no relatório: Objetos do caso 1.

O que o recorte não mostra

O recorte de 2.000.000 linhas cobre 50,8 s desta sessão. O que fica de fora:

• O fim da rotina. O arquivo acaba no meio do bloco #4. Os 50,8 s são a parte da execução que coube no recorte, e não a duração da operação; as contagens, como as 89.112 execuções, param ali.
• A CPU do próprio PL/SQL. A linha EXEC do bloco traria a CPU e a duração dele. Sem ela, os 37,419 s entre chamadas não se dividem entre trabalho do PL/SQL e espera pela CPU.
• A contribuição de cada comando. Sem a chamada de nível 0, a coluna Contribuição fica incompleta; compare pelo Inclusivo (passo 4).
• O que vem depois. O commit, outras fases da rotina e a volta para a aplicação ficam fora do arquivo.

O mesmo vale para um trace seu desligado antes do fim da operação, ou que parou no limite de tamanho do arquivo (trace cortado). Para medir a operação inteira, ligue o trace antes de ela começar e desligue depois do fim (trace cortado no meio).

Causa raiz provável

A rotina ROT_0001, chamada pelo bloco #4, processa linha a linha. Pela conta dos passos 4 e 5, para cada linha que grava em TAB_0001, ela monta com literais e executa 98 consultas a uma tabela de trabalho de 50 linhas, 49 do #1 e 49 do #2, e um INSERT, também com literais. No recorte, são cerca de 180 mil execuções de SQL, quase todas com o próprio PARSE. Uma a uma, elas custam pouco, cerca de 12 s de CPU no total; o tempo maior, 37,4 s, fica no PL/SQL entre um comando e outro, ou na espera pela CPU.

O que não é a causa: o disco (2,4% do tempo), a aplicação fora do banco (0,001 s de espera) e a falta de índice em TAB_0005 (5 leituras lógicas por execução).

O que fazer

Na aplicação

1. Leia TAB_0005 uma vez, antes do laço, numa coleção PL/SQL indexada pela chave, e consulte a coleção dentro do laço. Somem as 178.224 consultas, os PARSE delas e o PL/SQL gasto para montar e disparar cada uma:

   -- hoje, o mais provável: um SQL montado com o valor no texto, para cada chave
   execute immediate 'select valor from exemplo_parametros where chave = ' || v_chave
     into v_valor;
   
   -- na memória: as linhas lidas uma vez, antes do laço
   declare
     type t_valores is table of exemplo_parametros.valor%type index by pls_integer;
     v_valores t_valores;
   begin
     for r in (select chave, valor from exemplo_parametros) loop
       v_valores(r.chave) := r.valor;
     end loop;
     -- dentro do laço, sem ir ao banco: v_valor := v_valores(v_chave);
   end;
   /

2. Se der, troque o laço inteiro por um único INSERT ... SELECT que junte as tabelas de origem com TAB_0005 e grave todas as linhas de TAB_0001 de uma vez (linha a linha em PL/SQL).
3. O SQL que continuar dinâmico deve receber os valores como bind, com USING, e não no texto: um cursor serve a todos os valores, e os hard parses caem (literais em vez de bind).

No banco

1. Confira a carga de CPU do servidor no período do trace, pelo histórico do sar ou da monitoração. Se havia fila de CPU, ela explica parte dos 37,4 s, e a correção também passa pelo servidor (tempo não contabilizado dentro das chamadas).
2. Meça a rotina com o profiler hierárquico de PL/SQL (DBMS_HPROF), que separa o tempo de SQL e o de PL/SQL por subprograma (documentação do profiler). Ele mostra em que trecho do código ficam os 37,4 s.
3. Enquanto o código não muda, CURSOR_SHARING=FORCE na sessão da rotina reduz os 1.920 hard parses. É paliativo, pode mudar planos e não tira as execuções nem os PARSE: aqui, o ganho é pequeno (literais em vez de bind).
4. Com folga, veja o DELETE #7: confira o tamanho de IDX_0001 na página do objeto. Se a tabela é esvaziada a cada execução, avalie com quem mantém a rotina trocar o DELETE por TRUNCATE, que também esvazia os índices da tabela. O TRUNCATE é DDL: confirma a transação aberta e não volta com ROLLBACK (TRUNCATE TABLE).

Como confirmar

Ligue o trace com esperas antes da chamada da rotina e desligue depois do fim, antes e depois da mudança (ligar o trace com o DBMS_MONITOR). Com o trace inteiro, a linha EXEC do bloco entra no arquivo, e o tempo que hoje aparece entre chamadas passa para o bloco: em CPU: EXEC dbcalls se for trabalho do PL/SQL, ou em tempo não contabilizado dentro das chamadas se for espera pela CPU. Depois da mudança, Chamadas ao banco e Tempo total devem cair, e os achados de linha a linha e de PARSE a cada execução devem sumir. Compare as análises pela coluna Tempo total do Histórico (o método).