Alguns segredos nada secretos do Oracle Trace File

Alguns segredos (nada secretos) do Oracle Trace File Palestrante : José Laurindo Chiappa

“Trace files : o que são, onde vivem, como se reproduzem. . Hoje, no DBA Repórter”. . . Um SGBD é um software Complexo, que precisa executar inúmeras tarefas para poder entregar o resultado desejado, que é a entrega e a manutenção dos dados nele constantes : para Permitir debug e análise, muitos SGBDs (e em especial os que operam na arquitetura RDBMS) permitem/possuem algum método de gerar (em arquivo, dado o volume normalmente envolvido) logs, evidências e registros das tarefas efetuadas por ele E dos serviços providenciados pelo Sistema Operacional consumidos pelo SGBD para isso, e o RDBMS Oracle não foi e nem é exceção. Quase que desde a sua introdução, porém, além da informação referente aos SQLs em execução durante o trace, o RDBMS Oracle também registra no trace file Outras informações de interesse para DBAs e desenvolvedores, tal como SQLs internos gerados/executados pelo RDBMS em resposta aos SQLs dos usuários, informações detalhadas sobre cada WAIT que a sessão teve que esperar por, algumas indicações de performance de hardware. . . Um dos objetivos desta Palestra e discorrer sobre essa informação adicional, que não é de modo algum um segredo bem-escondido, mas muitos não conhecem. . .

“Se tem tanta informação de interesse, qual o Motivo dos trace files não serem mais populares/conhecidos ? ” A resposta mais própria é : além de não terem sido Documentados completamente nos manuais Oracle oficiais (e portanto não serem de conhecimento Amplo), Historicamente não havia maneira simples de obter um acompanhamento/log/trace de apenas parte duma sessão, nem havia como acompanhar uma sessão Compartilhada, em que uma sessão atende n pedidos de conexões (seja por pool de conexão, por Shared Server ou mecanismos similares) : ambos os itens Combinados com o aumento explosivo dos dados havido nos últimos anos, levava à geração de trace files Imensos, algo inviável em muitas situações. . . O segundo Objetivo desta Palestra é demonstrar as Melhorias havidas no tracing Oracle (principalmente a partir do RDBMS Oracle 10 g) que passaram a permitir opções tais como Trace de sessões compartilhadas, Trace de sessões que obedecerem a determinadas Condições, Trace Parcial apenas duma sessão (por exemplo, só de um dado SQL), e outras, Melhorias essas que passaram a Viabilizar uso de TRACE em muito casos onde o antigo procedimento de tracejar uma sessão inteira não o permitia. .

Disclaimers e Observações gerais • Parâmetros como TIMED_STATISTICS e STATISTICS_LEVEL devem estar Ativos/setados com o maior LEVEL possível/viável, se for desejado o Máximo de dados no trace. • Foi usado nos Exemplos o software RDBMS Oracle 11 g. R 2 EE versão 11. 2. 0. 4. 0 : em princípio os exemplos devem funcionar igualmente em qualquer versão igual ou Superior a 10 g. R 2 (com o último patchset), em qquer Edition e devem funcionar em CDBs e PDBs. Notar porém que (principalmente no 12 c) alguns BUGs (como os bugs 25989066 e 25994378) podem interferir, checar no Suporte Oracle. • Nas opções em que o trace vai ser gerado por sessão, é possível especificar o NOME com o qual o trace file vai ser gerado, com o parâmetro TRACEFILE_IDENTIFIER, seja via ALTER SESSION, seja numa trigger de logon ou na Aplicação • Para se localizar o nome e a localização de um trace file, nas versões Anteriores à 11 g era preciso recorrer ao parâmetro USER_DUMP_DEST (para a localização) e às views de Processos (para localizar o PID, que é parte do nome default) : na versão 11 g foi introduzida a view V$DIAG_INFO, e na versão 12 c a view V$DIAG_TRACE_FILE, bem como o conteúdo em si do trace file passou a ser disponível na view V$DIAG_TRACE_FILE_CONTENTS • Por facilidade/conveniência, na prática diária se usa a package DBMS_MONITOR, mas os outros métodos de geração de trace file (ie, parâmetro de banco, oradebug, package DBMS_SYSTEM, package DBMS_SET_EV ou ALTER SYSTEM SET EVENTS com evento 10046, package opcional DBMS_SUPPORT fornecida pela Oracle) funcionam ainda E na maioria aceitam as sintaxes/funcionalidades que serão discutidas : esta Palestra usará diversos deles em vários exemplos • Para detentores das licenças necessárias (em especial de Tuning Pack) , há também a opção de usar trace files em packages opcionais como DBMS_SQLTUNE com a função SELECT_SQL_TRACE : não comentaremos sobre essas opções

