Oracle mechanics

30.11.2016

12c: Log File Sync, параметр _DB_MTTR_ADVICE и опасности увеличения кол-ва LGWR-workers

Filed under: Диагностика системы (instance),Oracle — Игорь Усольцев @ 22:57
Tags: , ,

После switchover-а на аналогичное железо в разы выросло время ожидания log file sync:

12.1.0.2@ SQL> @ash_wait_tree "event = 'log file sync'" 0 "where inst_id = 1"
 
LVL BLOCKING_TREE         EVENT                         WAIT_CLASS WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- --------------------- ----------------------------- ---------- ----------- ---------- ------ ---------- ------------------
  1 (FOREGROUND)          log file sync                 Commit           37104       2019    395    1992400                 19 -- ну не 19 мс, конечно, но точно > 10 мс - недопустимо долго
  1 (J...)                log file sync                 Commit              37         35      0          0               1000
  2   (LGWR)              LGWR any worker group         Other            31107          1    518     134101                231 -- осн.блокер для log file sync
  2   (LGWR)              target log write size         Other             4053          1      7    1898397                  2
  2   (LGWR)              LGWR all worker groups        Other             1137          1    187      59184                 19
  2   (LGWR)              On CPU / runqueue                                 54          1      0          0               1000
  2   (LGWR)              enq: CF - contention          Other               19          1    316         60                317
  2   (LGWR)              control file sequential read  System I/O          12          1      1      10607                  1
  2   (LGWR)              control file parallel write   System I/O           7          1      1       6261                  1
  3     (LG..)            LGWR wait for redo copy       Other            25103          1    606      73038                340 -- осн.блокер для LGWR any worker group *
  3     (LG..)            log file parallel write       System I/O        6290          1    209     200335                 31
  3     (LG..)            LGWR worker group ordering    Other              406          1    223       2500                162
  4       (FOREGROUND)    On CPU / runqueue                              21073        354      0          0               1000
  4       (J...)          On CPU / runqueue                               3908         21      0          0               1000
  4       (LG..)          log file parallel write       System I/O         230          1    228       1014                227
  4       (LG..)          LGWR wait for redo copy       Other              176          1    198       1391                127
  4       (Q...)          On CPU / runqueue                                122          1      0          0               1000
  5         (FOREGROUND)  On CPU / runqueue                                176          4      0          0               1000

— при этом в качестве важного промежуточного блокера в вышеприведённой цепочке по частоте и продолжительности неожиданно проявилось LGWR wait for redo copy (*), что было отчётливо заметно в цепочке ожиданий, начиная с LGWR any worker group:

SQL> @ash_wait_tree "event = 'LGWR any worker group'" 0 "where inst_id = 1"
 
LVL BLOCKING_TREE         EVENT                         WAIT_CLASS WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- --------------------- ----------------------------- ---------- ----------- ---------- ------ ---------- ------------------
  1 (LGWR)                LGWR any worker group         Other              775          1    398       5161                150
  2   (LG..)              LGWR wait for redo copy       Other              605          1    475       2480                242 -- осн.блокер для LGWR any worker group *
  2   (LG..)              log file parallel write       System I/O         160          1    195       4362                 37
  2   (LG..)              LGWR worker group ordering    Other               10          1    201         72                139
  3     (FOREGROUND)      On CPU / runqueue                                505        354      0          0               1000
  3     (J...)            On CPU / runqueue                                 98         21      0          0               1000
  3     (LG..)            log file parallel write       System I/O           6          1    227         27                222
  3     (LG..)            LGWR wait for redo copy       Other                4          1    145         42                 95
  3     (Q...)            On CPU / runqueue                                  2          1      0          0               1000
  4       (FOREGROUND)    On CPU / runqueue                                  4          4      0          0               1000
 
SQL> -- в то же время, цепочка ожиданий, начиная с LGWR wait for redo copy выглядит вполне предсказуемо:
SQL> @ash_wait_tree "event = 'LGWR wait for redo copy'" 0 "where inst_id = 1"
 
