Troubleshooting в Oracle

Этот пост навеян статьями Часть 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`. Простой минимальный пример: https://github.com/xtender/xt_scripts/blob/master/error_logging/on_database.sql

К сожалению, для полноценного и срочного решения неординарных проблем, ни системы логгирования, ни таких триггеров, может быть недостаточно, и тут на помощь приходит вся мощь самой встроенной системы событий 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).

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