"Segredo" 1 : ativar TRACE apenas para um SQL Todo SQL (desde a versão 10 g) ao ser parseado/interpretado e executado assume um ID, uma chave artificial específica cara cada SQL, visível na coluna SQL_ID das views internas do RDBMS Oracle : a melhoria consiste na possibilidade de indicar o SQL_ID desejado a ser tracejado, exemplo : ÞExecuto um SQL qquer, para que ele receba um SQL_ID : HR@O 11 GR 2>select * from employees where salary > 5000; EMPLOYEE_ID FIRST_NAME LAST_NAME ---------------- MANAGER_ID DEPARTMENT_ID ------------- 100 Steven King 90 101 Neena Kochhar 100 90 205 Shelley Higgins 101 110 206 William Gietz 205 110 . . 58 linhas selecionadas. Þ OBSERVO que no RDBMS Oracle, desde o 10 g todo SQL depois de parseado recebe um SQL_ID, um Identificar único, que será a chave para poder estabelecer o TRACE apenas nele… Esse SQL_ID é mantido em Diversas views/tabelas internas do RDBMS, em tools de TUNING como AWR/ASH/STATSPACK, etc, podendo ser Recuperado de qquer uma delas….

Þ Obtenho o SQL_ID : SYSTEM@O 11 GR 2>select sql_id from v$sql where sql_text like 'select * from employees where%'; SQL_ID ------39 bh 8 g 4 rd 88 cq Þ Finalmente, Ativo o TRACE apenas para esse SQL_ID : SYSTEM@O 11 GR 2>alter system set events 'sql_trace[sql: 39 bh 8 g 4 rd 88 cq] level=12'; Þ A partir desse momento, QUALQUER sessão que executar EXATAMENTE esse mesmo SQL vai gerar um trace file Apenas com as infos da execução DESSE SQL… Após uma outra execução, Eis o trace file gerado : Trace file C: APPORACLEdiagrdbmso 11 gr 2traceo 11 gr 2_ora_4164. trc. . =========== PARSING IN CURSOR #529392904 len=42 dep=1 uid=0 oct=3 lid=0 tim=29522143103 hv=844002283 ad='7 ffc 8 e 2 b 6250' sqlid='ftj 9 uawt 4 wwzb' select condition from cdef$ where rowid=: 1 END OF STMT. . =========== PARSING IN CURSOR #529393848 len=43 dep=0 uid=85 oct=3 lid=85 tim=29522446692 hv=785654166 ad='7 ffc 8 e 222 d 00' sqlid='39 bh 8 g 4 rd 88 cq' select * from employees where salary > 5000 END OF STMT. . . STAT #529393848 id=1 cnt=58 pid=0 pos=1 obj=87272 op='TABLE ACCESS FULL EMPLOYEES (cr=10 pr=0 pw=0 time=84 us cost=3 size=6417 card=93)'

Um SQL_ID é um hash, uma computação que leva em conta (além da instância) principalmente o TEXTO do SQL : sendo assim, SEMPRE que um SQL for executado com o mesmo Exato SQL no mesmo exato database o SQL_ID não muda, permitindo assim que o TRACE por SQL_ID seja usado para manter registros das execuções de um SQL importante no Aplicativo. Exemplo : DICAS => Com o mesmo database usado no exemplo anterior restartado, Ativo o trace para esse SQL_ID do exemplo : SYSTEM@O 11 GR 2>alter system set events 'sql_trace[sql: 39 bh 8 g 4 rd 88 cq] level=12'; => Claro, como a instância acabou de ser startada o SQL quero tracejar não existe ainda : SYSTEM@O 11 GR 2>select sql_id from v$sql where sql_text like 'select * from employees where%'; não há linhas selecionadas ==> EM ALGUM MOMENTO, porém, o mesmo exato SQL que gerou (NESTE DATABASE!!) esse SQL_ID exemplo é executado : HR@O 11 GR 2>select * from employees where salary > 5000; EMPLOYEE_ID -----100 101. . 206 FIRST_NAME -----Steven Neena William 58 linhas selecionadas. . MANAGER_ID DEPARTMENT_ID. . . ------------. . . 90. . . 100 90. . . 205 110

