Главная > SQL > Трассировка сессии — event 10046


Трассировка сессии — event 10046

19 Сентябрь 2012 Написать комментарий К комментариям

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

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

alter session set sql_trace=true;

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

 

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

Включить трассировку в текущей сессии

alter session set events '10046 trace name context forever, level 1';

выключить трассировку в текущей сессии

alter session set events '10046 trace name context off';

Уровни:

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

Для включения трассировки в другой сессии можно воспользоваться командой

sys.dbms_system.set_ev(sid, serial#, 10046, 12, '');

Путь к директории, где появится файл трассировки

select value from v$parameter where name = 'user_dump_dest';

Задать имя для trace файла

alter session set tracefile_identifier = 'mytrace1';

 

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

Выполняем следующий код, чтобы создать trace файл:

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'
/

Заголовок файла — содержит информацию об инстансе и сессии для которой создан

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

Разбор курсора

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интаксис

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) под которым был разобран запрос 
    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

Основные операции

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интаксис

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, в микросекундах

Связываемые переменные / binds

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- значение переменной

Ожидания / wait

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, в микросекундах

Остальные параметры зависят от типа ожидания. Увидеть данные параметры можно с помощью запроса:

select * from v$event_name where name = :waitname;

План выполнения

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]

Похожие записи:

  • No Related Posts
Categories: SQL Tags: , , ,
  1. arlex
    17 Февраль 2016 в 10:27 | #1
    Ответить | Цитата

    Для включения трассировки в другой сессии можно воспользоваться командой

    begin
	dbms_monitor.session_trace_enable(session_id => sid, serial_num => serial#, 
		waits => true, binds => true);
end;

    Для выключения

    begin
	dbms_monitor.session_trace_disable(session_id => sid, serial_num => serial#);
end;

    Трассировочный файл с накопленной «сырой» информацией появится в следующей директории

    SELECT value FROM v_$parameter WHERE name = 'user_dump_dest';

    Имя этого файла будет в себе содержать идентификатор процесса операционной системы

    select p.spid, s.sid, s.serial#
		from v$session s
		left join v$process p on s.paddr = p.addr
	 where s.sid = 11 and s.serial# = 15143;

    Преобразовать «сырую» информацию в пригодный для чтения человеком вид

    tkprof input.trc output.prf EXPLAIN=/ sys=no waits=yes

    Перед включением трассировки — необходимо включить сбор временной статистики, иначе трассировочные файлы будут появляться с нулевыми временами

    alter system set timed_statistics=true

    в текущей сессии

    alter session set timed_statistics=true

    убедиться,что параметр max_dump_file_size, ограничивающий размер трассировочного файла выставлен в достаточно большое значение

    select value from v$parameter p  where name='max_dump_file_size'
  2. segaba
    18 Март 2016 в 18:11 | #2
    Ответить | Цитата 
    alter session set max_dump_file_size=unlimited

    для параметра ограничивающего размер трассировочного файла

  1. Пока что нет уведомлений.