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:

1. Criar triggers de logon/logoff com tracefile_identifier e SESSION_TRACE_ENABLE(waits, binds)
2. Deixar a aplicação rodar o cenário problemático
3. Localizar o arquivo com v$diag_info
4. Processar com tkprof ... sys=no sort=exeela
5. Ler o relatório focando em elapsed time, contagem de parse e plano de execução
6. 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.