Oracle mechanics

24.08.2016

12c, адаптивный LGWR: ожидания log file sync и target log write size

Из более-менее традиционной картинки ожиданий log file sync:

12.1.0.2@ SQL> @ash_wait_tree "event = 'log file sync' and inst_id = 1"
 
LVL INST_ID BLOCKING_TREE     WAIT_CLASS  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ----------- ----------------------------- ----------- ---------- ------
  1       1 (FOREGROUND)      Commit      log file sync                       10992       6879    130 -- польз.процессы
  1       1 (J...)            Commit      log file sync                          13         13      0 -- и Job-ы ожидают LGWR
  2       1   (LGWR)          Other       LGWR any worker group                4675          1    190 -- , висящий, восновном,
  2       1   (LGWR)          Other       target log write size                3880          1      4 -- на этих 3-х ожиданиях
  2       1   (LGWR)          Other       LGWR all worker groups                691          1    265 -- и облокируемый
  2       1   (LGWR)                      On CPU / runqueue                      61          1      0
...
  3       1     (LG..)        System I/O  log file parallel write              5064          1    217 -- LGWR-worker-ами (LG..)
  3       1     (LG..)        Other       LGWR worker group ordering            129          1    223
  3       1     (FOREGROUND)              On CPU / runqueue                       2          1      0
  4       1       (LG..)      System I/O  log file parallel write               129          1    347

— можно предположить, что для уменьшения log file sync достаточно сократить время/кол-во блокирующих ожиданий LGWR any worker group/LGWR all worker groups и target log write size, распределённых в этом случае приблизительно поровну

И если первая группа ожиданий очевидно «упирается» в кол-во/скорость работы LGWR-worker-ов, обозначенных как (LG..):

SQL> @ash_wait_tree "event = 'LGWR any worker group' and inst_id = 1"
 
LVL INST_ID BLOCKING_TREE     WAIT_CLASS  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ----------- ----------------------------- ----------- ---------- ------
  1       1 (LGWR)            Other       LGWR any worker group                 302          1    180 -- ожидает
  2       1   (LG..)          System I/O  log file parallel write               295          1    208 -- блокирует
  2       1   (LG..)          Other       LGWR worker group ordering              7          1    234
  3       1     (LG..)        System I/O  log file parallel write                 7          1    298
 
SQL> @ash_wait_tree "event = 'LGWR all worker groups' and inst_id = 1"
 
LVL INST_ID BLOCKING_TREE     WAIT_CLASS  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ----------- ----------------------------- ----------- ---------- ------
  1       1 (LGWR)            Other       LGWR all worker groups                 56          1    193 -- ожидает
  2       1   (LG..)          System I/O  log file parallel write                43          1    180 -- блокирует
  2       1   (LG..)          Other       LGWR worker group ordering              2          1    195
  3       1     (LG..)        System I/O  log file parallel write                 2          1    419

, то последнее ожидание target log write size, присутствуя изрядным числом, никак не обозначает блокеров в ASH:

SQL> @ash_wait_tree "event = 'target log write size' and inst_id = 1"
 
LVL INST_ID BLOCKING_TREE     WAIT_CLASS  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ----------- ----------------------------- ----------- ---------- ------
  1       1 (LGWR)            Other       target log write size                2489          1      2

По поводу последнего прочёл у Frits Hoogland следующее короткое наблюдение:

In scalable mode:
• I suspended execution of the slaves.	
• After	some time, this is noticed by LGWR:	
•• Wait ‘target log write size’.	
•• Wait ‘LGWR all worker groups’.

, подразумевающее, что LGWR worker-ы (slaves) выступают блокерами и для target log write size, что даёт надежду на простой путь сокращения ожиданий в цепочке log file sync -> LGWR -> LGWR workers (LG..) — через увеличение кол-ва процессов LGWR workers, например

Для проверки связи между target log write size и LGWR workers процессами на тестовой машинке с LGWR в scalable mode:

SQL> @param_ _use_single_log_writer
 
NAME                    VALUE     IS_DEF   IS_MOD     IS_ADJ   DSC
----------------------- --------- -------- ---------- -------- -----------------------------------------
_use_single_log_writer  ADAPTIVE  TRUE     FALSE      FALSE    Use a single process for redo log writing

, предварительно создал для LGWR транзакционную нагрузку, дабы запустить использование worker-ов(*):

*** 2016-08-12 19:05:58.777
Adaptive scalable LGWR disabling workers -- были отключены
...
*** 2016-08-19 11:51:25.009
Adaptive scalable LGWR enabling workers  -- включились при появлении нагрузки

Далее, не снимая транзакционной нагрузки и выполнив oradebug suspend/resume для worker-ов на определённое время:

*** 2016-08-19 12:04:29.316
Received ORADEBUG command (#3) 'suspend' from process '27319'
...
*** 2016-08-19 12:07:35.349
Received ORADEBUG command (#6) 'resume' from process '27319'

*** 2016-08-19 12:07:35.349
Finished processing ORADEBUG command (#6) 'resume'

*** 2016-08-19 12:07:35.349
Finished processing ORADEBUG command (#6) 'suspend'

— можно видеть, опять же по данным ASH, что пока процессы LGWR workers were suspended, ничего кроме LGWR any worker group в ожиданиях LGWR не отразилось:

SQL> select session_state, event, count(*)
  2    from v$active_session_history
  3   where program like '%LGWR%'
  4     and sample_time between
  5         to_date('2016-08-19 12:04:30', 'yyyy-mm-dd hh24:mi:ss') and
  6         to_date('2016-08-19 12:07:35', 'yyyy-mm-dd hh24:mi:ss')
  7   group by session_state, event
  8   order by count(*) desc
  9  /
 
SESSION_STATE EVENT                          COUNT(*)
------------- ---------------------------- ----------
WAITING       LGWR any worker group               185

ASH — вещь полезная, но не точная и с большими интервалами измерений, смотрим лог диагностического процесса DIA0, уже успевшего зафиксировать блокировки:)

Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'LGWR worker group idle'<='LGWR any worker group'<='log buffer space'<='buffer busy waits'
     Chain 1 Signature Hash: 0x468a4ab8
 [b] Chain 2 Signature: 'LGWR worker group idle'<='LGWR any worker group'<='log buffer space'
     Chain 2 Signature Hash: 0xcf41e489
 [c] Chain 3 Signature: 'LGWR worker group idle'<='LGWR any worker group'<='log buffer space'<='enq: SQ - contention'
     Chain 3 Signature Hash: 0xfeee20f4

— LGWR workers ждут LGWR worker group idle, блокируя LGWR на LGWR any worker group (, далее в Wait Chains — пользовательские процессы)

Аналогично успевает сработать LMHB (Global Cache/Enqueue Service Heartbeat Monitor), зафиксировав длительное зависание LGWR
и соответствующие Wait Chains:

*** 2016-08-19 12:05:46.508
==============================
LGWR (ospid: 16719) has not moved for 82 sec (1471597546.1471597464)
  : heartbeat check status 6 (no-heartbeat) (threshold 70 sec)
==================================================
=== LGWR (ospid: 16719) Heartbeat Report
==================================================
LGWR (ospid: 16719) has no heartbeats for 82 sec. (threshold 70)
  : heartbeat state 0x1.ffff (inwait) pso-flag 0x0
  : waiting for event 'LGWR any worker group' for 81 secs with wait_id 7036329.
===[ Wait Chain ]===
LGWR (ospid: 16719) waits for event 'LGWR any worker group'.
LG00 (ospid: 16723) waits for event 'LGWR worker group idle'.
==============================
Dumping PROCESS LGWR (ospid: 16719) States
==============================
...
  sample interval: 1 sec, max history 120 sec
  ---------------------------------------------------
    [82 samples,                                           12:04:25 - 12:05:46]
      waited for 'LGWR any worker group', seq_num: 24090
        p1: ''=0x0
        p2: ''=0x0
        p3: ''=0x0
        time_waited: >= 81 sec (still in wait)
    [5 samples,                                            12:04:20 - 12:04:24]
      idle wait at each sample
    [1 sample,                                                        12:04:19] -- **
      waited for 'target log write size', seq_num: 23626                        -- **
        p1: ''=0x0
        p2: ''=0x0
        p3: ''=0x0
        time_waited: 0.000818 sec (sample interval: 0 sec)
    [33 samples,                                           12:03:46 - 12:04:18]
      idle wait at each sample
  ---------------------------------------------------
  Sampled Session History Summary:
    longest_non_idle_wait: 'LGWR any worker group'
    [82 samples, 12:04:25 - 12:05:46]
        time_waited: >= 81 sec (still in wait)
  ---------------------------------------------------

— где хоть и фиксируется target log write size(**), но в последний раз в момент 12:04:19](**), предшествующий приостановке процессов LG00/LG01

Т.о., возвращаясь к первому скрипту:

SQL> @ash_wait_tree "event = 'log file sync' and inst_id = 1"
 
LVL INST_ID BLOCKING_TREE     WAIT_CLASS  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ----------- ----------------------------- ----------- ---------- ------
  1       1 (FOREGROUND)      Commit      log file sync                       10992       6879    130
  1       1 (J...)            Commit      log file sync                          13         13      0
  2       1   (LGWR)          Other       LGWR any worker group                4675          1    190 -- ***
  2       1   (LGWR)          Other       target log write size                3880          1      4 -- ****
  2       1   (LGWR)          Other       LGWR all worker groups                691          1    265 -- ***
  2       1   (LGWR)                      On CPU / runqueue                      61          1      0
...
  3       1     (LG..)        System I/O  log file parallel write              5064          1    217
  3       1     (LG..)        Other       LGWR worker group ordering            129          1    223
  3       1     (FOREGROUND)              On CPU / runqueue                       2          1      0
  4       1       (LG..)      System I/O  log file parallel write               129          1    347

— можно надеяться сократить log file sync увеличением кол-ва/ускорением LGWR worker-ов через уменьшение кол-ва LGWR any worker group/LGWR all worker groups (***), а вот ожидание target log write size (****), похоже является «внутренним» для LGWR и так просто уменьшить его не получится

*) В практических случаях при больших несвоевременных задержках переключения режимов LGWR disabling workers / LGWR enabling workers, которые встречаются, вероятно, в т.ч. ввиду новизны технологии, имеет смысл рассмотреть отказ от адаптивного поведения LGWR (но не от использования LGWR workers), изменив значение параметра параметр _use_single_log_writer ADAPTIVE -> FALSE

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

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

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