Oracle mechanics

13.11.2016

Oracle 12.1: Library Cache Lock на объекте типа $BUILD$, Adaptive Plan и параллельное выполнение

Filed under: Oracle,Scripts,shared pool,wait events — Игорь Усольцев @ 23:37
Tags: ,

Активизировавшаяся конкуренция за объекты Library Cache в форме ожиданий library cache lock, и в меньшей степени kksfbc child completion, library cache: mutex X:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ -----------
DB CPU                                          10.3K              77.6         
library cache lock                 159,109     1554.8       9.77   11.7 Concurrency -- здесь
db file sequential read            297,807      436.2       1.46    3.3 User I/O
cursor: pin S wait on X             26,087      322.5      12.36    2.4 Concurrency
log file sync                      116,938      267.6       2.29    2.0 Commit  
SQL*Net more data from client    1,809,223      131.1       0.07    1.0 Network 
kksfbc child completion              2,213      108.3      48.94     .8 Other       -- , здесь
control file sequential read       290,199       72.9       0.25     .5 System I
direct path write                    6,026       46.3       7.69     .3 User I/O
library cache: mutex X              83,522       45.7       0.55     .3 Concurrency -- и здесь

оказалось вызвана PX-slave процессами (P…) одного параллельно выполнявшимся запроса dx0fckp3gckku в стадии подготовки (IN_PARSE) адаптивного плана (SQL_ADAPTIVE_PLAN_RESOLVED = 1): (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…)

21.05.2014

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

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

При анализе проблем длительного выполнения concurrent request в системе OEBS, зная CLIENT_ID/SID-ы медленно выполнявшихся дочерних процессов и номера начального/конечного снапшотов интересующего периода, достаточно просто выделить «проблемный» запрос из истории ASH:

11.2.0.4@ SQL> @ash_sql_wait_tree_hist "client_id = 'USER007' and (instance_number, session_id, session_serial#) in ((1,2251,19231),(1,1707,26715))" 67983 67991
 
LVL INST_ID BLOCKING_TREE  CLIENT_ID   EVENT                          WAITS_COUNT EXECS_COUNT SESS_COUNT AVG_WA SQL_ID        TOP_LEVEL_SQL_ID SQL_TEXT
--- ------- -------------- ----------- ------------------------------ ----------- ----------- ---------- ------ ------------- ---------------- ------------------------------------------------
  1       1 FOREGROUND     USER007     On CPU / runqueue                      940        1064          2      0 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  1       1 FOREGROUND     USER007     On CPU / runqueue                      285           1          2      0                                
  1       1 FOREGROUND     USER007     library cache: mutex X                  30          30          2     10 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  1       1 FOREGROUND     USER007     library cache: mutex X                  14           0          2     11                                
...

и убедившись, что запрос c4wtbv2xcmq78 выполнялся в это время только сессиями интересующего нас клиента: (more…)

21.01.2014

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

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

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

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

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

(more…)

11.12.2013

Блокировки типа RC — Result Cache при использовании MTS

При использовании Multi-Threaded Server блокировки типа RC — Result Cache в AWR вполне ожидаемы при:

11.1.0.7.@ SQL> show parameter result_cache_mode

NAME                                 VALUE
------------------------------------ --------
result_cache_mode                    FORCE

Зависимости ожидания (wait tree) при этом представляют, в основном, логичную картину:

11.1.0.7.@ SQL> @ash_wait_tree "event = 'enq: RC - Result Cache: Contention'"

LVL BLOCKING_TREE       EVENT                              WAITS_COUNT SESS_COUNT AVG_WA
--- ------------------- ---------------------------------- ----------- ---------- ------
  1 FOREGROUND          enq: RC - Result Cache: Contention        3019         49    999 -- блокированные на кэше запросы ожидают:
  2   FOREGROUND        db file sequential read                   1243         13     50 -- ввод-вывод в процессе выполнения запроса/наполнения кэша
  2   FOREGROUND        read by other session                      844          1     69 -- --//--
  2   FOREGROUND        db file parallel read                      594          1     61 -- --//--
  2   FOREGROUND        db file scattered read                     230          9     59 -- --//--
  2   FOREGROUND        On CPU / runqueue                           37          8      0 -- ЦПУ при выполнении запроса/наполнения кэша
  2   FOREGROUND        virtual circuit wait                        14          2    146 -- ???
  2   FOREGROUND        log buffer space                             4          1     11 -- отложенная очистка блоков(delayed block cleanout)
  2   FOREGROUND        read by other session                        2          1     32
  3     FOREGROUND      db file sequential read                    834          4     69
  3     FOREGROUND      On CPU / runqueue                            5          2      0
  3     (LGWR)          control file parallel write                  4          1     24 -- и LGWR, её сдерживающий
  3     FOREGROUND      read by other session                        4          2     17
  3     FOREGROUND      read by other session                        1          1      9
  4       FOREGROUND    db file sequential read                      1          1      9 -- чтения нижнего уровня, завершения которых ждут на read by other session

— кроме ожидания virtual circuit wait, блокирующего доступ к кэшу на enq: RC — Result Cache: Contention (more…)

24.07.2013

Построение индекса в режиме ONLINE и ожидание enq: MD — contention

Filed under: commonplace,Блокировки,Oracle,wait events — Игорь Усольцев @ 09:27
Tags: ,

В 11.2.0.3 поспешно несвоевременно попытался построить индекс на таблице с materialized view log:

SID#283 SQL> @sid

INST_ID SID  SERIAL#  SPID
------- ---- ------- -----
1       283      295 32156