==> Como NÃO MUDOU EM NADA o TEXTO do SQL, que foi executado no mesmo banco, FOI GERADO o MESMO SQL_ID : SYSTEM@O 11 GR 2>select sql_id from v$sql where sql_text like 'select * from employees where%'; SQL_ID ------39 bh 8 g 4 rd 88 cq => E como eu HAVIA ativado o TRACE para esse SQL_ID, gerou um trace file dele, óbvio : Trace file C: APPORACLEdiagrdbmso 11 gr 2traceo 11 gr 2_ora_2024. trc Oracle Database 11 g Enterprise Edition Release 11. 2. 0. 4. 0 - 64 bit Production. . . *** SESSION ID: (137. 5) 2019 -04 -28 19: 33: 36. 666 *** CLIENT ID: () 2019 -04 -28 19: 33: 36. 666 *** SERVICE NAME: (SYS$USERS) 2019 -04 -28 19: 33: 36. 666 *** MODULE NAME: (SQL*Plus) 2019 -04 -28 19: 33: 36. 666 *** ACTION NAME: () 2019 -04 -28 19: 33: 36. 666. . . PARSING IN CURSOR #502127728 len=43 dep=0 uid=85 oct=3 lid=85 tim=2620760570 hv=785654166 ad='7 fffbad 7 a 720' sqlid='39 bh 8 g 4 rd 88 cq' select * from employees where salary > 5000 END OF STMT EXEC #502127728: c=0, e=26, p=0, cr=0, cu=0, mis=0, r=0, dep=0, og=1, plh=1445457117, tim=2620760568 WAIT #502127728: nam='SQL*Net message to client' ela= 7 driver id=1111838976 #bytes=1 p 3=0 obj#=-1 tim=2620760822 WAIT #502127728: nam='Disk file operations I/O' ela= 422 File. Operation=2 fileno=4 filetype=2 obj#=87272 tim=2620761383. .

"Segredo" 2 : indicadores de performance no TRACE file • O RDBMS Oracle registra (se os parâmetros necessários, como TIMED_STATISTICS, estiverem Ativos) não só cada ESPERA havida no processamento de um SQL, mas também o tempo que o RDBMS levou para ser atendido, no formato : WAIT #[numerodocursor]: nam="nomedoevento" ela=xx p 1 p 2 p 3 obj tim (ela=elapsed, ie, tempo gasto em microsegundos, p 1, p 2 e p 3 são os Argumentos do Wait Event – arquivo, bloco e qtdade de blocos, se o evento for de I/O, por exemplo. Os itens finais são o ID do objeto que sofreu o WAIT, se houver, e a data/hora do wait) O ponto relevante para a prática diária (E o segredo na secreto #2) é que há WAIT EVENTs referentes a I/O, a Rede, a cache/Concorrência de uso, a Locks : todos podem ser úteis para mensurar performance de discos´, eficiência de caches, gargalos em rede, etc. . . Claro, há DIVERSAS outras maneiras de se aferir performance e identificar Ineficiências nesses componentes, mas obter a informação no trace file é uma a mais, complementando as outras que SIM, devem ser usadas. . . Exemplo retirado de um dos trace files gerados: WAIT #502127728: nam='db file sequential read' ela= 22984 file#=4 block#=202 blocks=1 obj#=87272 tim=2620784426 Fazendo a conta (22984/1000000) esse único I/O single-block consumiu 0. 022984 segundos, ie, 2. 2984 milisegundos : normalmente qualquer I/O single-block num disco rígido abaixo de 8 milisegundos significa boa performance…

Observações e Restrições ao uso • O RDBMS Oracle automaticamente mantém informações de Média e Máximo de Tempos para os WAIT EVENTs de uma sessão na view (G)V$SESSION_EVENT : assim, se num dado trace se encontrar valores radicalmente diferentes dessa média, Provavelmente há concorrência ou planos mal-formados nesses SQLs tracejados • Num servidor Oracle, os recursos são COMPARTILHADOS : se for localizado um tempo gasto Anormal numa determinada operação/num determinado Evento, é Possível que a sessão/SQL esteja sendo afetada por Outras sessões que estão consumindo em demasia o recurso • Como já indicado, cada WAIT possui uma coluna TIM, indicando o o intervalo de microssegundos decorrido desde a última mensuração : isso pode ser usado como uma informação adicional. No exemplo usado, o TRACE FILE começou às 19 h 33 m 36 s do dia 28/04/2019 (vide o cabeçalho do trace file) , então temos : SYSTEM@O 11 GR 2>select to_date('2019 -04 -28 19: 33: 36', 'YYYY-MM-DD HH 24: MI: SS') + 2620784426/24/60/60/1000000 from dual; TO_DATE('2019 -04 -28 --------------28/04/2019 20: 17

"Segredo" 3 : end-to-end TRACE Devido principalmente à relativamente pequena quantidade de usuários num database Oracle, era Comum usar sessões não -compartilhadas e dedicadas, ie, cada usuário da Aplicação criava uma sessão própria e particular no database, e essa sessão Atendia apenas à essa conexão. O problema com essa abordagem é que cada sessão implica na criação de um PROCESSO dedicada à ela no servidor, e com o sempre crescente aumento do número de usuários num database, isso deixou de ser viável em muitos casos. A ALTERNATIVA para isso é COMPARTILHAR as sessões, ie, criar no banco um relativamente pequeno número de sessões e a cada vez que um usuário necessita de conexão ao database, uma dessas sessões atende à essa conexão e assim que a solicitação (comando SQL) do usuário foi atendida, a sessão está livre para atender a outras conexões : esse Conceito é o chamado POOL DE CONEXÕES. . A relevância disso pra o TRACE de SQL é : como Antigamente havia uma sessão para cada usuário, para se poder obter TRACE de todos os SQLs enviados por um programa bastava identificar a sessão que atendia à conexão feita por esse programa e ativar o TRACE para essa sessão, o que Não É Viável nesse cenário onde uma sessão atende a N conexões. . . O oferecimento da Oracle para cobrir esses casos é OU identificar o SQL_ID dos SQLs envolvidos e ativar o TRACE apenas para esses SQLs (como visto anteriormente) , OU usar a funcionalidade presente na package DBMS_MONITOR (rotina SERV_MOD_ACT_TRACE_ENABLE) que permite ativar o trace apenas sessões que estiverem atendendo à uma conexão que apresentar uma dada Identificação : esta pode ser um determinado MÓDULO, um ID de cliente, uma determinada Ação, ou que foi conectada mediante um determinado SERVICE_NAME. . . Como referência, além da Documentação Oracle pode ser indicada a nota My Oracle Support "Tracing Enhancements Using DBMS_MONITOR (In 10 g, 11 g and Above)", com o Doc ID 293661. 1 ….

EXEMPLO : como exemplo para uso do END-TO-END TRACE, utilizaremos o trace por Serviço de Rede – a idéia seria criar um novo serviço Oracle e alterar a aplicação para que o programa de interesse conecte ao database com esse serviço que está com TRACE ativo. . . Þ Notar que o LISTENER está ativo e aceitando Serviços de conexão : C: Usersjlchi_000>lsnrctl status listener 11 gr 2 STATUS do LISTENER ------------Apelido LISTENER 11 GR 2 Versão TNSLSNR for 64 -bit Windows: Version 11. 2. 0. 4. 0 - Production Segurança ON: Local OS Authentication SNMP OFF Arq. Parâm. Listn. C: apporacleproduct11 g. R 2dbhome_r 2networkadminlistener. ora Arq. Log Listener C: apporaclediagtnslsnrDell 15 Rselistener 11 gr 2alertlog. xml Resumo de Atendimento. . . (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=Dell 15 Rse)(PORT=1567))) Resumo de Serviços. . . O serviço "O 11 GR 2 XDB" tem 1 instância(s). Instância "o 11 gr 2", status READY, tem 1 handler(s) para este serviço. . . O serviço "o 11 gr 2" tem 1 instância(s). Instância "o 11 gr 2", status READY, tem 1 handler(s) para este serviço. . . O comando foi executado com êxito

Þ primeiro, criaremos um novo Serviço de conexão : SYS@O 11 GR 2>BEGIN 2 DBMS_SERVICE. create_service( 3 service_name => 'SERVICO_DE_TESTE', 4 network_name => 'SERVICO_DE_TESTE' 5 ); 6 END; 7 / Þ Iniciamos o serviço, e Confirmamos que está Ativo e Disponível : SYS@O 11 GR 2>BEGIN 2 DBMS_SERVICE. start_service(service_name => 'SERVICO_DE_TESTE'); 3 END; 4 / SYS@O 11 GR 2>select name, network_name from v$active_services; NAME ----------------SERVICO_DE_TESTE O 11 GR 2 XDB O 11 GR 2 NETWORK_NAME ----------------SERVICO_DE_TESTE O 11 GR 2 XDB O 11 GR 2 C: Usersjlchi_000>lsnrctl status listener 11 gr 2. . . Resumo de Serviços. . . O serviço "O 11 GR 2 XDB" tem 1 instância(s). Instância "o 11 gr 2", status READY, tem 1 handler(s) para este serviço. . . O serviço "SERVICO_DE_TESTE" tem 1 instância(s). Instância "o 11 gr 2", status READY, tem 1 handler(s) para este serviço. . . O serviço "o 11 gr 2" tem 1 instância(s). Instância "o 11 gr 2", status READY, tem 1 handler(s) para este serviço. . . O comando foi executado com êxito

