Oracle mechanics

29.11.2016

Наблюдение за Db File Scattered Read, SAMPLE операции планов выполнения и запросы с большим удельным Soft Parse

Разбираясь с использованием ожидания/активности db file scattered read при разных операциях планов выполнения, можно видеть:

12.1.0.2@ SQL> select sql_plan_operation, sql_plan_options, count(*)
  2    from gv$active_session_history
  3   where event = 'db file scattered read'
  4   group by sql_plan_operation, sql_plan_options
  5   order by count(*) desc
  6  /
 
SQL_PLAN_OPERATION  SQL_PLAN_OPTIONS                 COUNT(*)
------------------- ------------------------------ ----------
TABLE ACCESS        FULL                                 3220 -- ожидаемо большая доля FTS
                                                          901 -- scattered чтения без SQL_PLAN_OPERATION (*)
TABLE ACCESS        BY INDEX ROWID BATCHED                399 -- scattered read при INDEX BATCHED операциях
TABLE ACCESS        BY LOCAL INDEX ROWID BATCHED           57 -- // --
MAT_VIEW ACCESS     FULL                                   52
TABLE ACCESS        BY INDEX ROWID                         35 -- скорее всего также выполняется в режиме BATCHED
INDEX               FAST FULL SCAN                         23 -- ожидаемое многоблочное чтение
INDEX               SAMPLE FAST FULL SCAN                   5 -- SAMPLE операции (**)
INDEX               UNIQUE SCAN                             5
INDEX               RANGE SCAN                              3
TABLE ACCESS        SAMPLE                                  2 -- // -- (**)
MAT_VIEW ACCESS     SAMPLE                                  1 -- // -- (**)

(*) Scattered чтения без SQL_PLAN_OPERATION большей частью относятся к фазе Soft parse (***), определяемой здесь как промежуток, когда PLAN_HASH_VALUE уже сформирован (PHV exists), но выполнение запроса ещё не началось (SQL_EXEC_ID is null): (more…)

24.08.2016

12c, адаптивный LGWR: ожидания log file sync и target log write size

Из более-менее традиционной картинки ожиданий log file sync:

12.1.0.2@ SQL> @ash_wait_tree "event = 'log file sync' and inst_id = 1"
 
LVL INST_ID BLOCKING_TREE     WAIT_CLASS  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ----------- ----------------------------- ----------- ---------- ------
  1       1 (FOREGROUND)      Commit      log file sync                       10992       6879    130 -- польз.процессы
  1       1 (J...)            Commit      log file sync                          13         13      0 -- и Job-ы ожидают LGWR
  2       1   (LGWR)          Other       LGWR any worker group                4675          1    190 -- , висящий, восновном,
  2       1   (LGWR)          Other       target log write size                3880          1      4 -- на этих 3-х ожиданиях
  2       1   (LGWR)          Other       LGWR all worker groups                691          1    265 -- и облокируемый
  2       1   (LGWR)                      On CPU / runqueue                      61          1      0
...
  3       1     (LG..)        System I/O  log file parallel write              5064          1    217 -- LGWR-worker-ами (LG..)
  3       1     (LG..)        Other       LGWR worker group ordering            129          1    223
  3       1     (FOREGROUND)              On CPU / runqueue                       2          1      0
  4       1       (LG..)      System I/O  log file parallel write               129          1    347

— можно предположить, что для уменьшения log file sync достаточно сократить время/кол-во блокирующих ожиданий LGWR any worker group/LGWR all worker groups и target log write size, распределённых в этом случае приблизительно поровну

И если первая группа ожиданий очевидно «упирается» в кол-во/скорость работы LGWR-worker-ов, обозначенных как (LG..): (more…)

06.05.2016

Кластерные ожидания внутри одного инстанса RAC и количество LMS-процессов

Filed under: Active Session History,Oracle,RAC,SGA — Игорь Усольцев @ 12:48
Tags:

Краткосрочный всплеск ожиданий типа Cluster:

Top 5 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ --------
gc buffer busy acquire           1,157,219      59.3K      51.23   42.6 Cluster  
gc cr grant 2-way                2,838,562      24.8K       8.72   17.8 Cluster 
gc current grant busy              382,881      11.5K      30.05    8.3 Cluster 
DB CPU                                          10.6K               7.6         
gc current grant 2-way             141,095     8458.2      59.95    6.1 Cluster

был вызван сформирован* в бОльшей части двумя SQL с типом команд SELECT (без FOR UPDATE), выполнявшимися на 2-м инстансе: (more…)

18.02.2016

12c: эффекты Automatic Dynamic Sampling

Filed under: heuristics,Oracle,SQL Tuning — Игорь Усольцев @ 23:57
Tags: ,

Невысокая скорость выполнения запроса 8tx5kfa369rdb:

SQL> @shared_cu12_noxml 8tx5kfa369rdb 0
 
EXECS USERS_OPENING LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used  DS_LEVEL REASON#1 SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
----- ------------- -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- --------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- -------- ----------------- --------- ---------------- -----------
 2374             9 2016-02-08/12:47:01  12.02.2016 18:33:56   1474675990   1032495912               1        304100           8512     43756160     340539863      4044237314          10748     6 Y          N          Y          N                  N                       12        0                                                                                   

— ср.время / ELA_PER_EXEC ~ 1474 сек., много CPU и Concurrency, что визуально ассоциируется с 9 (в данном примере) одновременно открытыми курсорами / [V$SQL.]USERS_OPENING при полном отсутствии адаптивных эффектов (столбцы USE_FEEDBACK_STATS, REOPT, REOPT_HINTS, ADAPT, SPD_Used и DS_LEVEL) и нежданное событие ожидания в топе AWR:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ --------
DB CPU                                         181,6K              70.2         
latch: row cache objects        21,615,357      33,1K       1.53   12.8 Concurre -- тут
db file sequential read          4,369,250      23,5K       5.37    9.1 User I/O

судя по SQL Monitoring-у оказались связаны:) (more…)

30.09.2015

Об использовании Parallel Statement Queuing в процессе Complete Non-Atomic mview refresh

Filed under: Диагностика системы (instance),mview,Oracle — Игорь Усольцев @ 00:05
Tags: , ,

При выполнении DBMS_MVIEW.REFRESH(…, ‘C’, ATOMIC_REFRESH=>FALSE) можно видеть ожидание pipe get, что ожидаемо и описано в Complete Refresh Of Materialized View Hangs On Pipe Get (Doc ID 1193294.1), где, среди прочих «смелых» решений|solutions (удалять индексы перед обновлением, запретить job-ы на системном уровне, не использовать NONATOMIC REFRESH), рекомендуют использовать dbms_jobs вместо dbms_scheduler с помощью специального замысловатого event:)

$ oerr ora 10992
10992, 00000, "event to enable dbms_job instead of dbms_scheduler"
// *Cause:
// *Action:   enables dbms_job instead of dbms_scheduler
// *Comment:  set this event only under the supervision of Oracle Development
// LEVEL        ACTION
//---------------------------------------------------------------------------
//  0x0001      enable dbms_job instead of dbms_scheduler for MV refresh

Т.е. штатно DBMS_MVIEW.REFRESH после собственно обновления (TRUNCATE+INSERT /*+ APPEND*/) запускает одновременно несколько DBMS_SCHEDULER заданий с процедурами типа: (more…)

21.06.2015

Dynamic sampling (level=AUTO) в параллельных запросах с фиксированным планом выполнения

Filed under: Oracle,Plan Management — Игорь Усольцев @ 22:19
Tags: ,

При выполнении параллельного запроса наблюдалась неприятная картина ожиданий:

12.1.0.2.@ SQL> @ash_sqlmon2 8d49sjc17xwuc
 
LAST_PLSQL  SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                                                   PX ASH_ROWS WAIT_PROFILE
----------- ------------- --------------- ---- -------------------------------------------------------------------------------- -- -------- ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Soft Parse  8d49sjc17xwuc       162625646    0 sql_plan_hash_value > 0; sql_exec_id is null                                     39    26689 library cache lock(19424); cursor: pin S wait on X(7223); kksfbc child completion(29); ON CPU(9); db file sequential read(3); db file scattered read(1)
Main Query  8d49sjc17xwuc       162625646    0   SELECT STATEMENT                                                                           
                                             1     PX COORDINATOR                                                                           
...
                                            38                                                           TABLE ACCESS FULL      19      339 db file scattered read(194); ON CPU(80); db file sequential read(64); latch: gcs resource hash(1)
                                            39                                                     TABLE ACCESS BY INDEX ROWID  19       96 ON CPU(90); db file sequential read(6)
                                            40                                                       INDEX RANGE SCAN           19      158 ON CPU(129); db file sequential read(29)
                                            41                                                   INDEX RANGE SCAN               19      834 db file sequential read(737); ON CPU(97)
                                            42                                                 TABLE ACCESS BY INDEX ROWID      19     5278 db file sequential read(4076); gc cr grant 2-way(597); ON CPU(378); gcs drm freeze in enter server mode(219); gc current block 2-way(5); latch: gcs resource hash(1); gc cr request(1); read by other session(1)
...
SQL Summary                             0    0 ASH fixed 1 execs from 41 sessions                                                     34181  ash rows were fixed from 29.05.2015 12:13:09 to 29.05.2015 12:30:48

— где наряду с «нормальными» ожиданиями по ходу выполнения (ID 38-42, например), преобладают типичные для стадии Soft Parse (sql_plan_hash_value > 0 AND sql_exec_id is null) ожидания library cache lock и cursor: pin S wait on X, вероятно, связанные с параллельным выполнением судя по кол-ву ожидающих PX-процессов (столбец PX)

Что можно проверить во-время (выполнения запроса) запущенным скриптом: (more…)

19.06.2015

Короткие ожидания enq: TX — row lock contention в запросах FOR UPDATE SKIP LOCKED

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

Пример использования блокировок на уровне строки наблюдали с Дмитрием Балабановым для запросов этого типа:

11.2.0.3.@ SQL> @ash_sql_wait_tree "event = 'enq: TX - row lock contention' and sql_id in (select sql_id from gv$sqlarea where upper(sql_fulltext) like '%FOR%UPDATE%SKIP%LOCKED%' and command_type = 3)"


LVL  INST_ID BLOCKING_TREE  EVENT                          WAITS_COUNT  EXECS_COUNT  AVG_WAIT_TIME_MS DATA_OBJECT               BLOCK_SID       SQL_ID        SQL_PLAN_LINE_ID SQL_PLAN_OPERATION SQL_TEXT
--- -------- -------------- ----------------------------- ------------ ------------ ----------------- ------------------------- --------------- ------------- ---------------- ------------------ ----------------------------------------
  1        2 (USER)         enq: TX - row lock contention         1766         1764                 0 MY.AQ_TABLE.              GLOBAL i#       5cbp4s5jq04xg                1 FOR UPDATE         select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */
  1        1 (USER)         enq: TX - row lock contention         1163         1162                 0 MY.AQ_TABLE.              GLOBAL i#       5cbp4s5jq04xg                1 FOR UPDATE         select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */
  1        2 (USER)         enq: TX - row lock contention          304          304                 0 MY.U_TAABLE.U_PARTITION   GLOBAL i#       8x5xmcz928ydq                1 FOR UPDATE         SELECT                                   -- *
  1        1 (USER)         enq: TX - row lock contention          288          288                 0 MY.U_TAABLE.U_PARTITION   GLOBAL i#       8x5xmcz928ydq                1 FOR UPDATE         SELECT                                   -- *
  1        2 (USER)         enq: TX - row lock contention           29           29                 0 MY.AQ_TABLE.              UNKNOWN i#      5cbp4s5jq04xg                1 FOR UPDATE         select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */
  1        1 (USER)         enq: TX - row lock contention           11           11                 0 MY.AQ_TABLE.              UNKNOWN i#      5cbp4s5jq04xg                1 FOR UPDATE         select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */
  1        1 (USER)         enq: TX - row lock contention            7            7                 0 MY.U_TAABLE.OEBS          GLOBAL i#       fkrrfw2jmg1jw                1 FOR UPDATE         SELECT                                   -- *
  1        1 (USER)         enq: TX - row lock contention            7            7                 0 MY.U_TAABLE.U_PARTITION2  GLOBAL i#       8x5xmcz928ydq                1 FOR UPDATE         SELECT                                   -- *
  1        2 (USER)         enq: TX - row lock contention            3            3                 0 MY.AQ_TABLE.              VALID i#1       5cbp4s5jq04xg                1 FOR UPDATE         select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */
  1        2 (USER)         enq: TX - row lock contention            3            3                 0 MY.U_TAABLE.U_PARTITION2  GLOBAL i#       8x5xmcz928ydq                1 FOR UPDATE         SELECT                                   -- *
  1        1 (USER)         enq: TX - row lock contention            2            2                 0 MY.AQ_TABLE.              VALID i#2       5cbp4s5jq04xg                1 FOR UPDATE         select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */
  1        1 (USER)         enq: TX - row lock contention            1            1                 0 MY.U_LOCKS_TABLE.         GLOBAL i#       5c4mptv666r2x                1 FOR UPDATE         SELECT ID FROM U_LOCKS_TABLE WHERE NAME  -- *
  2        1   (USER)       On CPU / runqueue                        1            1                 0 ..                        NOT IN WAIT i#  5cbp4s5jq04xg                3 INDEX RANGE SCAN   select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */ -- **
  2        1   (USER)       On CPU / runqueue                        1            1                 0 MY.AQ$_AQ_TABLE_I.        NOT IN WAIT i#  5cbp4s5jq04xg                3 INDEX RANGE SCAN   select  /*+ INDEX(TAB AQ$_AQ_TABLE_I) */ -- **

— т.е. to skip any rows that are found to be already locked by another transaction, в ASH фиксируются формальные блокировки с 0-й длительностью AVG_WAIT_TIME_MS, вычисляемой как AVG(TIME_WAITED) / 1000

Среди запросов с использованием SKIP LOCKED, вролне естественно, много AQ-запросов, есть пользовательские запросы (*) и даже отмечена пара AQ-блокеров (**)

25.11.2014

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

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

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

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

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

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

12.08.2014

Кластерные ожидания и запросы Advanced Queuing

Filed under: Active Session History,Диагностика системы (instance),Oracle,RAC — Игорь Усольцев @ 22:08
Tags: ,

Периодически в Oracle 11.2 RAC системе возникают характерные кластерные проблемы, в основном, по причинам неверной конфигурации, например, выбора неподходящего сервиса для выполнения ресурсоёмких бизнес процессов / пакетных заданий

Далее описана наглядная краткосрочная проблема этого типа и, в частности, роль AQ запросов

Итак, AWR показал:

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:    296087 07-Aug-14 12:00:39       451       2.2
  End Snap:    296088 07-Aug-14 12:30:40       504       2.1
   Elapsed:               30.02 (mins)
   DB Time:            2,615.89 (mins)                       -- завышенный DB Time для 16 ядерного сервера

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc buffer busy acquire              354,144      67,484    191   43.0 Cluster    -- и богатый набор кластерных ожиданий
gc cr block 2-way                   319,644      16,234     51   10.3 Cluster
gc current grant busy               117,362      11,066     94    7.1 Cluster
gc current block 2-way              169,545       9,974     59    6.4 Cluster

(more…)

23.05.2014

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

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

Неожиданное замедление (типа зависания) конкретного выполнения business-critical запроса хорошо отражено в истории / статистике выполнения:

11.2.0.3@ SQL> @dba_hist_sqlstat "sql_id = 'acn3a69qq1shm' and snap_id between 13388 and 13398 and executions_delta > 0"
 
BEGIN_SNAP_ID BEGIN_SNAP_TIME    EXECS SQL_ID              PLAN ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC ROWS_PER_EXEC IOWAITS_PER_EXEC PLSQL_PER_EXEC
------------- --------------- -------- ------------- ---------- ------------ ------------ ------------- ------------- ---------------- --------------
        13397 11.05 17:00            4 acn3a69qq1shm 2432857935     12854543     12816052        264545         87880             4178         326776
        13396 11.05 16:00            4 acn3a69qq1shm 2432857935     13606742     13580436        264443         87877                0         330023
        13395 11.05 15:00            4 acn3a69qq1shm 2432857935     13334563     13310976        264512         87875                0         344457
        13394 11.05 14:00            4 acn3a69qq1shm 2432857935     13317390     13291479        264486         87872             2219         352094
        13393 11.05 13:00            4 acn3a69qq1shm 2432857935     12772781     12750312        264412         87868                0         325120
        13392 11.05 12:00            4 acn3a69qq1shm 2432857935   1509697104   1507157378        201421         65900             3778         262398 -- *here be dragonz*
        13390 11.05 10:00            3 acn3a69qq1shm 2432857935     17096391     17027411        284141         87862                0         409195
        13389 11.05 09:00            4 acn3a69qq1shm 2432857935     14647366     14618028        264570         87862                2         374048
        13388 11.05 08:00            4 acn3a69qq1shm 2432857935     14292003     14265081        264463         87861                0         376493
        13387 11.05 07:00            4 acn3a69qq1shm 2432857935     15069307     15043464        264489         87860                0         396593

— ср.время выполнения запроса (ELA_PER_EXEC) выросло в 100 раз (в действительности — больше, т.к. было фиксировано замедление лишь одного из 4-х выполнений за час)

При этом ни план, ни кол-во прочитанных буферов, ни кол-во возвращаемых строк значительно не изменились (небольшое видимое уменьшение GETS_PER_EXEC и ROWS_PER_EXEC связано с насильственным прерыванием выполнения «зависшего» запроса) (more…)

Следующая страница →

Блог на WordPress.com.