LVL BLOCKING_TREE         EVENT                         WAIT_CLASS WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- --------------------- ----------------------------- ---------- ----------- ---------- ------ ---------- ------------------
  1 (LG..)                LGWR wait for redo copy       Other              828          2    368     201130                  4 -- *
  2   (FOREGROUND)        On CPU / runqueue                                668        451      0          0               1000 -- логично блокируется ForeGround
  2   (J...)              On CPU / runqueue                                146         26      0          0               1000 -- и [Scheduler] Job процессами
  2   (J...)              db file sequential read       User I/O             2          1      0       4525                  0
  2   (FOREGROUND)        gc current grant busy         Cluster              2          2      1       3467                  1
  2   (Q...)              On CPU / runqueue                                  2          1      0          0               1000
  2   (M...)              On CPU / runqueue                                  1          1      0          0               1000

Ожидания log file parallel write и другие I/O related при этом переключении ни по кол-ву, ни по продолжительности никак не изменились

Несмотря на неполное совпадение симптомов (в частности, _DB_MTTR_ADVICE всегда был в default положении ON, никаких переключений READY -> ON не было), коллега Руслан Бикбаев точно определил совпадение симптомов с Increased Waits for ‘log file sync’ and ‘LGWR wait for redo copy’ Following Failover with MTTR Advisory set to ON (Doc ID 1968974.1) и решил проблему рекомендованным способом:

SQL> alter system set "_db_mttr_advice" = READY;

System altered

— т.е. default значение _db_mttr_advice оказывается неожиданно небезопасным и может сыграть роль «мины замедленного действия», активизированной тривиальной операцией switchover

После изменения _db_mttr_advice ожидания log file sync вернулись к нормальной продолжительности (и столбец EST_AVG_LATENCY_MS здесь адекватно отражает ср.значение), LGWR wait for redo copy практически исчезли, вернув профиль ожиданий log file sync к привычному виду:

SQL> @ash_wait_tree "event = 'log file sync'" 0 "where inst_id = 1"
 
LVL BLOCKING_TREE         EVENT                         WAIT_CLASS WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- --------------------- ----------------------------- ---------- ----------- ---------- ------ ---------- ------------------
  1 (FOREGROUND)          log file sync                 Commit            8185       6124    143    3294662                  2 -- разные польз.процессы
  1 (J...)                log file sync                 Commit              20         20      0          0               1000 -- в ожидании log file sync
  1 (M...)                log file sync                 Commit               1          1      0          0               1000
  2   (LGWR)              LGWR any worker group         Other             2807          1    170      21129                133 -- блокированы на ожиданиях worker group(s)
  2   (LGWR)              target log write size         Other             2412          1      5    1899257                  1 -- и target log write size
  2   (LGWR)              LGWR all worker groups        Other             1654          1    299      12009                138
  2   (LGWR)              control file sequential read  System I/O          32          1    128      12596                  3
  2   (LGWR)              On CPU / runqueue                                 27          1      0          0               1000
  2   (LGWR)              Disk file Mirror Read         User I/O            24          1    122       9587                  3
  2   (LGWR)              control file parallel write   System I/O           5          1      1       7931                  1
  2   (LGWR)              enq: CF - contention          Other                1          1    257          4                250
  2   (LGWR)              rdbms ipc message             Idle                 1          1      2        657                  2
  3     (LG..)            log file parallel write       System I/O        4233          1    263      22355                189 -- , ожидающих на System I/O
  3     (LG..)            LGWR worker group ordering    Other               93          1    191        488                191
  3     (LG..)            On CPU / runqueue                                 44          1      0          0               1000
  3     (CKPT)            control file parallel write   System I/O           1          1    249          4                250
  4       (LG..)          log file parallel write       System I/O          56          1    202        278                201
 
SQL> @ash_wait_tree "event in ('LGWR all worker groups','LGWR any worker group')" 0 "where inst_id = 1"
 
LVL BLOCKING_TREE         EVENT                         WAIT_CLASS WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- --------------------- ----------------------------- ---------- ----------- ---------- ------ ---------- ------------------
  1 (LGWR)                LGWR any worker group         Other              199          1    165       1477                135 -- ожидания worker group(s)
  1 (LGWR)                LGWR all worker groups        Other              150          1    195       9519                 16 -- , в свою очередь, 
  2   (LG..)              log file parallel write       System I/O         332          1    221       7641                 43 -- ожидают завершения записи логов
  2   (LG..)              LGWR worker group ordering    Other                3          1    193         16                188
  2   (LG..)              On CPU / runqueue                                  2          1      0          0               1000
  3     (LG..)            log file parallel write       System I/O           2          1    206         10                200

