TM — Library Cache Deadlock на этапе Parsing и Optimizer Finding

При выполнении ALTER TABLE DROP CONSTRAINT случился TM — library cache deadlock распределённого (RAC) вида, отразившийся в ASH следующим образом:

12.1.0.2@ SQL> @ash_sql_wait_tree "(session_id,session_serial#) in ((4460,16750)) and sample_time > trunc(sysdate,'hh24')" 0
 
LVL INST_ID BLOCKING_TREE   EVENT                 WAIT_CLASS   DATA_OBJECT_P1RAW  IN_PARSE SQL_CHILD_NUMBER WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT BLOCK_SID  MIN_STIME                  MAX_STIME                  SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID SQL_TEXT
--- ------- --------------- --------------------- ------------ ------------------ -------- ---------------- ----------- ----------- ------ ---------- ---------- -------------------------- -------------------------- ------------- ------------------- ----------- ----------------------------------------------------------------------------------------------------
  1       1 (USER)          enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0          11           1      0          1 GLOBAL i#  26-JUN-17 04.06.39.431 PM  26-JUN-17 04.06.49.451 PM  7kpzqksdg4wu8                   0           1 
  1       1 (USER)          enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           2           1      0          1 VALID i#2  26-JUN-17 04.06.50.451 PM  26-JUN-17 04.06.51.451 PM  7kpzqksdg4wu8                   0           1 
  1       1 (USER)          library cache pin     Concurrency  000000261138EA48   Y                       0           1           0      1          1 GLOBAL i#  26-JUN-17 04.06.37.431 PM  26-JUN-17 04.06.37.431 PM  73f85gf8qvb34          2024994732           0 select NULL AS TABLE_CAT, OWNER AS TABLE_SCHEM, 'NO' as IS_AUTOINCREMENT, cc.COMMENTS AS REMARKS,OWN
  1       1 (USER)          library cache pin     Concurrency  000000274A98AEE0   Y                       0           1           0      0          1 GLOBAL i#  26-JUN-17 04.06.36.431 PM  26-JUN-17 04.06.36.431 PM  6196bjzyj6dv7          2050374072           0 SELECT null as TABLE_CAT, a.OWNER as TABLE_SCHEM, a.TABLE_NAME as TABLE_NAME, a.TEMPORARY as TEMPORA
  2       2   (USER)        library cache lock    Concurrency  00000027E6E364A8   Y                      -1           4           0   6807          1 VALID i#1  26-JUN-17 04.06.50.574 PM  26-JUN-17 04.06.51.574 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  2       2   (USER)        library cache lock    Concurrency  00000027E6E364A8   Y                      -1           1           0      0          1 GLOBAL i#  26-JUN-17 04.06.49.564 PM  26-JUN-17 04.06.49.564 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  3       1     (USER)      enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           4           1      0          1 VALID i#2  26-JUN-17 04.06.50.451 PM  26-JUN-17 04.06.51.451 PM  7kpzqksdg4wu8                   0           1 
  3       1     (USER)      enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           2           1      0          1 GLOBAL i#  26-JUN-17 04.06.49.451 PM  26-JUN-17 04.06.49.451 PM  7kpzqksdg4wu8                   0           1 
  4       2       (USER)    library cache lock    Concurrency  00000027E6E364A8   Y                      -1           4           0   6807          1 VALID i#1  26-JUN-17 04.06.50.574 PM  26-JUN-17 04.06.51.574 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  4       2       (USER)    library cache lock    Concurrency  00000027E6E364A8   Y                      -1           2           0      0          1 GLOBAL i#  26-JUN-17 04.06.49.564 PM  26-JUN-17 04.06.49.564 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  5       1         (USER)  enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           2           1      0          1 GLOBAL i#  26-JUN-17 04.06.49.451 PM  26-JUN-17 04.06.49.451 PM  7kpzqksdg4wu8                   0           1 
 
11 rows selected

где:

Реклама

ASH_IO_WAITSBY.SQL

По причине ошибки ORA-00600: Internal Error Code, Arguments: [qmxtcsxmlt:xmltype] (Doc ID 2079499.1), характерной для использования функции XMLAgg в бд состояния MOUNTED (standby or non-standby), переписал скрипт ASH_IO_WAITS.SQL для поиска наиболее активных в WAIT_CLASS-ах ‘User I/O‘ и ‘System I/O‘ процессов/запросов на STANDBY и прочих MOUNTED системах

Например, при замедлившемся накате standby (в отсутствии Read Only пользовательских запросов) можно было наблюдать аномально интенсивную IO активность пользовательских процессов RFS в части control file sequential read и RFS write:

SQL> @ash_io_waitsby blocks 10 "1 = 1"
 
