Как стать автором
Обновить

Oracle diagnostic events — Cheat sheet

Время на прочтение 5 мин
Количество просмотров 3.7K

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).

Пример:

включаем event
включаем event
сначала выполняем запрос с настройками по умолчанию, а затем с _rowsource_statistics_sampfreq=1
сначала выполняем запрос с настройками по умолчанию, а затем с _rowsource_statistics_sampfreq=1
Разница в трейсе заметна
Разница в трейсе заметна

Как видите, при "_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           = ""

Update: В телеграм канале RuOUG спросили:
В качестве примера, у нас используется код расширения статистики оптимизатора, периодически падающий с ошибкой ORA-06550 PL/SQL compile error, т.е. этот код вызывает сам оптимизатор Oracle. Возможно ли в Oracle diagnostic events одновременно задать kg_event и sql_id, чтобы в alert.log появились ошибки ORA-06550 и имена соответствующих trace файлов, например так: alter system set events 'kg_event[6550] {occurence: start_after 1, end_after 3} [sql: 7ujay4u33g337] errorstack(3) ';

И я вспомнил, что хотел описать и еще один крайне полезный ACTION - incident(). Пример:

alter system set events 
    'kg_event[6550]
        [sql: 5cmnpq8t0g7pd]
            {occurence: start_after 1, end_after 3}
                errorstack(3)
                incident(plserrors)
      ';

kg_event[6550] - трассировать ошибки "ORA-06550: line %, column %" и incident(plserrors) - создать инцидент-файл (при необходимости его можно легко упаковать через adrci и отправить для разбора консультантам или в Oracle Support)

сгенерируем ошибку
сгенерируем ошибку
включим трейс и увидим, что инцидент-файл сформировался
включим трейс и увидим, что инцидент-файл сформировался

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

Теги:
Хабы:
+4
Комментарии 5
Комментарии Комментарии 5

Публикации

Истории

Работа

Ближайшие события

Московский туристический хакатон
Дата 23 марта – 7 апреля
Место
Москва Онлайн
Геймтон «DatsEdenSpace» от DatsTeam
Дата 5 – 6 апреля
Время 17:00 – 20:00
Место
Онлайн