Caso 2: sessão dominada por espera de I/O

O caso 2 é uma sessão de 17 min 9 s em que a classe User I/O soma 51,4% do tempo e as 323.268 leituras de bloco único, 35,6%. Esta página percorre o relatório do caso 2 na ordem das seções, do resumo aos objetos, até a causa provável e o que fazer. O caso mostra por que achar o comando antes de acelerar o disco, e o que fazer quando o comando mais pesado não tem plano no trace.

Passo 1: resumo e aviso

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

• Tempo total: 1.029,051 s, ou 17 min 9 s;
• Chamadas ao banco: 305.623, 180 de nível 0;
• Esperas: 341.608, com 75,177 s entre chamadas;
• Comandos distintos: 185, com 65 commits.

Quase todo o trabalho é SQL recursivo (SQL recursivo), e o trace gravou as esperas. Em Chamadas de nível 0 mais longas, a mais longa leva 0,044 s: nenhuma chamada da aplicação explica 17 minutos. Na mesma tabela, a 74,823 s do início, aparece o PARSE do comando #53, um bloco PL/SQL anônimo (DECLARE ... BEGIN ... END;) que chama rotinas de pacotes. No detalhe do #53, o quadro Chamadas só tem esse PARSE: o EXEC do bloco não está no arquivo, porque ainda rodava quando o recorte acaba (linhas do trace).

O trace tem, então, duas fases: cerca de 75 s de chamadas curtas da aplicação e cerca de 954 s dentro do bloco #53, até o fim do arquivo.

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

Passo 2: diagnóstico

O Diagnóstico traz quatro achados:

O primeiro achado pede para olhar o plano antes do disco, e o link Ver distribuição de latência leva à prova (passo 7). O laço do #1 e do #2 existe, mas os dois somam 1,3% do tempo: corrigi-los agora não muda o caso. Os achados não dizem qual comando faz as leituras: o que mais gasta, o #5, não tem plano no recorte, e sem plano não há achado de plano para ele (passo 6). O perfil e os comandos mostram o tamanho de cada coisa.

Veja no relatório: Diagnóstico do caso 2. Para ler: Diagnóstico.

Passo 3: perfil

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

Por classe de espera, User I/O soma 51,4%, Não contabilizado 23,0%, CPU 18,3% e Idle 7,3%. O que o perfil sustenta e o que descarta:

• Disco lento: fora como causa principal. A média é de 1,132 ms por leitura: o armazenamento responde rápido, e o tempo vem da quantidade, 323.268 leituras (leitura lenta). O passo 7 confirma pela distribuição.
• Tempo na aplicação: só na primeira fase. Os 74,696 s de SQL*Net message from client cabem nos 74,8 s antes do bloco #53. É tempo fora do banco, que ajuste de SQL não reduz, e não é a parte lenta do caso (sessão esperando a aplicação).
• Uma chamada pesada, e não muitas. O máximo de 104,206 s de CPU numa chamada EXEC mostra que um comando concentra o trabalho. O passo 4 diz qual.
• Tempo não contabilizado: confira o servidor. Os 149,483 s dentro das chamadas são tempo em que a sessão não estava na CPU nem numa espera registrada, e uma causa comum é fila de CPU (dentro das chamadas). Os 87,678 s entre chamadas são, como no caso 1, tempo do bloco entre um SQL e outro (entre chamadas).

Veja no relatório: Perfil do caso 2, com as linhas db file sequential read e SQL*Net message from client. 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, o mesmo comando aparece no topo de quase todos os grupos: o #5, um SELECT que começa com WITH TAB_0082 AS (SELECT DISTINCT.

O segundo é o #7, DELETE FROM TAB_0049 A WHERE A.COL_0086 = :B1, com 55,010 s de CPU de EXEC (32,3% do componente) e 41,699 s de tempo não contabilizado dentro das chamadas (27,9%).

Em Comandos SQL por contribuição, o #5 tem contribuição de 0,587 s, mas Inclusivo de 740,853 s: 72,0% do tempo total num único comando. A lista ordena pela contribuição, e por isso ele fica atrás de quatro comandos que, juntos, somam menos de 21 s de inclusivo. O #5 tem profundidade 2, Exec 1, Fetch 126 e 63.000 linhas, com 7.669.408 leituras lógicas (LIO) e 3.528.057 blocos lidos do disco (PIO). O #7 tem Inclusivo de 102,905 s, 10,0% do total, e apagou 2.953.545 linhas numa execução. Como no caso 1, a contribuição não serve para ordenar: o bloco #53 não fecha no arquivo, e Tempo não atribuído a nenhum comando soma 1.017,699 s. Compare pelo inclusivo.

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