INST SQL_PROCESS   SUM(WAIT_COUNT) waits%  SUM(REQUESTS) reqs%   SUM(BLOCKS) blocks% event(waits:requests:blocks)
---- ------------- --------------- ------- ------------- ------- ----------- ------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   1 (USER)                 156134   73.56        156134   11.11     1269165   39.07 control file sequential read(11699:11699:1123994); RFS write(105538:105538:105538); RMAN backup & recovery I/O(29486:29486:29486); Data file init write(6877:6877:6877); control file parallel write(736:736:1472); Disk file operations I/O(1049:1049:1049); Disk file Mirror Read(641:641:641); Log archive I/O(108:108:108)
   1 (DBW.)                  14696    6.92       1207318   85.94     1207318   37.16 db file parallel write(14696:1207318:1207318)
   1 (PR..)                  17569    8.28         17569    1.25      523541   16.12 log file sequential read(3984:3984:506025); recovery read(13311:13311:13311); control file sequential read(120:120:4020); direct path write(91:91:91); control file parallel write(31:31:62); direct path read(31:31:31); Disk file operations I/O(1:1:1)
   1 (ARC.)                  16169    7.62         16169    1.15      234540    7.22 control file sequential read(8614:8614:226728); Log archive I/O(7104:7104:7104); control file parallel write(280:280:560); Disk file Mirror Read(106:106:106); Disk file operations I/O(40:40:40); log file sequential read(25:25:2)
   1 (CKPT)                   4624    2.18          4624    0.33        8932    0.27 control file parallel write(3301:3301:6602); control file sequential read(1007:1007:2014); Disk file Mirror Read(316:316:316)
   1 a5xcbum9zpyzn            1750    0.82          1750    0.12        2912    0.09 control file sequential read(1162:1162:2324); Disk file Mirror Read(588:588:588)
   1 6jaghrm3vy74f             769    0.36           769    0.05        1303    0.04 control file sequential read(534:534:1068); Disk file Mirror Read(235:235:235)
   1 89z2u0fdrdg66             397    0.19           397    0.03         761    0.02 control file sequential read(364:364:728); Disk file Mirror Read(33:33:33)
   1 (M...)                     50    0.02            50    0.00          92    0.00 control file sequential read(42:42:84); Disk file Mirror Read(8:8:8)
   1 7mgr3uwydqq8j              13    0.01            13    0.00          22    0.00 control file sequential read(9:9:18); Disk file Mirror Read(4:4:4)
 
10 rows selected

в сравнении с нормальным поведением, где RFS заметен лишь на 4-м месте с 5% прочитанных/записанных blocks:

log file sequential read

Всплеск нагрузки на IO подсистему:

сопровождался, по нашим с Дмитрием Якубеней наблюдениям, дисбалансом в отчёте AWR — совершенно незначительные цифры пользовательской нагрузки (*):

Load Profile                    Per Second   Per Transaction  Per Exec  Per Call
~~~~~~~~~~~~~~~            ---------------   --------------- --------- ---------
             DB Time(s):              73.0               0.0      0.01      0.00
              DB CPU(s):              10.5               0.0      0.00      0.00
      Background CPU(s):               0.9               0.0      0.00      0.00
      Redo size (bytes):       6,734,104.6           3,153.3
  Logical read (blocks):       2,698,366.4           1,263.6
          Block changes:          41,001.2              19.2
 Physical read (blocks):          11,301.7               5.3
Physical write (blocks):           3,319.9               1.6
       Read IO requests:           4,417.3               2.1
      Write IO requests:             721.0               0.3
           Read IO (MB):              44.2               0.0                      -- *
          Write IO (MB):              13.0               0.0                      -- *
...

никак не коррелировали с Total (MB) нагрузкой AWR IO Profile (**):

Наблюдаемые особенности компиляции Matview курсоров на примере 12c Out-of-Place (OOP) Refresh

В процессе тестирования с Максимом Филатовым Patch 20933264: OUT-OF-PLACE COMPLETE REFRESH NOT USING DIRECT LOAD IN POPULATING OUTSIDE TABLE наблюдали следующее воспроизводимое поведение:

12.1.0.2@ SQL> CREATE MATERIALIZED VIEW scott.EMP_SNAPSHOT2 tablespace users REFRESH complete ON DEMAND as SELECT * FROM "SCOTT"."EMP" join "SCOTT"."DEPT" using(deptno)
  2  /

Materialized view created.

SQL> alter session set events '10979 trace name context forever';

Session altered.

SQL> alter session set events '10046 trace name context forever , level 12';

Session altered.

SQL> exec dbms_mview.refresh('"SCOTT"."EMP_SNAPSHOT2"', method => '?', atomic_refresh => false, out_of_place => TRUE)

PL/SQL procedure successfully completed.

После чего SYS.SNAP_REFOP$ содержит три операции:

Доклад Александра Токарева о Result Cache на семинаре RuOUG

— живой и интересный!

Несколько иллюстраций к рассказанному Александром:

Oracle 12.1: OR-Expansion and Adaptive features

