Linhas do trace 10046 que o WaitScope lê

O trace 10046 é um arquivo de texto: cada linha começa pelo tipo (PARSE, WAIT, STAT...) e segue com campos no formato nome=valor. Esta página lista as linhas que o WaitScope lê, os campos que ele usa e onde cada um aparece no relatório. Os exemplos são do trace sintético de exemplo, o mesmo do relatório de exemplo.

Um trace curto

No trace sintético, um SELECT de nível 0 dispara uma consulta recursiva ao dicionário e depois espera a aplicação:

Trace file /u01/app/oracle/diag/rdbms/orcl/ORCL1/trace/ORCL1_ora_4242.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
Node name: db-exemplo
Instance name: ORCL1
Unix process pid: 4242, image: oracle@db-exemplo

*** 2024-01-02T10:00:00.000000-03:00
*** SESSION ID:(10.20) 2024-01-02T10:00:00.000000-03:00
*** MODULE NAME:(app-exemplo) 2024-01-02T10:00:00.000000-03:00

=====================
PARSING IN CURSOR #1 len=26 dep=0 uid=1 oct=3 lid=1 tim=1000100 hv=111 ad='a' sqlid='7zq3k1c9m2x4p'
select * from t where id=1
END OF STMT
PARSE #1:c=50,e=100,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=10,tim=1000100
EXEC #1:c=10,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=10,tim=1000150
WAIT #1: nam='SQL*Net message to client' ela= 2 driver id=1 #bytes=1 p3=0 obj#=-1 tim=1000160
=====================
PARSING IN CURSOR #2 len=31 dep=1 uid=0 oct=3 lid=0 tim=1000200 hv=222 ad='b' sqlid='0w5n8r2t6v1yb'
select obj# from obj$ where x=1
END OF STMT
EXEC #2:c=5,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=20,tim=1000210
BINDS #2:
 Bind#0
  value=1
WAIT #2: nam='db file sequential read' ela= 300 file#=1 block#=100 blocks=1 obj#=50 tim=1000520
FETCH #2:c=40,e=380,p=1,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=20,tim=1000600
WAIT #1: nam='db file sequential read' ela= 1000 file#=1 block#=100 blocks=1 obj#=50 tim=1001700
FETCH #1:c=200,e=1600,p=1,cr=10,cu=0,mis=0,r=1,dep=0,og=1,plh=10,tim=1001800
WAIT #1: nam='SQL*Net message from client' ela= 5000 driver id=1 #bytes=1 p3=0 obj#=-1 tim=1006900
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=50 op='TABLE ACCESS BY INDEX ROWID T (cr=10 pr=1 pw=0 time=1500 us cost=2 size=10 card=1)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=51 op='INDEX UNIQUE SCAN T_PK (cr=2 pr=0 pw=0 time=30 us cost=1 size=0 card=1)'
CLOSE #1:c=1,e=2,dep=0,type=0,tim=1007000
XCTEND rlbk=0, rd_only=1, tim=1007010

O tempo total desse trace é de 7.010 microssegundos: do início do primeiro PARSE (tim 1000100 menos e 100) até o tim do XCTEND.

Unidade de tempo

Do Oracle 9i em diante, os tempos do trace (c, e, ela e tim) estão em microssegundos. Nos traces do Oracle 7 e 8, estão em centissegundos. O WaitScope reconhece o trace antigo pela versão do banco no cabeçalho e converte tudo para microssegundos. O resumo mostra a unidade em Unidade de tempo: microssegundos ou centissegundos (trace antigo).

O tim é o instante em que a chamada ou a espera terminou. O início é o tim menos o e, ou menos o ela. Em trace antigo, a espera pode vir sem tim: aí a separação entre esperas dentro e fora das chamadas usa o nome do evento, e o relatório avisa.

Cabeçalho e linhas com ***

Esses campos ficam no cartão Sessão e ambiente do resumo, sem máscara: veja Resumo.

PARSING IN CURSOR

PARSING IN CURSOR #1 len=26 dep=0 uid=1 oct=3 lid=1 tim=1000100 hv=111 ad='a' sqlid='7zq3k1c9m2x4p'
select * from t where id=1
END OF STMT

