Oracle mechanics

Ожидания, статистики, коэффициенты

Некоторые важные для анализа производительности систем Oracle события ожидания (wait events), статистики (statistics) и вычисляемые коэффициенты (ratio), используемые при анализе производительности и отчётов Statspack/AWR

События ожидания

В документации есть таблица о типичных причинах частовстречающихся ожиданий —  Wait Events and Potential Causes

Дисковый ввод-вывод (I/O wait events)

Oracle: IO Waits by Kyle Hailey — отличное описание на английском (с картинками)

db file sequential read

Среднее время этого ожидания = фактическому среднему времени чтения одного блока БД (что на уровне ОС обычно называют выборочным или случайным чтением (random read)). Типичное нормальное значение ~10 ms (10 ms — это значение по умолчанию параметра IOSEEKTIM системной статистики из sys.aux_stats$), в реальных системах может быть значительно меньше при использовании RAID controller cache + OS cache. В зависимости от соотношения (очереди на выполнение операций ввода-вывода)/(производительность системы I/O) может многократно меняться. Полезно сравнить это время ожидания со значениями, используемыми Oracle CBO для расчётов — значением параметра SREADTIM, либо IOSEEKTIM + DB_BLOCK_SIZE / IOTFRSPEED при наличии или отсутствии WORKLOAD системной статистики (sys.aux_stats$)

При обращении к undo сегментам операция одноблочного чтения используется при типичных «быстрых» многоблочных операциях плана выполнения (TABLE ACCESS FULL, INDEX FAST FULL SCANи т.д.):

SQL> select event,
  2         p3 as "BLOCKS",
  3         sql_plan_operation || ' ' || sql_plan_options,
  4         count(*)
  5    from dba_hist_active_sess_history
  6   where p1text = 'file#'
  7     and p3text = 'blocks'
  8     and session_state = 'WAITING'
  9     and p1 in (select file_id
 10                  from dba_data_files
 11                 where tablespace_name in
 12                       (select tablespace_name
 13                          from dba_tablespaces
 14                         where contents = 'UNDO'))
 15   group by event, p3, sql_plan_operation || ' ' || sql_plan_options
 16  order by count(*) desc
 17  /

EVENT                    BLOCKS SQL_PLAN_OPERATION              COUNT(*)
------------------------ ------ ------------------------------- --------
db file sequential read       1 TABLE ACCESS FULL                   6789 -- *
db file sequential read       1 INDEX RANGE SCAN                    4638
db file sequential read       1 TABLE ACCESS BY INDEX ROWID         1781
db file sequential read       1 MAT_VIEW ACCESS BY INDEX ROWID       173
db file sequential read       1 MAT_VIEW ACCESS FULL                 149 -- *
db file sequential read       1                                       27
db file sequential read       1 FIXED TABLE FULL                      19 -- *
db file sequential read       1 INDEX FAST FULL SCAN                  14 -- *

SQL>
SQL> -- Признаком чтения undo блока может быть current_obj# = 0 при ожиданиях чтения файловых блоков бд (p1text = 'file#')
SQL>
SQL> select sql_plan_operation || ' ' || sql_plan_options as SQL_PLAN_OPERATION,
  2         event,
  3         t.contents,
  4         count(*)
  5    from gv$active_session_history ash, dba_tablespaces t, dba_data_files f
  6   where ash.session_state = 'WAITING'
  7     and ash.current_obj# = 0
  8     and ash.p1text = 'file#'
  9     and ash.event = 'db file sequential read'
 10     and t.tablespace_name = f.tablespace_name
 11     and f.file_id = ash.p1
 12   group by sql_plan_operation || ' ' || sql_plan_options, t.contents, event
 13   having count(*) > 2
 14   order by count(*) desc
 15  /

SQL_PLAN_OPERATION              EVENT                    CONTENTS  COUNT(*)
------------------------------- ------------------------ --------- --------
INDEX RANGE SCAN                db file sequential read  UNDO          1167
TABLE ACCESS FULL               db file sequential read  UNDO           265 -- одноблочные чтения при выполнении FULL SCAN
MAT_VIEW ACCESS BY INDEX ROWID  db file sequential read  UNDO           112
TABLE ACCESS BY INDEX ROWID     db file sequential read  UNDO            24
db file scattered read

Фактическое среднее время многоблочного чтения файлов БД (на уровне ОС называется последовательным чтением — disk sequential read). CBO использует для расчётов значения MREADTIM либо IOSEEKTIM + DB_FILE_MULTIBLOCK_READ_COUNT*DB_BLOCK_SIZE / IOTFRSPEED при наличии или отсутствии WORKLOAD системной статистики (sys.aux_stats$)

read by other session

«сессия ожидает блок данных, который в настоящий момент считывается в буферный кэш (SGA buffer cache) другой сессией. До версии 10g событие учитывалось в группе ожиданий buffer busy wait«

SQL> @ash_wait_tree "read by other session" ""

WAIT_LEVEL BLOCKING_TREE  EVENT                    COUNT(*) AVG_TIME_WAITED_MS
---------- -------------- ------------------------ -------- ------------------
         1 FOREGROUND     read by other session         781                 30 -- одни сессии ждут
         2   FOREGROUND   db file sequential read       748                 30 -- пока другие читают
         2   FOREGROUND   db file parallel read           4                272
db file async i/o submit

недокументированное событие, появившееся начиная с Oracle 11.2, проявляется при установке комбинации параметров

disk_asynch_io                       TRUE
filesystemio_options                 none

с точки зрения настройки производительности ожидание db file async I/O submit должно рассматриваться как db file parallel write, или как другое ожидание выполнения операции дискового ввода-вывода (например, log file switch (checkpoint incomplete)). Точное название ожидания можно получить изменив значение параметра FILESYSTEMIO_OPTIONS на отличное от NONE

См. на Металинке ‘db file async I/O submit’ when FILESYSTEMIO_OPTIONS=NONE [ID 1274737.1]

direct path read

Документация: «Возникает при чтении пользовательским процессом данных с диска напрямую  в PGA (в отличие от чтения в buffer cache SGA)
В синхронном режиме ввода-вывода каждое ожидание соответствует запросу на физическое чтение. При использовании асинхронного ввода-вывода, [пользовательский] процесс Oracle способен совмещать генерацию запросов на чтение данных с обработкой блоков, уже находящихся в PGA. [И только] когда процесс пытается получить доступ к блоку, который ещё не был прочитан с диска в PGA, генерируется вызов (wait call) и обновляется статистика этого события. Таким образом, количество ожиданий не обязательно совпадает с кол-вом запросов на чтение (в отличие от ожиданий db file scattered read и db file sequential read)

Типичные ситуации возникновения ожидания:

  • Сортировка большого (по сравнению с размером PGA или sort_area_size) объёма данных, после записи во временный сегмент, данные считываются с использованием операций direct path read temp
  • Использование параллельные процессами (parallel slaves)
  • Пользовательский серверный процесс обрабатывает данные в PGA быстрее, чем система ввода-вывода может считывать очередные блоки данных (buffers). Может быть индикатором недостаточной производительности ввода-вывода»

Операция direct path read также применяется при непараллельном сканировании больших таблиц (serial direct path read) — см. High ‘direct path read’ waits in 11g [ID 793845.1]: «Начиная с Oracle 11g произошли изменения правил при выборе между операциями direct path reads и чтением через buffer cache (ожидание db file scattered read) при сканировании таблиц [full table scan].
В версии 10g, сканирование «больших» таблиц выполнялось через буферный кэш (по умолчанию). В 11g, решение о выполнении чтения данных с использованием direct path или через буферный кэш основывается на размере таблицы, размере буферного кэша и др.статистиках.
Direct path reads быстрее, чем scattered reads и меньше влияет на производительность др.процессов, т.к. исключает конкуренцию за latches«

Документ How does Oracle load data into the buffer cache for table scans ? [ID 787373.1] описывает правила выбора метода сканирования «больших» таблиц (или разделения таблиц на большие и маленькие —  smallness logic):

  • Если кол-во блоков меньше или равно параметру _small_table_threshold Oracle сканирует объект через buffer cache,  считая это более эффективным, чем использование direct read
  • Любой объект (таблица) размером менее 2% буферного кэша будет сканироваться через buffer cache без использования direct load

В блоге Alex’а Fatkulin 11G adaptive direct path reads — what is the cached/dirty blocks threshold? можно найти исследование некоторых параметров, которые берутся в расчёт Oracle при выборе использования direct path read:

  • размер (в блоках) таблицы ~ _small_table_threshold умноженный на 5
  • cached blocks threshold — кол-во блоков таблицы, уже находящихся в буферном кэше SGA
  • dirty blocks threshold— кол-во изменённых блоков таблицы, находящихся в буферном кэше SGA, не сброшенных на диск процессом DBWR

по умолчанию, при старте инстанса параметр _small_table_threshold устанавливается ~ 1.9-2 % от размера буферного кэша [__]db_cache_size / db_block_size

Для форсированного включения direct path read в документах поддержки упоминается установка параметра _serial_direct_read=TRUE (доступно на уровне сессии, значение по умолчанию FALSE до 11.2.0.1 включительно)

Для отключения Dion Cho Disabling direct path read for the serial full table scan– 11g нашёл и описал событие 10949:

$ oerr 10949
  "Disable autotune direct path read for full table scan"
// *Cause:
// *Action:  Disable autotune direct path read for serial full table scan.
//
SQL> alter session set events '10949 trace name context forever, level 1';

Соответствующая ожиданию статистика physical reads direct

direct path write / direct path write temp

Документация: «Ожидание выполнения операции записи (write call) возникает, когда пользовательский процесс пишет блоки данных данные напрямую из PGA (в отличие от DBWR, пишущего на диск из buffer cache SGA). Direct path writes выполняется при след.операциях: дисковые сортировки (direct path write temp), параллельные DML, direct-path INSERT, параллельные create table as select и некоторые операции с LOB

Аналогично direct path reads, количество ожиданий не обязательно совпадает с кол-вом запросов на запись в асинхронном режиме»

Соответствующая ожиданию статистика physical write direct

Операции LOAD TABLE CONVENTIONAL / LOAD AS SELECT: direct-path и другие способы вставки в 11.2

db file parallel read

«… кроме recovery, операция используется при buffer prefetching [опережающем чтении блоков данных] как оптимизация I/O (заменяя несколько одноблочных чтений (single-block reads))…»

В 11g используется, в основном, при индексном доступе к блокам таблицы, выполняемом параллельно PX slaves процессами

11.2.0.3.@ SQL> select sql_opname,
  2         case when qc_session_id is not null then 'PX' else session_type end as "Program",
  3         sql_plan_operation, sql_plan_options,
  4         p1text, round(avg(p1)) p1, p2text, round(avg(p2)) p2, p3text, round(avg(p3)) p3,
  5         count(*)
  6    from gv$active_session_history
  7  where event = 'db file parallel read'
  8   group by sql_opname,
  9         case when qc_session_id is not null then 'PX' else session_type end,
 10         sql_plan_operation, sql_plan_options,
 11         p1text, p2text, p3text
 12   order by count(*) desc
 13  /

SQL_OPNAME  Program     SQL_PLAN_OPERATION  SQL_PLAN_OPTIONS  P1TEXT  P1 P2TEXT   P2 P3TEXT     P3   COUNT(*)
----------- ----------- ------------------- ----------------- ------- -- --- --- --- -------- ---- ----------
SELECT      PX          TABLE ACCESS        FULL              files    1 blocks   39 requests   39       1261 -- НЕиндексный доступ PX процессами
INSERT      PX          INDEX               RANGE SCAN        files    3 blocks    6 requests    6        553 -- индексный доступ PX процессами
SELECT      FOREGROUND  INDEX               UNIQUE SCAN       files    5 blocks   26 requests   26        311 -- чтение блоков индекса
SELECT      FOREGROUND  INDEX               RANGE SCAN        files    9 blocks   58 requests   58        166
UPDATE      FOREGROUND  TABLE ACCESS        FULL              files    1 blocks  106 requests  106        121
SELECT      FOREGROUND  TABLE ACCESS        BY INDEX ROWID    files    3 blocks   19 requests   19         82
INSERT      PX          TABLE ACCESS        BY INDEX ROWID    files    3 blocks   10 requests   10         65
SELECT      FOREGROUND  TABLE ACCESS        FULL              files    1 blocks   33 requests   33         26
DELETE      FOREGROUND  TABLE ACCESS        FULL              files    1 blocks  116 requests  116         24
SELECT      PX          INDEX               FAST FULL SCAN    files    1 blocks   37 requests   37         23

см.также комментарии к Index Join vs Index Bitmap и использование db file parallel read при доступе к блокам таблицы

async disk IO | ksfd: async disk IO

Ожидание выполнения асинхронной операции ввода-вывода, описание для 9.2 WAITEVENT: «async disk IO» Reference Note [ID 170357.1]

http://www.saptechies.com/oracle-wait-events/: «… может наблюдаться в следующих ситуациях: создание табличных пространств, создание и расширение файлов данных, операции RMAN backup, архивирование логов процессами ARCH, AUTOEXTEND расширений файлов (например, при операциях INSERT)»

control file sequential read

блокирующее чтение данных из контрольного файла, доступ регулируется блокировкой CF — contention:

SQL> select event, count(*)
2    from v$active_session_history
3   where (sample_time, session_id, session_serial#) in
4         (select sample_time, blocking_session, blocking_session_serial#
5            from v$active_session_history
6           where event = 'enq: CF - contention'
7             and blocking_session_status <> 'GLOBAL')
8   group by event
9   order by count(*) desc
10  /

EVENT                                                              COUNT(*)
---------------------------------------------------------------- ----------
control file sequential read                                            900
control file parallel write                                              61
...

см. также enq: CF – contention

Не учитывается в ожиданиях пользовательского ввода-вывода, например, в V$SQL.USER_IO_WAIT_TIME

Disk file operations I/O

Параметры:

SQL> select parameter1, parameter2, parameter3 from v$event_name where name = 'Disk file operations I/O';

PARAMETER1     PARAMETER2  PARAMETER3
-------------- ----------- ----------
FileOperation  fileno      filetype

Типы файлов и операций из блога Kyle Hailey:

SQL> select distinct filetype_id as filetype, filetype_name from DBA_HIST_IOSTAT_FILETYPE order by 1;

   FILETYPE FILETYPE_NAME
----------- ------------------------------
          0 Other
          1 Control File
          2 Data File
          3 Log File
          4 Archive Log
          6 Temp File
          9 Data File Backup
         10 Data File Incremental Backup
         11 Archive Log Backup
         12 Data File Copy
         17 Flashback Log
         18 Data Pump Dump File

FileOperation Desc
------------- --------------------------------------------------------
            1 file creation
            2 file open
            3 file resize
            4 file deletion
            5 file close
            6 wait for all aio requests to finish
            7 write verification
            8 wait for miscellaneous io (ftp, block dump, passwd file)
            9 read from snapshot files
utl_file I/O

В соответствии с документацией ожидание фиксируется при использовании процедур пакета UTL_FILE

Ожидание utl_file I/O

Обработка логов (Log waits)

log file sync

Пользовательский сессия (foreground process) ожидает совершения системным (background) процессом LGWR операции записи модифицированных данных из буфера в локальный или удалённый (при SYNC конфигурации standby сервиса) redo log файл во время выполнения пользовательской сессией операции завершения транзакции COMMIT / ROLLBACK

Может быть заметно в случае низкой скорости дисковой записи / сетевой передачи логов или высокой конкуренции за системные ресурсы (диск, процессор).

Типичные причины: неудачное размещение и [коственно] малый размер файлов redo, низкая производительность и/или неудачная конфигурация подсистемы ввода-вывода*), либо высокая (возможно, избыточная?) интенсивность операций COMMIT / ROLLBACK**. Нормальное время ожидания не должно превышать нескольких миллисекунд для OLTP систем

*) Пример: несколько копий лог файлов (для «надёжности») на одном небыстром разделе RAID5 либо RAID6 (для «экономии»). Время ожидания может легко превышать и 20, и 30, и 80 ms. Oracle категорически не рекомендует RAID5 для размещения online redo log файлов

**) При невозможности изменить приложение с целью уменьшить частоту транзакций, для буферизации и выбора асинхронного режима можно рассмотреть изменение параметров COMMIT_WRITE (начиная с Oracle 10g) или COMMIT_LOGGING, COMMIT_WAIT (начиная с 11g)

WAITEVENT: «log file sync» Reference Note [ID 34592.1]:

Ожидание log file sync может состоит из следующих компонент:
1. сессия пользователя посылает вызов системному процессу LGWR, который начинает обработку запроса, если не занят обработкой др.вызовов
2. LGWR собирает/готовит необходимые для записи redo данные и вызывает операцию ввода/вывода
3. операция записи redo write
4. обработка результатов записи процессом LGWR
5. LGWR посылает сообщение пользовательской сессии сообщение о выполнении операции записи
6. сессия пользователя продолжает работу

Шаги 2 и 3 суммируются в статистике redo write time
Шаг 3 соответствует системному событию ожидания (Background Wait Events) log file parallel write
Шаги 5 и 6 могут занимать значительное время при увеличенной системной загрузке (load average) … после посылки сообщения пользовательскому процессу о завершении выполнения операции, ОС может потребоваться время до очередного запуска пользовательского процесса на выполнение…

RAC life cycle of ‘log file sync’:

  1. A user sessions issues a commit or rollback and starts waiting on log file sync
  2. LGWR gather redo information to be written to redo log files, issues IO and queues BOC to an LMS process and posts LMS process
  3. LGWR waits for redo buffers to be flushed to disk and SCN to be ACK’d
  4. Completion of IO and receiving ACK from LMS signal write complete. LGWR then posts foreground process to continue
  5. Foreground process wakes up and log file sync wait ends

На пример отчёта AWR небольшого RAC 11.2.0.3 можно видеть, что время ожидания log file sync , в основном, тратится на запись логов процессом LGWR с ожиданием log file parallel write, которое кроме того включает время обработки запросов Global Cache Service  от процессов LMS с соответсвующим ожиданием gcs log flush sync:

Load Profile              Per Second    Per Transaction
~~~~~~~~~~~~         ---------------    ---------------
...
       Redo size:        3,996,082.0           24,189.1

                                                             Avg
                                        %Time Total Wait    wait    Waits   % DB
Event                             Waits -outs   Time (s)    (ms)     /txn   time
-------------------------- ------------ ----- ---------- ------- -------- ------
...
log file sync                     8,551     0        820      96      0.0    8.4
...
log file parallel write          72,780     0      1,214      17      0.2   22.8 --> Total Wait Time ~ "log file sync" + "gcs log flush sync" Wait Times - в этом случае
...                                                                              --> Avg wait ~= "redo write time" / "redo writes" = 1.677 cs
gcs log flush sync              191,999    10        451       2      0.6    8.5

Statistic                                     Total     per Second     per Trans
-------------------------------- ------------------ -------------- -------------
redo blocks written                      14,623,063        8,096.2          49.0 --> per Second: "Redo size" / "redo blocks written" = redo block size ~ 500 bytes
redo synch time                              82,123           45.5           0.3 --> centisec, Total ~= "log file sync" Total Wait Time
redo synch time (usec)                  821,182,214      454,655.9       2,752.1 --> --//--
redo synch writes                             8,593            4.8           0.0 --> Total ~= "log file sync" Waits
redo write broadcast ack count                  255            0.1           0.0 --> BOC SCN = Broadcast On Commit SCN
redo write broadcast ack time             1,394,821          772.3           4.7 --> микросекунды в отличие от "redo synch time", т.е. всего 1.3 сек
redo write time                             122,031           67.6           0.4 --> centisec, ~= "log file parallel write" Total Wait Time
redo writes                                  72,779           40.3           0.2 --> per Second: "redo blocks written" / "redo writes" ~= 200 redo blocks | 100 KB per LGWR write operation

Для диагностики log file sync и связанных ожиданий может быть полезен скрипт lfsdiag.sql с сайта поддержки Oracle:

  • параметры, влияющие на log file sync
  • гистограммы ожиданий
  • вычисляет и выводит данные о периодах наихудших средних времён ожидания log file sync из репозиториев Active Session History / AWR

Простой пример влияния конфигурации передачи логов на удалённый standby (определяемой параметром log_archive_dest_n) на ожидания log file sync и log file switch completion, первоначальная конфигурация:

11.1.0.7@ SQL> @param log_archive_dest

NAME                                       VALUE
------------------------------------------ -------------------------------------------------------------------------
log_archive_dest_1                         location=+DATA/
log_archive_dest_2                         SERVICE=stby_service sync affirm VALID_FOR=(ONLINE_LOGFILE,PRIMARY_ROLE)

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           28,136          45.2
db file sequential read           5,361,381      12,673      2   20.3 User I/O
log file sync                        96,207      11,887    124   19.1 Commit     -- более 100 мс в среднем!

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

BLOCKING_TREE  EVENT                        WAITS_COUNT AVG_WA
-------------- ---------------------------- ----------- ------
FOREGROUND     log file sync                      21629    544
  (LGWR)       LGWR-LNS wait on channel           17062     10 -- основное блокирующее ожидание, при этом
  (LGWR)       log file parallel write             3372    202 -- передачу логов на стендбай осуществляет LGWR
  (LGWR)       control file parallel write           31     91
  (LGWR)       LGWR wait for redo copy               22      5
  (LGWR)       LGWR wait on LNS                      14      0
  (LGWR)       control file sequential read          14     49

SQL> @ash_wait_tree "event='log file switch completion'"

BLOCKING_TREE                  EVENT                         WAITS_COUNT AVG_WA
------------------------------ ----------------------------- ----------- ------
FOREGROUND                     log file switch completion           1214    101
  (LGWR)                       LGWR-LNS wait on channel              741     11 -- также блокируется передачей логов процессом LGWR
  (LGWR)                       ARCH wait for netserver start         415   1026 -- --//--
  (LGWR)                       control file parallel write            14     49
  (LGWR)                       log file parallel write                 2     56

, после установки log_archive_dest_2 = «SERVICE=stby_service_2 ARCH ASYNC NOAFFIRM VALID_FOR=(ONLINE_LOGFILE,PRIMARY_ROLE)»:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           20,937          57.4
db file sequential read           4,005,014       8,256      2   22.6 User I/O
log file sync                        73,409         856     12    2.3 Commit     -- ср.время и доля ожидания снизились на порядок
...

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

BLOCKING_TREE  EVENT                        WAITS_COUNT AVG_WA
-------------- ---------------------------- ----------- ------
FOREGROUND     log file sync                       3667    443
  (LGWR)       log file parallel write             2976    310 -- в основном блокируется локальной записью логов процессом LGWR
  (LGWR)       control file sequential read          65    656
  (LGWR)       control file parallel write           37    928
  (LGWR)       LGWR wait for redo copy                8      1
  (LGWR)       enq: CF - contention                   1     15
  (LGWR)       rdbms ipc message                      1     55
    (CKPT)     control file sequential read           1      5
...
                                                             Avg
                                        %Time Total Wait    wait    Waits   % bg
Event                             Waits -outs   Time (s)    (ms)     /txn   time
-------------------------- ------------ ----- ---------- ------- -------- ------
log file parallel write          79,889     0        452       6      1.1   20.8 -- скорость локальной записи в обоих случаях не менялась
log buffer space

Tuning the Redolog Buffer Cache and Resolving Redo Latch Contention (Doc ID 147471.1)

log file switch completion

комплексное ожидание завершения процесса переключения online лог файлов

вероятные причины:

  • недостаточный размер online лог файлов
  • недостаточное количество групп лог файлов
  • недостаточная скорость записи / передачи redo
  • блокировки синхронного доступа к controlfile
11.2.@ SQL> @ash_wait_tree "log file switch completion" ""

WAIT_LEVEL BLOCKING_TREE  EVENT                        WAITS_COUNT AVG_TIME_WAITED_MS
---------- -------------- ---------------------------- ----------- ------------------
         1 FOREGROUND     log file switch completion       108                    749
         2   LGW          control file sequential read      16                     97
         2   LGW          control file parallel write       13                     49
         2   LGW          log file sequential read          11                     54
         2   LGW          log file single write              4                     30
         2   LGW          log file parallel write            1                    338
log file switch (checkpoint incomplete)

задержка переключения лог файлов по причине незаконченной операции checkpoint — записи процессом DBWR модифицированных блоков бд из буферного кэша бд (db buffer cache) на диск

log file switch (private strand flush incomplete)

Data Guard Wait Events [ID 233491.1]
Data Guard Redo Transport & Network Best Practices. Oracle Database 10g Release 2 (2007)

 — описываются системные ожидания (background wait events) процессов LGWR, LNS, ARCH при выполнении сетевых операций в зависимости от атрибутов ARCH, LGWR, SYNC, ASYNC параметра LOG_ARCHIVE_DEST_n

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

LVL INST_ID BLOCKING_TREE   EVENT                     WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS
--- ------- --------------- ------------------------- ----------- ---------- ----------------
  1       1 (LGWR)          LGWR wait for redo copy            15          1                2 -- LGWR блокирован/ожидает освобождения redo copy latch
  2       1   FOREGROUND    On CPU / runqueue                   8          6                0 -- пользовательскими процессами
  1       2 (LGWR)          LGWR wait for redo copy             9          1                7 -- --//--
  2       2   FOREGROUND    On CPU / runqueue                   7          5                0 -- --//--

SQL> select * from v$event_name where name = 'LGWR wait for redo copy';

NAME                      PARAMETER1     PARAMETER2   PARAMETER3   WAIT_CLASS
------------------------- -------------- ------------ ------------ ----------
LGWR wait for redo copy   copy latch #                             Other      -- один параметр - номер дочернего latch-а,

SQL> select count(*) from v$latch_children where name like 'redo copy';

  COUNT(*)
----------
        48                                                                    -- общее кол-во которых определяется параметром

SQL> @param_  _log_simultaneous_copies

NAME                      VALUE  IS_DEF   DSC
------------------------- ------ -------- -----------------------------------------------------------------
_log_simultaneous_copies  48     TRUE     number of simultaneous copies into redo buffer(# of copy latches)
{ARCH | LGWR | LNS} wait on ATTACH

ожидание ARC | LGWR соединения с процессами RFS (Remote File Server) для выполнения архивации на удалённый сервис

Например, при безуспешных попытках архивации логов на отсутствующие/неработающие LOG_ARCHIVE_DESTINATION SERVICE, в AWR можно наблюдать сетевой таймаум ~ 352 сек.:

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
ARCH wait on ATTACH                      10     .0       3,525  352549       0.0

при этом соответствующий V$ARCHIVE_DEST.STATUS будет периодически менять значение VALID / ERROR

{ARCH | LGWR | LNS} wait on SENDREQ

открытие, запись полученных redo данных, закрытие удалённых лог-файлов

{ARCH | LGWR | LNS} wait on DETACH

завершение RFS соединения

LGWR wait on LNS
LNS wait on LGWR

обмен сообщениями между LGWR и LNS

LGWR-LNS wait on channel

отражает время ожидания сообщений по KSR (Control message Service Remote?) каналу процессами LoG WriteR (LGWR) или LGWR Network Server (LNS)

Пример: при передаче логов на standby в SYNC режиме:

SQL> select a.status, a.target, a.ARCHIVER, a.DESTINATION, a.PROCESS, a.TRANSMIT_MODE, a.AFFIRM, a.VALID_TYPE
2  from V$ARCHIVE_DEST a where dest_id in (1,2,3)
3  /

STATUS TARGET  ARCHIVER DESTINATION      PROCESS    TRANSMIT_MODE AFFIRM VALID_TYPE
------ ------- -------- ---------------- ---------- ------------- ------ ---------------
VALID  PRIMARY ARCH     +DATA            ARCH       SYNCHRONOUS   NO     ALL_LOGFILES
VALID  STANDBY LGWR     standby-db1.net  LGWR       PARALLELSYNC  YES    ONLINE_LOGFILE
VALID  STANDBY LGWR     standby-db2.net  LGWR       PARALLELSYNC  YES    ONLINE_LOGFILE

AWR показывает значительную долю ожиданий log file sync в топе:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                          Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           57,572          38.6
db file sequential read           3,390,943      25,810      8   17.3 User I/O
log file sync                        47,988      22,466    468   15.0 Commit

Пользовательские процессы (JDBC Thin Client) при выполнении commit ожидают завершения операции log file sync, выполняемой системным процессом LGWR, который в свою очередь ожидает (в основном) события LGWR-LNS wait on channel, вызванного синхронной передачей логов (на standby):

SQL> select * from (
2  select w1.SQL_ID, w1.EVENT WAIT_EVENT, en.wait_class, w1.PROGRAM waiting_process, h1.PROGRAM holding_process, h1.EVENT hold_event, count(*)
3  from v$active_session_history w1, v$active_session_history h1, dba_hist_event_name en
4  where w1.event = 'log file sync'
5  and w1.EVENT_ID = en.event_id
6  and w1.BLOCKING_SESSION = h1.SESSION_ID
7  and w1.BLOCKING_SESSION_SERIAL# = h1.SESSION_SERIAL#
8  and w1.SAMPLE_TIME = h1.SAMPLE_TIME
9  group by w1.SQL_ID, w1.EVENT, en.wait_class, w1.PROGRAM , h1.PROGRAM, h1.EVENT
10  order by count(*) desc
11  ) where rownum 12  /

SQL_ID        WAIT_EVENT     WAIT_CLASS  WAITING_PROCESS   HOLDING_PROCESS              HOLD_EVENT                COUNT(*)
------------- -------------- ----------- ----------------- ---------------------------- ------------------------- --------
              log file sync  Commit      JDBC Thin Client  oracle@primary-db.ru (LGWR)  LGWR-LNS wait on channel     13440
              log file sync  Commit      JDBC Thin Client  oracle@primary-db.ru (LGWR)  log file parallel write       2867

После отключения SYNC режима для удалённых LOG_ARCHIVE_DEST среднее и суммарное времена ожидания log file sync снижаются на порядок (примерно в той же пропорции ускоряя бизнес-процессы, активно пишущие/обновляющие данные):

                                                             Avg
                                        %Time Total Wait    wait    Waits   % DB
Event                             Waits -outs   Time (s)    (ms)     /txn   time
-------------------------- ------------ ----- ---------- ------- -------- ------
...
log file sync                    48,947     0      2,105      43      1.0    2.4

Ожидание LGWR-LNS wait on channel ожидаемо исчезает из топа ожиданий, блокирующих пользовательские операции commit:

SQL> select * from (
2  select w1.SQL_ID, w1.EVENT WAIT_EVENT, en.wait_class, w1.PROGRAM waiting_process, h1.PROGRAM holding_process, h1.EVENT hold_event, count(*)
3  from v$active_session_history w1, v$active_session_history h1, dba_hist_event_name en
4  where w1.event = 'log file sync'
5  and w1.EVENT_ID = en.event_id
6  and w1.BLOCKING_SESSION = h1.SESSION_ID
7  and w1.BLOCKING_SESSION_SERIAL# = h1.SESSION_SERIAL#
8  and w1.SAMPLE_TIME = h1.SAMPLE_TIME
9  group by w1.SQL_ID, w1.EVENT, en.wait_class, w1.PROGRAM , h1.PROGRAM, h1.EVENT
10  order by count(*) desc
11  ) where rownum 12  /

SQL_ID        WAIT_EVENT     WAIT_CLASS  WAITING_PROCESS   HOLDING_PROCESS              HOLD_EVENT               COUNT(*)
------------- -------------- ----------- ----------------- ---------------------------- ------------------------ ----------
              log file sync  Commit      JDBC Thin Client  oracle@primary-db.ru (LGWR)  log file parallel write  2921
              log file sync  Commit      JDBC Thin Client  oracle@primary-db.ru (LGWR)  enq: CF - contention      139

*) LNS process is «LGWR Network Server», which is used when the LGWR is responsible for REDO transport to the Standby Database

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

Ожидания при работе с разделяемой памятью Oracle Shared Pool

library cache load lock
library cache lock [object handle]
library cache pin [object heap]

События, контролирующие загрузку и совместный доступ к объектам Library Cache (table, view, procedure, function, package, package body, trigger, index, cluster, synonym)

Лучшее описание: Troubleshooting Library Cache: Lock, Pin and Load Lock [ID 444560.1]

Сергей Жилин. Практическое администрирование Oracle — Ожидание Library cache pin

Пример:

11.2.0.1.ORCL112@SCOTT SQL> create or replace procedure scott.sleep(n number default 60)
  2  as
  3  begin
  4    dbms_lock.sleep(n);
  5  end;
  6  /

Procedure created.

SID#368 SQL> exec sleep(1000);
...

SID#357 SQL> ALTER PROCEDURE scott.sleep COMPILE;
...

SID#347 SQL> ALTER PROCEDURE scott.sleep COMPILE;
...

11.2.0.3.ORCL112@SYS SQL> @kgllockpin

HANDLER          KGLOBTYD  KGLNAOWN KGLNAOBJ  KGLLKTYPE  MODE_HELD  MODE_REQ   SECS_IN_WAIT EVENT              SID    SERIAL PROGRAM      SQL_TEXT
---------------- --------- -------- --------- ---------- ---------- ---------- ------------ ------------------ ------ ------ ------------ ------------------------------------
000007FF1E2DA3E0 PROCEDURE SCOTT    SLEEP     Lock       Null       None       368          PL/SQL lock timer      52  32319 plsqldev.exe  begin sleep(1000); end;
000007FF1E2DA3E0 PROCEDURE SCOTT    SLEEP     Pin        Share      None       368          PL/SQL lock timer      52  32319 plsqldev.exe  begin sleep(1000); end;
000007FF1E2DA3E0 PROCEDURE SCOTT    SLEEP     Lock       Exclusive  None       357          library cache pin      91  1651  plsqldev.exe  ALTER PROCEDURE scott.sleep COMPILE
000007FF1E2DA3E0 PROCEDURE SCOTT    SLEEP     Pin        None       Exclusive  357          library cache pin      91  1651  plsqldev.exe  ALTER PROCEDURE scott.sleep COMPILE
000007FF1E2DA3E0 PROCEDURE SCOTT    SLEEP     Lock       None       Exclusive  347          library cache lock     48  1093  plsqldev.exe  ALTER PROCEDURE scott.sleep COMPILE
  1. сессия 368 на время выполнения процедуры sleep(1000); удерживает Library Cache Lock (на дескриптор процедуры) в состянии Null и Pin (на объект пула) в моде Share
  2. следующая по времени запуска сессия 357 для рекомпиляции той же процедуры получила Lock в состянии Exclusive и ожидает Exclusive Pin на соответствующем событии library cache pin. Pin (объект процедуры в Library Cache) блокирован сессией 368 на время выполнения в Share моде во избежание изменений
  3. последняя по времени сессия 347 ожидает Lock в Exclusive моде, кот.удерживается сессией 357 на соответствующем событии library cache lock. Получение Pin (блокировки на объект) до получения Lock (нахождение и блокировка дескриптора) невозможно

Скрипт KGLLOCKPIN.SQL

SQL> select kglhdnsd, kglobtyd, kglnaown, kglnaobj--, kglnatim, kglobt03, kglobts0, kglobts5, kglnao1n
  2    from x$kglob w, gv$active_session_history ash
  3   where kglhdadr = lpad(trim(to_char(p1, 'xxxxxxxxxxxxxxxx')), 16, '0')
  4     and ash.event = 'library cache lock'
  5  /
 
KGLHDNSD        KGLOBTYD  KGLNAOWN  KGLNAOBJ
--------------- --------- --------- ----------------
SQL AREA BUILD  CURSOR    $BUILD$   8810fb124cc9bf92
SQL AREA BUILD  CURSOR    $BUILD$   73367f4f9672070a
...
cursor: pin S wait on X (library cache pin)

WAITEVENT: «cursor: pin S wait on X» Reference Note [ID 1298015.1]:

  • P1 = idn = Mutex identifier = V$SQL.hash_value
  • P2 = value = Mutex value (includes details of holder)
    High order bits contain the session id of the session holding the mutex
    Low order bits contain a reference count (which should be 0 if there is an X mode holder)
  • P3 = where = The high order bits of P3 give a number which represents a location in the Oracle code where the mutex was requested from …

… сессия ожидает получить  shared mutex pin на курсор в то время как другая сессия удерживает exclusive mutex pin на тот же курсор. Т.о. сессия вынуждена ждать пока блокирующая в X mode сессия освободит ресурс (release the mutex)…
Mutexes — локальные структуры текущей системы (инстанса) в RAC

select h.sid SID_WAITING_MUTEX,
       s.sql_id,
       s.sql_text,
       decode(trunc(h.p2 / 4294967296),
              0,
              trunc(h.p2 / 65536),
              trunc(h.p2 / 4294967296)) SID_HOLDING_MUTEX,
       m.MUTEX_TYPE,
       m.LOCATION MUTEX_LOCATION
from v$session h, v$sqlarea s, x$mutex_sleep m
where h.event = 'cursor: pin S wait on X'
  and h.p1 = s.HASH_VALUE
  and decode(trunc(h.p3 / 4294967296),
             0,
             trunc(h.p3 / 65536),
             trunc(h.p3 / 4294967296)) = m.location_id(+)
  and nvl(m.mutex_type, 'Cursor Pin') like 'Cursor Pin%';

SID_WAITING_MUTEX SQL_ID        SQL_TEXT       SID_HOLDING_MUTEX MUTEX_TYPE MUTEX_LOCATION
----------------- ------------- -------------- ----------------- ---------- --------------
1017 6vbz13st2s8p0  INSERT INTO "               968                          

Ожидание, связанное с разбором SQL при использовании mutex механизма (начиная с Oracle 10.2, аналог события library cache pin традиционного library cache механизма) во время компиляции child cursor –> см. подробное обсуждение, системные обзоры:

V$MUTEX_SLEEP — статистика

V$MUTEX_SLEEP_HISTORY — история

Связанные параметры:

_KKS_USE_MUTEX_PIN = FALSE — отключает использование mutex механизма, см. 564719.1 Catupgrd.sql Hangs waiting for Cursor: Pin S Wait On X

CURSOR_SHARING – в частности, событие оказывало значительное влияние на производительность (загрузку процессоров) при значении параметра CURSOR_SHARING = SIMILAR в присутствии гистограмм (автоматический сбор статистики по столбцам METHOD_OPT = FOR ALL COLUMNS SIZE AUTO) – OLTP DB Web приложения без использования связанных переменных в версии 10.2.

Связанные проблемы:

high version count — см. 261020.1 High Version Count with CURSOR_SHARING = SIMILAR or FORCE
unsafe binds — см. 731468.1 QUERIES HAVING HUGE VERSION COUNTS WHEN CURSOR_SHARING=SIMILAR

Возможные способы уменьшения ожиданий:

Отключение (исключение) гистограм распределения значений в столбцах таблиц в статистике объектов БД. Например, можно установить на уровне системы параметр METHOD_OPT = FOR ALL COLUMNS SIZE 1, который отключит исключит расчёт гистограм из процедур автоматического сбора статистики

SQL> exec dbms_stats.set_param('METHOD_OPT','FOR ALL COLUMNS SIZE 1');

Использование значения параметра CURSOR_SHARING=FORCE

Использование связанных переменных в приложении и значения по умолчанию параметра CURSOR_SHARING=EXACT

Ожидание может быть заметно при проблемах свободного места в shared pool — см. ASMM: ORA-04031 и «cursor: pin S wait on X»

11.2: ожидание cursor: pin S wait on X при избыточной генерации курсоров параллельного выполнения

Ещё одним источником кратковременных всплесков ожиданий cursor: pin S wait on X / library cache lock могут быть DDL операции при наличии проблем ввода-вывода, например, при выполнении TRUNCATE партицированной таблицы можно наблюдать:

11.1.0.7@ SQL> @ash_wait_tree "event = 'cursor: pin S wait on X'"

LVL BLOCKING_TREE   SQL_ID        EVENT                        WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS
--- --------------- ------------- ---------------------------- ----------- ---------- ----------------
  1 FOREGROUND      as03vv3zvnfdv cursor: pin S wait on X             8335         31               11 -- 31 сессия, выполняя "MERGE INTO "SOME_TABLE" ..."
  2   FOREGROUND    as03vv3zvnfdv library cache lock                  8335          1             7853 -- много раз ожидали 1 сессию, ожидавшую
  3     FOREGROUND  a2wnku2uzfvnd local write wait                    4549          1              852 -- сессию, выполнявшую "truncate table "SOME_TABLE" drop storage"
  3     FOREGROUND  a2wnku2uzfvnd db file sequential read             1939          1              409
  3     FOREGROUND  a2wnku2uzfvnd enq: RO - fast object reuse         1233          1             1027
  3     FOREGROUND  a2wnku2uzfvnd reliable message                     552          1              875
  4       (CKPT)                  control file parallel write          114          1              526
  4       (CKPT)                  control file sequential read         110          1              460
  4       (CKPT)                  direct path write                     29          1              785

SQL> @ash_wait_tree "event = 'library cache lock' and sql_id = 'as03vv3zvnfdv'"

LVL BLOCKING_TREE  SQL_ID        EVENT                        WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS
--- -------------- ------------- ---------------------------- ----------- ---------- ----------------
  1 FOREGROUND     as03vv3zvnfdv library cache lock                   296          1             7133 -- MERGE INTO "SOME_TABLE" ...
  2   FOREGROUND   a2wnku2uzfvnd local write wait                     165          1              853 -- truncate table "SOME_TABLE" ...
  2   FOREGROUND   a2wnku2uzfvnd db file sequential read               65          1              407 -- --\\--
  2   FOREGROUND   a2wnku2uzfvnd enq: RO - fast object reuse           44          1             1025 -- --\\--
  2   FOREGROUND   a2wnku2uzfvnd reliable message                      20          1              883 -- --\\--
  3     (CKPT)                   control file sequential read           4          1              457
  3     (CKPT)                   control file parallel write            4          1              517
  3     (CKPT)                   direct path write                      1          1              785

SQL> @ash_wait_tree "event = 'enq: RO - fast object reuse' and sql_id = 'a2wnku2uzfvnd'"

LVL BLOCKING_TREE  SQL_ID        EVENT                        WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS
--- -------------- ------------- ---------------------------- ----------- ---------- ----------------
  1 FOREGROUND     a2wnku2uzfvnd enq: RO - fast object reuse           44          1             1025 -- truncate table "SOME_TABLE" ...
  2   (CKPT)                     control file sequential read           4          1              457
  2   (CKPT)                     control file parallel write            4          1              517
  2   (CKPT)                     direct path write                      1          1              785

*) local write waitTruncate operations cause the DBWR to be posted to flush out the space header

SQL> select p1text,
  2         count(distinct p1) as "Count",
  3         p2text,
  4         count(distinct p2) as "Count",
  5         count(distinct current_obj#) as "ObjCount"
  6    from v$active_session_history
  7   where event = 'local write wait'
  8     and sql_id = 'a2wnku2uzfvnd'
  9   group by p1text, p2text, p3text
 10  /

P1TEXT    Count P2TEXT      Count   ObjCount
------ -------- ------ ---------- ----------
file#         7 block#        111         35 -- truncate партицированной таблицы зафиксировал запись 111 блоков (заголовков) 35 объектов (партиций)

SQL> select distinct object_type
  2    from dba_hist_seg_stat_obj
  3   where obj# in (select current_obj#
  4                    from v$active_session_history
  5                   where event = 'local write wait'
  6                     and sql_id = 'a2wnku2uzfvnd')
  7  /

OBJECT_TYPE
------------------
INDEX PARTITION    -- зафиксированы оказались только партиции индексов
Library cache: mutex X

WAITEVENT: «library cache: mutex X» [ID 727400.1]

Bug 10632113 — OLS calls cause mutex contention even with low number of concurrent users [ID 10632113.8] наблюдается на 11.2.0.2 не только при использовании Oracle Label Security, но и при др.частых вызовах нескольких PL/SQL процедур, например, при логине/инициализации окружения. Патч включен в 11.2.0.3

Cursor: pin S

Последние 2 события связаны с высокой конкуренцией за частоиспользуемые объекты library cache, которая, начиная с Oracle 11.2.0.2 может быть уменьшена «клонированием»  (созданием нескольких копий объекта в  library cache) —  подробное описание технологии -> Divide and conquer the “true” mutex contention

kksfbc child completion

ожидание завершения процесса формирования/построения дочернего курсора, относится к фазе hard parse, часто наблюдается при большом количестве дочерних курсоров, сигнализируя о проблеме high version count

Наблюдаемый в Oracle 11g таймаут 50 мс

SGA: allocation forcing component growth

Doc:

Process waiting on an immediate mode memory transfer with auto-tune SGA after a 4031 for MMAN to get the memory and post it.
Wait Time: 10 msec

The waits for «SGA: allocation forcing component growth» indicates that SGA is inadequate. It looks like there is no enough memory available in SGA for the growth of components.

Для уменьшения ожидания логично выяснить и устранить причины конкуренции за память в области shared pool SGA (ORA-4031):

  • избыточную активность процесса автоматического перераспределения памяти ASMM
  • использование и фрагментацию shared pool
  • баги Oracle

ASMM: ORA-04031 и «cursor: pin S wait on X»

ORA-04031 errors and monitoring shared pool subpool memory utilization with sgastatx.sql

Блокировки / Enqueue разного рода

102925.1 Tracing sessions: waiting on an enqueue:

«Зачастую слово «блокировка» («lock») используется в качестве синонима к слову enqueue — очередь, ожидание очереди. Термин enqueue используется [Oracle] для обозначения механизма блокировки (locking mechanism), детали которого отражены в системном обзоре V$LOCK. Термин блокирование («locking») будет использоваться для следующих событий: запрос на постановку в очередь (requesting an enqueue) [для доступа к разделяемому ресурсу], ожидания доступа (waiting on an enqueue) и блокирование доступа со стороны других процессов во время использования (blocking others while holding the enqueue).

Блокировка (lock) — это ресурс, который требуется удерживать для получения доступа к ресурсу. У Oracle есть два типа блокировок (locks): enqueues (очереди) и latches (защёлки) …» [с различными механизмами доступа]

Описание типов (V$LOCK.TYPE) и параметров блокировок (V$LOCK.ID1, V$LOCK.ID2) можно получить из обзора V$LOCK_TYPE

Удельный вес разных типов блокировок (с момента старта системы) можно получить из GV$ENQUEUE_STAT

SQL> select * from GV$ENQUEUE_STAT order by CUM_WAIT_TIME desc;

 INST_ID   EQ TOTAL_REQ# TOTAL_WAIT#  SUCC_REQ# FAILED_REQ# CUM_WAIT_TIME
---------- -- ---------- ----------- ---------- ----------- -------------
         2 TX    1135032        2175    1132833        2192       4137530
         1 TX     363081         719     362528         549       1913420
         2 TM    1488558        3589    1488072         483         43320
         1 TM     474879         774     474788          89         21800
         2 KO       3032         809       3032           0         11780
         2 WF        190         100        190           0          8260
         2 TS         18          13         17           1          4610

Режимы, в которых блокировки удерживаются или ожидаются сессиями в Oracle (lock mode, V$LOCK.LMODE)

  • 1 — null (NULL)
  • 2 — row-S (SS) — Sub[set] Share
  • 3 — row-X (SX) — Sub[set] eXclusive
  • 4 — share (S)
  • 5 — S/Row-X (SSX)
  • 6 — exclusive (X)

При описании глобальных блокировок (global deadlock detection) в разделе Global Wait-For-Graph(WFG) трейса LMD используются другие цифровые обозначения типов блокировок (GES enqueue lock mode)

#define KJUSERNL 0         /* no permissions */   (Null)
#define KJUSERCR 1         /* concurrent read */  (Row-S (SS))
#define KJUSERCW 2         /* concurrent write */ (Row-X (SX))
#define KJUSERPR 3         /* protected read */   (Share)
#define KJUSERPW 4         /* protected write */  (S/Row-X (SSX))
#define KJUSEREX 5         /* exclusive access */ (Exclusive)

10.3.6.1 Finding Locks and Lock Holders: как найти сессии, удерживающие/ожидающие блокировки

SELECT DECODE(request,0,'Holder: ','   Waiter: ') ||
sid sess, id1, id2, lmode, request, type
FROM V$LOCK
WHERE (id1, id2, type) IN (SELECT id1, id2, type FROM V$LOCK WHERE request > 0)
ORDER BY id1, request;
enq: TX — row lock contention

Типичные причины из документации

«… ожидание блокировки в mode 6 [V$LOCK.LMODE=6 — exclusive (X)]: наблюдается когда сессия ожидает освобождения блокировки уровня строки (row level lock), удерживаемой другой сессией»

«… ожидание блокировки в mode 4 [V$LOCK.LMODE=4 — share (S)] может возникать если сессия ожидает [завершения транзакции, начатой другой сессией] для избежания возможных дубликатов уникального индекса»

«… ожидание блокировки в mode 4 [V$LOCK.LMODE=4 — share (S)] … если 2 сессии планируют обновить строки, контролируемые тем же значением bitmap-индекса (bitmap index fragment)», пример:

SQL> select blocking_session, event, dba_objects.owner||'.'||dba_objects.object_name req_object, sid as blocked_sid, sql_text
 2  from v$session, dba_objects, v$sql
 3  where v$session.ROW_WAIT_OBJ# = dba_objects.object_id
 4  and v$session.event = 'enq: TX - row lock contention'
 5  and v$session.sql_id = v$sql.sql_id
 6  /
 BLOCKING_SESSION EVENT                          REQ_OBJECT             BLOCKED_SID  SQL_TEXT
 ---------------- ------------------------------ ---------------------- ------------ -----------------------------------------------------------------
 682              enq: TX - row lock contention  SCOTT.SOME_BITMAP_IDX  458          update some_table set used = 1 where id in (5392963) and used = 0

SQL> select index_type from dba_indexes where index_name = 'SOME_BITMAP_IDX';
 INDEX_TYPE
 ---------------------------
 BITMAP

SQL> select sid, type, id1, id2, lmode, request, block from v$lock where type = 'TX' and sid in (458,682);
 SID        TYPE        ID1        ID2      LMODE    REQUEST      BLOCK
 ---------- ---- ---------- ---------- ---------- ---------- ----------
 458        TX      2097192      60978          0          4          0 -- ожидающая сессия
 458        TX       786493      96568          6          0          0
 682        TX      2097192      60978          6          0          1 -- блокирующая сессия

Также по теме:

62354.1 TX Transaction locks — Example wait scenarios
15476.1 FAQ about Detecting and Resolving Locking Conflicts

Про анализ взаимых блокировок (deadlocks, сопровождаются сообщениями в alert.log: ORA-04020: deadlock detected while…, ORA-00060: Deadlock detected. More info in file название трейс-файла) с примерами различных типов Deadlock graph из трейс-файлов:

Mark Bobak Understanding and Interpreting Deadlocks. Presented at Hotsos 2006
62365.1 What to do with «ORA-60 Deadlock Detected» Errors
131885.1 ORA-04020 : Analyzing the Deadlock Graph

Также ожидание enq: TX — row lock contention используется при выполнении ALTER INDEX REBUILD PARTITION ONLINE для партиции индекса таблицы на время конкурирующего DML:

11.2.0.3.@ SQL> select blocking_session,
  2         event,
  3         dba_objects.owner || '.' || dba_objects.object_name req_object,
  4         sid as blocked_sid,
  5         sql_text
  6    from v$session, dba_objects, v$sql
  7   where v$session.ROW_WAIT_OBJ# = dba_objects.object_id
  8     and v$session.event = 'enq: TX - row lock contention'
  9     and v$session.sql_id = v$sql.sql_id
 10  /

BLOCKING_SESSION EVENT                          REQ_OBJECT  BLOCKED_SID SQL_TEXT
---------------- ------------------------------ ----------- ----------- --------------------------------------------------------------
             344 enq: TX - row lock contention  T_STAT3             406 alter index IDX_PART_STAT3 rebuild partition SYS_P15477 online

SQL> select sid, type, id1, id2, lmode, request, block
  2    from v$lock
  3   where type = 'TX'
  4     and sid in (344, 406);

       SID TYPE        ID1        ID2      LMODE    REQUEST      BLOCK
---------- ---- ---------- ---------- ---------- ---------- ----------
       344 TX       458764   14314482          6          0          1
       406 TX       458764   14314482          0          4          0
       406 TX       393219   14491109          6          0          2

SQL> SELECT sid,
  2         event,
  3         seconds_in_wait,
  4         row_wait_obj#,
  5         row_wait_file#,
  6         row_wait_block#,
  7         row_wait_row#,
  8         sql_text
  9    FROM v$session s, v$sqlarea q
 10   WHERE sid in (344, 406)
 11     and s.sql_id = q.sql_id
 12  /

SID EVENT                         SECONDS_IN_WAIT ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW# SQL_TEXT
--- ----------------------------- --------------- ------------- -------------- --------------- ------------- --------------------------------------------------------------------------------
344 db file sequential read                     0        794428              0               0             0 DELETE FROM BO.T_PARTNER_TAGS_STAT3 WHERE DT BETWEEN TO_DATE('28.03.2012',...
406 enq: TX - row lock contention              69        794427              0               0             0 alter index BO.IPARTNER_TAGS_PAGE_PLACE_ID rebuild partition SYS_P15477 online

SQL> select object_name, subobject_name, object_id, data_object_id, object_type from user_objects where object_id in (794427, 794428)
  2  /

OBJECT_NAME     SUBOBJECT_NAME  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
--------------- -------------- ---------- -------------- ---------------
T_STAT3         SYS_P15477         794427         794427 TABLE PARTITION
IDX_PART_STAT3  SYS_P15477         794428        1089848 INDEX PARTITION

— точнее, похоже, при выполнении любой ONLINE DDL операции:

11.1.0.7 @SQL> @lock_tree

BLOCKING_TREE                    EVENT                         SECONDS_IN_WAIT BLOCKING_SESSION_STATUS SQL_TEXT
-------------------------------- ----------------------------- --------------- ----------------------- -------------------------------------------------------------------------------------
INST#1 SID#1192 JDBC Thin Client db file sequential read                     0 NO HOLDER               INSERT INTO hist_entity(entity_id, ...) VALUES (...)
  INST#1 SID#992 sqlplus@        enq: TX - row lock contention             360 VALID                   create index IDX_HIST_ENTITY_ATTR_ENTITY_ID on HIST_ENTITY_ATTR (ENTITY_ID) ...ONLINE

Также транзакционные блокировки на SYS.MLOG$ используются Oracle при конкурирующих операциях DML (dbms_mview.refresh) / DDL с Materialized View Log:

SQL> select--+ rule
       l.sid,
       l.type,
       t.name,
       l.id1,
       l.id2,
       l.lmode,
       l.request,
       l.block,
       decode(l.type, 'TX', q.sql_text, o.owner||'.'||o.object_name) as "SQL / OBJ"
  from gv$lock l, gv$session s, gv$sqlarea q, dba_objects o, v$lock_type t
 where (l.inst_id, l.sid) in
       (select distinct inst_id, sid
          from gv$lock
         where (id1, id2) in
               (select id1, id2 from gv$lock where request > 0))
   and l.inst_id = s.inst_id
   and l.sid = s.sid
   and s.inst_id = q.inst_id(+)
   and s.sql_id = q.sql_id(+)
   and l.id1 = o.object_id(+)
   and l.type = t.type
 order by l.sid, l.type
/

 SID TYPE NAME                                 ID1        ID2 LMODE REQUEST BLOCK SQL / OBJ
---- ---- ----------------------------- ---------- ---------- ----- ------- ----- -------------------------------------------------------------------------------------------------------------------
 264 AE   Edition Lock                      711465          0     4       0     2 SYS.ORA$BASE
 264 MS   Materialized View Refresh Log       4096          0     6       0     2 SC.T1
 264 TM   DML                              1163913          0     3       0     2 SC.MLOG$_T1
 264 TM   DML                                  153          0     3       0     2 SYS.MLOG$
 264 TX   Transaction                     11993095   10651609     6       0     1 update "SC"."MLOG$_T1" set snaptime$$ = :1 where snaptime$$ > to_date('2100-01-01:00:00:00','YYYY-MM-DD:HH24:MI:SS')
1035 AE   Edition Lock                      711465          0     4       0     2 SYS.ORA$BASE
1035 MD   Materialized View Log DDL           4096          0     6       0     2 SC.T1
1035 TM   DML                                  153          0     3       0     2 SYS.MLOG$
1035 TX   Transaction                     11993095   10651609     0       6     0 ALTER MATERIALIZED VIEW LOG on SC.T1 move tablespace USERS
enq: TX — allocate ITL entry

«… может наблюдаться когда сессии нужно заблокировать строку в блоке бд, в то время как одна или несколько др.сессий уже блокируют строки в том же блоке, занимая все выделенные ITL-слоты. Обычно в этом случае Oracle динамически добавляет следующий ITL-слот [не более MAXTRANS, или 48% размера блока —  INITRANS Relationship with DB_BLOCK_SIZE. [ID 151473.1]], что может быть невозможно при отсутствии свободного места в блоке…»

Стандартная рекомендация — пересоздание (например, MOVE) сегмента с увеличением значения INITRANS, либо уменьшение времени выполнения транзакций

Дапм заголовка потенциально проблемного блока 4K:

Block header dump:  0x054c339b
Object id on Block? Y
seg/obj: 0x1753  csc: 0x78c.1b2a3560  itc: 2  flg: -  typ: 1 - DATA
fsl: 0  fnx: 0x0 ver: 0x01

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0028.008.0022698e  0x10c69323.bd71.05  --U-    4  fsc 0x0000.1b2a3752
0x02   0x002e.005.00198290  0x0f06390b.7823.13  C---    0  scn 0x078c.1b29d9be   # 2 ITL слота
bdba: 0x054c339b
data_block_dump,data header at 0x7fc44665ce5c
===============
tsiz: 0xfa0                                    # TotalSIZe = 4000 bytes
hsiz: 0xae
pbl: 0x7fc44665ce5c
76543210
flag=--------
ntab=1                                         # N of TABles = 1
nrow=78                                        # N of ROWs   = 78
frre=-1
fsbo=0xae
fseo=0xb8
avsp=0xa                                       # AVailable SPace = 10 bytes
tosp=0xa

— недостаточно места для 3-го ITL-слота размером 24 байта

enq: TX — index contention

«… транзакция во время добавления значения в индекс (inserting a row in an index) вынуждена ожидать завершения операции разделения индексного блока (index block split), производимой другой транзакцией»

enq: TM — contention

«Наиболее вероятной причиной ожиданий блокировок типа TM (TM locks) является использование ограничений по внешнему ключу (foreign key constraints) для неиндексированных столбцов (constrained columns). Во избежание проблемы нужно проиндексировать столбцы с ограничениями по внешнему ключу (foreign key columnsСкрипт Т.Кайта для нахождения таблиц с неиндексированными FK столбцами (с учётом порядка следования столбцов в FK и в индексе) Ожидание также может быть заметным при выполнении конкурентных операций direct path insert — см. direct-path INSERT и ожидания enq: TM – contention

enq: HW — contention

HW enqueue используется для упорядочивания операций выделения дискового пространства сегмента за пределами текущей границы — high water mark (HWM)

Кроме того, эта блокировка используется для сериализации доступа к [заголовку] LOB-сегмента, например при интенсивных DML и недостаточной производительности ввода-вывода можно наблюдать:

SQL> with ash as (select /*+ materialize*/ * from v$active_session_history)
  2  select LEVEL as WAIT_LEVEL,
  3         LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',REGEXP_SUBSTR(program, '\([^\)]+\)'),'FOREGROUND') as BLOCKING_TREE,
  4         ash.EVENT,
  5         count(*) as WAITS_COUNT,
  6         count(distinct sql_exec_id) as EXECS_COUNT,
  7         round(avg(time_waited) / 1000) as AVG_WT,   -- ср.время ожидания по данным ASH, в мс
  8         DBMS_UTILITY.DATA_BLOCK_ADDRESS_FILE(p3) FILE#,
  9         DBMS_UTILITY.DATA_BLOCK_ADDRESS_BLOCK(p3) BLOCK#,
 10         hs.sql_id,
 11         dbms_lob.substr(hs.sql_text,60) as sql_text
 12    from ash
 13         left join dba_hist_sqltext hs on ash.sql_id = hs.sql_id
 14   where session_state = 'WAITING'
 15   start with event = 'enq: HW - contention'
 16  connect by nocycle ash.SAMPLE_ID       = prior ash.SAMPLE_ID
 17                 and ash.SESSION_ID      = prior ash.BLOCKING_SESSION
 18   group by LEVEL,
 19            LPAD(' ',(LEVEL-1)*2)||decode(ash.session_type,'BACKGROUND',REGEXP_SUBSTR(program, '\([^\)]+\)'),'FOREGROUND'),
 20            ash.EVENT,
 21            DBMS_UTILITY.DATA_BLOCK_ADDRESS_FILE(p3),
 22            DBMS_UTILITY.DATA_BLOCK_ADDRESS_BLOCK(p3),
 23            hs.sql_id,
 24            dbms_lob.substr(hs.sql_text,60)
 25   order by LEVEL, count(*) desc
 26  /
LVL BLOCKING_TREE  EVENT                        WAITS_COUNT EXECS_COUNT AVG_WT      FILE#     BLOCK# SQL_ID        SQL_TEXT
--- -------------- ---------------------------- ----------- ----------- ------ ---------- ---------- ------------- ---------------------------------------
  1 FOREGROUND     enq: HW - contention                2295          29    463        506    3614070 439gjg783wdw4 UPDATE "TABLE_WITH_LOB" SET value=:p1,  -- сессии, ожидающие на HW enqueue
  1 FOREGROUND     enq: HW - contention                 567          10    470        506    3614070 cxu8yrp5n8h79 INSERT INTO "TABLE_WITH_LOB" (id, value -- --\\--
  2   FOREGROUND   db file sequential read             2283          29    372          0          1 439gjg783wdw4 UPDATE "TABLE_WITH_LOB" SET value=:p1,  --  в основном блокированы сессиями, выполняющими
  2   FOREGROUND   db file sequential read              544          10    376          0          1 cxu8yrp5n8h79 INSERT INTO "TABLE_WITH_LOB" (id, value --  одноблочные операции чтения LOB сегмента в рамках DML
  2   FOREGROUND   enq: HW - contention                   7           5    180        506    3614070 439gjg783wdw4 UPDATE "TABLE_WITH_LOB" SET value=:p1,
  2   FOREGROUND   log file switch completion             4           1     81          0          0 439gjg783wdw4 UPDATE "TABLE_WITH_LOB" SET value=:p1,
  2   FOREGROUND   enq: HW - contention                   3           1      6        506    3614070 cxu8yrp5n8h79 INSERT INTO "TABLE_WITH_LOB" (id, value
  3     (LGWR)     control file parallel write            2           0    304          0          2
  3     (LGWR)     control file sequential read           1           0    618          0          1
  3     (LGWR)     log file sequential read               1           0    214          0          1

Конкуренция происходит за LOB segment header:

SQL> select l.table_name,
  2         l.column_name,
  3         segment_type,
  4         segment_subtype,
  5         header_file,
  6         header_block
  7    from dba_segments s, dba_lobs l
  8   where s.segment_name = 'SYS_LOB0002335396C00002$$'
  9     and l.segment_name = s.segment_name
 10  /

TABLE_NAME      COLUMN_NAME  SEGMENT_TYPE SEGMENT_SUBTYPE HEADER_FILE HEADER_BLOCK
--------------- ------------ ------------ --------------- ----------- ------------
TABLE_WITH_LOB  VALUE        LOBSEGMENT   ASSM                    506      3614070

В этом случае уменьшить ожидание можно как увеличив производительность ввода-вывода, так и изменив метод хранения LOB:

How to convert FND_LOBS from basicfile to securefile LOBS and overcome ‘enq: HW contention’ waits? [ID 1451379.1]:

How can APPLSYS.FND_LOBS.FILE_DATA column be convered from the default LOB storage (basicfile) to securefile?
Please review the above mentioned Oracle Database documentation for detailed steps…
из прекрасного

SecureFiles Performance — сравнительные тесты производительности ввода-вывода от Oracle

Практический пример на sql.ru: Partitioning как решение при ‘enq: HW — contention’:

Инсерт 10000 копий файла в TEST таблицу в 10 сессиях
время выполнения с SECUREFILE ~4minutes
время выполнения с BASIC ~30minutes

enq: SQ — contention

Sequence Cache enqueue, используется для доступа к последовательностям Oracle, ожидание может наблюдаться в кластерных конфигурациях (Oracle RAC), могут быть значительно уменьшены модификацией последовательностей с опциями CACHE NOORDER

SQL> alter sequence my_rac_seq cache 10000 noorder;

, которые официально рекомендуются для Oracle RAC конфигураций, если не противоречат логике приложения

enq: RC — Result Cache: Contention

Механизм возникновения, параметры, события, обзоры в Query result cache

В 11.1.0.7 параметр _result_cache_timeout (maximum time (sec) a session waits for a result) определяем макс.время ожидания, отображаемое в поле SECONDS_IN_WAIT (v$session_wait | v$session_wait). При этом ожидать получения result cache следующие сессии могут долго — сотни и тысячи секунд — пока первая не получит результатов запроса

enq: SS — contention

Temporary tablespaces in RAC
Diagnosing High Waits for ‘enq: SS — contention’…:

p2 p3 argument
tablespace_number 1 Local enqueue, to notify SMON to request some action for tablespace identified by tablespace id
tablespace_number 2 Global enqueue, to release space for releasing space in tablespace identified by tablespace id

_

enq: KO — fast object checkpoint

Ожидание вызывается необходимостью checkpoint‘а на уровне сегмента / записи всех изменённых блоков сегмента из буферного кеша SGA на диск/ для последующей операции [serial] direct path reads — см. отличное объяснение Tanel Poder’а на форуме OTN

Latch contention

Со стороны настройки производительности, является индикатором других проблем (приложения, конфигурации системы) и требуют анализа причин. Или, по словам Anjo Kolk «…latch contention — это симптом, а не проблема»

22908.1 What are Latches and What Causes Latch Contention

Inner look on Oracle latches

latch: library cache
latch: library cache pin

WAITEVENT: «library cache pin» Reference Note [ID 34579.1]:

«Запрос для определения сессий, удерживающих (holding) и/или запрашивающих (requesting) pins on the object (специальная форма блокировки объекта бд в Library Cache), указанный в параметре P1 события ожидания:»

SELECT s.sid, kglpnmod "Mode", kglpnreq "Req"
FROM x$kglpn p, v$session s
WHERE p.kglpnuse=s.saddr
AND kglpnhdl='&P1RAW';

значение параметра P1RAW из V$SESSION_WAIT / V$SESSION:

select p1raw from v$session_wait where event like '%library cache pin%';

Определение запрашиваемых объектов бд:

SELECT kglnaown "Owner", kglnaobj "Object_to_pin"
FROM x$kglob
WHERE kglhdadr in (select p1raw from v$session_wait where event like '%library cache pin%') ;

How to analyze ORA-04021 or ORA-4020 errors? [ID 169139.1]

How to Find the Blocker of the ‘library cache pin’ in a RAC environment? [ID 780514.1] — через последовательные запросы dba_kgllock (объединение x$kgllk и x$kglpn), x$kglob (Kernel Generic Library cache objects — список объектов), v$session на разных инстансах

How to Find which Session is Holding a Particular Library Cache Lock [ID 122793.1] с использованием:

  1. oradebug dump systemstate 266 / alter session set events ‘immediate trace name systemstate level 10’
  2. X$KGLLK

Mark Bobak’s script для определения блокера и блокируемого объекта при library cache pin

Причины:

latch: library cache lock
latch: shared pool

Ожидания типов latch: library cache [pin|lock] и latch: shared pool указывают на проблемы с частым разбором или совместным использованием SQL курсоров (SQL parsing or sharing). «Рекомендуется проанализировать обзоры V$SQLAREA / V$SQLSTATS в поисках запросов с относительно большим количеством разборов (parse calls)  либо с большим количеством дочерних курсоров (child cursors) — столбец V$SQLAREA.VERSION_COUNT…»

Возможные причины из документации:

  • SQL предложения не используются повторно
  • Не используются связанные переменные
  • Недостаточный размер кэша курсоров приложения (application cursor cache) [см. параметр SESSION_CACHED_CURSORS]
  • Курсоры закрываются приложением [explicitly] после каждого выполнения
  • Частые пересоединения со стороны приложения [logins and logoffs]
  • Структура объектов, используемых курсорами модифицируется (например, командой truncate)
  • Недостаточный размер shared pool
latch: cache buffers chains

Из документации

«… используется для разделения/регулирования доступа к списку буферов буферного кэша (to protect a buffer list in the buffer cache). … используются во время поиска, добавления или удаления буферных блоков (buffer) из кэша. Соперничество  на этом latch обычно означает, что есть активно используемый запросами блок или группа блоков (также известные как hot blocks).

Для определения активно используемой цепочки буферов (buffer chain) … рекомендуется проанализировать статистику для  latches типа cache buffers chains с помощью системного обзора V$LATCH_CHILDREN. Если будет обнаружен child latch типа cache buffers chains со сравнительно большими (относительно других child latch того же типа) значениями GETS, MISSES, и SLEEPS, значит имеет место соперничество за этот child latch.

Этот latch характеризуется адресом (memory address), определённом в столбце ADDR. Используйте значение столбца ADDR в соединении с таблицей X$BH для определения списка блоков, доступ к которым регулируется с помощью этого latch. Например, получив адрес (V$LATCH_CHILDREN.ADDR) активно используемого latch типа cache buffers chains, с помощью запроса можно определить data_object_id, файл данных (FILE#) и номер блока (DBABLK):

SELECT OBJ data_object_id, FILE#, DBABLK,CLASS, STATE, TCH as "Touch count"
FROM X$BH
WHERE HLADDR = 'address of latch'
ORDER BY TCH;

X$BH.TCH — количество обращений к буферу (touch count). Высокое значение X$BH.TCH указывает на активно используемый запросами блок (hot block).

Каждый latch отвечает за доступ к нескольким блокам буферного кэша… Любой блок с высоким значением TCH может быть hot block. [статистика буферного кэша X$BH может быстро меняться и поэтому] выполните запрос несколько раз для определения блока, постоянно появляющегося в первых строках запроса. После определения hot block, зная номера файла и блока, сделайте запрос к DBA_EXTENTS для определения сегмента данных

SELECT OBJECT_NAME, SUBOBJECT_NAME
FROM DBA_OBJECTS
WHERE DATA_OBJECT_ID = &obj;

В этом запросе переменной &obj нужно присвоить значение столбца OBJ предыдущего запроса из X$BH»

163424.1 How To Identify a Hot Block Within The Database Buffer Cache

Запрос к V$LATCH_CHILDREN

select CHILD#  "cCHILD"
,      ADDR    "sADDR"
,      GETS    "sGETS"
,      MISSES  "sMISSES"
,      SLEEPS  "sSLEEPS"
from v$latch_children
where name = 'cache buffers chains'
order by SLEEPS desc;

Объединённый запрос для определения сегментов с hot blocks по значению V$LATCH_CHILDREN.ADDR

select /*+ RULE */
 x.hladdr,
 e.owner || '.' || e.segment_name segment_name,
 e.extent_id extent#,
 x.dbablk - e.block_id + 1 block#,
 x.tch,
 l.child#,
 decode(x.state,  0, 'FREE',
                  1, 'XCUR',
                  2, 'SCUR',
                  3, 'CR',
                  4, 'READ',
                  5, 'MREC',
                  6, 'IREC',
                  7, 'WRITE',
                  8, 'PI',
                  9, 'MEMORY',
                 10, 'MWRITE',
                 11, 'DONATED',
                 x.state) state,
 decode(x.state, 3, cr_scn_bas, NULL) scn_bas
  from sys.v_$latch_children l, sys.x$bh x, sys.dba_extents e
 where x.hladdr in (&ADDR)
   and e.file_id = x.file#
   and x.hladdr = l.addr
   and x.dbablk between e.block_id and e.block_id + e.blocks - 1
 order by x.tch desc, 2, 3;

Однако на практике внезапный рост кол-ва ожиданий:

SQL> select decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue') as EVENT, count(*)
  2    from gv$active_session_history
  3   group by decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue')
  4   having count(*) > 10000
  5   order by count(*) desc
  6  /
 
EVENT                                      COUNT(*)
---------------------------------------- ----------
latch: cache buffers chains                  268432
On CPU / runqueue                            103070

часто сопровождается появлением/частым одновременным выполнением конкретных запросов:

SQL> select sql_id, sql_plan_operation || ' ' || sql_plan_options, count(*)
  2    from gv$active_session_history
  3   where event = 'latch: cache buffers chains'
  4     and session_state = 'WAITING'
  5   group by sql_id, sql_plan_operation || ' ' || sql_plan_options
  6   order by count(*) desc
  7  /
 
SQL_ID        SQL_PLAN_OPERATION                   COUNT(*)
------------- ---------------------------------- ----------
f08p9pu29n43r INDEX RANGE SCAN                       137952
5cmdf7vkwbtt7 INDEX RANGE SCAN                       126957
f08p9pu29n43r INDEX UNIQUE SCAN                         125
5cmdf7vkwbtt7 INDEX UNIQUE SCAN                         108
f08p9pu29n43r TABLE ACCESS BY LOCAL INDEX ROWID          42
5cmdf7vkwbtt7 TABLE ACCESS BY LOCAL INDEX ROWID          18
5cmdf7vkwbtt7 TABLE ACCESS BY INDEX ROWID                 9
f08p9pu29n43r TABLE ACCESS BY INDEX ROWID                 5

— с интенсивным чтением одних и тех же блоков кэша (операцией INDEX RANGE SCAN в этом случае) ввиду высокого кол-ва GETS_PER_EXEC*:

SQL> @v$sqlstats f08p9pu29n43r
 
INST  EXECS SQL_ID              PLAN ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC CONC_PER_EXEC
---- ------ ------------- ---------- ------------ ------------ ------------- -------------
   1  10870 f08p9pu29n43r 1718475856    117484443     30223125        203682      81109704
   2  10896 f08p9pu29n43r 1718475856    135764919     31807427        359100      96072721
--                                                                    *           ^latch: cache buffers chains

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

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
    1593984  consistent gets -- исходный вариант запроса, порождавший latch: cache buffers chains
          0  physical reads
...
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        707  consistent gets -- оптимизированный вариант запроса
          0  physical reads
latch: object queue header operation

Кроме общей конкуренции за буферный кэш (большое кол-во чтений Gets), может сигнализировать об интенсивных операциях над CLOB переменными в PL/SQL

Например, при замедлении выполнения неких процедурных отчётных заданий (типа concurrent) в 11.2.0.3:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                                Avg
                                                                wait   % DB
Event                                       Waits     Time(s)   (ms)   time Wait Class
------------------------------------ ------------ ----------- ------ ------ -----------
DB CPU                                                 24,203          72.9
latch: object queue header operation       69,650         312      4     .9 Other       -- событие интенсивное, но недолгое
db file sequential read                    35,367         212      6     .6 User I/O
latch: cache buffers chains                14,934          46      3     .1 Concurrency -- сопутствующее событие в конкуренции за буферный кэш
library cache: mutex X                      3,326          25      7     .1 Concurrency

Host CPU (CPUs:    8 Cores:    8 Sockets:    2)
~~~~~~~~         Load Average
               Begin       End     %User   %System      %WIO     %Idle
           --------- --------- --------- --------- --------- ---------
               13.11      2.61      86.8       2.5       0.4      10.6                 -- интенсивное потребление ЦПУ %User
...

SQL ordered by Gets                   DB/Inst: OEBS/DB1  Snaps: 57437-57438            -- активные читатели кэша
...
-> Total Buffer Gets:   1,119,744,137
-> Captured SQL account for    2.7% of Total

     Buffer                 Gets              Elapsed
      Gets   Executions   per Exec   %Total   Time (s)  %CPU   %IO    SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
7.30087E+08       2,689    271,508.8   65.2   22,388.2  72.9    .4 cgta5wsufthy4  -- PL/SQL выполняет более 65 процентов чтений
Module: XXXL
BEGIN XXL_GROUP_PRINT_PKG.REPORT... END;

-- SQL трейс выполнения PL/SQL ситуацию не проясняет
SQL ID: cgta5wsufthy4 Plan Hash: 0

BEGIN XXL_GROUP_PRINT_PKG.REPORT... END;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     25    145.01     217.85          0     377858    3847741          25 -- единственное, что можно сказать - основное время/работа при выполнении блока уходит на обработку кэшированных блоков в актуальном состоянии (current)
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25    145.01     217.85          0     377858    3847741          25

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch: object queue header operation          333        0.11          1.64   -- присутствует, но не влияет на время выполнения, скорее как индикатор
  SQL*Net message to client                      25        0.00          0.00
  SQL*Net message from client                    25        0.05          0.14
  latch free                                      2        0.00          0.01
  latch: cache buffers chains                     3        0.00          0.01
********************************************************************************

SQL> -- DBMS_PROFILER показывает слабое место в коде
SQL> select u.unit_name,
  2         d.LINE#,
  3         d.TOTAL_OCCUR occured,
  4         (d.TOTAL_TIME / 1000000000) tot_time,
  5         (d.MIN_TIME / 1000000000) min_time,
  6         (d.MAX_TIME / 1000000000) max_time
  7    from plsql_profiler_units u, plsql_profiler_data d
  8   where d.RUNID = u.runid
  9     and d.UNIT_NUMBER = u.unit_number
 10     and d.total_occur > 0
 11     and d.TOTAL_TIME > 100000000
 12     and u.runid = 1
 13   order by d.TOTAL_TIME desc
 14  /

UNIT_NAME                 LINE#    OCCURED   TOT_TIME   MIN_TIME   MAX_TIME -- соответствующий код проблемного пакета XXL_GROUP_PRINT_PKG:
-------------------- ---------- ---------- ---------- ---------- ---------- -- ...
XXL_GROUP_PRINT_PKG         271       5712 20,8853939 0,00032494 0,00998029 --    clob_var4xml := clob_var4xml || p_text || chr(13) || chr(10);
XXL_GROUP_PRINT_PKG         272       5712 11,3423976 0,00011498 0,00664186 --  END;
XXL_OTHER_PKG              3288        550 0,12800618    9,99E-7 0,00054790

— основное время (и конкуренция, соответственно) соответствует выполнению операции (конкатенации) pl/sql переменной типа CLOB

Варианты решения:

  • использование VARCHAR2 вместо CLOB — Reducing CLOB concatenation
  • уменьшение кол-ва операций (конкатенации) в расчёте на одну переменную типа CLOB, например, используя/добавляя в PL/SQL промежуточные CLOB переменные — этот вариант придумал/проверил ©Евгений Монахов

Цепочка ожиданий по ASH выглядит так:

SQL> @ash_sql_wait_tree "event = 'latch: object queue header operation'" ""

LVL INST_ID BLOCKING_TREE  EVENT                                 WAITS_COUNT EXECS_COUNT AVG_WA SQL_ID
--- ------- -------------- ------------------------------------- ----------- ----------- ------ -------------
  1       1 FOREGROUND     latch: object queue header operation          300         441      9 cgta5wsufthy4
  1       1 FOREGROUND     latch: object queue header operation          129         147      9 56502tyfbkcma
  2       1   FOREGROUND   On CPU / runqueue                              41          41      0 cgta5wsufthy4 -- чтение кэша
  2       1   FOREGROUND   On CPU / runqueue                              22          22      0 56502tyfbkcma -- --//--

Кластерные ожидания — Wait class «Cluster»

gc cr multi block request
gc current multi block request

многоблочные запросы блоков в статусах Consistent Read | Current, используются не только для типичных FULL SCAN‘ов, но и для одноблочных операций — NLJ batching?

11.2.@ SQL> select inst_id,
  2         event,
  3         sql_plan_operation || ' ' || sql_plan_options as SQL_PLAN_OPERATION,
  4         count(*)
  5    from gv$active_session_history
  6   where event like 'gc c% multi block request'
  7   group by inst_id, event, sql_plan_operation || ' ' || sql_plan_options
  8   order by count(*) desc
  9  /

INST_ID EVENT                          SQL_PLAN_OPERATION                  COUNT(*)
------- ------------------------------ --------------------------------- ----------
      2 gc cr multi block request      TABLE ACCESS FULL                        476
      1 gc cr multi block request      TABLE ACCESS FULL                        213
      1 gc cr multi block request      MAT_VIEW ACCESS FULL                     140
      2 gc cr multi block request      MAT_VIEW ACCESS FULL                     123
      2 gc cr multi block request      TABLE ACCESS BY INDEX ROWID               41 -- *
      1 gc cr multi block request      INDEX RANGE SCAN                          15 -- *
      1 gc cr multi block request      INDEX UNIQUE SCAN                          3 -- *
      1 gc cr multi block request      TABLE ACCESS BY LOCAL INDEX ROWID          3 -- *
      2 gc cr multi block request      INDEX RANGE SCAN                           2 -- *
      2 gc cr multi block request      INDEX FAST FULL SCAN                       2
      1 gc current multi block request UPDATE                                     1

Особенности:в параметрах ожидания указывается ПОСЛЕДНИЙ блок из набора и не указывется полное кол-во запрашиваемых блоков — RAC Internals by Julian Dyke:

SQL> select INST_ID,
  2         SID,
  3         (select command_name from v$sqlcommand where command_type = command) as "COMMAND",
  4         STATE,
  5         EVENT,
  6         P1 AS FILE#,
  7         P2 AS BLOCK#,
  8         P3,
  9    from gv$session
 10   where event like 'gc %'
 11  /

INST_ID   SID COMMAND  STATE               EVENT                       FILE#   BLOCK#         P3
------- ----- -------- ------------------- -------------------------- ------ -------- ----------
      2   611 SELECT   WAITING             gc buffer busy acquire         19     8749          1
      2  1291 SELECT   WAITED SHORT TIME   gc cr multi block request      19     8750          1

— похоже, что сессия 611 ожидает грант на блок 8749 из набора, запрошенного сессией 1291 в процессе gc cr multi block request, начиная с блока 8750

gc cr request | global cache cr request | gc cr block request

WAITEVENT: «global cache cr request» Reference Note [ID 69048.1]

gc current block request

ожидания блоков в статусе consistent read (cr) (для операций чтения) или current — для операций DML или чтения (SELECT). Зависимости запрашиваемых статусов блоков от операций

gc current block busy

DML (update, delete) с использованием FULL SCAN

buffer busy waits

Чудесно в документации: Wait until a buffer becomes available!

Один из возможных случаев отражает диаграмма ожиданий из окружающей действительности:

11.1.0.7@ SQL> @ash_wait_tree "event = 'buffer busy waits'"

LVL INST_ID BLOCKING_TREE     EVENT                    WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ------------------------ ----------- ---------- ------
  1       1 FOREGROUND        buffer busy waits                217         69    848 -- ожидают по причинам
  2       1   FOREGROUND      buffer exterminate               224         11     11 --   агрессивный ASMM в версии 11.1
  2       1   FOREGROUND      db file sequential read           15          5     17 --   буфер читается в кэш другой сессией
  2       1   FOREGROUND      On CPU / runqueue                  6          5      0 --   буфер меняется в кэше другой сессией, т.е. находится в incompatible mode
  2       1   FOREGROUND      buffer busy waits                  3          1    874 --   циклическое ожидание
  3       1     FOREGROUND    buffer exterminate                 6          1     11

, другой случай — buffer busy waits блокируется кластерными ожиданиями/ЦПУ, плюс циклические цепочки ожиданий:

11.2.0.4@ SQL> @ash_wait_tree "event = 'buffer busy waits' and inst_id = 1"

LVL INST_ID BLOCKING_TREE  WAIT_CLASS    EVENT                          WAITS_COUNT SESS_COUNT AVG_WAIT_TIME_MS EST_AVG_LATENCY_MS
--- ------- -------------- ------------- ------------------------------ ----------- ---------- ---------------- ------------------
  1       1 (USER)         Concurrency   buffer busy waits                      800        122                7                  4
  2       1   (USER)       Cluster       gc buffer busy release                  59         12                7                  7
  2       1   (USER)                     On CPU / runqueue                       53         21                0               1000
  2       1   (USER)       Concurrency   latch: cache buffers chains             50         10                1                  1
  2       1   (USER)       Concurrency   buffer busy waits                       49         12                8                  7
  2       1   (USER)       Cluster       gc buffer busy acquire                   9          2                1                  1
  2       1   (USER)       Cluster       gc current block 2-way                   6          2                2                  2
  2       1   (USER)       Application   SQL*Net break/reset to client            5          3                0                  1
  3       1     (USER)     Concurrency   buffer busy waits                       52          6                5                  5
  3       1     (USER)     Concurrency   latch: cache buffers chains             17          3                5                  4
  3       1     (USER)                   On CPU / runqueue                       13          6                0               1000
  3       1     (USER)     Cluster       gc current block busy                    2          2                1                  1

Ожидание buffer busy waits в некластерном окружении

gc buffer busy
gc buffer busy release
gc buffer busy acquire

Индикаторы невозможности немедленного получения гранта на доступ (grant access) к блокам данных локального buffer cache

Начиная с 11g, gc buffer busy разделено на 2 ожидания:

  • В случае, если блокирующий Global Cache запрос (GC request) открыт локальной сессией, ожидается gc buffer busy acquire
  • Если же блокирующий GC запрос открыт сессией другого инстанса (remote instance), будет отражено ожидание gc buffer busy release

Заметный уровень ожиданий сигнализирует об одновременных попытках доступа (локально или через cluster interconnect с помощью механизма cache fusion) с получением соответсвующего уровня доступа (grant access) большим количеством пользовательских процессов к определённому набору блоков buffer cache, например:

11.2.@ SQL> select INST_ID,
  2         SID,
  3         (select command_name from v$sqlcommand where command_type = command) as "COMMAND",
  4         STATE,
  5         EVENT,
  6         P1 AS FILE#,
  7         P2 AS BLOCK#,
  8         P3,
  9         BLOCKING_INSTANCE,
 10         BLOCKING_SESSION,
 11         BLOCKING_SESSION_STATUS
 12    from gv$session
 13   where event like 'gc %'
 14  /

INST_ID  SID COMMAND  STATE    EVENT                   FILE# BLOCK#         P3 BLOCKING_INSTANCE BLOCKING_SESSION BLOCKING_SESSION_STATUS
------- ---- -------- -------- ----------------------- ----- ------ ---------- ----------------- ---------------- -----------------------
      1  114 SELECT   WAITING  gc buffer busy acquire      8  16458          1                                    UNKNOWN
      1  312 SELECT   WAITING  gc buffer busy acquire      8  16458          1                                    UNKNOWN
      1  880 SELECT   WAITING  gc buffer busy acquire      8  16458          1                                    UNKNOWN
      1  985 SELECT   WAITING  gc current request          8  16458   33554433                                    UNKNOWN
      1  986 SELECT   WAITING  gc buffer busy acquire      8  16458          1                                    UNKNOWN
      1 1446 SELECT   WAITING  gc buffer busy acquire      8  16458          1                                    UNKNOWN

— cессия SID=985 на 1-м инстансе блокирует буфер блока (8,16458), остальные локальные сессии ждут на gc buffer busy acquire

SQL> /

INST_ID   SID COMMAND  STATE               EVENT                       FILE#   BLOCK#         P3 BLOCKING_INSTANCE BLOCKING_SESSION BLOCKING_SESSION_STATUS
------- ----- -------- ------------------- -------------------------- ------ -------- ---------- ----------------- ---------------- -----------------------
      2  1170          WAITING             gc buffer busy release         60     1073         99                                    UNKNOWN
      1   970 DELETE   WAITING             gc current request             60     1073   16777315                                    UNKNOWN

— cессия SID=970 на 1-м инстансе блокирует буфер блока (60,1073) в сосотоянии currentна момент удаления данных, SID=1170 на 2-м инстансе ждёт gc buffer busy release.

По значению параметра P3 можно определить, что сессии конкурирую за заголовок UNDO сегмента (undo header):

SQL> select tablespace_name, segment_name, segment_id, file_id, block_id
  2  from dba_rollback_segs
  3  where segment_id =
  4  (case when mod(&&block_class, 2) = 1
  5    then -- undo segment header
  6      (bitand(&&block_class, 1023) - 15) / 2
  7    else -- undo block
  8      (bitand(&&block_class, 1023) - 16) / 2
  9   end)
 10  /
Enter value for block_class: 16777315

TABLESPACE_NAME                SEGMENT_NAME                   SEGMENT_ID    FILE_ID   BLOCK_ID
------------------------------ ------------------------------ ---------- ---------- ----------
UNDOTBS2                       _SYSSMU42_2229574035$                  42         60       1073

SQL> /
Enter value for block_class: 99

TABLESPACE_NAME                SEGMENT_NAME                   SEGMENT_ID    FILE_ID   BLOCK_ID
------------------------------ ------------------------------ ---------- ---------- ----------
UNDOTBS2                       _SYSSMU42_2229574035$                  42         60       1073

Красивый пример исследования события gc buffer busy с использованием ASH можно прочитать на сайте Jeremy Schneider’а GC Buffer Busy Waits in RAC: Finding Hot Blocks

Параметры ожидания:

P1 = file#
P2 = block#
P3 = id (Reason Code)/Block Class#(10g) — см. Dion Cho:Parameter3 of gc buffer busy/gc current request wait event:

SQL> select rownum, class from v$waitstat;

ROWNUM CLASS
------ ------------------
1      data block
2      sort block
3      save undo block
4      segment header
5      save undo header
6      free list
7      extent map
8      1st level bmb        -- BMB versus Freelist Segment: DBMS_SPACE.UNUSED_SPACE and DBA_TABLES.EMPTY_BLOCKS (Doc ID 149516.1)
9      2nd level bmb
10     3rd level bmb
11     bitmap block
12     bitmap index block
13     file header block
14     unused
15     system undo header
16     system undo block
17     undo header           -- для UNDO сегмента с USN=1, для следующих - bitand(:p3,1023) = 2 * USN + 15
18     undo block            -- для UNDO сегмента с USN=1, для следующих - bitand(:p3,1023) = 2 * USN + 16

Другой пример исследования в 11.2 RAC — Кластерные ожидания и запросы Advanced Queuing

gc cr block lost / gc current block lost

Статистика потерянных блоков глобального кэша (gc — Global Cache), появление этих событий в Top 5 Events указывает на проблему или неэффективную обработку пакетов interconnect интерфейса на уровне конфигурации оборудования / ОС — рекомендации по диагностике gc lost blocks diagnostics [ID 563566.1]

gcs log flush sync

Процессы LMS, обслуживающий запросы Global Cache Service, ожидает записи логов локальным процессом LGWR:

SQL> select ash.INST_ID,
          LPAD(' ', (LEVEL - 1) * 2) || decode(ash.session_type, 'BACKGROUND', substr(ash.PROGRAM,28,4), 'FOREGROUND') as BLOCKING_TREE,
          ash.EVENT,
          ash.BLOCKING_INST_ID,
          count(*), round(avg(time_waited)/1000) as AVG_TIME_WAITED_MS
     from gv$active_session_history ash
     where session_state = 'WAITING'
    start with event = 'gcs log flush sync'
   connect by nocycle prior ash.SAMPLE_ID  = ash.SAMPLE_ID
          and ash.SESSION_ID = prior ash.BLOCKING_SESSION
          and ash.INST_ID = prior ash.BLOCKING_INST_ID
    group by ash.INST_ID,
             LPAD(' ', (LEVEL - 1) * 2) || decode(ash.session_type, 'BACKGROUND', substr(ash.PROGRAM,28,4), 'FOREGROUND'),
             ash.EVENT,
             ash.BLOCKING_INST_ID
    having count(*) > 10
    order by LPAD(' ', (LEVEL - 1) * 2) || decode(ash.session_type, 'BACKGROUND', substr(ash.PROGRAM,28,4), 'FOREGROUND') desc,
             ash.INST_ID,
             count(*) desc
 20  /

INST_ID BLOCKING_TREE  EVENT                         BLOCKING_INST_ID   COUNT(*) AVG_TIME_WAITED_MS
------- -------------- ----------------------------- ---------------- ---------- ------------------
      1 LMS            gcs log flush sync                           1       3462                  8
      2 LMS            gcs log flush sync                           2       2559                  9
      2   LGWR         log file parallel write                              2061                202
      2   LGWR         control file sequential read                          214                119
      2   LGWR         enq: CF - contention                         2         91                779
      2   LGWR         control file parallel write                            58                267
      2   LGWR         enq: CF - contention                                   13                531
      2     CKPT       control file parallel write                            18                139
      2     ARC        control file sequential read                           66                118

— LGWR, кроме собственно операций записи (log file parallel write), может ожидать блокировок во время синхронного доступа к контрольному файлу (enq: CF — contention), который пишется/читается системными процессами CKPT и ARC

Соответствующие статистики:

gc cr block flush time
gc current block flush time

отражаются в AWR:

Global Cache and Enqueue Services - Workload Characteristics
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
...
            Avg global cache cr block flush time (ms):     38.8

...
       Avg global cache current block flush time (ms):     62.5

Advanced RAC troubleshooting — OraInternals

Deep review of LMS/LGWR process — в частности, обращается внимание на тот факт, что по умолчанию, процессы LMS действуют в RT-mode:

11.2.@SQL> @param_ _high_priority_processes

NAME                      VALUE      IS_DEF   DSC
------------------------- ---------- -------- -------------------------------
_high_priority_processes  LMS*|VKTM  TRUE     High Priority Process Name Mask

, в то время как блокирующий процесс LGWR выполняется с обычным приоритетом

DFS lock handle

ожидание глобальной блокировки (lock handle), обслуживаемой процессом Distributed Lock Manager (DLM). Слово DFS (Distributed File System) унаследовано со времён Oracle Parallel Server

SQL> select chr(bitand(p1, -16777216) / 16777215) ||
2         chr(bitand(p1, 16711680) / 65535) "Lock",
3         t.name,
4         count(*),
5         round(avg(time_waited)) as TIME_WAITED
6    from gv$active_session_history s, v$lock_type t
7   where event = 'DFS lock handle'
8     and session_state = 'WAITING'
9     and chr(bitand(p1, -16777216) / 16777215) ||
10         chr(bitand(p1, 16711680) / 65535) = t.type
11   group by chr(bitand(p1, -16777216) / 16777215) ||
12            chr(bitand(p1, 16711680) / 65535),
13            t.name
14   order by count(*) desc
15  /

Lock NAME                                                               COUNT(*) TIME_WAITED
---- ---------------------------------------------------------------- ---------- -----------
IV   Library Cache Invalidation                                              166         182
TA   Instance Undo                                                            16         200
CI   Cross-Instance Call Invocation                                            2           0
SV   Sequence Ordering                                                         1           0

Пример Troubleshooting ‘DFS lock handle’ waits

CI Lock «Cross-Instance Call Invocation» (Doc ID 34631.1)

Сетевые ожидания (Wait class: Network)

virtual circuit status
shared server idle wait
virtual circuit wait

комплексное ожидание, параметры:

  • p1   circuit#   номер ожидаемого circuit
  • p2   type         тип операции
    • 1 — means a wait on a reset (as in «break / reset»)
    • 2 — (most typical operations) waiting on a receive from the client — ожидание ответа клиента
    • 3 — waiting on a send to the client
SQL> select STATE, P1TEXT, P1, P2TEXT, P2, SECONDS_IN_WAIT, WAIT_TIME_MICRO from v$session_wait where event = 'virtual circuit wait';

STATE               P1TEXT            P1 P2TEXT          P2 SECONDS_IN_WAIT WAIT_TIME_MICRO
------------------- --------- ---------- ------- ---------- --------------- ---------------
WAITING             circuit#          96 type             2              15        14697304
WAITING             circuit#          80 type             2              23        22766118

Ожидание virtual circuit wait

Ожидания, наблюдаемые при параллельном выполнении запросов

Параметры:

  • P1 = sleeptime/senderid
  • P2 = passes
SQL> select bitand(&&p1, 16711680) - 65535 as SNDRINST,
  2         decode(bitand(&&p1, 65535),
  3                65535,
  4                'QC',
  5                'P' || to_char(bitand(&&p1, 65535), 'fm000')) as SNDR
  6    from dual
  7   where bitand(&&p1, 268435456) = 268435456;
Enter value for p1: 268500992

  SNDRINST SNDR
---------- -----
         1 P000
PX Deq: Parse Reply

Начиная с версии 10g из частей целого запроса процесс-координатор (QC) готовит отдельные SQL для выполнения процессами PX Slaves. На этом событии QC ожидает выполнения разбора (parse & binds variable) частичных SQL  параллельными серверами

WAITEVENT: «PX Deq: Parse Reply» [ID 257596.1]

Практический пример Library cache lock deadlock

PX Deq: Test for msg

характерно для parallel recovery — H.Tonguç Yılmaz. Data Guard Redo Apply and Media Recovery Best Practices 10g

Прочие ожидания

buffer exterminate

достаточно экзотическое событие ожижания, возникающего при динамическом изменении размера DB CACHE BUFFER

259137.1 When Does «Buffer Exterminate» Wait Event Occur ?

events in waitclass Other

События отражаются (группируются в event_class Other) в V$SESSION_EVENT, в V$SESSION_WAIT и SQL_TRACE отображаются без группировки — см. пример исследования Another use case for WaitProf — diagnosing “events in waitclass Other”

resmgr:cpu quantum

«Сессия ожидает выделения кванта ЦПУ (quantum of cpu). Событие возникает при использовании resource manager, ограничивающего выделение ресурса процессора [для сессий]. Для уменьшения ожидания рекомендуется увеличение процессорных квот (CPU allocation) текущей группе (consumer group) ожидающих сессий»

В версиях 11.1.0.6+ может наблюдаться при отключенном resource managerHigh «Resmgr:Cpu Quantum» Wait Events In 11g Even When Resource Manager Is Disabled [ID 949033.1] по причине установки ресурсного плана для функционирующих Maintenance Windows:

SQL> select distinct resource_plan from dba_scheduler_windows where enabled = 'TRUE';

RESOURCE_PLAN
------------------------
DEFAULT_MAINTENANCE_PLAN

В последнем случае, как правило, событие является индикатором активного выполнения других ресурсоёмких задач / запросов

Диагностика resmgr:cpu quantum

Wait for stopper event to be increased

Официально Database Appears to Hang Waits for «Wait for a undo record» and «Wait for stopper event to be increased» Due to Parallel Transaction Recover (Doc ID 464246.1)

Практический эффект установки fast_start_parallel_rollback = false на Oracle 10.2.0.3

Статистики Oracle (statistics)

redo size

Объём генерируемых данных redo

Для исторического анализа не хватает данных в AWR обзоре DBA_HIST_SESSMETRIC_HISTORY, который, как и DBA_HIST_FILEMETRIC_HISTORY (соответствующие таблицы WRH$_FILEMETRIC_HISTORY, WRH$_SESSMETRIC_HISTORY), не заполняется ни в Oracle 10g, ни в Oracle 11g при значении параметра CONTROL_MANAGEMENT_PACK_ACCESS = DIAGNOSTIC+TUNING на платформах Linux x86_64, Windows x86 — см. замечания и предложения аргентинских товарищей и описания багов на Metalink

Генерация redo включает в себя redo entries for lost write detection в объёме, например:

SQL> with redo_entries as (select value from v$sysstat where name = 'redo entries'),
  2       redo_size    as (select value from v$sysstat where name = 'redo size')
  3  select name,
  4         round(ss.value / decode(instr(name, 'redo entries'),
  5                                 1,
  6                                 redo_entries.value,
  7                                 redo_size.value) * 100,
  8               2) as "Total Redo PerCent"
  9    from v$sysstat ss, redo_entries, redo_size
 10   where name like 'redo entries_%'
 11      or name like 'redo size_%'
 12  /

NAME                                                             Total Redo PerCent
---------------------------------------------------------------- ------------------
redo entries for lost write detection                                          7.64
redo size for lost write detection                                             9.48 -- почти 9.5 процентов
redo size for direct writes                                                    2.31

SQL> @param DB_LOST_WRITE_PROTECT

NAME                   VALUE    IS_DEF   DSC
---------------------- -------- -------- ---------------------------
db_lost_write_protect  TYPICAL  FALSE    enable lost write detection                -- при включенном механизме
redo synch time

суммарное время ожиданий log file sync, csec

redo synch long waits

кол-во «длительных» (> 10 mc ?) ожиданий log file sync.

Индикатор медленной записи, в трейсе LGWR:

*** 2012-08-02 00:08:03.515
Warning: log write elapsed time 1269ms, size 3KB

, либо задержек в процессе SCN broadcast acknowledge при использовании RAC, в трейсе LGWR или LMD|LMS:

*** 2012-08-02 01:13:29.568
Warning: log write broadcast wait time 842ms (SCN 0x799.ad8a17c1)

— в последнем случае таймаут предупреждений определяется параметром:

NAME                               VALUE  DSC
---------------------------------- ------ ---------------------------------------------------
_long_bcast_ack_warning_threshold  500    threshold for long bcast ack warning messages in ms
gc cr block receive time

«cуммарное время ожидания клиентскими процессами получения через interconnect блоков бд в состоянии Consistent Read (CR)«

gc cr blocks received

«общее количество полученных блоков»

gc current block receive time

cуммарное время ожидания клиентскими процессами получения через interconnect блоков бд в состоянии CURRENT

gc current blocks received

общее количество полученных блоков

Запрос для оценки средних времён получения блоков по Oracle Cluster мс момента запуска инстансов)

SQL> select 'GC CR BLOCKS',
  2         b1.inst_id,
  3         b2.value "BLOCKS RECEIVED",
  4         b1.value "RECEIVE TIME",
  5         round((b1.value / b2.value) * 10000) "AVG BLOCK RECEIVE TIME (us)"
  6    from gv$sysstat b1, gv$sysstat b2
  7   where b1.name in
  8         ('gc cr block receive time', 'global cache cr block receive time')
  9     and b2.name in
 10         ('gc cr blocks received', 'global cache cr blocks received')
 11     and b1.inst_id = b2.inst_id
 12  union all
 13  select 'GC CURRRENT BLOCKS',
 14         b1.inst_id,
 15         b2.value "BLOCKS RECEIVED",
 16         b1.value "RECEIVE TIME",
 17         round((b1.value / b2.value) * 10000) "AVG BLOCK RECEIVE TIME (us)"
 18    from gv$sysstat b1, gv$sysstat b2
 19   where b1.name in ('global cache current block receive time',
 20                     'gc current block receive time')
 21     and b2.name in ('global cache current blocks received',
 22                     'gc current blocks received')
 23     and b1.inst_id = b2.inst_id
 24  /

'GCCRBLOCKS'       INST_ID BLOCKS RECEIVED RECEIVE TIME AVG BLOCK RECEIVE TIME (us)
------------------ ------- --------------- ------------ ---------------------------
GC CR BLOCKS             1        83238397     11013542                        1323
GC CR BLOCKS             2       291480768     19895574                         683
GC CURRRENT BLOCKS       1       316885309     12275997                         387
GC CURRRENT BLOCKS       2       347957865     13478474                         387

более подробные и полезные данные о производительности interconnect можно найти в разделе AWR Global Cache and Enqueue Services — Workload Characteristics

Avg global cache cr block receive time (ms)
Avg global cache current block receive time (ms)
RowCR — row contention
RowCR attempts
RowCR hits

Статистики row CR (Consistent Read на уровне строки, не блока) — механизма «оптимизации с целью уменьшения consistent-read rollbacks при выполнении запросов»

http://www.freelists.org/

«CR feature уменьшает количество CR rollbacks , избегая, таким образом, необходимости выполнения дорогостоящих (дисковых) операций block cleanout/rollback в RAC окружении. Вместо выполнения [стандартной операции] block cleanout, Row CR пытается сгенерировать консистентную версию определённой строки. [В Oracle 9i] Row CR выполнялся только для операций UPDATE с использованием Unique Index Scan или Fetch by Row ID

Статистика Row CR attempts показывает количество попыток выполнения updates, удовлетворяющих этим условиям [про update здесь пишется применительно к Oracle 9i, начиная с Oracle 10g механизм Row CR используется также для операций SELECT с доступом по индексу].

Статистика Row CR hits отображает количество удачных использований Row CR. Начиная с Oracle10g применение этого механизма должно быть расширено для index range scans для дальнейшей оптимизации операций cleanout…»

«RowCR разрешён (значение параметра по умолчанию _row_cr = TRUE) и поддерживается с версии 10.2″

Применение RowCR может сопровождаться различными ошибками ORA-600 типа Bug 8771916 OERI [kdsgrp1] during CR read, одним из методов решения которых может быть «отключение rowCR … установкой параметра «_row_cr»=FALSE … Однако, это может привести к ухудшению времени выполнения запросов — соотношение статистик RowCR hits / RowCR attempts поможет увидеть, насколько это критично для производительности…»

class slave wait

Неправильно классифицированное ожидание в версии 10.1.0.3 (непропатченный Oracle 10) ошибочно относится к классу ожиданий Other, в отчёте ADDM выглядит так

FINDING 5: 13% impact (626 seconds)
-----------------------------------
Wait class "Other" was consuming significant database time.
NO RECOMMENDATIONS AVAILABLE
ADDITIONAL INFORMATION: Database latches in the "Other" wait class were not
consuming significant database time.

в AWR

~~~~~~~~~~~~~~~~~~                                        % Total
Event                                 Waits    Time (s)   DB Time     Wait Class
------------------------------ ------------ ----------- --------- --------------
...
class slave wait                        122         625     12.52          Other

исправлено в 10.1.0.4, 10.2, см. Bug 3876475 «class slave wait» has the wrong wait classification

index scans kdiixs1

Кол-во операций индексного сканирования (index scans)

Статистика обращения к корневым блокам индекса

Popular Statistics with Database In-Memory

Коэффициенты Statspack / AWR

Execute to Parse % = 100 * (1 — Parses/Executions)

execute to parse ratio — обратное соотношение количества разборов SQL (включая hard parses и soft parses) к количеству выполнений запросов (executions). Может рассматриваться как коэффициент эффективности работы приложения с бд: чем больше выполнений запросов на один разбор, тем выше коэффициент (меньше ресурсов / времени тратится на разбор = выше эффективность работы бд). Если количество выполнений равно числу разборов SQL — этот коэффициент = 0 (эффективность работы бд низкая). Если количество разборов больше числа выполнений запросов, например, если приложение многократно делает разбор запроса parse и не выполняет execute — коэффициент execute to parse может быть отрицательным

Это соотношение не может быть изменено с помощью параметра cursor_sharing, поскольку этот параметр не влияет на суммарное число разборов (может изменить только соотношение между hard parses и soft parses) — см. Ask Tom «execute to parse ratio» : для уменьшения эффективно уменьшать количество разборов кэшируя открытые курсоры для дальнейшего повторного использования с использованием jdbc statement caching, Oracle .NET statement cache или «… перемещая все [возможные] SQL внутрь PL/SQL (как в машину для кэширования запросов), который автоматически кэширует запросы (сохраняет открытыми куксоры) для нас»

% Non-Parse CPU = 100*(1-(:prscpu/:tcpu))

(1-parse time CPU / CPU used by session)*100

доля процессорного времени, затраченная пользовательскими процессами (сессиями) на продуктивную работу, в отличие от подготовки к выполнению/ разбора запросов (SQL parsing)

Parse CPU to Parse Elapsd % = 100*:prscpu/:prsela

parse time CPU / parse time elapsed

Время, затраченное на разбор запросов (parse time elapsed) делится на «продуктивную работу» процессора — parse time CPU и время ожиданий: низкое значение Parse CPU to Parse Elapsd означает затрату значительного времени при разборе на непродуктивные ожидания , наиболее вероятно — ожидания событий latch free, рекомендуется проверить статистику ожиданий. Пример с картинками в блоге Jeremy Schneider

Estd Interconnect traffic (KB)

Средний (за период между измерениями — snapshot‘ами суммарный трафик через cluster interconnect

(gc cr blocks received/sec + gc current blocks received/sec + gc cr blocks served/sec + gc current blocks served/sec) * db_block_size
+
( messags sent directly/sec + messages send indirectly/sec + messages received/sec ) * 200 bytes

формула из sprepins.sql

round((((:gccrrv+:gccurv +:gccrsv+:gccusv) * :bs) + ((:dpms+:dnpms+:pmrv+:npmrv)* 200))/&&btokb/:ela,2)
gccrrv = global cache consistent read blocks received
gccurv = global cache current blocks received
gccrsv = global cache consistent read blocks served (обработано, отправлено)
gccusv = global cache current blocks served (обработано, отправлено)
bs     = block size (размер блока бд)
dpms   = global cache service messages sent
dnpms  = global enqueue service messages sent
pmrv   = global cache service msgs received
npmrv  = global enqueue service msgs received
200    = средний размер ges/gcs сообщения, применяемый для оценки
btokb  = 1024
ela    = elapsed, период между измерениями(snapshot), сек.
SQL ordered by Reads
SQL ordered by Physical Reads (UnOptimized)

How to Interpret the «SQL ordered by Physical Reads (UnOptimized)» Section in AWR Reports (11.2 onwards) [ID 1466035.1]:

«Optimized Read Requests — это запросы на чтение, выполняемые из Smart Flash Cache ( или из Smart Flash Cache в OracleExadata V2 … [две близкие, но не совпадающие по реализации технологии]). Операции (запросы) на чтение выполняемые из [такого] кэша называются оптимизированными/’optimized’ поскольку выполняются много быстрее, чем чтение с обычного диска ( ввиду использования SSD). Дополнительно, запросы на чтение, использующие Storage Indexes в процессе smart scans на Oracle Exadata V2 (и значительно сокращающие количество  I/O), также учитываются в категории ‘optimized read requests‘ поскольку они исключают чтение блоков, не содержащих требуемые данные.

В системах без ‘Optimized Read Requests’, UnOptimized Read Reqs будут равны Physical Read Reqs (I/O с диска).  В этом случае … ‘%Opt‘  покажет 0 …»

TBD

2 комментария »

  1. Спасибо! Очень хорошая статья ! Весь блог весьма полезен.
    Respect!

    комментарий от Александр Беляков — 16.09.2011 @ 12:56 | Ответить

  2. класс, спасибо!

    комментарий от Аноним — 23.04.2014 @ 10:08 | Ответить


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