TKPROF: ativando trace por usuário e interpretando o resultado

O que é o TKPROF

O TKPROF é um utilitário de linha de comando do Oracle que transforma arquivos de trace (.trc), que são praticamente ilegíveis, em relatórios de texto estruturados, com tempos de execução, contagens de parse/execute/fetch e o plano de execução de cada SQL rastreado.

É uma das ferramentas mais antigas e mais úteis do ambiente Oracle. Quando você precisa entender o que uma sessão específica está fazendo com o banco, quais SQLs está executando, quantas vezes, quanto tempo gasta em parse vs. execute, onde estão os waits, o trace + TKPROF é a resposta direta.

A diferença para AWR e ASH: enquanto AWR e ASH dão visão agregada e histórica de toda a instância, o trace captura tudo que uma sessão específica faz, com granularidade de microsegundo. É diagnóstico cirúrgico.

Ativando trace automaticamente por usuário

O jeito mais prático para rastrear um owner específico em produção é usar triggers de logon/logoff. Assim o trace liga e desliga automaticamente toda vez que o usuário se conecta, sem precisar interceptar a sessão manualmente.

-- Ativa o trace ao conectar
CREATE OR REPLACE TRIGGER tr_trace_on
  AFTER LOGON ON DATABASE
BEGIN
  IF sys_context('USERENV', 'SESSION_USER') = '<USER>' THEN
    EXECUTE IMMEDIATE 'ALTER SESSION SET tracefile_identifier = ''<USER>''';
    EXECUTE IMMEDIATE 'BEGIN DBMS_SESSION.SESSION_TRACE_ENABLE(waits => TRUE, binds => TRUE); END;';
  END IF;
END tr_trace_on;
/

-- Desativa o trace ao desconectar
CREATE OR REPLACE TRIGGER tr_trace_off
  BEFORE LOGOFF ON DATABASE
BEGIN
  IF sys_context('USERENV', 'SESSION_USER') = '<USER>' THEN
    DBMS_SESSION.SESSION_TRACE_DISABLE;
  END IF;
END tr_trace_off;
/

O parâmetro tracefile_identifier injeta uma string no nome do arquivo gerado, fundamental para localizar o trace depois, já que o Oracle gera arquivos com nomes como XE_ora_32486.trc e sem o identificador fica difícil saber qual é qual.

Os parâmetros do SESSION_TRACE_ENABLE:

waits => TRUE — captura eventos de espera (I/O, locks, latch, etc.)
binds => TRUE — captura os valores das bind variables — essencial para reproduzir o SQL com dados reais

Localizando o arquivo de trace

Depois que a sessão conecta e executa alguma coisa, o Oracle grava o trace no diretório de diagnóstico. Para saber onde é:

SELECT value FROM v$diag_info WHERE name = 'Default Trace File';

Resultado típico:

/opt/oracle/diag/rdbms/xe/XE/trace/XE_ora_32486_<USER>.trc

O nome do arquivo segue o padrão <SID>_ora_<PID>_<IDENTIFIER>.trc. O identificador que definimos (<USER>) aparece no final, é por isso que vale sempre setar o tracefile_identifier.

Executando o TKPROF

Com o arquivo em mãos, o comando básico é:

tkprof XE_ora_32486_<USER>.trc out-01.txt sys=no sort=exeela

Parâmetros usados:

Parâmetro	Significado
`sys=no`	Exclui chamadas internas do usuário SYS do relatório. Foca no que a aplicação executou de fato.
`sort=exeela`	Ordena os SQLs por tempo total de execução (elapsed) decrescente, os mais lentos aparecem primeiro.

Outros valores de sort úteis:

Valor	Ordena por
`exeela`	Elapsed time de execução (mais comum)
`fchela`	Elapsed time de fetch
`execpu`	CPU de execução
`exerow`	Linhas processadas na execução
`prsela`	Elapsed time de parse, útil para investigar hard parse excessivo

Lendo o relatório gerado

O arquivo de saída do TKPROF tem uma seção por SQL rastreado. O bloco de cada SQL tem esta estrutura:

SELECT ...
FROM   ...
WHERE  ...

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    842      1.23       4.87         12      15302          0           0
Fetch      842      0.18       0.21          0       2526          0         842
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      ...

Rows     Row Source Operation
-------  ---------------------------------------------------
    842  TABLE ACCESS FULL <TABELA> (cr=17828 pr=12 pw=0 time=4870ms)

O que observar:

Parse count alto — hard parse repetido. SQL não está usando bind variables ou está sendo reconstruído a cada execução.
Execute count >> Fetch count — execuções sem retorno de linhas. Possível DML desnecessário ou query sem resultado.
**disk alto em Execute** — leituras físicas. O dado não está no buffer cache. Pode indicar tabela grande sem índice eficiente ou buffer cache insuficiente.
**TABLE ACCESS FULL em tabela grande** — índice ausente ou não utilizado.
Elapsed >> CPU — a diferença é tempo de espera (I/O, locks, latch). Com waits=TRUE ativado, o relatório também lista os eventos de espera.

Limpando as triggers após o diagnóstico

Quando o diagnóstico terminar, remover as triggers:

DROP TRIGGER tr_trace_on;
DROP TRIGGER tr_trace_off;

Deixar trace ativo em produção gera arquivos .trc contínuos que consomem espaço em disco no diretório de diagnóstico. Em ambientes movimentados isso enche o filesystem em questão de horas.

Conclusão

O fluxo completo:

Criar triggers de logon/logoff com tracefile_identifier e SESSION_TRACE_ENABLE(waits, binds)
Deixar a aplicação rodar o cenário problemático
Localizar o arquivo com v$diag_info
Processar com tkprof ... sys=no sort=exeela
Ler o relatório focando em elapsed time, contagem de parse e plano de execução
Remover as triggers após o diagnóstico

AWR e ASH para visão macro. TKPROF para dissecar o que um owner específico está fazendo. As duas abordagens se complementam.