Traz o texto do SQL do cursor, nas linhas seguintes, até END OF STMT. Daí em diante, as linhas com o mesmo número de cursor (#1) são desse comando, até o cursor receber outro texto.

PARSE, EXEC, FETCH e CLOSE

PARSE #1:c=50,e=100,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=10,tim=1000100
FETCH #1:c=200,e=1600,p=1,cr=10,cu=0,mis=0,r=1,dep=0,og=1,plh=10,tim=1001800
CLOSE #1:c=1,e=2,dep=0,type=0,tim=1007000

Uma linha por chamada ao banco, com o número do cursor depois de #. As mesmas regras valem para UNMAP, SORT UNMAP e as chamadas de LOB (LOBREAD:, LOBWRITE: e as demais), que entram em Tipos de chamada pelo nome. Chamada sem tim fica de fora.

A CPU, as esperas e as chamadas recursivas que terminam dentro de uma chamada contam para ela. O que sobra da duração vira tempo não contabilizado dentro das chamadas.

WAIT

WAIT #1: nam='db file sequential read' ela= 1000 file#=1 block#=100 blocks=1 obj#=50 tim=1001700
WAIT #1: nam='SQL*Net message from client' ela= 5000 driver id=1 #bytes=1 p3=0 obj#=-1 tim=1006900

Uma linha por espera. Os parâmetros depois de ela= mudam com o evento. Nos traces recentes, eles vêm com nome (file#, block#, driver id); nos antigos, como p1, p2 e p3.

A espera que termina dentro de uma chamada conta para essa chamada. A que fica entre o fim de uma chamada de nível 0 e o início da próxima é espera entre chamadas, como a SQL*Net message from client do exemplo.

STAT

STAT #1 id=1 cnt=1 pid=0 pos=1 obj=50 op='TABLE ACCESS BY INDEX ROWID T (cr=10 pr=1 pw=0 time=1500 us cost=2 size=10 card=1)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=51 op='INDEX UNIQUE SCAN T_PK (cr=2 pr=0 pw=0 time=30 us cost=1 size=0 card=1)'

Uma linha por operação do plano do cursor. Cada plano gravado vira um bloco Plano de execução no detalhe do comando. Quando o mesmo plano é gravado mais de uma vez, o relatório mostra o último.

Veja Plano de execução para ler essas colunas no detalhe do comando.

BINDS

BINDS #2:
 Bind#0
  value=1

Os valores de bind aparecem nos níveis 4 e 12 do 10046, ou com binds => TRUE no DBMS_MONITOR. O WaitScope reconhece a linha BINDS e ignora o bloco inteiro: os valores não entram no relatório. Mesmo assim, prefira gerar o trace sem eles (valores de bind).

XCTEND

XCTEND rlbk=0, rd_only=1, tim=1007010

O fim de uma transação. rlbk=0 é commit e rlbk=1 é rollback: o resumo conta os dois, como “N commits · N rollbacks”. O tim entra no tempo total e no período; rd_only não é usado.

ERROR e PARSE ERROR

PARSE ERROR #2:len=24 dep=0 uid=1 oct=3 lid=1 tim=150 err=942
select * from nao_existe
ERROR #1:err=1403 tim=201

ERROR registra um erro ORA- numa chamada do cursor: o WaitScope lê o código (err=) e o liga à chamada anterior do mesmo cursor. PARSE ERROR registra o erro no parse, com o texto do SQL nas linhas seguintes. Os dois vão para a seção Erros, com o código, quantas vezes ele apareceu e onde. O trace guarda só o código: o texto completo da mensagem fica com quem recebeu o erro. Veja Erros.

Bloco de deadlock

DEADLOCK DETECTED ( ORA-00060 )

[Transaction Deadlock]

Deadlock graph:
                                          ------------Blocker(s)-----------  ------------Waiter(s)------------
Resource Name                             process session holds waits serial  process session holds waits serial
TX-00090014-00000A01-00000000-00000000         31      10     X           20      32      11           X     30
TX-00170008-00000B02-00000000-00000000         32      11     X           30      31      10           X     20

Quando a sessão recebe o ORA-00060, o Oracle grava no trace dela o bloco que começa em DEADLOCK DETECTED. O WaitScope lê o grafo (Deadlock graph:), as linhas esperadas (Rows waited on:), as outras sessões envolvidas, o SQL da sessão que recebeu o erro e a pilha PL/SQL (PL/SQL Call Stack). O bloco vale tanto no trace só de deadlock quanto dentro de um 10046. Veja trace de deadlock e Deadlocks.

TRACE CONTINUES IN FILE

*** TRACE CONTINUES IN FILE /u01/trace/ORCL1_ora_4242_etapa2.trc ***

Quando a aplicação troca o tracefile_identifier, o Oracle fecha o trecho com *** TRACE CONTINUES IN FILE e segue em outro arquivo, que começa com *** TRACE CONTINUED FROM FILE. Na análise de um arquivo só, essas linhas não mudam nada. Na coleta, o WaitScope corta cada arquivo nesses pontos e junta os trechos da mesma sessão na ordem do tim: veja analisar vários traces juntos.

Linhas ignoradas

• Os valores de bind, no bloco BINDS.
• As linhas de separação (=====================).
• Qualquer linha que não seja de um dos tipos desta página.

Arquivo sem nenhuma linha do 10046 nem bloco de deadlock é recusado: veja arquivos recusados.

Para onde ir depois

• O conteúdo do trace: o que o arquivo traz e que dados ele carrega.
• Níveis do evento 10046: que linhas cada nível grava.
• Glossário: os termos do relatório e do trace.