Oracle diagnostic events

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.payloadfrom v$diag_trace_file_contents cwhere 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 Oracles diagnostic events, part 1: Syntax for KSD debug event handling
2. The full power of Oracles 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