Passo 5: detalhe do comando

No detalhe do #5, Peso no tempo total é 0,587 s e Inclusivo, 740,853 s, com Profundidade 2, SQL recursivo: o comando roda para atender a um SQL de profundidade 1, dentro do bloco. O quadro Chamadas mostra onde está o tempo:

Quase todo o tempo está na única chamada EXEC: 688,659 s antes de o primeiro FETCH devolver linhas. As 63.000 linhas saem em 126 FETCH, em média 500 por FETCH: a rotina já busca as linhas em lote. São cerca de 122 leituras lógicas e 56 blocos do disco para cada linha devolvida: a consulta lê muito mais do que devolve.

O Perfil do comando soma 364,191 s de db file sequential read em 322.865 leituras, 104,206 s de CPU de EXEC, 98,163 s de tempo não contabilizado, 82,616 s de direct path read e 62,222 s de leitura e gravação no TEMP. São três tipos de trabalho: leitura bloco a bloco, típica de acesso por índice e por ROWID; leitura direta de um segmento grande; e ordenação ou hash que não coube na memória.

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

Passo 6: plano

O detalhe do #5 não tem o bloco Plano de execução, e o quadro Chamadas não tem CLOSE: o cursor ainda estava aberto no fim do recorte. O plano vem das linhas STAT, que o trace traz quando o cursor fecha (guia de tracing do 19c). Sem o CLOSE, as linhas STAT do #5 não chegaram ao arquivo.

Pegue o plano no banco, enquanto o cursor estiver no cursor cache, com o sql_id do título do detalhe (no caso 2, d7sadnr6zu6k9):

select *
  from table(dbms_xplan.display_cursor('&sql_id', null, 'ALLSTATS LAST'));

As linhas e as leituras reais de cada operação só aparecem se a execução coletou as estatísticas do plano, com a dica GATHER_PLAN_STATISTICS ou com STATISTICS_LEVEL em ALL na sessão; sem isso, o plano traz só as estimativas (referência do DBMS_XPLAN). No plano, procure a operação com mais leituras e confira quantas vezes ela executa e quantas linhas devolve, como no plano do relatório.

O plano do #7 está no recorte. A operação 1, DELETE TAB_0049, tem 98,1% do tempo do plano e o destaque Gravou 66.842 blocos no TEMP: a workarea da PGA não bastou. A operação 2, INDEX RANGE SCAN IDX_0034, devolveu 2.953.545 linhas para 2.943.270 estimadas: a estimativa está certa, então o problema não é de estatística (estimativa de linhas errada). No quadro Chamadas, o único EXEC leva 102,905 s, com 55,010 s de CPU e 13.153.243 leituras em Corrente (CU), o modo de quem altera dados (cu). O custo está em apagar quase 3 milhões de linhas, e não em achá-las: o índice levou 1,952 s.

Veja no relatório: operação 1 do plano do #7. Para ler: operação que concentra o plano.

Passo 7: esperas e latência

Em Distribuição de latência, o db file sequential read mostra 271.109 leituras abaixo de 1 ms (83,9%), que somam 99,938 s; 47.699 de 1 a 10 ms, com 186,767 s; e 4.460 acima de 10 ms, com 79,162 s. A maioria das leituras é rápida, e só a parte rápida já soma 99,9 s: reduzir a quantidade rende mais que acelerar o disco. A cauda acima de 10 ms vale levar à equipe de armazenamento, como item secundário.

Em Leituras, a tabela Primeira leitura e releitura do mesmo bloco mostra 323.225 blocos distintos e só 43 releituras. Não é buffer cache pequeno obrigando a ler o mesmo bloco de novo: é o plano visitando 323 mil blocos diferentes, um por vez.

Em Tipos de chamada, são 394 PARSE para 102.658 EXEC: ao contrário do caso 1, a rotina mantém os cursores abertos, e parse não é problema aqui.

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 pelo objeto 192892, sem nome, com 404,790 s em 290.860 esperas, 39,3% do tempo total. Em seguida vêm o 202849, com 66,670 s em 33.428 leituras de bloco único, e o 192893, com 15,837 s. Pelo passo 4, são objetos que o #5 lê: ele tem 99,5% do tempo de db file sequential read e todo o direct path read.

Eles não têm nome porque o nome vem das linhas STAT, e o #5 não tem as dele no recorte. Identifique os objetos no banco do trace pelo object_id:

