Oracle mechanics

25.09.2012

Ожидания DML операций при синхронном параллельном режиме передачи логов (на удалённый STANDBY)

Filed under: Active Session History,commonplace,Oracle,wait events — Игорь Усольцев @ 23:48
Tags: , ,

Классический случай: при синхронной параллельной конфигурации LOG_ARCHIVE_DEST_n = SYNC MAX_CONNECTIONS=5,  DML операция вставки в обыкновенную таблицу «притормаживает»:

SQL> insert into hist_table(id, phone, status, user_id, ts, user_comment, rec_url, rec_call_id) values(id_seq.nextval, ?, ?, ?, ?, ?, ?, ?);

Цепочка ожиданий из Active Session History оказывается следующей:

11.1.0.7.@ SQL> select LEVEL as WAIT_LEVEL,
  2         LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,4),'FOREGROUND') as BLOCKING_TREE,
  3         ash.EVENT,
  4         count(*),
  5         round(avg(time_waited) / 1000) as AVG_TIME_WAITED_MS
  6    from v$active_session_history ash
  7   where session_state = 'WAITING'
  8   start with sql_id = '33ff0dv0u954z'
  9  connect by nocycle
 10   prior ash.SAMPLE_ID = ash.SAMPLE_ID
 11         and ash.SESSION_ID = prior ash.BLOCKING_SESSION
 12   group by LEVEL,
 13            LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,4),'FOREGROUND'),
 14            ash.EVENT
 15   order by LEVEL, count(*) desc
 16  /

 

WAIT_LEVEL BLOCKING_TREE  EVENT                          COUNT(*) AVG_TIME_WAITED_MS
---------- -------------- ------------------------------ -------- ------------------
         1 FOREGROUND     log file switch completion           20                 98
         1 FOREGROUND     latch: In memory undo latch          18               1046
         1 FOREGROUND     log buffer space                     17                988
         1 FOREGROUND     enq: SQ - contention                 13               1086
         2   FOREGROUND   log buffer space                     31               1001
         2   LGWR         LGWR-LNS wait on channel             24                 11
         2   LGWR         ARCH wait for netserver start        12               1271
         3     LGWR       ARCH wait for netserver start        21               1115
         3     LGWR       LGWR-LNS wait on channel              5                 11

— сессии, непосредственно выполняющие проблемный DML (WAIT_LEVEL=1) ожидают типичных событий, связанных со скоростью записи redo процессом LGWR:

  • log file switch completion
  • latch: In memory undo latch
  • log buffer space

Интересно, что получение следующего значения id_seq.nextval из последовательности — enq: SQ — contention — также коственно блокируется процессом LGWR до завершения COMMIT:

SQL> select LEVEL as WAIT_LEVEL,
  2         LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,4),'FOREGROUND') as BLOCKING_TREE,
  3         ash.EVENT,
  4         count(*),
  5         round(avg(time_waited) / 1000) as AVG_TIME_WAITED_MS
  6    from dba_hist_active_sess_history ash
  7   where session_state = 'WAITING'
  8   start with sql_id = '33ff0dv0u954z'
  9           and event = 'enq: SQ - contention'
 10  connect by nocycle
 11   prior ash.SAMPLE_ID = ash.SAMPLE_ID
 12         and ash.SESSION_ID = prior ash.BLOCKING_SESSION
 13   group by LEVEL,
 14            LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,4),'FOREGROUND'),
 15            ash.EVENT
 16   order by LEVEL, count(*) desc
 17  /

 

WAIT_LEVEL BLOCKING_TREE   EVENT                                             COUNT(*) AVG_TIME_WAITED_MS
---------- --------------- ------------------------------------------------- -------- ------------------
         1 FOREGROUND      enq: SQ - contention                                    22               1081
         2   FOREGROUND    log buffer space                                         8                873
         2   FOREGROUND    log file switch (private strand flush incomplete)        8                101
         2   FOREGROUND    log file switch completion                               3                101
         2   FOREGROUND    buffer busy waits                                        3               1001
         3     LGWR        ARCH wait for netserver start                            9                  0
         3     LGWR        LGWR-LNS wait on channel                                 9                 11
         3     FOREGROUND  log file switch completion                               3                101
         4       LGWR      ARCH wait for netserver start                            1                  0

LGWR, в свою очередь, ожидает процессов LNSn (Log Network Service) и ARCn:

  • LGWR-LNS wait on channel — фактически сетевое ожидание по каналу KSR (Service Remote?)
  • ARCH wait for netserver start — также связанное с сетевой передачей логов ожидание, указывающее на ARCH

, которые по очереди «параллельно» (MAX_CONNECTIONS=5) занимаются передачей на standby online redo и архивных логов:

SQL> select creator, registrar, count(*)
  2    from v$archived_log
  3   where standby_dest = 'YES'
  4     and first_time between trunc(sysdate - 5) and trunc(sysdate - 4)
  5   group by creator, registrar
  6  /

CREATOR REGISTRAR   COUNT(*)
------- --------- ----------
LGWR    LGWR             279
ARCH    ARCH             103

и в свою очередь ожидают удалённой записи логов на диск:

SQL> select LEVEL as WAIT_LEVEL,
  2         LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,3),'FOREGROUND') as BLOCKING_TREE,
  3         ash.EVENT,
  4         count(*),
  5         round(avg(time_waited) / 1000) as AVG_TIME_WAITED_MS
  6    from dba_hist_active_sess_history ash
  7   where session_state = 'WAITING'
  8         and wait_class <> 'System I/O'
  9   start with (program like '%ARC%' or program like '%LNS%')
 10           and session_type = 'BACKGROUND'
 11           and snap_id = 15141
 12  connect by nocycle
 13   prior ash.SAMPLE_ID = ash.SAMPLE_ID
 14         and ash.SESSION_ID = prior ash.BLOCKING_SESSION
 15   group by LEVEL,
 16            LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,3),'FOREGROUND'),
 17            ash.EVENT
 18   order by LEVEL, count(*) desc
 19  /

 

WAIT_LEVEL BLOCKING_TREE  EVENT                      COUNT(*) AVG_TIME_WAITED_MS
---------- -------------- ------------------------ ---------- ------------------
         1 LNS            LNS wait on SENDREQ             169                283 -- открытие/запись/закрытие удалённого лога (включая сетевые задержки, имхо)
         1 ARC            LGWR-LNS wait on channel          4                 11
         1 ARC            ARCH wait on SENDREQ              4                421 -- -//-
         1 ARC            enq: CF - contention              1                745 -- типичное ожидание синхронного доступа к CF, напрямую не относится к теме
         1 LNS            LNS wait on DETACH                1                 28
         2   LGW          LGWR-LNS wait on channel          1                 11

Проблемы и пути решения понятны — скорость передачи и записи redo на удалённом standby, но в данном случае синхронный режим передачи не был необходимым требованием

После переключения передачи логов на standby в ASYNC режим статистика выполнения DML заметно улучшилась:

SQL> select st.snap_id,
  2         round(st.executions_delta) as EXECS_DELTA,
  3         st.plan_hash_value,
  4         st.optimizer_cost,
  5         st.optimizer_mode,
  6         round(st.elapsed_time_delta /
  7               decode(st.executions_delta, 0, 1, st.executions_delta)) as ELA_PER_EXEC,
  8         round(st.cpu_time_delta /
  9               decode(st.executions_delta, 0, 1, st.executions_delta)) as CPU_PER_EXEC,
 10         round(st.iowait_delta /
 11               decode(st.executions_delta, 0, 1, st.executions_delta)) as IO_PER_EXEC,
 12         round(st.ccwait_delta /
 13               decode(st.elapsed_time_delta, 0, 1, st.executions_delta)) as CC_PER_EXEC,
 14         round(st.buffer_gets_delta /
 15               decode(st.executions_delta, 0, 1, st.executions_delta)) as GETS_PER_EXEC,
 16         round(st.rows_processed_delta /
 17               decode(st.executions_delta, 0, 1, st.executions_delta)) as ROWS_PER_EXEC
 18    from dba_hist_sqlstat st, dba_hist_snapshot sn
 19   where sql_id = '33ff0dv0u954z'
 20     and st.snap_id = sn.snap_id
 21     and st.instance_number = sn.instance_number
 22     and st.executions_delta > 0
 23   order by st.snap_id desc, st.instance_number
 24  /
   SNAP_ID EXECS_DELTA PLAN_HASH_VALUE OPTIMIZER_COST OPTIMIZER_MODE ELA_PER_EXEC CPU_PER_EXEC IO_PER_EXEC CC_PER_EXEC GETS_PER_EXEC ROWS_PER_EXEC
---------- ----------- --------------- -------------- -------------- ------------ ------------ ----------- ----------- ------------- -------------
     15191         990      2746425734              1 ALL_ROWS               1603          106         346           0            17             1 -- ASYNC
     15141        1016      2746425734              1 ALL_ROWS             137552          141         558       13260            17             1 -- SYNC

— время выполнения ELA_PER_EXEC упало почти в 100 раз, исчезли блокировки — ожидания класса Concurrency (CC_PER_EXEC)

Список текущих ожиданий «проблемного» sql стал локальным:

SQL> select LEVEL as WAIT_LEVEL,
  2         LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,4),'FOREGROUND') as BLOCKING_TREE,
  3         ash.EVENT,
  4         count(*),
  5         round(avg(time_waited) / 1000) as AVG_TIME_WAITED_MS
  6    from v$active_session_history ash
  7   where session_state = 'WAITING'
  8   start with sql_id = '33ff0dv0u954z'
  9  connect by nocycle
 10   prior ash.SAMPLE_ID = ash.SAMPLE_ID
 11         and ash.SESSION_ID = prior ash.BLOCKING_SESSION
 12   group by LEVEL,
 13            LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',substr(ash.PROGRAM,30,4),'FOREGROUND'),
 14            ash.EVENT
 15   order by LEVEL, count(*) desc
 16  /

 

WAIT_LEVEL BLOCKING_TREE  EVENT                        COUNT(*) AVG_TIME_WAITED_MS
---------- -------------- -------------------------- ---------- ------------------
         1 FOREGROUND     log file switch completion          1                 71
         1 FOREGROUND     db file sequential read             1                 10
         2   LGWR         log file parallel write             1                 90

Соответственно, в ожиданиях пользовательских сессий AWR, ожидания, связанные с записью redo, становятся менее заметными и более короткими

  • было в режиме SYNC:
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           19,763          34.9
log file sync                        50,607      18,541    366   32.8 Commit     -- ***
db file sequential read           3,173,654       8,422      3   14.9 User I/O
read by other session               897,519       1,636      2    2.9 User I/O
log buffer space                        853         765    897    1.4 Configurat -- ***
...
Avg
%Time Total Wait    wait    Waits   % DB
Event                             Waits -outs   Time (s)    (ms)     /txn   time
-------------------------- ------------ ----- ---------- ------- -------- ------
db file scattered read           14,032     0        241      17      0.3     .4
log file switch completion        2,365    96        233      99      0.0     .4 --***
  • стало в режиме ARCH (ASYNC):
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           21,198          48.9
db file sequential read           2,716,989       9,608      4   22.2 User I/O
log file sync                        59,686       3,889     65    9.0 Commit     -- ***
db file parallel read                18,823         225     12     .5 User I/O
db file scattered read               16,009         206     13     .5 User I/O
...
log file switch completion          197    55         15      76      0.0     .0 -- ***

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

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

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