Þ Ativo o TRACE para as sessões que se conectarem com esse serviço : SYS@O 11 GR 2>exec dbms_monitor. serv_mod_act_trace_enable(SERVICE_NAME=>'SERVICO_DE_TESTE', MODULE_NAME=>DBMS_MONITOR. ALL_MODULES, ACTION_NAME=>DBMS_MONITOR. ALL_ACTIONS, waits=>TRUE, binds=>TRUE); Þ Confirmo que o TRACE está Ativo : SYS@O 11 GR 2>select trace_type, primary_id, waits, binds, plan_stats from DBA_ENABLED_TRACES; TRACE_TYPE ----------SERVICE_MODULE_ACTION SERVICE PRIMARY_ID --------SERVICO_DE_TESTE WAITS ----TRUE BINDS ----TRUE PLAN_STATS -----FIRST_EXEC Þ Conecto no banco com o serviço sendo tracejado (já com o TNSNAMES. ORA setado ok) e executo um SQL qquer : HR@servico_de_teste>select department_id, department_name from departments where rownum < 4; DEPARTMENT_ID ------10 20 30 DEPARTMENT_NAME ---------------Administration Marketing Purchasing 3 linhas selecionadas. HR@servico_de_teste>

Þ Eis o TRACE FILE gerado : Trace file C: APPORACLEdiagrdbmso 11 gr 2traceo 11 gr 2_ora_5788. trc. . . *** 2019 -04 -30 22: 00: 35. 858 *** SESSION ID: (203. 53) 2019 -04 -30 22: 00: 35. 858 *** CLIENT ID: () 2019 -04 -30 22: 00: 35. 858 *** SERVICE NAME: (SERVICO_DE_TESTE) 2019 -04 -30 22: 00: 35. 858 *** MODULE NAME: (sqlplus. exe) 2019 -04 -30 22: 00: 35. 858 *** ACTION NAME: () 2019 -04 -30 22: 00: 35. 858. . . =========== PARSING IN CURSOR #466103704 len=71 dep=0 uid=85 oct=3 lid=85 tim=42405279134 hv=224241611 ad='7 ff 9 bcc 0 f 210' sqlid='fv 2 pjvh 6 pv 9 yb' select department_id, department_name from departments where rownum < 4 END OF STMT PARSE #466103704: c=31250, e=44229, p=1, cr=61, cu=0, mis=1, r=0, dep=0, og=1, plh=393971569, tim=42405279133 EXEC #466103704: c=0, e=36, p=0, cr=0, cu=0, mis=0, r=0, dep=0, og=1, plh=393971569, tim=42405279425 WAIT #466103704: nam='SQL*Net message to client' ela= 9 driver id=1413697536 #bytes=1 p 3=0 obj#=-1 tim=42405279550 WAIT #466103704: nam='Disk file operations I/O' ela= 405 File. Operation=2 fileno=4 filetype=2 obj#=87267 tim=42405280089 WAIT #466103704: nam='db file sequential read' ela= 18157 file#=4 block#=170 blocks=1 obj#=87267 tim=42405298305 WAIT #466103704: nam='db file scattered read' ela= 374 file#=4 block#=171 blocks=5 obj#=87267 tim=42405298997. . . DICA#1 : a nota metalink/My Oracle Support " Tracing Enhancements Using DBMS_MONITOR (In 10 g, 11 g and Above)" , com Doc ID 293661. 1 traz alguns detalhes Críticos de sintaxe e utilização das novas funcionalidades de TRACE de SQL via DBMS_MONITOR , sua leitura é Extremamente Recomendada a quem for utilizar essa package. DICA#2 : é possível consultar CLIENT_ID, MODULE, ACTION e SERVICE_NAME de uma sessão na V$SESSION DICA#3 : se a tool/linguagem/aplicativo não popular corretamente essas colunas, é possível as popular MANUALMENTE com packages como a DBMS_APPLICATION_INFO