select owner, object_name, subobject_name, object_type
  from dba_objects
 where object_id in (192892, 202849, 192893);

Na console, o obj# abre a página do objeto, com essa consulta e as de colunas, índices e estatísticas (página do objeto). Com o nome dos objetos e o plano do passo 6, você sabe qual tabela ou índice o #5 lê bloco a bloco.

Veja no relatório: Objetos do caso 2.

O que o recorte não mostra

O recorte de 2.000.000 linhas cobre 17 min 9 s desta sessão. O que fica de fora:

• O fim da rotina. O bloco #53 não termina no arquivo: os 17 min 9 s são cerca de 75 s antes do bloco e cerca de 954 s dentro dele, e a duração da rotina inteira fica desconhecida.
• O plano do #5 e o nome dos objetos. As linhas STAT do comando mais pesado não chegaram ao arquivo (passos 6 e 8).
• O resto da regravação. O #7 apagou 2.953.545 linhas de TAB_0049, e o #4 gravou na mesma tabela 52.500 linhas em 35 execuções. Se a rotina regrava o que apagou, o recorte mostra só o começo dessa fase, e a rotina inteira leva bem mais.
• A contribuição de cada comando. Com o bloco aberto, compare pelo Inclusivo (passo 4).

Para medir a rotina inteira, ligue o trace antes da chamada e desligue depois do fim, sem limite de tamanho no arquivo (trace cortado no meio). Os outros limites de um trace estão em o que o WaitScope não faz.

Causa raiz provável

A rotina que o bloco #53 chama gasta 72,0% do recorte numa consulta, a #5, executada uma vez. Para devolver 63.000 linhas, ela lê 3.528.057 blocos do disco: 322.865 um a um, rápidos, num acesso típico de índice e ROWID, mais leituras diretas de um segmento grande e ordenações que vão para o TEMP. O disco responde rápido; o problema é o volume que o plano lê. O segundo item é o #7, que apaga 2.953.545 linhas numa execução e leva 10,0% do tempo. O laço do #1 e do #2 existe, mas pesa 1,3%.

O que não é a causa: disco lento (média de 1,132 ms por leitura), buffer cache pequeno (43 releituras), parse (394 PARSE) e estimativa errada no DELETE (2.953.545 linhas para 2.943.270 estimadas).

O que fazer

No banco

1. Pegue o plano do #5 com DBMS_XPLAN.DISPLAY_CURSOR (passo 6) e identifique os objetos 192892, 202849 e 192893 (passo 8).
2. Na página de cada objeto, na console, confira os índices e as estatísticas das tabelas que o plano lê bloco a bloco: índice que não atende o filtro, ou estatística velha que leva o otimizador a acessar por índice muitas linhas (muitas leituras).
3. Confira a carga de CPU do servidor no período: os 149,483 s não contabilizados dentro das chamadas, quase todos no #5 e no #7, podem ser fila de CPU (tempo não contabilizado dentro das chamadas).
4. Se, com menos linhas chegando às ordenações, o #5 e o #7 ainda gravarem no TEMP, avalie a memória das workareas, pelo pga_aggregate_target (operação que concentra o plano).
5. Leve à equipe de armazenamento as 4.460 leituras acima de 10 ms, como item secundário.

Na aplicação

1. Com o plano em mãos, reescreva o #5 para chegar às 63.000 linhas sem visitar milhões de blocos: o filtro mais seletivo primeiro, com índice que o atenda, e HASH JOIN em vez de NESTED LOOPS se o plano mostrar acesso por índice sobre muitas linhas.
2. Reveja o par DELETE e INSERT em TAB_0049. Se a maior parte das 2.953.545 linhas não muda de uma execução para outra, altere só o que mudou, por exemplo com MERGE, em vez de apagar e gravar tudo de novo.
3. Depois do principal, junte as consultas #1 e #2, com 44.591 e 44.590 execuções, ao SQL que as alimenta, em vez de uma consulta por linha (linha a linha em PL/SQL).

Como confirmar

Gere um trace da rotina inteira, com esperas, antes e depois da mudança (ligar o trace com o DBMS_MONITOR). Compare o Tempo total, as Ocorrências de db file sequential read no perfil e a coluna PIO do comando em Comandos SQL; o achado de muitas leituras deve sumir. Na primeira execução depois da mudança, parte dos blocos pode vir do disco por ainda não estar no cache: compare medidas feitas na mesma condição (o método).