Hoje vou está postando uma informação que muita das vezes precisamos conhecer para nós ajudar em certas situações.
Habilitar o trace do Oracle em uma determinada sessão e utilizar o tkprof para converter este trace para um formato mais legível.
Isso nós ajuda quando desejamos captura algumas informações que uma determinada sessão está fazendo no Banco de dados.
Para iniciar este processo vou está utilizando 2 views do Oracle: "V$SESSION" e a "V$PROCESS".
V$SESSION - Informações de sessões abertas no Banco de Dados.
V$PROCESS - Informações de processos do SO relacionadas com as do Banco de Dados.
"Cada processo aberto no Banco de Dados existe um processo do SO relacionado."
Estarei exemplificando em um Sistema SO Linux, capturando um processo que esta com um elevado consumo de CPU.
Para captura as sessões estou executando o comando " top " do linux para podermos visualizar alguns processos que estão tendo um consumo elevado de CPU.
Neste exemplo estarei analisando o processo 5900, que está com 99%.
Já conectado no Banco de Dados estarei fazendo uso deste pid que acabei de coletar => 5900.
Executando a seguinte query:
select s.username, s.sid, s.serial#, p.spid, p.tracefile from V$session s, v$process p
where s.paddr = p.addr and p.spid = <id do processo do SO>;
username - nome do usuário conectado no banco de dados
sid - sessão id do usuário conectado no banco de dados
serial# - serial do usuário conectado no banco de dados
spid - id do processo do SO relacionada a sessão conectada no banco de dados.
tracefile - arquivo de trace que esta sessão conectada no oracle está habilitado a escrever.
SYS@ha1> select s.username, s.sid, s.serial#, p.spid, p.tracefile from V$session s, v$process p
2 where s.paddr = p.addr and p.spid = 5900;
USERNAME SID SERIAL# SPID TRACEFILE
CAND_VALEBR 407 11485 5900 /u01/app/oracle/diag/rdbms/prd1/prd1/trace/ha1_ora_5900.trc
SYS@ha1>
##Cláusula utilizada para habilitar o trace será a seguinte:
execute sys.dbms_system.set_sql_trace_in_session(SID, SERIAL#, TRUE);
Por padrão, o trace será gerado na área de diagnostico apartir do 10g , com a nomenclatura
NOMEDOBANCO_ora_SpidDaSessaoNoSistemaOperacional.trc.
Sendo assim , como o banco possui o nome de ha , logo o nome do trace é ha1_ora_númeroSpid.trc.
Posteriormente habilitar o trace:
SYSTEM@ha1> execute sys.dbms_system.set_sql_trace_in_session(407, 11485, TRUE);
BEGIN sys.dbms_system.set_sql_trace_in_session(266, 54165, TRUE); END;
*
ERRO na linha 1:
ORA-06550: linha 1, coluna 7:
PLS-00201: identifier 'SYS.DBMS_SYSTEM' must be declared
ORA-06550: linha 1, coluna 7:
PL/SQL: Statement ignored
Obs: Ao tentar habilitar com o usuário system do Banco de Dados ocorrerá o erro acima, o mesmo de ser habilitado com o usuário sys.
SYSTEM@ha1> conn sys@ha1 as sysdba
Informe a senha:********
Conectado.
SYS@ha1>
SYS@ha1> execute sys.dbms_system.set_sql_trace_in_session(407, 11485, TRUE);
Procedimento PL/SQL concluído com sucesso.
Após um determinado momento de coleta de dados no trace.
Posteriormente desabilitar o trace:
SYS@ha1>
SYS@ha1> execute sys.dbms_system.set_sql_trace_in_session(407, 11485, FALSE);
TKPROF
É uma ferramenta que converte os arquivos de trace do Oracle num formato de leitura mais compreensível.
O parâmetro TIMED_STATISTICS deve ser configurado para TRUE.
Não vou entrar em detalhes sobre como gerar o TKPROF, mas sim, como interpretar seu resultado. Mesmo assim uma pequena parte dele, pois o assunto é extenso.
O resultado do TKPROF contém algumas informações de performance consolidadas para todos os SQLs analisados.
Vou destacar as descritas abaixo:
********************************************************************************
count = número de vezes que o SQL foi executado
cpu = tempo de CPU utilizado em segundos
elapsed = tempo decorrido (elapsed time) em segundos. Inclui CPU Time + Wait Time
disk = número de data blocks(1) físicos lidos do disco (datafiles)
query = número de buffers(2) (blocks) CR recuperados (Consistent Read). Usualmente são recuperados em queries
current = número de buffers (blocks) CURRENT recuperados (Current Mode). Geralmente para updates,inserts e deletes
rows = número de linhas (rows) processadas pelo fetch ou execute call
********************************************************************************
Veja um exemplo:
select a.owner,b.object_name,b.status from dba_tables a, dba_objects b
where a.owner='SYSTEM' and
a.table_name = b.object_name and a.owner = b.owner
Aproveito para explicar o que é PARSE, EXECUTE e FETCH, visto que essa pergunta já me foi feita algumas vezes.
PARSE : Verifica a sintaxe do SQL, segurança/existência dos objetos envolvidos e o traduz para um plano de execução;
EXECUTE : A real execução do SQL pelo Oracle. Modifica os dados para INSERT, DELETE E UPDATE. Identifica as linhas (rows) selecionadas pelo SELECT;
FETCH : Recupera as linhas (rows) retornadas pela query. É utilizado somente para SELECTS; Observamos, no exemplo acima, que para um determinado SQL:
a) Feito o PARSE 1 vez com tempo de duração de 1.68 segundos (CPU time + 0.23 segundos);
b) Foi executado 1 vez com tempo de CPU de 0,00 segundos e elapsed time de 0.00 segundos;
c) As 191 linhas foram recuperadas em 0.26 segundos (CPU time + 0.04 segundos);
d) Foram lidos 1 buffer físico do disco, 1868 CR e 0 CURRENTs
e) #blocks in the table: #blocks = query mode / # of times the query was executed
f) Cada chamada do fetch recuperou aproximadamente 95 linhas (rows/count);
g) Um fetch no database realiza no mínimo um LIO (Logical I/O) para fazer o PIN do Oracle block no database buffer cache;
(1) data block é a menor unidade de dados usada pelo oracle database (DB_BLOCK_SIZE)
(2) buffer é onde os blocos são colocados após a leitura deles no disco.
O parâmetro TIMED_STATISTICS deve ser configurado para TRUE.
Não vou entrar em detalhes sobre como gerar o TKPROF, mas sim, como interpretar seu resultado. Mesmo assim uma pequena parte dele, pois o assunto é extenso.
O resultado do TKPROF contém algumas informações de performance consolidadas para todos os SQLs analisados.
Vou destacar as descritas abaixo:
********************************************************************************
count = número de vezes que o SQL foi executado
cpu = tempo de CPU utilizado em segundos
elapsed = tempo decorrido (elapsed time) em segundos. Inclui CPU Time + Wait Time
disk = número de data blocks(1) físicos lidos do disco (datafiles)
query = número de buffers(2) (blocks) CR recuperados (Consistent Read). Usualmente são recuperados em queries
current = número de buffers (blocks) CURRENT recuperados (Current Mode). Geralmente para updates,inserts e deletes
rows = número de linhas (rows) processadas pelo fetch ou execute call
********************************************************************************
Veja um exemplo:
select a.owner,b.object_name,b.status from dba_tables a, dba_objects b
where a.owner='SYSTEM' and
a.table_name = b.object_name and a.owner = b.owner
| call | count | cpu | elapsed | disk | query | current | rows |
| Parse | 1 | 1.45 | 1.68 | 0 | 6 | 0 | 0 |
| Execute | 1 | 0.00 | 0.00 | 0 | 0 | 0 | 0 |
| Fetch | 2 | 0.22 | 0.26 | 1 | 1868 | 0 | 191 |
| total | 4 | 1.67 | 1.95 | 1 | 1874 | 0 | 191 |
Aproveito para explicar o que é PARSE, EXECUTE e FETCH, visto que essa pergunta já me foi feita algumas vezes.
PARSE : Verifica a sintaxe do SQL, segurança/existência dos objetos envolvidos e o traduz para um plano de execução;
EXECUTE : A real execução do SQL pelo Oracle. Modifica os dados para INSERT, DELETE E UPDATE. Identifica as linhas (rows) selecionadas pelo SELECT;
FETCH : Recupera as linhas (rows) retornadas pela query. É utilizado somente para SELECTS; Observamos, no exemplo acima, que para um determinado SQL:
a) Feito o PARSE 1 vez com tempo de duração de 1.68 segundos (CPU time + 0.23 segundos);
b) Foi executado 1 vez com tempo de CPU de 0,00 segundos e elapsed time de 0.00 segundos;
c) As 191 linhas foram recuperadas em 0.26 segundos (CPU time + 0.04 segundos);
d) Foram lidos 1 buffer físico do disco, 1868 CR e 0 CURRENTs
e) #blocks in the table: #blocks = query mode / # of times the query was executed
f) Cada chamada do fetch recuperou aproximadamente 95 linhas (rows/count);
g) Um fetch no database realiza no mínimo um LIO (Logical I/O) para fazer o PIN do Oracle block no database buffer cache;
(1) data block é a menor unidade de dados usada pelo oracle database (DB_BLOCK_SIZE)
(2) buffer é onde os blocos são colocados após a leitura deles no disco.
Utilizando o tkprof para colocar o trace em um formato legível e de fácil entendimento.
Através do tkprof estarei gerando sem muitos detalhes um arquivo chamado ha1_ora_5900.txt
[oracle@ha1:/u01/app/oracle/diag/rdbms/ha1/ha1/trace]$ tkprof ha1_ora_5900.trc ha1_ora_5900.txt
TKPROF: Release 11.2.0.3.0 - Development on Mon Oct 27 14:59:42 2014
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Estarei efetuando a execução do comando head -70 no arquivo para listar as 70 primeiras linhas do arquivo para exemplificar abaixo o conteúdo do arquivo gerado ha1_ora_5900.txt
[oracle@ha1:/u01/app/oracle/diag/rdbms/ha1/ha1/trace]$ head -70 prd1_ora_5900.txt
TKPROF: Release 11.2.0.3.0 - Development on Mon Oct 27 14:59:42 2014
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: ha1_ora_5900.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
The following statement encountered a error during parse:
select rowid,sqlcheck, sqlalias, nomlink link, Decode(nompropkey,'infoPerfil.experienciaPro','infoPerfil.experienciaProExt',nompropkey) prop_key, blnobrigat obrigat from reqcv, reqcvperfil where pkreqcv = fkrqcv$codreqcv and fkpepr$codperfil = (select cod_perfil from candidato where codigo = 3003908)
Error encountered: ORA-00918
********************************************************************************
SQL ID: 04hw3btjxum15 Plan Hash: 2205550052
select codigo, nome
from
region where codigo in (select ps.estado from vw_anuncio ps where ps.estado
is not null) order by codigo
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 842 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 842 0 10
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: 112
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
5 5 5 MERGE JOIN SEMI (cr=421 pr=0 pw=0 time=2700 us cost=4 size=34 card=1)
26 26 26 TABLE ACCESS BY INDEX ROWID REGION (cr=3 pr=0 pw=0 time=52 us cost=1 size=390 card=26)
26 26 26 INDEX FULL SCAN PK$REGION (cr=2 pr=0 pw=0 time=10 us cost=1 size=0 card=26)(object id 74451)
5 5 5 SORT UNIQUE (cr=418 pr=0 pw=0 time=2674 us cost=3 size=1064 card=56)
57 57 57 TABLE ACCESS BY INDEX ROWID PROCESSO_SELETIVO (cr=418 pr=0 pw=0 time=600 us cost=2 size=1064 card=56)
1563 1563 1563 INDEX RANGE SCAN FK_PS_STATUS (cr=18 pr=0 pw=0 time=370 us cost=1 size=0 card=1563)(object id 107800).
Dessa forma podemos habilitar o trace para monitorar uma determinada sessão do Oracle e capturar todas as suas ações em um determinado momento.
Isso nos possibilita depois analisar o arquivo trace objetivando uma query que desejamos analisar.