Но до этого, в процессе поиска способов уменьшения log file sync, были использованы разные подходы, в том числе и увеличение кол-ва LGWR-worker-ов, что позже, похоже, сыграло с нами злую шутку в виде instance hang, к счастью, подробно записанному славным процессом DIAG, который performs diagnostic dumps requested by other processes and dumps triggered by process or instance termination с уровнем:

SQL> @param_ _diag_crashdump_level
 
NAME                   VALUE  IS_DEF  DSC
---------------------- ------ ------- ---------------------------------------------------------------
_diag_crashdump_level  10     TRUE    parameter for systemstate dump level, used by DIAG during crash

и которому системный процесс (LMD0 в этом случае), занимавшийся экстренной терминацией инстанса по причине отстреливания одного из системных процессов (поскольку при зависшем даже LGWR shutdown abort выполняется небыстро), дал 5 секундный таймаут для записи диагностической информации:

*** 2016-10-13 14:19:08.072
LMD0 (ospid: 7207): terminating the instance due to error 472
...
*** 2016-10-13 14:19:09.590
ksuitm: waiting up to [5] seconds before killing DIAG(7192) -- приятная забота о диагностике)

Содержимымое сформированного т.о. DIAG-трейса типа during crash подробно описывает причины instance hang:

$ less orcl1212_diag_7192_20161013141908.trc

PROCESS 27: LGWR
  ----------------------------------------
...
    Current Wait Stack:
     0: waiting for 'LGWR any worker group'                                    -- ожидание LGWR
        =0x0, =0x0, =0x0
        wait_id=281874130 seq_num=19111 snap_id=1
        wait times: snap=31 min 48 sec, exc=31 min 48 sec, total=31 min 48 sec -- со временем ожидания 30+ минут!!!
        wait times: max=infinite, heur=31 min 48 sec
        wait counts: calls=5 os=635
        in_wait=1 iflags=0x15a0
    There is at least one session blocking this session.
      Dumping first 3 direct blockers:
        inst: 1, sid: 4119, ser: 32303                                         -- LG00
        inst: 1, sid: 4403, ser: 24496                                         -- LG01
        inst: 1, sid: 143, ser: 43198                                          -- LG02
      Dumping final blocker:
        inst: 1, sid: 428, ser: 32733                                          -- LG03
    There are 158 sessions blocked by this session.
    Dumping one waiter:
      inst: 1, sid: 2027, ser: 19939
      wait event: 'log file sync'                                              -- все процессы ждут от LGWR
        p1: 'buffer#'=0x20f3
        p2: 'sync scn'=0x97ca3a2f
        p3: ''=0x0
...
PROCESS 29: LG00                                                               -- один из direct blockers
  ----------------------------------------
