Oracle mechanics

30.05.2013

Блокировки direct path DML

Filed under: Active Session History,commonplace,direct-path DML,Блокировки,Oracle — Игорь Усольцев @ 01:02
Tags: ,

Периодически alert.log версии 11.1.0.7 демонстрирует пакетные сообщения об ошибках ORA-00060:

Sun May 19 20:15:25 2013
ORA-00060: Deadlock detected. More info in file /opt/oracle/admin/diag/rdbms/orcl11107/orcl11107/trace/orcl11107_s000_1386.trc.
Sun May 19 20:15:26 2013
ORA-00060: Deadlock detected. More info in file /opt/oracle/admin/diag/rdbms/orcl11107/orcl11107/trace/orcl11107_s009_6543.trc.
Sun May 19 20:15:27 2013
ORA-00060: Deadlock detected. More info in file /opt/oracle/admin/diag/rdbms/orcl11107/orcl11107/trace/orcl11107_s001_3077.trc.

Причина блокировок известна — попытка одновременного выполнения нескольких транзакций на одной таблице в режиме parallel dml (alter session enable parallel dml => V$SESSION.PDML_ENABLED=’YES’, далее составляющие транзакцию 2 последовательные непараллельные операции DELETE, INSERT /*+ APPEND*/ на непартиционированной таблице TAB1) — и относится к вопросам разработки и архитектуры приложения. Интересны детали отображения и обработки Oracle блокировок типа TM Lock Requesting Mode X (6) (SX X SX X)

Кроме необходимости преобразования / эскалации блокировки TM SX -> X при переходе от DELETE к direct path insert, первый трейс не показывает ничего неожиданного:

--orcl11107_s000_1386.trc (deadlock#1)
*** SESSION ID:(809.674) 2013-05-19 20:15:25.592
...
Deadlock graph:
                       ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name          process session holds waits  process session holds waits
TM-000b664d-00000000        38     809    SX             70     711    SX     X -- 000b664d соответсвует TAB1
TX-00130022-00016c73        70     711     X             38     809           X

session 809: DID 0001-0020-00002BE6     session 711: DID 0001-0026-0000453A
session 711: DID 0001-0026-0000453A     session 809: DID 0001-0020-00002BE6

Rows waited on:
  Session 809: obj - rowid = 000B664D - AADArQADzAAFBvAAAA         -- DELETE  FROM TAB1 WHERE (FIELDDATE = TO_DATE(:
  (dictionary objn - 747085, file - 243, block - 1317824, slot - 0)-- TAB1
  Session 711: no row                                              -- INSERT /*+ APPEND */ INTO TAB1 (...) SELECT ... FROM TEMP_TABLE1
...
      Current Wait Stack:
       0: waiting for 'enq: TX - row lock contention'
...
          wait times: snap=2 min 27 sec, exc=2 min 27 sec, total=2 min 27 sec
...
      There is at least one session blocking this session.                   -- всё выглядит как в классическом deadlock
      Dumping one blocker:
        inst: 1, sid: 711, ser: 3773                                         -- SID 809 блокирован сессией 711
      There is at least one session blocked by this session.
      Dumping one waiter:
        inst: 1, sid: 711, ser: 3773                                         -- и блокирует ту же сессию 711
        wait event: 'enq: TM - contention'
...
      ---------------------------------------------------
      Sampled Session History Summary:
        longest_non_idle_wait: 'enq: TX - row lock contention'
        [121 samples, 20:13:25 - 20:15:25]
            time_waited: >= 120 sec (still in wait)                          -- время последнего ожидания SID 809 120 секунд
      ---------------------------------------------------

Post factum мониторинг блокоровок по записям ASH отражает общую до момента возниктовения первого deadlock с 20:13:25 по 20:15:25:

11.1.0.7.@ SQL> @ash_lock3 "20130519 20:13:25" "20130519 20:15:26"

LVL BLOCKING_TREE          START_WT STOP_WTI XID              EVENT                         Lock_Mode    BLOCKER      OBJECT_NAME  WAITS_COUNT SQL_PLAN_OPERATION  SQL_TEXT
--- ---------------------- -------- -------- ---------------- ----------------------------- ------------ ------------ ------------ ----------- ------------------- ----------------------------------------
  1   703,4460             20:13:25 20:15:25                  enq: TX - row lock contention              765,9226     TABLE TAB1           121 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
**1   711,3773             20:13:34 20:15:06 13002200736C0100 read by other session                      765,9226     INDEX IDX1            38 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
* 1   711,3773             20:15:24 20:15:25 13002200736C0100 enq: TM - contention          TM 6         809,674      TABLE TAB1             2 INSERT STATEMENT
**1   765,9226             20:13:25 20:15:07 120001004D9C0100 read by other session                      711,3773     INDEX IDX1            57 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
* 1   809,674              20:13:25 20:15:25                  enq: TX - row lock contention              711,3773     TABLE TAB1           121 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
  2     711,3773           20:13:25 20:15:07 13002200736C0100 db file sequential read                    ,            INDEX IDX1            63 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
**2     711,3773           20:13:34 20:15:06 13002200736C0100 read by other session                      765,9226     INDEX IDX1            38 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
* 2     711,3773           20:15:24 20:15:25 13002200736C0100 enq: TM - contention          TM 6         809,674      TABLE TAB1             2 INSERT STATEMENT
**2     765,9226           20:13:25 20:15:07 120001004D9C0100 read by other session                      711,3773     INDEX IDX1            57 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
  2     765,9226           20:13:27 20:15:06 120001004D9C0100 db file sequential read                    ,            INDEX IDX1            43 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
  2     765,9226           20:13:38 20:13:38 120001004D9C0100 read by other session                      ,            INDEX IDX1             1 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
* 2     809,674            20:15:24 20:15:25                  enq: TX - row lock contention              711,3773     TABLE TAB1             2 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
  3       711,3773         20:13:25 20:15:07 13002200736C0100 db file sequential read                    ,            INDEX IDX1            57 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
  3       765,9226         20:13:34 20:15:06 120001004D9C0100 db file sequential read                    ,            INDEX IDX1            37 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =

*) — собственно взаимная блокировка сессий 711 и 809 продолжалась не более 19 секунд, с 20:15:07 по 20:15:25

**) — с 20:13:25 до 20:15:06 сессия 711 в рамках одной транзакции (судя по XID) читает индекс IDX1, периодически мирно блокируясь пересекаясь по чтению с сессией 765 (read by other session), выполняющей аналогичную операцию DELETE. При этом, судя по выше и ниже приведённым графам, обе сессии 711 и 765 удерживают обычную в случае DELETE TM блокировку уровня 3(SX) на таблицу TAB1. По данным ASH эти сессии читают индекс IDX1, отличный от индекса IDX2, по которому выполнялся доступ:

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | DELETE STATEMENT  |      |       |       |     6 (100)|          |
|   1 |  DELETE           | TAB1 |       |       |            |          |
|   2 |   INDEX RANGE SCAN| IDX2 |  4087 |   518K|     6   (0)| 00:00:01 |
--------------------------------------------------------------------------

— т.е. занимаются перестройкой индекса IDX1 в обычном conventional режиме после выполнения DELETE

Срабатывание механизма deadlock в этот момент даёт возможность сессии 711 завершить начатую транзакцию — выполнить INSERT /*+ APPEND */ после уже выполненного DELETE

Трейс второй блокировки:

--orcl11107_s009_6543.trc (deadlock#2)
*** SESSION ID:(703.4460) 2013-05-19 20:15:26.212
...
Deadlock graph:
                       ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name          process session holds waits  process session holds waits
TM-000b664d-00000000        32     703    SX             38     765    SX     X
TX-00120001-00019c4d        38     765     X             32     703           X

session 703: DID 0001-0047-00003BCF     session 765: DID 0001-004D-00002A1E
session 765: DID 0001-004D-00002A1E     session 703: DID 0001-0047-00003BCF

Rows waited on:
  Session 703: obj - rowid = 000B664D - AADArQADzAAFCXAAAA         -- DELETE  FROM TAB1 WHERE (FIELDDATE = TO_DATE(:
  (dictionary objn - 747085, file - 243, block - 1320384, slot - 0)
  Session 765: no row                                              -- INSERT /*+ APPEND */ INTO TAB1 (...) SELECT ... FROM TEMP_TABLE2
...
      Current Wait Stack:
       0: waiting for 'enq: TX - row lock contention'
...
          wait times: snap=3 min 9 sec, exc=3 min 9 sec, total=3 min 9 sec
...
      There is at least one session blocking this session.                 -- SID 703
      Dumping one blocker:
        inst: 1, sid: 765, ser: 9226                                       -- блокирован сессией 765, как и следует из Deadlock graph,
      There is at least one session blocked by this session.
      Dumping one waiter:
        inst: 1, sid: 711, ser: 3773                                       -- но блокирует ещё и сессию 711
        wait event: 'enq: TM - contention'
...
      ---------------------------------------------------
      Sampled Session History Summary:
        longest_non_idle_wait: 'enq: TX - row lock contention'
        [120 samples, 20:13:26 - 20:15:25]
            time_waited: >= 119 sec (still in wait)
      ---------------------------------------------------

также не показывает ничего странного, кроме второй сессии 711, также как и 765 блокированной SID 703:

SQL> @ash_lock3 "20130519 20:15:26" "20130519 20:15:27"

LVL BLOCKING_TREE  START_WT STOP_WTI XID              EVENT                              Lock_Mode BLOCKER  OBJECT_NAME   WAITS_COUNT SQL_PLAN_OPERATION  SQL_TEXT
--- -------------- -------- -------- ---------------- ---------------------------------- --------- -------- ------------- ----------- ------------------- ----------------------------------------
1   703,4460       20:15:26 20:15:26                  enq: TX - row lock contention                765,9226    TABLE TAB1           1 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
1   711,3773       20:15:26 20:15:26 13002200736C0100 enq: TM - contention               TM 6      703,4460    TABLE TAB1           1 INSERT STATEMENT
1   765,9226       20:15:26 20:15:26 120001004D9C0100 enq: TM - contention               TM 6      703,4460    TABLE TAB1           1 INSERT STATEMENT
2     703,4460     20:15:26 20:15:26                  enq: TX - row lock contention                765,9226    TABLE TAB1           1 DELETE              DELETE  FROM TAB1 WHERE (FIELDDATE =
2     765,9226     20:15:26 20:15:26 120001004D9C0100 enq: TM - contention               TM 6      703,4460    TABLE TAB1           1 INSERT STATEMENT

В результате второго срабатывания deadlock сессии 765 также получила возможность завершить начатую транзакцию (с уже выполненным DELETE). И в первом, и во втором случае «пострадали» сессии, выполнявшие первый запрос транзакции, а «выигрывали» — уже выполнившие первый dml

Третий трейс показывает «чистую» TM блокировку direct path insert:

--orcl11107_s001_3077.trc (deadlock#3)
*** SESSION ID:(711.3773) 2013-05-19 20:15:27.031
...
Deadlock graph:
                       ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name          process session holds waits  process session holds waits
TM-000b664d-00000000        70     711    SX     X       38     765    SX     X
TM-000b664d-00000000        38     765    SX     X       70     711    SX     X

session 711: DID 0001-0026-0000453A     session 765: DID 0001-004D-00002A1E
session 765: DID 0001-004D-00002A1E     session 711: DID 0001-0026-0000453A

Rows waited on:
  Session 711: no row    -- INSERT /*+ APPEND */ INTO TAB1 (...) SELECT ... FROM TEMP_TABLE1
  Session 765: no row    -- INSERT /*+ APPEND */ INTO TAB1 (...) SELECT ... FROM TEMP_TABLE2
...
      Current Wait Stack:
       0: waiting for 'enq: TM - contention'
          name|mode=544d0006, object #=b664d, table/partition=0
          wait_id=51459 seq_num=5747 snap_id=1
          wait times: snap=3.004426 sec, exc=3.004426 sec, total=3.004426 sec -- таймаут 3 сек
          wait times: max=infinite
          wait counts: calls=1 os=1
          in_wait=1 iflags=0x15a0
      There is at least one session blocking this session.
      Dumping one blocker:
        inst: 1, sid: 809, ser: 674                                           -- SID 711 блокирован сессией 809
      There is at least one session blocked by this session.
      Dumping one waiter:
        inst: 1, sid: 809, ser: 674                                           -- и блокирует сессию 809, что интересно
        wait event: 'enq: TX - row lock contention'
...
      sample interval: 1 sec, max history 120 sec
      ---------------------------------------------------
        [3 samples,                                        20:15:24 - 20:15:26] -- тут SID 711 пытается получить блокировку,
          waited for 'enq: TM - contention', seq_num: 5747                      -- чтобы начать выполнять INSERT /*+ APPEND */
            p1: 'name|mode'=0x544d0006
            p2: 'object #'=0xb664d
            p3: 'table/partition'=0xb664d
            time_waited: >= 2 sec (still in wait)
        [13 samples,                                       20:15:11 - 20:15:23]
          idle wait at each sample
        [1 sample,                                                    20:15:10]
          not in wait at each sample
        [1 sample,                                                    20:15:09]
          idle wait at each sample
        [1 sample,                                                    20:15:08]
          not in wait at each sample
        [1 sample,                                                    20:15:07] -- похоже в этот момент SID 711 завершил перестроение индексов после DELETE
          waited for 'db file sequential read', seq_num: 4238
...
      ---------------------------------------------------
      Sampled Session History Summary:
        longest_non_idle_wait: 'enq: TM - contention'
        [3 samples, 20:15:24 - 20:15:26]
            time_waited: >= 2 sec (still in wait)                               
      ---------------------------------------------------

— SID 809, уже был «отработанный» в процессе deadlock#1 и завершающий откат, по-прежнему удерживает TM mode 3, блокируя SID 711 — что подтверждается данными ASH:

SQL> @ash_lock3 "20130519 20:15:27" "20130519 20:16:59"

LVL   BLOCKING_TREE  START_WT STOP_WTI XID              EVENT                    Lock_Mode BLOCKER  OBJECT_NAME    WAITS_COUNT SQL_PLAN_OPERATION  SQL_TEXT
----- -------------- -------- -------- ---------------- ------------------------ --------- -------- -------------- ----------- ------------------- --------
  1   711,3773       20:15:27 20:15:27 13002200736C0100 enq: TM - contention     TM 6      809,674     TABLE TAB1            1 INSERT STATEMENT
* 1   765,9226       20:15:27 20:16:58 120001004D9C0100 enq: TM - contention     TM 6      711,3773    TABLE TAB1           92 INSERT STATEMENT
  2     711,3773     20:15:27 20:15:27 13002200736C0100 enq: TM - contention     TM 6      809,674     TABLE TAB1            1 INSERT STATEMENT
* 2     711,3773     20:15:29 20:16:58 13002200736C0100 db file sequential read            ,                                89

*) примечательно, что сессия 711, продолжая выполнять первоначальную транзацию XID 13002200736C0100, также уже после срабатывания deadlock#3 с 20:15:27 до 20:16:58 (т.е. как минимум полуторы минуты), не выполняя видимых в ASH запросов, продолжает блокировать SID 765 — вероятно читая undo в процессе отката

В качестве иллюстрации последствий массированного использования parallel dml можно оценить долю времени, которая тратится на ожидания блокировок в процессе вышеописанного DELETE:

SQL> @ash_sqlmon fjsb8zv2c30dd "" ""

ID PLAN_OPERATION          OBJECT_NAME  COST CARDINALITY WAIT_PROFILE
-- ----------------------- ------------ ---- ----------- --------------------------------------------------------------------------------------------------------------------------------------------
 0   DELETE STATEMENT                      6             enq: TM - contention(6845);
 1     DELETE              TAB1                          db file sequential read(2677); read by other session(2233); enq: TX - row lock contention(1484); ON CPU(122); log file switch completion(2);
 2       INDEX RANGE SCAN  IDX2            6        4087 db file sequential read(24);

Добавить комментарий »

Комментариев нет.

RSS feed for comments on this post. TrackBack URI

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

Создайте бесплатный сайт или блог на WordPress.com.

%d такие блоггеры, как: