Oracle diagnostic events — Cheat sheet

Oracle diagnostic events — это очень мощное средство, но, к сожалению, слабо документированное, поэтому я решил перечислить и свести воедино несколько неизвестных или малоизвестных способов его использования.

Единственная его документация — это очень краткая встроенная документация, доступная по команде oradebug doc в SQL*Plus, и она отсутствует в официальной документации. Вы можете встретить только отрывки из нее в разных блогах, что не очень удобно, поэтому я скомпилировал ее полностью: http://orasql.org/files/events/

Современный синтаксис и несколько простых примеров приведены в oradebug doc event. Я их здесь приводить не буду и начну сразу с примеров.

alter system set events     'kg_event[1476]         {occurence: start_after 1, end_after 3}             trace("stack is: %\n", shortstack())             errorstack(2)     ';

1. kg_event[errno] — это Kernel Generic event из библиотеки Generic, инструктирующее сработать на ошибку с номером errno;

2. {occurence: start_after X, end_after Y} — это один из фильтров , инструктирующий пропустить X срабатываний данного event и выполниться Y раз;

3. trace(format, str1, str2, …, str15) — это функция из ACTIONS для вывода в трейс-файл своих сообщений;

4. shortstack() — это функция из ACTIONS , возвращающая call stack в кратком виде;

5. errorstack(level) — это функция из ACTIONS, выводящая в трейс-файл расширенную информацию (level: 0 — только errorstack, 1 — errorstack + call stack, 2 — как level=1 + processtate, 3 — как level=2 + context area). Еще более расширенную информацию можно получить с помощью PROCESSSTATE или SYSTEMSTATE. Если нужен только call stack можно воспользоваться CALLSTACK(level) — при level>1 запишет и аргументы.

alter system set events      'trace[SQL_Compiler.* | SQL_Execution.*]         [SQL: ...]             {process: ospid = ...}             {occurence:end_after 3}                 controlc_signal()';

1. trace[component] — это основной диагностический event, позволяющий указать компоненты, внутри которых надо срабатывать. В данном случае, я указал срабатывать внутри всех дочерних функций в SQL_Compiler и SQL_Execution. Например, RDBMS.SQL_Compiler.SQL_Optimizer.SQL_Transform.* указало бы срабатывать только в функциях трансформации запросов.

2. SQL[SQL: sqlid ] — это единственный SCOPE в библиотеке RDBMS, позволяющий отфильтровать все события, связанные с указанными запросами, включая события его рекурсивных запросов(например, если это sql_id PL/SQL вызова, то будут оттрассированы все запросы внутри него, или для запроса — все его внутренние запросы во время парсинга и оптимизации, внутренних запросов PL/SQL функций и тд.);

3. {process: …} — это фильтр, позволяющий указать процессы для которых данный event будет включен.

4. controlc_signal — это ACTION, вызывающий ошибку «ORA-01013: user requested cancel of current operation», т.е. сессия запустившая этот запрос получит эту ошибку, как будто она сама прервала выполнение запроса.

   Конкретно, данным примером я воспользовался, когда в ходе нагрузочного тестирования большого веб-приложения на hibernate, были обнаружены очень плохие фактически ненужные запросы и нужно было помочь разработчикам быстро найти откуда в их коде они выполняются.

alter system set events      'sql_trace {process: ospid = ...}       trace("sqlid(%): %\n", sqlid(), evfunc())      ';

sql_trace — это старый добрый event 10046, а целиком команда предписывает при каждом событии инструментированным этим event 10046, вывести функцию, его вызвавшую(evfunc) и sqlid запроса (ACTION sqlid).

Пример:

Как видите, при «_rowsource_statistics_sampfreq» =1 инструментировано намного больше событий: 26 против 12! Подробнее тут.

alter system set events      'wait_event["enq: TM - contention"]         {wait: minwait=1000}              errorstack(1)             trace("event=[%] sqlid=%, ela=% p1=% p2=% p3=%\n",                     evargs(5), sqlid(), evargn(1), evargn(2), evargn(3), evargn(4))     ';

