Некоторые важные для анализа производительности систем 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 filesutl_file I/O
В соответствии с документацией ожидание фиксируется при использовании процедур пакета UTL_FILE
Обработка логов (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’:
- A user sessions issues a commit or rollback and starts waiting on log file sync
- LGWR gather redo information to be written to redo log files, issues IO and queues BOC to an LMS process and posts LMS process
- LGWR waits for redo buffers to be flushed to disk and SCN to be ACK’d
- Completion of IO and receiving ACK from LMS signal write complete. LGWR then posts foreground process to continue
- 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 338log 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_LOGFILEAWR показывает значительную долю ожиданий 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Ожидания 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
- сессия 368 на время выполнения процедуры sleep(1000); удерживает Library Cache Lock (на дескриптор процедуры) в состянии Null и Pin (на объект пула) в моде Share
- следующая по времени запуска сессия 357 для рекомпиляции той же процедуры получила Lock в состянии Exclusive и ожидает Exclusive Pin на соответствующем событии library cache pin. Pin (объект процедуры в Library Cache) блокирован сессией 368 на время выполнения в Share моде во избежание изменений
- последняя по времени сессия 347 ожидает Lock в Exclusive моде, кот.удерживается сессией 357 на соответствующем событии library cache lock. Получение Pin (блокировки на объект) до получения Lock (нахождение и блокировка дескриптора) невозможно
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 — локальные структуры текущей системы (инстанса) в RACselect 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 wait — Truncate 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 msecThe 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 USERSenq: 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 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 ~30minutesenq: 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
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] с использованием:
- oradebug dump systemstate 266 / alter session set events ‘immediate trace name systemstate level 10’
- X$KGLLK
Mark Bobak’s script для определения блокера и блокируемого объекта при library cache pin
Причины:
- выполнение DDL (Grant/Revoke/Drop/Create or replace) с выполняемой в настоящий момент PL/SQL процедурой ORA-4021 ‘LIBRARY CACHE PIN’ and PL/SQL blocks [ID 264476.1]
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 readslatch: 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.5Advanced 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Ожидания, наблюдаемые при параллельном выполнении запросов
Параметры:
- 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 P000PX 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 manager — High «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
Практический эффект установки 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 msgc 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 при выполнении запросов»
«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)«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
Спасибо! Очень хорошая статья ! Весь блог весьма полезен.
Respect!
комментарий от Александр Беляков — 16.09.2011 @ 12:56 |
класс, спасибо!
комментарий от Аноним — 23.04.2014 @ 10:08 |