Этот пост навеян статьями Часть 1. Логирование событий в Oracle PL/SQL и Часть 2. Идентификация событий происходящих в Oracle PL/SQL. В первую очередь, как специалисту по performance tuning и troubleshooting, хотелось бы прокомментировать некоторые нюансы.

1. Уровни детализации логгирования

В показанной системе не хватает гибкости настройки логгирования: как уровня детализации, так и места, куда их выводить. Можно было позаимствовать функциональность из широко известных систем логгирования а-ля java.util.logging (SLF4j, log4j и его вариации для других языков/систем, и тд), гибкую настройку для какого кода с какого уровня сообщений и куда их сохранять. Например, в том же log4plsql можно настроить вывод и в alert.log, и в trace file (с помощью `dbms_system.ksdwrt()`)

2. Пользовательские ошибки и сообщения

Из самой внутренней системы ошибок Оракл можно было позаимствовать использование UTL_LMS.FORMAT_MESSAGE. Кстати, сами ошибки(и events) можно посмотреть с помощью sys.standard.sqlerrm(N):

SQL> select sys.standard.sqlerrm(-1476) errmsg from dual;

ERRMSG
-------------------------------------
ORA-01476: divisor is equal to zero

Примеры: err_by_code.sql, trace_events.sql

Кроме того, я, конечно, понимаю, что не все ошибки можно предусмотреть, но все-таки считаю, что их надо добавлять в exception handler после того как они уже были отловлены. Это будет полезно как минимум при последующих изменениях логики и будет проще видеть нестандартные или непредусмотренные ранее ситуации.

3. Что же делать в случае незалоггированных ошибок

Естественно, может случиться так, что существующая система логгирования не регистрирует какие-то неординарные ошибки, или даже ее совсем нет в базе. Тут могут быть полезны триггеры `after servererror on database/schema`. Простой минимальный пример.

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

Например, недавно Nenad Noveljic расследовал проблему c "TNS-12599: TNS:cryptographic checksum mismatch" для чего ему нужно было получить callstack:

К счастью, помимо использованного у него в статье "ERRORSTACK", есть еще большой список "ACTIONS", включающий в себя и "CALLSTACK":

В этой команде 12599 - это номер события(event), callstack - инструктирует сделать дамп call стека, level 2 - указывает вывести еще и аргументы функций, lifetime 1 - только один раз.

Более подробно об этом у Tanel Poder с примерами:

• http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc

• https://tanelpoder.com/2010/06/23/the-full-power-of-oracles-diagnostic-events-part-2-oradebug-doc-and-11g-improvements/

Мало того, как сам Танел и посоветовал, можно еще воспользоваться и "trace()" для форматированного вывода shortstack():

Так что этим же мы можем воспользоваться этим для вывода callstack:

alter system set events '12599 trace("stack is: %\n", shortstack())';

Или в более новом формате:

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

Как вы видите, здесь я еще добавил фильтр на количество срабатываний: после первого выполнения и только 1 раз.

Покажу на примере "ORA-01476: divisor is equal to zero":

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

Здесь kg_event - это Kernel Generic event, 1476 - ORA-1476. После этого запускаем в своей сессии:

SQL> alter session set events 'kg_event[1476]{occurence: start_after 1, end_after 1} trace("stack is: %\n", shortstack())';

Session altered.

SQL> select 1/0 x from dual;
select 1/0 x from dual
        *
ERROR at line 1:
ORA-01476: divisor is equal to zero


SQL> select 1/0 x from dual;
select 1/0 x from dual
        *
ERROR at line 1:
ORA-01476: divisor is equal to zero


SQL> select 1/0 x from dual;
select 1/0 x from dual
        *
ERROR at line 1:
ORA-01476: divisor is equal to zero

И в трейсфайле получаем:

# cat ORA19_ora_12981.trc
Trace file /opt/oracle/diag/rdbms/ora19/ORA19/trace/ORA19_ora_12981.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.9.0.0.0
Build label:    RDBMS_19.9.0.0.0DBRU_LINUX.X64_200930
ORACLE_HOME:    /opt/oracle/product/19c/dbhome_1
System name:    Linux
Node name:      b7c493c7f9b0
Release:        3.10.0-1062.12.1.el7.x86_64
Version:        #1 SMP Tue Feb 4 23:02:59 UTC 2020
Machine:        x86_64
Instance name: ORA19
Redo thread mounted by this instance: 1
Oracle process number: 66
Unix process pid: 12981, image: oracle@b7c493c7f9b0


*** 2021-05-08T14:12:27.000816+00:00 (PDB1(3))
*** SESSION ID:(251.9249) 2021-05-08T14:12:27.000846+00:00
*** CLIENT ID:() 2021-05-08T14:12:27.000851+00:00
*** SERVICE NAME:(pdb1) 2021-05-08T14:12:27.000855+00:00
*** MODULE NAME:(sqlplus.exe) 2021-05-08T14:12:27.000859+00:00
*** ACTION NAME:() 2021-05-08T14:12:27.000862+00:00
*** CLIENT DRIVER:(SQL*PLUS) 2021-05-08T14:12:27.000865+00:00
*** CONTAINER ID:(3) 2021-05-08T14:12:27.000868+00:00

stack is: dbgePostErrorKGE<-dbkePostKGE_kgsf<-kgeade<-kgeselv<-kgesecl0<-evadiv<-kpofcr<-qerfiFetch<-opifch2<-kpoal8<-opiodr<-ttcpip<-opitsk<-opiino<-opiodr<-opidrv<-sou2o<-opimai_real<-ssthrdmain<-main<-__libc_start_main

Или, например, недавно я посоветовал использовать alter system set events 'trace[sql_mon.*] [SQL: ...] disk=high,memory=high,get_time=highres'; для выяснения причин, почему конкретный запрос не мониторится/сохраняется real-time SQL монитором (RTSM - Real Time SQL Monitor).

Получилось несколько сумбурно, в связи с недостатком времени, но на этом, пожалуй, закончу. Будут рад вопросам - задавайте, и я постараюсь их раскрыть отдельно.