1. wait_event[name] — event, срабатывающий по имени событий ожидания (wait events), имена и их параметры вы можете посмотреть в v$event_name:
   select wait_class,name,parameter1,parameter2,parameter3 ,display_name from v$event_name

2. {wait: … } — фильтр позволяющий отфильтровать как по долготе ожидания(в мс), так и по параметрам P1, P2, P3. Например, для указанного ожидания «TM-contention», P2 — это object #, и можно указать {wait: minwait=1000; p2=12345}, т.е. только ожидания табличной блокировки на таблице с object_id=12345 и длившиеся дольше 1 сек.

3. evargX() — это функции из ACTION, возвращающие аргументы event-check события, где 1-й аргумент это elapsed time(ms), 2-4 — p1-p3, 5-й — имя ожидания. Соответствующие функции имеет и kg_event: errargX.

Или еще пример, когда вам надо узнать какие сессионные переменные были изменены. Допустим, кто-то забыл указать nls-параметры в to_number, on conversion error не указан, и какие-то сессии периодически получают ORA-01722: invalid number:

-- допустим, изначально должны стоять следующие параметры: SQL> alter session set nls_numeric_characters='.,';  Session altered.  -- и все работает нормально SQL> select to_number('1,200.3','999g999d999') + 10 from dual;  TO_NUMBER('1,200.3','999G999D999')+10 -------------------------------------                                1210.3  -- до тех пор, пока в какой-то момент они не меняются: SQL> alter session set nls_numeric_characters=q'[.']';  'Session altered.  -- соответственно вылетает ошибка: SQL> select to_number('1,200.3','999g999d999') + 10 from dual; select to_number('1,200.3','999g999d999') + 10 from dual                  * ERROR at line 1: ORA-01722: invalid number

Хотя нет никакой вьюхи для получения параметров чужой сессии, не входящих в v$ses_optimizer_env, мы можем легко их получить с помощью MODIFIED_PARAMETERS():

alter system set events      'kg_event[1722]          {process: ospid=27556}         {occurence:end_after 1}             MODIFIED_PARAMETERS()';

И благодаря тому, что сейчас есть удобные v$diag_alert_ext — для доступа к alert.log, v$diag_trace_file_contents — для доступа к трейс-файлам, мы можем все получить простым запросом:

select c.payload from v$diag_trace_file_contents c where 1=1   and c.session_id   = ... -- sid сессии   and c.serial#      = ... -- serial#   and c.section_name = 'Error Stack' -- параметры будут в секции Error Stack --  and c.payload like '%nls_numeric%' -- можно отфильтровать именно   and c.timestamp>systimestamp-interval'15'minute;  -- результат: DYNAMICALLY MODIFIED PARAMETERS:   nls_language             = "AMERICAN"   nls_territory            = "AMERICA"   nls_sort                 = "BINARY"   nls_date_language        = "AMERICAN"   nls_date_format          = "yyyy-mm-dd hh24:mi:ss"   nls_currency             = "$"   nls_numeric_characters   = ".'"   nls_iso_currency         = "AMERICA"   nls_calendar             = "GREGORIAN"   nls_time_format          = "hh24:mi:ssxff"   nls_timestamp_format     = "yyyy-mm-dd hh24:mi:ssxff"   nls_time_tz_format       = "hh24:mi:ssxff TZR"   nls_timestamp_tz_format  = "yyyy-mm-dd hh24:mi:ssxff TZR"   nls_dual_currency        = "$"   nls_comp                 = "BINARY"   local_listener           = ""

PS. Дополнительные детали вы можете узнать в статьях Tanel Poder:
1. The full power of Oracle’s diagnostic events, part 1: Syntax for KSD debug event handling
2. The full power of Oracle’s diagnostic events, part 2: ORADEBUG DOC and 11g improvements
3. What Caused This Wait Event: Using Oracle’s wait_event[] tracing
4. http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc

О внутренних функциях у Frits Hoogland: http://orafun.info/

Полная внутренняя документация по oradebug/diagnostic events: http://orasql.org/files/events