На нескольких запросах столкнулись со ситуацией, когда при по умолчанию включенными optimizer_adaptive_features=true план запроса может не применять преобразование OR-Expansion, что значительно увеличивает формальную стоимость/Cost и реальное время выполнения:

12.1.0.2.@ SQL> explain plan for
  2  select *
  3    from 
...
 64  /

Explained.

SQL> select * from table(dbms_xplan.display('','','+alias -predicate'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------
Plan hash value: 1699389027

-----------------------------------------------------------------------------------------------------------
| Id  | Operation                                         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                                  |    10 | 17700 |       |  2197K  (1)| 00:00:43 |
|*  1 |  VIEW                                             |    10 | 17700 |       |  2197K  (1)| 00:00:43 |
|*  2 |   WINDOW SORT PUSHED RANK                         |    39 | 13767 |       |  2197K  (1)| 00:00:43 |
|   3 |    NESTED LOOPS OUTER                             |    39 | 13767 |       |  2197K  (1)| 00:00:43 |
...
|* 39 |      INDEX UNIQUE SCAN                            |     1 |       |       |     0   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$D48D1E2F / from$_subquery$_001@SEL$1
   2 - SEL$D48D1E2F
...

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)
   - 7 Sql Plan Directives used for this statement

114 rows selected.

Судя по трейсу 10053 оптимизатор выполняет попытки:

12c: Простейшее использование INMEMORY при обновлении Materialized View

Предварительно усилив параллельность выполнения — как несложный и действенный метод ускорения FULL SCAN-ов, HASH JOIN-ов, сокращения direct path temp read / write- операций и потребления TEMP пространства, соответственно:

12.1.0.2@ SQL> alter session force parallel QUERY parallel 32;

Session altered

, получаем:

SQL> exec dbms_mview.refresh('"BI"."MV_EXPENSES_DETAIL"', atomic_refresh => TRUE, parallelism => 32) -- parallelism => 32 - особой роли не играет, скорее как индикатор
 
PL/SQL procedure successfully completed
 
Executed in 140,578 seconds

— стартовый рез-т, SQL MONITOR которого показывает много direct path read на MAT_VIEW ACCESS FULL (*) + всё ещё заметное, несмотря на параллельное выполнение, потребление TEMP (11G) с сопутствующими direct path temp — операциями при выполнении вышележащего HASH JOIN (**):

Direct path read при обновлении матвью

Полное атомарное обновление матвью / Complete Atomic MV Refresh:

12.1.0.2.@ SQL> exec dbms_refresh.refresh('"GEORGIA"."ON_MY_MIND"')

PL/SQL procedure successfully completed.

Elapsed: 01:40:04.67

большую часть времени тратит на непараллельное выполнение запроса на вставку:

INSERT /*+ BYPASS_RECURSIVE_CHECK */ INTO "GEORGIA"."ON_MY_MIND" select * from GEORGIA.ON_MY_MIND_VIEW

, который в свою очередь, в основном ожидает db file scattered read:

Oracle 12.1.0.2: глобальное параллельное построение индекса при PARALLEL_FORCE_LOCAL=TRUE

При установленном параметре:

SQL> @param parallel_force_local
 
NAME                  VALUE  IS_DEF   IS_MOD     DSC
--------------------- ------ -------- ---------- -------------------------------
parallel_force_local  TRUE   FALSE    FALSE      force single instance execution

параллельное построение индекса легко распеределяется между нодами RAC:

12c CDB: особенности отображения блокировок, скрипт LOCK_TREE_LOCAL_CDB

В PDB snapshot copy окружении версии 12.1.0.2:

SQL> ALTER SESSION SET CONTAINER = CDB$ROOT;

Session altered.

SQL> select con_id, name from v$containers;

CON_ID NAME
------ ---------------
     1 CDB$ROOT
     2 PDB$SEED
     3 PDBCLONE0101
...
    15 PDBCLONE0113
...

18 rows selected.

Артём Горбик показал странно отображаемую сессию-блокер:

SQL> select service_name,con_id,program from gv$session where sid=4921;

SERVICE_NAME CON_ID PROGRAM
------------ ------ ----------------------
SYS$USERS         1 oracle@hostname (J017)

— формально работающую в CDB$ROOT:

SQL> select name, con_id from v$containers where con_id=1;

NAME                     CON_ID
-------------------- ----------
CDB$ROOT                      1

, и в то же время выполняющую Scheduler Job в контейнере-клоне:

SQL> select SESSION_ID,JOB_NAME,con_id from cdb_scheduler_running_jobs where session_id = 4921;

SESSION_ID JOB_NAME               CON_ID
---------- ------------------ ----------
      4921 update_mviews              15

SQL> select name, con_id from v$containers where con_id=15;

NAME                     CON_ID
-------------------- ----------
PDBCLONE0113                 15

Модифицировал под это дело скрипт (с суффиксом _CDB), добавив к инстансу/сессии (INST#/SID#4) номер контейнера — CON#: