Oracle mechanics

18.08.2011

enq: CF — contention

Нечастое событие enq: CF — contention в топе ожиданий AWR:

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                          9,620          51.2
db file sequential read             977,369       4,530      5   24.1   User I/O
db file scattered read              761,460       1,914      3   10.2   User I/O
enq: CF - contention                  2,133       1,002    470    5.3      Other
log file sync                        22,429         666     30    3.5     Commit

Документация не даёт никакой информации, кроме общего описания транзакционной блокировки/синхронизации доступа к controlfile:

SQL> select NAME, DESCRIPTION from v$lock_type where type = 'CF';

NAME                      DESCRIPTION
------------------------- ----------------------------------------
Controlfile Transaction   Synchronizes accesses to the controlfile

Однако на сайте поддержки можно найти документ (отлично заполняющий пробелы в документации) Performance Degradation as a result of ‘enq: CF — contention’ [ID 1072417.1]:

The CF enqueue can be seen during any action that requires reading the control file, the CF locks are used to serialize controlfile transactions and read and writes on shared portions of the controlfile. Typically CF locks are allocated for a very brief time and used when:

— checkpointing
— switching logfiles
— archiving redologs
— performing crash recovery
— logfile manipulation
— begin/end hot backup
— DML access for NOLOGGING objects

Из описания понятно, что доступ к контролфайлу блокируется при операциях чтения (соотв.ожидание control file sequential read) и записи (control file parallel write, control file single write), можно попробовать найти текущие блокирующие сессии (CF enqueue holders):

SQL> select p.program, s.event
 from v$lock l, v$session s, v$process p
 where l.sid = s.sid
 and s.paddr = p.addr
 and l.type='CF'
 and l.lmode >= 5;

oracle@hostname.ru (CKPT)    control file sequential read
oracle@hostname.ru (ARC2)    control file sequential read
oracle@hostname.ru (LGWR)    control file sequential read

Результат ожидаемый, особенно ничего не проясняющий, пробуем получить данные о блокирующих сессиях (по blocking_session, blocking_session_serial#) из истории активных сессий (dba_hist_active_sess_history):

SQL> select program, event, count(*) from dba_hist_active_sess_history where (session_id, session_serial#, snap_id) in
 (select blocking_session, blocking_session_serial#, ash.snap_id
 from dba_hist_active_sess_history ash
 where ash.event = 'enq: CF - contention' and ash.sample_time between trunc(sysdate) and trunc(sysdate)+1/2)
 group by program, event
 order by 3 desc;

PROGRAM                      EVENT    COUNT(*)
oracle@hostname.ru (ARCa)    control file sequential read    369
oracle@hostname.ru (ARCa)    control file parallel write     180
oracle@hostname.ru (LGWR)                                     86
oracle@hostname.ru (LGWR)    log file parallel write          48
rman@hostname.ru (TNS V1-V3) control file sequential read     41
oracle@hostname.ru (ARCa)    log file sequential read         39
oracle@hostname.ru (ARC3)                                     29
oracle@hostname.ru (ARCa)    enq: CF - contention             26
oracle@hostname.ru (ARCa)                                     23
rman@hostname.ru (TNS V1-V3)                                  19
oracle@hostname.ru (LGWR)    enq: CF - contention             18
...

Видно,  что самым заметным блокиратором CF enqueue является один из дочерних процессов архивации ARCa, в свою очередь читающий/пишущий в контролфайл (control file sequential read/control file parallel write) — можно предположить, при архивирации (или, попытках архивации):

SQL> select blocking_session, blocking_session_serial#, count(*)
 from dba_hist_active_sess_history ash where ash.event = 'enq: CF - contention'
 and ash.sample_time between trunc(sysdate) and trunc(sysdate)+1/2
 group by blocking_session, blocking_session_serial#;

858    1    821
880    1    28
881    1    16
864    1    7
 ...
SQL> select distinct ash.session_id, ash.session_serial#, ash.program from dba_hist_active_sess_history ash where (ash.session_id, ash.session_serial#)
 in ((858,    1),(880,    1),(881,    1))
 and ash.sample_time between trunc(sysdate) and trunc(sysdate)+1/2;

SESSION_ID    SESSION_SERIAL#    PROGRAM
 858                        1    oracle@hostname.ru (ARCa)
 880                        1    oracle@hostname.ru (CKPT)
 881                        1    oracle@hostname.ru (LGWR)

Состояние архивации online log файлов не вызвало вопросов:

SQL> select group#, ARCHIVED, STATUS from v$log;

GROUP#     ARCHIVED STATUS
---------- -------- --------
21         NO       CURRENT
22         YES      INACTIVE
23         YES      INACTIVE
24         YES      INACTIVE
...

Но обнаружились неиспользуемые standby log файлы (на primary бд), один из которых был отмечен как неархивированный (ARCHIVED=NO) при статусе UNASSIGNED (Online redo log has never been written to… — никогда не использовавшийся standby log):

SQL> SELECT GROUP#,THREAD#,SEQUENCE#,ARCHIVED,STATUS, first_change#, last_change# FROM V$STANDBY_LOG;
GROUP# THREAD# SEQUENCE# ARCHIVED STATUS      FIRST_CHANGE# LAST_CHANGE#
------ ------- --------- -------- ----------- ------------- ------------
 1          1          0 NO        UNASSIGNED             0            0
 2          1          0 YES       UNASSIGNED             0            0
 3          1          0 YES       UNASSIGNED             0            0
...
9 rows selected.

— явная логическая неконсистентность, возможно, приводящая в замешательство процесс архивирования (ARCa)

Удаление неактивных и неактуальных standby log файлов более чем на порядок снизило количество ожиданий enq: CF — contention:

                                                                   Avg
                                              %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file sequential read             284,539     .0         723       3       0.2
db file scattered read              162,627     .0         336       2       0.1
direct path read temp             1,998,072     .0         306       0       1.4
log file sync                        23,203     .3         278      12       0.0
ARCH wait on SENDREQ                  7,122     .0         206      29       0.0
log file parallel write              79,470     .0         155       2       0.1
control file sequential read        152,490     .0         123       1       0.1
enq: CF - contention                    169    4.1          71     422       0.0
enq: TX - row lock contentio            601    2.7          60     100       0.0

Однако ожидание осталось заметным и, учитывая версию 10.2.0.4, полезно проверить влияние запросов, использующих subquery factoring (точнее, выполняющих direct path writes во временную таблицу при операции TEMP TABLE TRANSFORMATION — подробно описано в блоге Timur Akhmadeev «Control file sequential read», где указан и протестирован Bug 7515779, см.также обсуждение http://forums.oracle.com/forums/thread.jspa?threadID=1013481) на интенсивность ожиданий, связанных с блокировками контролфайла (enq: CF — contention, control file sequential read):

SQL> select * from (
2  with sf_sql as
3   (select distinct sql_id, plan_hash_value from v$sql_plan where operation = 'TEMP TABLE TRANSFORMATION'
4    union
5    select distinct sql_id, plan_hash_value from dba_hist_sql_plan where operation = 'TEMP TABLE TRANSFORMATION')
6  select PROGRAM, EVENT, ash.sql_id, nvl2(p.sql_id, 'TEMP TABLE TRANSFORMATION', 'Other CF activities') AS CF_ENQUEUE_REASON, count(*)
7    from v$active_session_history ash, sf_sql p
8   where EVENT in ('enq: CF - contention',
9                   'control file sequential read')
10     and SESSION_STATE = 'WAITING'
11     and ash.SQL_ID = p.sql_id(+)
12     and ash.SQL_PLAN_HASH_VALUE = p.plan_hash_value(+)
13   group by PROGRAM, EVENT, ash.sql_id, nvl2(p.sql_id, 'TEMP TABLE TRANSFORMATION', 'Other CF activities')
14   order by count(*) desc
15  ) where rownum <= 5
16  /

PROGRAM                                          EVENT                         SQL_ID        CF_ENQUEUE_REASON           COUNT(*)
------------------------------------------------ ----------------------------- ------------- ------------------------- ----------
JDBC Thin Client                                 enq: CF - contention          0cufxa3h8bp1b TEMP TABLE TRANSFORMATION       1132
JDBC Thin Client                                 enq: CF - contention          60tftk50vu96h TEMP TABLE TRANSFORMATION        266
oracle@hostname.ru (LGWR)                        enq: CF - contention                        Other CF activities              189
JDBC Thin Client                                 control file sequential read  0cufxa3h8bp1b TEMP TABLE TRANSFORMATION        184
oracle@hostname.ru (ARC5)                        control file sequential read                Other CF activities              179

— запросы, использующие TEMP TABLE TRANSFORMATION, хорошо заметны в количественном топе ожиданий controlfile

Или в суммарных процентах только по ожиданию enq: CF — contention:

SQL> with sf_sql as
2   (select distinct sql_id, plan_hash_value from v$sql_plan where operation = 'TEMP TABLE TRANSFORMATION'
3    union
4    select distinct sql_id, plan_hash_value from dba_hist_sql_plan where operation = 'TEMP TABLE TRANSFORMATION')
5  select nvl2(p.sql_id, 'TEMP TABLE TRANSFORMATION', 'Other CF activities') AS CF_ENQUEUE_REASON,
6         round(RATIO_TO_REPORT(count(*)) OVER() * 100, 2) AS PCTTOT
7    from v$active_session_history ash, sf_sql p
8   where EVENT in ('enq: CF - contention')
9     and SESSION_STATE = 'WAITING'
10     and ash.SQL_ID = p.sql_id(+)
11     and ash.SQL_PLAN_HASH_VALUE = p.plan_hash_value(+)
12   group by nvl2(p.sql_id, 'TEMP TABLE TRANSFORMATION', 'Other CF activities')
13   order by PCTTOT desc
14  /

CF_ENQUEUE_REASON             PCTTOT
------------------------- ----------
TEMP TABLE TRANSFORMATION      76,02
Other CF activities            23,98

Ещё одна причина обновляться :)

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

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

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