Трассировка сессии

Трассировка сессии Oracle помогает найти проблемные запросы и понять в чем именно причина.

Что именно будет записываться в трассировочный файл, определяется номером события (event).
Стандартный номер события 10046. Именно такой уровень устанавливается при выполнении команды1 alter session set sql_trace=true;


Список данных событий и для чего они предназначены можно посмотреть здесь EventReference



Событие трассировки 10046 / Trace event 10046

Включить трассировку в текущей сессии1 alter session set events '10046 trace name context forever, level 1';


выключить трассировку в текущей сессии1 alter session set events '10046 trace name context off';


Уровни:
0 – трассировка отключена
1 – стандартная трассировка
4 – добавлены значения связываемых (binds) переменных
8 – добавлены события ожидания (waits)
12 – связываемые переменные + события ожидания

Для включения трассировки в другой сессии можно воспользоваться командой1 sys.dbms_system.set_ev(sid, serial#, 10046, 12, '');


Путь к директории, где появится файл трассировки1 select value from v$parameter where name = 'user_dump_dest';


Задать имя для trace файла1 alter session set tracefile_identifier = 'mytrace1';




Понимание трасировочного файла


Выполняем следующий код, чтобы создать trace файл:1
2
3
4
5
6
7
8
9
10
11
12
13
14
15 SET SERVEROUTPUT ON
alter session set tracefile_identifier = 'mytrace2'
/
alter session set events '10046 trace name context forever, level 12'
/
declare
l_row_num number;
l_owner varchar2(10) := 'SYS';
begin
select count(1) into l_row_num from all_tables t where t.owner = l_owner;
dbms_output.put_line('num='||l_row_num);
end;
/
alter session set events '10046 trace name context forever, level 0'
/


Заголовок файла – содержит информацию об инстансе и сессии для которой создан1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20 Trace file .../"instance_name"_ora_12591_mytrace2.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = ...
System name: ...
Node name: ...
Release: ...
Version: ...
Machine: ...
Instance name: "instance_name"
Redo thread mounted by this instance: 1
Oracle process number: 545
Unix process pid: 12591, image: ...

*** 2012-09-19 12:07:49.268
*** SESSION ID:(669.6321) 2012-09-19 12:07:49.268
*** CLIENT ID:() 2012-09-19 12:07:49.268
*** SERVICE NAME:(...) 2012-09-19 12:07:49.268
*** MODULE NAME:(PL/SQL Developer) 2012-09-19 12:07:49.268
*** ACTION NAME:(Command Window - New) 2012-09-19 12:07:49.268


Разбор курсора1
2
3 PARSING IN CURSOR #11529215044981500944 len=54 dep=1 uid=44 oct=3 lid=44 tim=10192202222475 hv=1751201178 ad='c0000005d60dcaf0' sqlid='1f79yzdn62dcu'
SELECT COUNT(1) FROM ALL_TABLES T WHERE T.OWNER = :B1
END OF STMT


cинтаксис1
2
3 PARSING IN CURSOR #[CURSOR] len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X' sqlid='X'
[statement]
END OF STMT

[CURSOR] – номер курсора
len – длина SQL запроса
dep – рекурсивная глубина SQL запроса
uid – id пользователя (user) под которым был разобран запрос 1 select * from all_users where user_id = :uid;

oct – ID команды oracle. Можно увидеть в V$SQL.COMMAND_TYPE и V$SESSION.COMMAND
lid – ID схемы в которой был разобран запрос. Может отличаться от uid
tim – timestamp, в микросекундах
hv – hash значение, V$SQL.HASH_VALUE
ad – адрес. V$SQL.ADDRESS, V$SQLTEXT.ADDRESS
sqlid – ID запроса, V$SQL.SQL_ID

Основные операции1
2
3 PARSE #11529215044981500944:c=0,e=370,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=10192202222474
EXEC #11529215044981500944:c=270000,e=276923,p=0,cr=3,cu=0,mis=1,r=0,dep=1,og=1,plh=242196440,tim=10192202499569
FETCH #11529215044981500944:c=840000,e=1466871,p=2776,cr=71124,cu=0,mis=0,r=1,dep=1,og=1,plh=242196440,tim=10192203966668


PARSE – разбор курсора, EXEC – выполнение курсора, FETCH – получение данных
cинтаксис1
2
3 PARSE #[CURSOR]:c=X,e=X,p=X,cr=X,cu=X,mis=X,r=X,dep=X,og=X,plh=X,tim=X
EXEC #[CURSOR]:c=X,e=X,p=X,cr=X,cu=X,mis=X,r=X,dep=X,og=X,plh=X,tim=X
FETCH #[CURSOR]:c=X,e=X,p=X,cr=X,cu=X,mis=X,r=X,dep=X,og=X,plh=X,tim=X

[CURSOR] – номер курсора
c – время в микросекундах затраченное процессором
e – общее затраченное время в микросекундах
p – число физических чтений (physical reads)
cr – количество блоков полученных в режиме согласованного чтения (retrieved for CR reads)
cu – количество блоков полученных в текущем режиме (retrieved in current mode)
mis – отсутствие курсора в кеше, выполняется hard parse
r – количество возвращаемых строк
dep – рекурсивная глубина запроса
og – Цель оптимизатора: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose
plh – Hash значение для выполняемого плана. V$SQL_PLAN.PLAN_HASH_VALUE
tim – timestamp, в микросекундах

Связываемые переменные / binds1
2
3
4
5
6 BINDS #11529215044981500944:
Bind#0
oacdty=01 mxl=32(10) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=01 csi=171 siz=32 off=0
kxsbbbfp=9fffffffbf3b37b8 bln=32 avl=03 flg=09
value="SYS"

[CURSOR] – номер курсора
bind#N – номер переменной
oacdty – тип данных
mxl- maximum length of the bind variable value (private maximum length in parentheses)
mxlc – ?
mal – длина массива
scl – масштаб (scale)
pre – точность (precision)
oacflg – special flag indicating bind options
fl2 – second part of oacflg
frm – ?
csi – идентификатор кодировки
siz – объем выделяемой памяти
off – offset into the chunk of the bind buffer
kxsbbbfp – адрес переменной
bln – длина буфера для переменной
avl – актуальная длина переменной
flg – статус переменной
value- значение переменной

Ожидания / wait1
2 WAIT #11529215044981500944: nam='Disk file operations I/O' ela= 285 FileOperation=2 fileno=4 filetype=2 obj#=397424 tim=10192202526355
WAIT #11529215044981500944: nam='db file sequential read' ela= 583 file#=4 block#=7927 blocks=1 obj#=397424 tim=10192202526996

[CURSOR] – номер курсора
nam- тип ожидания
ela – затраченное время в микросекундах
obj#- номер объекта
tim – timestamp, в микросекундах

Остальные параметры зависят от типа ожидания. Увидеть данные параметры можно с помощью запроса:1 select * from v$event_name where name = :waitname;


План выполнения1
2
3
4
5
6
7
8 STAT #11529215044981500944 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=71124 pr=2776 pw=0 time=1466915 us)'
STAT #11529215044981500944 id=2 cnt=1047 pid=1 pos=1 obj=0 op='FILTER (cr=71124 pr=2776 pw=0 time=1123290 us)'
STAT #11529215044981500944 id=3 cnt=1047 pid=2 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=68261 pr=2735 pw=0 time=1080842 us cost=3024 size=14145 card=115)'
STAT #11529215044981500944 id=4 cnt=1047 pid=3 pos=1 obj=0 op='HASH JOIN RIGHT OUTER (cr=64291 pr=2289 pw=0 time=954642 us cost=2820 size=11322 card=102)'
...
STAT #11529215044981500944 id=9 cnt=28 pid=8 pos=1 obj=16 op='TABLE ACCESS FULL TS$ (cr=33 pr=0 pw=0 time=1609 us cost=8 size=84 card=28)'
STAT #11529215044981500944 id=10 cnt=1047 pid=8 pos=2 obj=0 op='NESTED LOOPS (cr=62544 pr=2252 pw=0 time=561698 us cost=2620 size=8976 card=102)'
...

[CURSOR] – номер курсора
id – номер строки плана
cnt – количество обработанных строк
pid – идентификатор родителя
pos – позиция относительно родителя
obj – ID объекта. ALL_OBJECTS.OBJECT_ID и V$SQL_PLAN.OBJECT#.
op – операция
cr – согласованное чтение (Consistent read)
pr – физическое чтение (Physical reads)
pw – физическая запись (Physical writes)
time – timestamp, в микросекундах
cost – оценка выполнения запроса (CBO)
size – объем данных в байтах
card – число возвращаемых строк

Дополнительно можно почитать ноту Interpreting Raw SQL_TRACE output [ID 39817.1]