Oracle mechanics

25.11.2014

Медленный накат логов / Media Recovery Log и скрипт для standby ASH

Filed under: Oracle,Standby — Игорь Усольцев @ 00:04
Tags: ,

Сразу после разрешения предыдущих проблем ASM диагностики успешно возобновлённый накат логов / Standby Log Apply может выполняться чрезвычайно медленно, по крайней мере, первое время

Итак, физический стендбай:

SQL> @inst
 
INST_ID INSTANCE_NAME HOST_NAME    VERSION    PLATFORM_NAME        DATABASE_STATUS DATABASE_ROLE    OPEN_MODE
------- ------------- ------------ ---------- -------------------- --------------- ---------------- ---------
1*      orcl1         stby1.com.ru 11.2.0.2.0 Linux x86 64-bit     ACTIVE          PHYSICAL STANDBY MOUNTED

Для анализа причин медлительности работы standby удобно использовать несколько упрощённый скрипт ash_wait_tree4stby.sql для ожиданий в ASH, которая, к счастью, продолжает успешно заполняться и в статусе MOUNTED

Поскольку накат выполняется естественно параллельно, интерес представляют прежде всего трудности фоновых процессов Parallel Recovery (PR):

SQL> @ash_wait_tree4stby "program like 'oracle@stby1.com.ru (PR%' and sample_time < trunc(sysdate-1)+19/24"
 
LVL BLOCKING_TREE                  EVENT                                 WAITS_COUNT SESS_COUNT AVG_WA
--- ------------------------------ ------------------------------------- ----------- ---------- ------
  1 (PR0                           enq: CF - contention                         1238          1   1001
  1 (PR0                           On CPU / runqueue                             522         17      0
  1 (PR0                           control file sequential read                  231          1     86
  1 (PR0                           log file sequential read                      210          1     89
  1 (PR0                           control file parallel write                   150          1     58
  1 (PR0                           checkpoint completed                           48         16    821
  1 (PR0                           direct path write                              30          1     72
  1 (PR0                           direct path read                               15          1     24
  1 (PR0                           Data file init write                           13          1    130
  1 (PR0                           DFS lock handle                                 8          1    987
  1 (PR0                           parallel recovery change buffer free            3          1     11
  1 (PR0                           recovery read                                   1          1     85
  1 (PR0                           parallel recovery slave next change             1          1     11
  2   FOREGROUND                   control file sequential read                 1179         19     94
  2   FOREGROUND                   control file parallel write                    37         17     90
  2   FOREGROUND                   RFS create                                     10          9      0
  2   FOREGROUND                   Log archive I/O                                 5          4     90
  2   (ARC                         control file sequential read                    5          4     18
  2   (DBW                         enq: CF - contention                            4          1    817
  2   (DBW                         control file sequential read                    4          1     73
  2   FOREGROUND                   RFS close                                       1          1      1
  3     FOREGROUND                 control file sequential read                    2          2     85
  3     FOREGROUND                 control file parallel write                     2          2     69

— а основное время доблестные PR процессы проводят в борьбе за доступ к controlfile, причём блокерами являются некие пользовательские (FOREGROUND) процессы, количесвом ~ 19:

SQL> @ash_wait_tree4stby "program like 'oracle@stby1.com.ru (PR%' and event = 'enq: CF - contention' and sample_time < trunc(sysdate-1)+19/24"
 
LVL BLOCKING_TREE                  EVENT                                 WAITS_COUNT SESS_COUNT AVG_WA
--- ------------------------------ ------------------------------------- ----------- ---------- ------
  1 (PR0                           enq: CF - contention                         1232          1   1006 -- PR процесс хочет CF,
  2   FOREGROUND                   control file sequential read                 1174         19     94 -- уже занятый FG процессами
  2   FOREGROUND                   control file parallel write                    37         17     90
  2   FOREGROUND                   RFS create                                     10          9      0
  2   FOREGROUND                   Log archive I/O                                 5          4     90
  2   (ARC                         control file sequential read                    5          4     18
  2   FOREGROUND                   RFS close                                       1          1      1

Генезис блокирующих FG процессов несложно выяснись из той же ASH:

SQL> select program, event, count(*)
  2    from v$active_session_history
  3   where session_type = 'FOREGROUND'
  4     and event in ('control file sequential read')
  5     and sample_time < trunc(sysdate-1)+19/24
  6   group by program, event
  7   order by count(*) desc
  8  /
 
PROGRAM                                   EVENT                           COUNT(*)
----------------------------------------- ----------------------------- ----------
oracle@pri.com.ru (TNS V1-V3)             control file sequential read        2860 -- с primary
oracle@stby2.com.ru (TNS V1-V3)           control file sequential read          29 -- немного со 2-го standby
rman@stby1.com.ru (TNS V1-V3)             control file sequential read           8 -- и совсем чуть-чуть
python@stby1.com.ru (TNS V1-V3)           control file sequential read           4 -- от локальных процессов

— приходят эти FG, в основном, с primary и, судя по профилю ожиданий, активно занимаются записью пропущенной порции архивных логов:

SQL> @ash_wait_tree4stby "program = 'oracle@pri.com.ru (TNS V1-V3)' and sample_time < trunc(sysdate-1)+19/24"
 
LVL BLOCKING_TREE                  EVENT                                 WAITS_COUNT SESS_COUNT AVG_WA
--- ------------------------------ ------------------------------------- ----------- ---------- ------
  1 FOREGROUND                     enq: CF - contention                        18496         19   1010 -- ждут CF
  1 FOREGROUND                     Log archive I/O                              5995         19    135 -- пишут логи
  1 FOREGROUND                     SQL*Net vector data from client              4497         19    143 -- ожидают данные
  1 FOREGROUND                     control file sequential read                 2833         19     91 -- читают и
  1 FOREGROUND                     RFS write                                    1818         19     18
  1 FOREGROUND                     control file parallel write                    71         18    100 -- пишут CF
  1 FOREGROUND                     kfk: async disk IO                             24         12     81
  1 FOREGROUND                     RFS create                                     16         13      0
  1 FOREGROUND                     RFS close                                       3          3      0
  1 FOREGROUND                     RFS sequential i/o                              1          1     23
  2   FOREGROUND                   control file sequential read                14357         19     92
  2   (PR0                         control file parallel write                  1537          1     56
  2   (PR0                         control file sequential read                 1495          1     81
  2   FOREGROUND                   control file parallel write                   440         18     91
  2   (PR0                         direct path write                             237          1     74
  2   (PR0                         On CPU / runqueue                             119          1      0
  2   FOREGROUND                   RFS create                                    101         11      0
  2   (PR0                         direct path read                               94          1     22
  2   (ARC                         control file sequential read                   48          4     19
  2   FOREGROUND                   Log archive I/O                                40          4     98
  2   (DBW                         control file sequential read                   15          1     71
  2   FOREGROUND                   RFS close                                      13          2      1

При этом на основном ожидании enq: CF — contention эти FG процессы с primary в основном и активно блокируют друг друга:

SQL> @ash_wait_tree4stby "program = 'oracle@pri.com.ru (TNS V1-V3)' and event = 'enq: CF - contention' and sample_time < trunc(sysdate-1)+19/24"
 
LVL BLOCKING_TREE                  EVENT                                 WAITS_COUNT SESS_COUNT AVG_WA
--- ------------------------------ ------------------------------------- ----------- ---------- ------
  1 FOREGROUND                     enq: CF - contention                        18414         19   1012
  2   FOREGROUND                   control file sequential read                14275         19     91
  2   (PR0                         control file parallel write                  1537          1     56
  2   (PR0                         control file sequential read                 1495          1     81
  2   FOREGROUND                   control file parallel write                   440         18     91
  2   (PR0                         direct path write                             237          1     74
  2   (PR0                         On CPU / runqueue                             119          1      0
  2   FOREGROUND                   RFS create                                    101         11      0
  2   (PR0                         direct path read                               94          1     22
  2   (ARC                         control file sequential read                   48          4     19
  2   FOREGROUND                   Log archive I/O                                40          4     98
  2   (DBW                         control file sequential read                   15          1     71
  2   FOREGROUND                   RFS close                                      13          2      1

Остаётся убедиться что это именно те процессы, о которых мы думаем:)

SQL> select * from v$session where program = 'oracle@pri.com.ru (TNS V1-V3)' and rownum <= 1
  2  /
 
SADDR                   SID    SERIAL#     AUDSID PADDR                 USER# USERNAME  SERVER    OSUSER  PROCESS  MACHINE      PORT
---------------- ---------- ---------- ---------- ---------------- ---------- --------- --------- ------- -------- ----------- -----
00000018D0F53638        164          1 4294967295 0000001850F45810          1 PUBLIC    DEDICATED oracle  10932    pri.com.ru  52547

— в 11.2 TCP-порт на клиентской машине (pri.com.ru) крайне удобно показан в v$session, для более ранних версий:

SQL> select * from v$process where addr = '0000001850F45810'
  2  /
 
ADDR                    PID SPID  USERNAME
---------------- ---------- ----- --------
0000001850F45810        133 10191 oracle  

[oracle@stby1 ~]$ lsof -p 10191 | grep TCP
oracle  10191 oracle   18u  IPv4          413390549       0t0                  TCP stby1.com.ru:ncube-lm->pri.com.ru:52547 (ESTABLISHED)

Порт ожидаемо указывает на primary ARCH процесс:

[root@pri ~]# netstat -tpn | grep 52547
tcp        0      0 192.168.127.55:52547         192.168.127.31:1521          ESTABLISHED 10932/ora_arc2_pri

— т.е. в случае большого Archived Log Gap-а имеем замедление процесса наката логов, большей частью связанное с конфигурацией архивирования на primary:

SQL> @param log_archive
 
NAME                       VALUE                                  DSC
-------------------------- -------------------------------------- ---------------------------------------
log_archive_dest_3         service=orcl-stby1.com.ru ARCH SYNC... archival destination #3 text string
log_archive_max_processes  20                                     maximum number of active ARCH processes

— в соответствии с которой передача логов на стендбай производится большой, возможно, избыточной группой ARCH-иверов, толпой спешащих и блокирующих друг друга, в т.ч. под влиянием спорного режима передачи SYNC. Предлагаемый Oracle по умолчанию асинхронный ASYNC режим передачи в этом месте может быть предпочтительнее

После разрешения коллизий, связанных с массовой пересылкой логов, профиль нагрузки PR процессов нормализуется:

SQL> @ash_wait_tree4stby "program like 'oracle@stby1.com.ru (PR%' and sample_time > trunc(sysdate)"
 
LVL BLOCKING_TREE  EVENT                                 WAITS_COUNT SESS_COUNT AVG_WA
--- -------------- ------------------------------------- ----------- ---------- ------
  1 (PR0           checkpoint completed                        58617         16    911 --*
  1 (PR0           On CPU / runqueue                           51973         17      0 --**
  1 (PR0           log file sequential read                    12057          1     51 --***
  1 (PR0           control file sequential read                 7732          1     48 --****
  1 (PR0           control file parallel write                  4002          1     32 --*****
  1 (PR0           Data file init write                         2361          1     27
  1 (PR0           direct path write                            2284          1     41
  1 (PR0           direct path read                              634          1     25
  1 (PR0           parallel recovery change buffer free          407          1     11
  1 (PR0           enq: CF - contention                          329          1    820
  1 (PR0           ASM file metadata operation                    87         14     50
  1 (PR0           recovery read                                  50         15     50
  1 (PR0           parallel recovery slave next change             9          3     11
  1 (PR0           DFS lock handle                                 7          1    577
  1 (PR0           kfk: async disk IO                              1          1      6
  2   (CKP         control file parallel write                 16860          1    905
  2   FOREGROUND   control file sequential read                  281          7     71
  2   (CKP         On CPU / runqueue                             134          1      0
  2   (ARC         control file sequential read                   13          6     68
  2   FOREGROUND   control file parallel write                     8          6     48
  2   (DBW         control file sequential read                    7          1      7
  2   FOREGROUND   RFS ping                                        2          1      0
  2   (TNS         control file sequential read                    2          2     63
  2   (TNS         control file parallel write                     1          1     15

, топовым блокером процедуры parallel recovery по основному ожиданию checkpoint completed логично становится процесс CKPT:

SQL> @ash_wait_tree4stby "program like 'oracle@stby1.com.ru (PR%' and event = 'checkpoint completed' and sample_time > trunc(sysdate)"
 
LVL BLOCKING_TREE  EVENT                                 WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- -------------- ------------------------------------- ----------- ---------- ------ ---------- ------------------
  1 (PR0           checkpoint completed                        58524         16    911      74711                562
  2   (CKP         control file parallel write                 16838          1    904      15709                781
  2   (CKP         On CPU / runqueue                             134          1      0          0               1000

, собственный профиль ожиданий которого собственно и состоит из этих 2-х состояний: control file parallel write и CPU:

SQL> @ash_wait_tree4stby "program like 'oracle@stby1.com.ru (CKP%' and sample_time > trunc(sysdate)"
 
LVL BLOCKING_TREE  EVENT                                 WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- -------------- ------------------------------------- ----------- ---------- ------ ---------- ------------------
  1 (CKP           control file parallel write                  1536          1    760      11329                131
  1 (CKP           On CPU / runqueue                              18          1      0          0               1000

с достаточно странными данными из ASH о продолжительности control file parallel write, получаемыми и по обычному среднему (AVG_WA), и по рекомендованному специалистами Oracle методу (EST_AVG_LATENCY_MS)

Обе оценки не согласуются даже по порядку величин с данными v$system_event:

SQL> select * from v$system_event where event in ('checkpoint completed','control file parallel write');
 
EVENT                       TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT TIME_WAITED_MICRO TOTAL_WAITS_FG TIME_WAITED_FG AVERAGE_WAIT_FG WAIT_CLASS
--------------------------- ----------- -------------- ----------- ------------ ----------------- -------------- -------------- --------------- -------------
control file parallel write      605344              0     1134068         1,87       11340684072          34825         123738            3,55 System I/O
checkpoint completed             112813           1720     8411860        74,56       84118599339              0              0               0 Configuration

, по данным которого, учитывая что интересуют нас ожидания иницированные background процессами PR, ср.время ожидания control file parallel write не более 20 ms против 130-500+ ms по данным ASH. В то время как ср.время checkpoint completed ~ 750 ms вполне согласуется с данными ASH

Тем не менее очевидно, что для дальнейшей оптимизации процедуры наката логов может быть полезно, например:

1) ускорение checkpoint-ов (*), например, перемещением controlfile на быстрые/выделенные диски, что также поспособствует ускорению чтения(****) и записи(*****) controlfile PR-процессами
2) использование быстрых процессоров/дальнейшее распараллеливание процедуры наката(**)
3) использование более быстрых файловых систем для хранения логов(***)

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

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

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