"Segredo" 4 : ativação e desativação de TRACE global para todo um database Até algumas versões atrás, o parâmetro SQL_TRACE que existe para permitir Ativar e Desativar um TRACE DE SQL globalmente, em todas as sessões (útil para um banco de testes ou de Homologação, por exemplo) só podia ser alterado no aquivo de init, Demandando um restart para mudar de valor. O workaround que se usava então (ie, setar o EVENTO de banco que ativa o TRACE) continua sendo possível até hoje , exemplo : SYS@O 11 GR 2>ALTER SYSTEM SET EVENTS '10046 trace name context forever, level 12'; Þ A partir deste momento TODAS as sessões que conectarem serão tracejadas … Faço algumas conexões, executo alguns SQLs e obtenho : C: Usersjlchi_000>dir C: APPORACLEdiagrdbmso 11 gr 2traceo 11 gr 2_ora*. trc /od. . . 01/05/2019 18: 05 0 o 11 gr 2_ora_1080. trc 01/05/2019 18: 10 11. 205 o 11 gr 2_ora_10884. trc 01/05/2019 18: 20 50. 020 o 11 gr 2_ora_9384. trc 01/05/2019 18: 20 40. 995 o 11 gr 2_ora_4796. trc 01/05/2019 18: 21 105. 205 o 11 gr 2_ora_3028. trc ÞPara Desativar esse TRACE global, desativo o evento : SYS@O 11 GR 2>alter system SET EVENTS '10046 trace name context off';