SID#283 SQL> create index T_CLIENT_CLASS_ID_UIDX on T_CLIENT(CLASS_ID, ID) tablespace ITS online parallel;

Однако, заметив затянувшееся ожидание enq: MD — contention:

SQL> select * from v$lock_type where type = 'MD';

TYPE  NAME                       ID1_TAG          ID2_TAG  IS_USER DESCRIPTION
----- -------------------------- ---------------- -------- ------- -----------------------------------------------------
MD    Materialized View Log DDL  master object #  0        NO      Lock held during materialized view log DDL statements

, попытался терминировать сессию средствами Oracle:

OTHER_SID SQL> Alter system kill session '283,295';

Alter system kill session '283,295'

ORA-00031: session marked for kill

Через некоторое время на этой ( конечно же, тестовой ;) системе были замечены ряд сессий в длительном ожидании library cache lock: (more…)

31.03.2013

asynch descriptor resize, Oracle 11.2.0.3 Linux x86_64

Запрос с непредсказуемыми изменениями времени выполнения:

11.2.0.3.@ SQL> select sql_exec_id,
  2         sql_plan_hash_value,
  3         max(sample_time) - min(sample_time) as QUERY_DURATION,
  4         round(sum(tm_delta_db_time) / 1000000) as db_time_sec,
  5         round(sum(tm_delta_cpu_time) / 1000000) as cpu_time_sec,
  6         sum(delta_read_io_requests + delta_write_io_requests) IO_REQUESTS,
  7         round(sum(delta_read_io_bytes + delta_write_io_bytes) / 1024 / 1024) as IO_MB
  8    from v$active_session_history
  9   where sql_id = 'fspy8r76zbmvq'
 10     and sql_exec_id between 17017534 and 17017547
 11   group by sql_exec_id, sql_plan_hash_value
 12   order by sql_exec_id
 13  /

SQL_EXEC_ID PLAN_HASH_V QUERY_DURATION DB_TIME_SEC CPU_TIME_SEC IO_REQUESTS      IO_MB
----------- ----------- -------------- ----------- ------------ ----------- ----------
   17017534  1249237767  00:04:44.432          284           23         342        333
   17017537  1249237767  00:00:02.000            2            1         356        334
   17017539  1249237767  00:00:02.000            1            0         339        327
   17017540  1249237767  00:00:01.000            3            1         395        385
   17017541  1249237767  00:00:02.000            3            2         341        320
   17017542  1249237767  00:00:03.000            2            0         343        334
   17017543  1249237767  00:00:01.000            6            5         323        288
   17017544  1249237767  00:00:01.000            2            1         307        298
   17017545  1249237767  00:00:02.000            3            1         346        334
   17017546  1249237767  00:00:02.000            2            1         258        247
   17017547  1249237767  00:45:49.989         2753           59         346        334

— разброс времени выполнения от 1 сек до 45 минут (что представляет некоторое неудобство для пользователей), при этом план, статистика, значения св.переменных в запросе и общая загрузка сервера не менялись. Различным значениям DB_TIME, зафиксированным в V$ACTIVE_SESSION_HISTORY, соответствует приблизительно одинаковый ввод-вывод и незначительно различающиеся CPU_TIME, например, в последнем выполнении из 2753 сек DB_TIME только 59 секунд занимает CPU_TIME согласно ASH, в отличие от V$SESS_TIME_MODEL, где увеличение длительности таких запросов полностью отражается в увеличении CPU_TIME
(more…)

03.03.2013

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

Filed under: heuristics,hints,Oracle,wait events — Игорь Усольцев @ 21:26
Tags: , ,

Сравнение методов соединения индексов Index Join и Index Bitmap, релизуемых, например, подсказками /*+ INDEX_JOIN */ и /*+ INDEX_COMBINE */ , показывает, что оптимизатор отдаёт предпочтение Index Join, даже в случае проигрыша по стоимости

Далее приведены простые тесты индексных методов, а также попутно полученный тесткейс использования операции db file parallel read на шаге TABLE ACCESS BY INDEX ROWID плана выполнения (more…)

02.03.2013

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

В почти идеальном топе ожиданий AWR версии 11.2.0.3 попалось странное :

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           16,642          77.7
direct path read                  7,870,194       3,309      0   15.4 User I/O
log file sync                       154,270         292      2    1.4 Commit
cursor: pin S wait on X                 218         269   1235    1.3 Concurrenc -- ***
direct path read temp               157,474         204      1    1.0 User I/O

— нечастое ожидание cursor: pin S wait on X с огромной длительностью ~ 1.2 сек занимает больше процента DB time

Согласно классическим описаниям Troubleshooting ‘cursor: pin S wait on X’ waits. [ID 1349387.1]«cursor: pin S wait on X» Reference Note основными причинами ожидания являются:

  • частые или длительные hard parse
  • либо множественные копии курсора в shared pool — high version count

(more…)

24.11.2012

Таймауты параллельных ожиданий, или почему по умолчанию объекты бд создаются noparallel

Filed under: Oracle,parameters,PX,statistics,wait events — Игорь Усольцев @ 00:43
Tags: , , , ,

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

11.2.0.3.@ SQL> select /*+ noparallel */ *
  2    from view_history
  3   where order_id = 4181494
  4     and start_dt >= sysdate - 20
  5     and sysdate - 20 < end_dt
  6  /

no rows selected

Elapsed: 00:00:00.12

(more…)

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

Создайте бесплатный сайт или блог на WordPress.com.