Oracle mechanics

21.01.2014

Ожидание log file sync на медленных дисках

Filed under: Linux,Oracle,wait events — Игорь Усольцев @ 23:08
Tags: ,

В результате переноса бд с SAS на более ёмкие SATA (в обоих случаях — ASM), с заметной периодичностью на уровне ОС стали наблюдаться симптомы перегрузки отдельных дисков в случайном порядке следующего типа:

# iostat -x 2 /dev/sd*5
...
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          12.81    0.00    0.66   10.37    0.00   76.16

Device:         rrqm/s   wrqm/s    r/s    w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda5              0.00     0.00   0.00   0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
sdb5              9.50     0.00  82.00 181.50 17616.00  6864.00    92.90     3.08   11.69   1.68  44.15
sdc5             11.00     0.00 113.00 176.50 22608.00  7136.00   102.74     3.23   11.17   1.70  49.15
sdh5             11.50     0.00  53.50 207.50 19120.00  8292.00   105.03     3.84   14.74   1.80  46.85
sdi5              8.00     0.00  47.50 148.50 15568.00  5616.00   108.08     1.61    8.16   1.65  32.35
sdj5              7.50     0.00  56.50 163.50 16016.00  6576.00   102.69     2.70   12.28   1.77  38.85
sdg5             10.00     0.00  58.50 185.00 19104.00  7344.00   108.62     3.77   15.49   1.82  44.40
sdd5             15.50    15.50  94.00 182.00 21840.00  8000.00   108.12   115.31  494.38   3.62 100.00 -- здесь,
sde5             13.00     5.00  68.00 179.50 15536.00  7760.00    94.13   129.35  507.48   4.04 100.00 -- здесь
sdn5              9.00     0.00  67.00 178.50 19376.00  6608.00   105.84     2.67   10.85   1.64  40.25
sdl5              7.00     0.00 104.50 191.00 14384.00  7376.00    73.64     2.13    7.22   1.38  40.90
sdf5             15.50     6.00  66.50 145.00 18272.00  5616.00   112.95   137.51  404.19   4.73 100.00 -- и здесь
...

При этом значительнее всего такого рода замедления отражались на OLTP активности в виде увеличения средней продолжительности log file sync:

Load Profile              Per Second    Per Transaction   Per Exec   Per Call
~~~~~~~~~~~~         ---------------    --------------- ---------- ----------
      DB Time(s):               88.6                4.6       0.47       0.18 -- при общем уровне загрузки
       DB CPU(s):                5.3                0.3       0.03       0.01
       Redo size:        3,237,937.4          169,601.5
   Logical reads:          574,013.5           30,066.5
   Block changes:           21,529.2            1,127.7
  Physical reads:            2,062.7              108.0
 Physical writes:              522.0               27.3
      User calls:              506.0               26.5
          Parses:              168.8                8.8
     Hard parses:               30.4                1.6
W/A MB processed:       17,814,195.6          933,098.2
          Logons:               15.8                0.8
        Executes:              187.5                9.8
       Rollbacks:                0.6                0.0
    Transactions:               19.1

...

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
log file sync                        71,320     186,570   2616   58.2 Commit     -- до 2.6 секунд на ожидание
db file sequential read           5,028,995      82,447     16   25.7 User I/O
DB CPU                                           19,201           6.0
read by other session               617,095       7,854     13    2.4 User I/O

После переноса redo log на оказавшиеся в пределах досягаемости SAS диски, картинка с точки зрения ОС (iostat) в части SATA дисков, на которых продолжали находиться файлы бд, изменилась незначительно, однако AWR показал:

Load Profile              Per Second    Per Transaction   Per Exec   Per Call
~~~~~~~~~~~~         ---------------    --------------- ---------- ----------
      DB Time(s):               35.7                1.3       0.12       0.04
       DB CPU(s):                7.0                0.3       0.02       0.01
       Redo size:        3,747,844.9          131,272.7
   Logical reads:        1,074,264.5           37,627.4
   Block changes:           24,714.3              865.7
  Physical reads:            3,288.7              115.2
 Physical writes:              409.8               14.4
      User calls:              920.2               32.2
          Parses:              248.9                8.7
     Hard parses:               41.8                1.5
W/A MB processed:       16,110,582.1          564,292.0
          Logons:               18.6                0.7
        Executes:              297.8               10.4
       Rollbacks:                0.6                0.0
    Transactions:               28.6
...

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
db file sequential read           5,497,331      72,206     13   55.9 User I/O
DB CPU                                           25,429          19.7
log file sync                       102,342      11,139    109    8.6 Commit     -- ср.время уменьшилось в 20+ раз
read by other session               506,272       6,194     12    4.8 User I/O

— не только значительное сокращение ср.времени log file sync, что ожидаемо, но и значительное общее (DB Time) более чем 2-х кратное снижение загрузки сервера бд при такой же (или даже большей) полезной нагрузке

Следующим логичным шагом будет посмотреть профиль ожидания log file sync:

SQL> @ash_wait_tree "event='log file sync'"

 LVL  BLOCKING_TREE       EVENT                         WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS
---- -------------------- ----------------------------- ----------- ---------- ---------------
   1  FOREGROUND          log file sync                       13010        356              821
   1  PX                  log file sync                         164         56              850
   2    (LGWR)            control file parallel write          6516          1              811 -- интересная пара основных блокирующих ожиданий
   2    (LGWR)            enq: CF - contention                 3422          1             1290 -- --//--
   2    (LGWR)            log file parallel write              1787          1              111 -- вместо вот этого ожидаемого
   2    (LGWR)            control file sequential read         1284          1               64
   2    (LGWR)            On CPU / runqueue                     128          1                0
   3      (CKPT)          control file parallel write          2817          1             1113 -- процессы, блокирующие LGWR
   3      (CKPT)          direct path write                     127          1             1151 -- на ожидании CF - contention
   3      (LNS2)          control file parallel write           110          1             1176 -- ...
   3      (ARC0)          control file parallel write            95          1             1383
   3      (CKPT)          control file sequential read           71          1               68
   3      (ARC5)          control file parallel write            45          1             1716
   3      FOREGROUND      control file sequential read           31          2               17
   3      (ARC3)          control file sequential read           21          1               74
   3      (ARC3)          control file parallel write            19          1              137

и подробнее чего ждёт и кем блокируется процесс LGWR:

SQL> @ash_wait_tree "program like '%LGWR%'";

 LVL BLOCKING_TREE       EVENT                         WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS
---- ------------------- ----------------------------- ----------- ---------- ----------------
   1 (LGWR)              log file parallel write               448          1               35 -- относительно короткое "основное" ожидание
   1 (LGWR)              control file parallel write           325          1              538 -- control file на "медленных" дисках
   1 (LGWR)              control file sequential read          305          1               85 -- --//--
   1 (LGWR)              enq: CF - contention                  214          1              863 -- очередь для чтения/записи control file
   1 (LGWR)              On CPU / runqueue                      37          1                0
   1 (LGWR)              LGWR wait for redo copy                 2          1                1 -- *
   2   (CKPT)            control file parallel write           157          1              782
   2   FOREGROUND        control file sequential read           16          2              165
   2   (CKPT)            control file sequential read           15          1               95
   2   (ARC3)            control file sequential read            8          1               98
   2   (ARC0)            control file parallel write             7          1             1037
   2   FOREGROUND        On CPU / runqueue                       2          2                0 -- redo copy latch blocker
...

— из чего хорошо видно, что неплохой оптимизацией на уровне системы (не обязательно способной значительно/пропорционально улучшить производительность конкретных запросов/бизнес-процессов) станет перенос на быстрые диски control file**, что потребует рестарта и потому в отличие от переноса логов не так быстро/просто осуществить

Кроме того, снять часть нагрузки можно переключив/перепоручив передачу логов на standby ARCH-процессам, освободив т.о. LGWR, который занимается логами по умолчанию:

SQL> select distinct archiver, transmit_mode from v$archive_dest where target = 'STANDBY';

ARCHIVER TRANSMIT_MODE
-------- -------------
LGWR     ASYNCHRONOUS

— такая нагрузка без сомнения присутствует — LGWR на экземпляр всего один, даже несмотря на то, что докунтация Oracle 11g отчего-то именует атрибуты LGWR/ARCH в определении параметра LOG_ARCHIVE_DEST_n deprecated

*) нечастонаблюдаемая короткое ожидание высвобождения redo copy latch:

SQL> select distinct decode(session_type,
  2                         'BACKGROUND',
  3                         REGEXP_SUBSTR(program, '\([^\)]+\)'),
  4                         nvl2(qc_session_id, 'PX', 'FOREGROUND')) as program,
  5                  event,
  6                  p1text,
  7                  wait_class,
  8                  session_state
  9    from v$active_session_history
 10   where event = 'LGWR wait for redo copy'
 11  /

PROGRAM  EVENT                    P1TEXT        WAIT_CLASS  SESSION_STATE
-------- ------------------------ ------------- ----------- -------------
(LGWR)   LGWR wait for redo copy  copy latch #  Other       WAITING       -- определение

SQL> @ash_wait_tree "event='LGWR wait for redo copy'"

LVL BLOCKING_TREE        EVENT                         WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS
--- -------------------- ----------------------------- ----------- ---------- ----------------
  1 (LGWR)               LGWR wait for redo copy                16          1                0 -- ждёт
  2   FOREGROUND         On CPU / runqueue                       7          7                0 -- блокирует

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

**) P.S. После переноса control file на условно быстрые SAS диски ср.продолжительность log file sync упала со 100 до 5 мс, соответственно, в правильную сторону изменился профиль ожиданий:

SQL> @ash_wait_tree "event='log file sync'"
 
LVL INST_ID BLOCKING_TREE                  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ------------------------------ ----------------------------- ----------- ---------- ------
  1       1 FOREGROUND                     log file sync                         829        274    165
  1       1 PX                             log file sync                           9          9    149
  2       1   (LGWR)                       log file parallel write               704          1     90
  2       1   (LGWR)                       enq: CF - contention                   88          1   1230
  2       1   (LGWR)                       On CPU / runqueue                      13          1      0
  2       1   (LGWR)                       control file sequential read            5          1     10
...
 
SQL> @ash_wait_tree "program like '%LGWR%'"
 
LVL INST_ID BLOCKING_TREE                  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ------------------------------ ----------------------------- ----------- ---------- ------
  1       1 (LGWR)                         log file parallel write               510          1     32
  1       1 (LGWR)                         On CPU / runqueue                      34          1      0
  1       1 (LGWR)                         control file sequential read           11          1      6
  1       1 (LGWR)                         enq: CF - contention                    6          1    753
  1       1 (LGWR)                         LGWR wait for redo copy                 3          1      2
  1       1 (LGWR)                         control file parallel write             2          1      1
  2       1   (CKPT)                       direct path write                       5          1   1728
  2       1   FOREGROUND                   On CPU / runqueue                       2          2      0

— и теперь в подавляющем большинстве случаев LGWR ожидает log file parallel write — т.е. занимается своим прямым делом

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

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

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