Referências, Avisos e Observações para o Uso : Þ O evento 10046 usado no exemplo é um evento INTERNO e não-documentado do RDBMS Oracle: diversas referências para ele e os demais Eventos possíveis existem (http: //www. juliandyke. com/Diagnostics/Events. php é uma Þ Pode haver OVERHEAD sério ao se ativar o trace Globalmente, mesmo que por pouco tempo : usar com Cautela extrema Þ A Oracle oferece junto com o RDBMS, além da ferramenta tkprof (que serve para extrair relatório / sumarizar WAITs e SQLs de um trace file bruto), Também a ferramenta trcsess , que serve para Consolidar múltiplos traces gerados por múltiplas sessões num só arquivo, o que pode ser Útil para casos do tipo deste Exemplo, onde há grande quantidade de trace files a analisar Þ DICA : esta Apesentação está focando nos dados brutos, "ocultos" num trace file, E em métodos alternativos de geração de trace files, mas de Forma Alguma análise manual de um trace file bruto é a única maneira/a única utilidade possível, há ferramentas que Auxiliam nessa tarefa. . . O tkprof (presente em qquer RDBMS Oracle por princípio) é a ferramenta default para se extrair somatórios e indicadores de um trace file mas Não É a única, nem a melhor sob qualquer circunstância : gratuitas (mas podendo ser acessadas apenas por usuários com acesso ao Suporte Oracle) originalmente a Oracle oferecia a ferramenta TRCA (TRa. Ce Analyzer), que desde 2018 foi depreciada e a alternativa é a SQLT/SQLTXPLAIN - vide as notas Metalink/My Oracle Support "TRCANLZR (TRCA): SQL_TRACE/Event 10046 Trace File Analyzer - Tool for Interpreting Raw SQL Traces (NO LONGER SUPPORTED - Use SQLTXPLAIN sqltrcanlzr. sql)", com Doc ID 224270. 1, e a "All About the SQLT Diagnostic Tool" (Doc ID 215187. 1), para Referências, Documentação e download das mesmas. .

"Segredo" 5 : usando o raw trace file para demonstrar ineficiências de I/O Não é segredo que os dados num database Oracle TEM que residir em BLOCOS, cada bloco tem um espaço FINITO, normalmente de 8 k. B e VIA DE REGRA num bloco cabem alguns tantos registros/linhas da tabela. Quando um dado não cabe no bloco (por exemplo, foi feito um UPDATE aumentando o dado, que não coube mais), o que o RDBMS faz é gravar o dado num OUTRO bloco e no bloco original ele coloca um "pointer", um INDICADOR indicando que a informação continua no novo bloco. . . Isso pode ser de interesse do DBA e/ou do Analista porque (obviamente) esse NOVO I/O necessário para ler a informação que foi migrada para o OUTRO BLOCO não é 'grátis' em termos de performance. . . Tal situação PODE (e normalmente é) identificada pelos Indicadores de performance da sessão e/ou do database (como V$SESSTAT e V$SYSSTAT) mas PODE também ser identificada nos TRACE FILEs. . .

Exemplo de trace que PODE indicar a issue : PARSE #4573135368: c=29, e=48, p=0, cr=0, cu=0, mis=0, r=0, dep=0, og=1, plh=4116693033, tim=79008343283418 EXEC #4573135368: c=53, e=93, p=0, cr=0, cu=0, mis=0, r=0, dep=0, og=1, plh=4116693033, tim=79008343283607 WAIT #4573135368: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p 3=0 obj#=15477650 tim=79008343283636 WAIT #4573135368: nam='Disk file operations I/O' ela= 38 File. Operation=2 fileno=101 filetype=2 obj#=1462951 tim=79008343283973 WAIT #4573135368: nam='direct path read' ela= 8991 file number=100 first dba=947580 block cnt=13 obj#=1462951 tim=79008343293041 WAIT WAIT WAIT #4573135368: #4573135368: #4573135368: nam='db nam='db nam='db file file file sequential sequential sequential read' read' read' ela= ela= ela= 4934 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343298032 155 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343298216 127 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343298378 125 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343298526 128 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343298677 123 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343298826 134 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343298983 129 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343299135 180 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343299341 133 file#=100 block#=2513181 blocks=1 obj#=1462951 tim=79008343299497 WAIT WAIT WAIT #4573135368: #4573135368: #4573135368: nam='db nam='db nam='db file file file sequential sequential sequential read' read' read' ela= ela= ela= 11039 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343310565 133 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343310730 139 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343310895 124 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343311045 122 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343311190 127 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343311339 125 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343311490 134 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343311647 128 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343311797 124 file#=100 block#=2513245 blocks=1 obj#=1462951 tim=79008343311947 WAIT #4573135368: nam='db file sequential read' ela= 10592 file#=100 block#=2513309 blocks=1 obj#=1462951 tim=79008343322564 WAIT #4573135368: nam='db file sequential read' ela= 142 file#=100 block#=2513309 blocks=1 obj#=1462951 tim=79008343322740 WAIT #4573135368: nam='db file sequential read' ela= 126 file#=100 block#=2513309 blocks=1 obj#=1462951 tim=79008343322889

Þ No slide anterior, o objeto 1462951 começou a ser lido por um I/O em modo direto MAS ao invés da sequência de eficientes I/Os multiblocos , vimos uma série de visitas e revisitas ao MESMO bloco, implicando um diversos I/Os singleblock. . . Óbvio, outras situações/condições podem causar isso mas Migração de Linhas é uma Possibilidade. . . OU SEJA, o TRACE FILE entre outras indicações (como Planos de Execução, SQLs internos executados pelo próprio RDBMS, performance dos I/Os, da rede, etc) nos mostra também QUAIS tipos de I/Os estão sendo feitos, indicador esse que pode ser Precioso em determinados tipos de Análise / Tuning. . .

"Segredo" 6 : TRACE FILEs podem ser usados para evidenciar o "overhead" causado pela Consistência de Dados no RDBMS ORACLE Não é (ou não deveria ser) novidade que um RDBMS é construído para dar a melhor Performance COM INTEGRIDADE DE DADOS, não só integridade lógica mas também Integridade Transacional : por exemplo, digamos que num dado sistema uma VENDA é representada por um INSERT na tabela NOTAS_FISCAIS, n INSERTs na tabela ITENS_DA_NOTA (um para cada Item) e n UPDATEs na tabela PRODUTOS (um para cada Produto vendido), atualizando (digamos) a coluna QUANTIDADE_EM_ESTOQUE. Se essas operações são feitas numa Transação e num SGBD que garante Integridade Transacional, a Transação só obtém status de sucesso se TODAS as operações forem bem sucedidas – se apenas uma Falhar, a Transação fica como Pendente, e (cfrme a exigência de definição de um RDBMS) a SGBD tem que dar a opção de DESFAZER as operações todas, não importando o tamanho da Transação. . . Num banco que não respeita integridade Transacional (digamos, um SGBD onde cada operação seja comitada/gravada permanentemente automaticamente), podemos ter um caso onde o INSERT na tabela NOTAS_FISCAIS foi ok, os INSERTs na tabela ITENS_DA_NOTA foi OK e gravou, MAS os UPDATEs na PRODUTOS falharam : pronto, neste momento temos uma venda "PERNETA", com a consistência da operação de VENDA como um todo COMPROMETIDA. . . Claro, ficaria a cargo da Aplicação corrigir isso mas na prática 99, 99% dos desenvolvedores absolutamente não prevê isso. . . Þ Para que os RDBMSs possam desfazer as N operações de uma Transação, Obviamente isso não é grátis, há Overhead mas é parte do CUSTO que se paga para Integridade Transacional. . . Alguns RDBMSs armazenam os dados não confirmados/comitados nos próprios blocos que contém os dados anteriores, alguns mantém um LOG das alterações e esse LOG é relido do fim para o começo para desfazer a Transação, mas no RDBMS Oracle o procedimento é : a versão atual do bloco é copiada para uma área separada, chamada de UNDO , E os dados alterados mas ainda não comitados vão para outra área, o REDO LOG : isso inclusive Facilita funcionalidades como o FLASHBACK e FLASHBACK_QUERY.

Muito bem, nesse caso do Oracle, se enquanto uma Transação está aberta outra sessão precisar acessar os dados como estavam antes da Transação começar (é um paradigma nos RDBMSs e no Oracle em particular que NUNCA é feita leitura "suja", ie, dados não comitados NUNCA são visíveis para ouras sessões) , esses 'blocos de UNDO' que contém a informação como estava antes é que serão lidos, pois lá é que estará a informação CONSISTENTE. . . Esse 'overhead' pode ser mensurado facilmente em diversas views/tabelas internas do sistema (entre outras, V$UNDOSTAT, V$SESSTAT, V$SYSSTAT, etc) MAS também fica registrado (obviamente) num trace file – como dito anteriormente, um TRACE FILE além de mostrar planos, Waits e Indicadores para os SQLs do usuário, mostra TAMBÉM os SQLs internos emitidos pelo RDBMS (os SQL Recursivos) e TAMBÉM 'overhead' referente à Integridade de dados, como leitura de UNDO. Exemplo : STAT #531189392 id=1 cnt=999 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=1257 pr=0 pw=0 time=9730 us)' STAT #531189392 id=2 cnt=999 pid=1 pos=1 obj=88007 op='TABLE ACCESS FULL BIG_TABLE (cr=1257 pr=0 pw=0 time=8867 us cost=8 size=9326582 card=59029)' =========== PARSING IN CURSOR #530450792 len=454 dep=1 uid=85 oct=3 lid=85 tim=2252079068 hv=1153300516 ad='7 ff 971301 ed 8' sqlid='g 4 dfbf 52 bvy 14'. . *** 2019 -05 -02 20: 59: 51. 306 BINDS #530450792: Bind#0 oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00 oacflg=10 fl 2=0100 frm=00 csi=00 siz=24 off=0 kxsbbbfp=7127 a 3 b 0 bln=22 avl=01 flg=09 value=0. . EXEC #530450792: c=0, e=30491, p=0, cr=0, cu=0, mis=1, r=0, dep=1, og=1, plh=4255388684, tim=2252203120 FETCH #530450792: c=0, e=13100, p=0, cr=4085, cu=0, mis=0, r=1, dep=1, og=1, plh=4255388684, tim=2252216278

Dentro de um TRACE FILE, essas colunas de estatísticas de uso significam : C= cpu time, e=elapsed time, p=number of database blocks read, cr=number of consistent mode blocks read, cu=number of current mode blocks read, mis=nº de library cache misses (útil para sabermos se um SQL foi recompilado/parseado OU se houve aproveitamento de cache de SQLs) e r=número de linhas. Þ E claro, essa informação PODE ser extraída do TRACE FILE pelos Analisadores de TRACE FILEs, um exemplo com o Analisador default, o TKPROF : C: apporaclediagrdbmso 11 gr 2trace>tkprof o 11 gr 2_ora_5744. trc o 11 gr 2_ora_5744. out Þ Obtendo : SQL ID: 96 ptnxqtcrrsz Plan Hash: 2899355174 select * from call count -------Parse 1 Execute 1 Fetch 68 -------total 70 BIG_TABLE where rownum < 1000 cpu elapsed disk query current ---------- -----0. 04 0. 19 0 8200 0 0. 01 0 1257 0 ---------- -----0. 06 0. 21 0 9457 0 rows -----0 0 999 -----999 Misses in library cache during parse: 1 Rows (1 st) Rows (avg) Rows (max) ----------999 999 999 Row Source Operation -------------------------COUNT STOPKEY (cr=1257 pr=0 pw=0 time=9730 us) TABLE ACCESS FULL BIG_TABLE (cr=1257 pr=0 pw=0 time=8867 us cost=8 size=9326582 card=59029)

Perguntas ? ? ?