...
    (latch info) hold_bits=0x0
      Waiting For:
        0x60028628 Child 'log write slave phase' (level=1, child#=2)           -- latch name
        Holder Location: kcrfh.h LINE:5124 ID:kcrfw_slave_phase_enter: phase
        Holder Context: 1
        Waiter Location: kcrfh.h LINE:5129 ID:kcrfw_slave_phase_exit: phase
        Waiter Context: 1
        Latch State:
          state=busy [value=0x23]
          holder orapid=35, ospid=7266                                         -- holded by LG03
          wlstate=free [value=0]
          waiters [orapid (seconds since: put on list, posted, alive check)]:
            29 (1905, *, 1799)
            31 (1905, *, 1905)
            33 (1006, *, 1006)
            waiter count=3
          gotten 2310992 times wait, failed first 8863 sleeps 5
          gotten 0 times nowait, failed 0
...
    service name: SYS$BACKGROUND
    Current Wait Stack:
     0: waiting for 'latch free'                                               -- соотв.ожидание
        address=0x60028628, number=0x111, tries=0x0
        wait_id=341686902 seq_num=53460 snap_id=1
        wait times: snap=31 min 48 sec, exc=31 min 48 sec, total=31 min 48 sec -- с соотв.временем
        wait times: max=infinite, heur=31 min 48 sec
        wait counts: calls=0 os=0
        in_wait=1 iflags=0x2520
    There is at least one session blocking this session.
      Dumping 1 direct blocker(s):
        inst: 1, sid: 428, ser: 32733                                          -- direct blocker - LG03
      Dumping final blocker:
        inst: 1, sid: 428, ser: 32733
    There are 159 sessions blocked by this session.
    Dumping one waiter:
      inst: 1, sid: 3835, ser: 23208
      wait event: 'LGWR any worker group'                                      -- и этот one waiter - LGWR
...
PROCESS 35: LG03                                                               -- final blocker
  ----------------------------------------
...
    (latch info) hold_bits=0x2
      Holding:
        0x60028628 Child 'log write slave phase' (level=1, child#=2)           -- LG03 simple holds the latch
        Holder Location: kcrfh.h LINE:5124 ID:kcrfw_slave_phase_enter: phase
        Holder Slot: slot=1, efd=3, pdb=0
        Holder Context: 1
        Latch State:
          state=busy [value=0x23]
          holder orapid=35, ospid=7266
          wlstate=free [value=0]
          waiters [orapid (seconds since: put on list, posted, alive check)]:
            29 (1905, *, 1799)                                                 -- LG03 blocks LG00
            31 (1905, *, 1905)                                                 --            ,LG01
            33 (1006, *, 1006)                                                 --            ,LG02
            waiter count=3
...
    (session) sid: 428 ser: 32733 trans: (nil), creator: 0x2bf90eea40
...
    service name: SYS$BACKGROUND
    Current Wait Stack:
      Not in wait; last wait ended 31 min 48 sec ago                           -- LG03 not in wait for 31 min 48 sec (on CPU)
    There are 162 sessions blocked by this session.
    Dumping one waiter:
      inst: 1, sid: 3835, ser: 23208
      wait event: 'LGWR any worker group'                                      -- one waiter - LGWR again
        p1: ''=0x0
        p2: ''=0x0
        p3: ''=0x0
      row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
      min_blocked_time: 801 secs, waiter_cache_ver: 49472
    Wait State:
      fixed_waits=0 flags=0x20 boundary=(nil)/-1
    Session Wait History:
        elapsed time of 31 min 48 sec since last wait
     0: waited for 'log file parallel write'                                   -- последнее зафиксированное разумное ожидание LG03

— интересен latch типа log write slave phase, на котором в состоянии On CPU / runqueue «задумался» на 30+ минут конечный блокер LG03

Для нашей системы решением было возвращение кол-ва _max_outstanding_log_writes к default значению, что отразилось в уменьшении кол-ва LGWR-workers с 4 до 2-х, SR заводить не стали по причине

P.S. Другим признаком приближения проблем, по моим наблюдениям, могут быть циклические ожидания LGWR worker group ordering между LG-worker процессами в трейсе другого полезного монитора LMHB типа:

==============================
LG03 (ospid: 7266) has not moved for 21 sec (1476355558.1476355537)
  : heartbeat check status 2 (acceptable) (threshold 70 sec)
  : heartbeat state 0x1.ffff (inwait) pso-flag 0x0
  : waiting for event 'LGWR worker group ordering' for 20 secs with wait_id 855610.
  ===[ Wait Chain ]===
  LG03 (ospid: 7266) waits for event 'LGWR worker group ordering'.
  LG00 (ospid: 7252) waits for event 'LGWR worker group ordering'.
  LG01 (ospid: 7258) waits for event 'LGWR worker group ordering'.
  LG00 (ospid: 7252) waits for event 'LGWR worker group ordering'.
  A cycle is detected.

— по ключевым словам находятся ряд похожих багов для 12.1.0.2, правда, для AIX Power платформы:

Bug 21915719 : LGWR AND ITS SLAVES HANG WAITING FOR ‘LGWR ANY WORKER GROUP’ (базовый, исправлен в 12.1.0.2.DBBP:160419 / 12.1.0.2.160419 DB PSU(Apr 2016)
Bug 19181582 : DEADLOCK BETWEEN LG0N ON LGWR WORKER GROUP ORDERING
Bug 21135739 : DEADLOCK BETWEEN LG00 AND LG01 ON ‘LGWR WORKER GROUP ORDERING’

— где в качестве быстрого варианта решения рекомендуется полный отказ от LGWR-worker-ов в виде установки _use_single_log_writer = TRUE — похоже, что пока использование множественных LGWR-workers пока находится в процессе живой активной разработки, imho

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

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

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 такие блоггеры, как: