Oracle mechanics

24.09.2013

Подсказка PARALLEL в тексте обзора

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

Итак, порядка 1/4 DB Time, как обычно, «вдруг» стало расходоваться на пустое ожидание, связанное с конкуренцией за курсоры в library cache:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time  Wait Class
------------------------------ ------------ ----------- ------ ------ -----------
DB CPU                                           17,090          39.1
cursor: pin S wait on X               6,590      12,110   1838   27.7 Concurrency -- here be dragonz
db file sequential read             816,817       6,573      8   15.1 User I/O
direct path read                     37,219       1,910     51    4.4 User I/O
log file sync                        43,174       1,140     26    2.6 Commit    

Для начала выясняю какого типа процессы висят на ожидании?

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

LVL INST_ID BLOCKING_TREE                  SQL_OPNAME EVENT                      WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ------------------------------ ---------- -------------------------- ----------- ---------- ------
  1       1 PX                             SELECT     cursor: pin S wait on X          39735        332    620 -- основные waiter-ы
  1       1 FOREGROUND                     SELECT     cursor: pin S wait on X            142         22    988
  1       1 FOREGROUND                                cursor: pin S wait on X             11          4    939
  2       1   PX                           SELECT     On CPU / runqueue                39586        241      0 -- основные blocker-ы
  2       1   FOREGROUND                   SELECT     On CPU / runqueue                   65         23      0
  2       1   FOREGROUND                   SELECT     gc cr multi block request           51          4     76
  3       1     FOREGROUND                 SELECT     On CPU / runqueue                   15          1      0
  1       2 PX                             SELECT     cursor: pin S wait on X          45012        323    678 -- --//--
  1       2 FOREGROUND                     SELECT     cursor: pin S wait on X            347         36    998
  1       2 FOREGROUND                                cursor: pin S wait on X             58          5   1019
  2       2   PX                           SELECT     On CPU / runqueue                44893        249      0 -- --//--
  2       2   FOREGROUND                   SELECT     gc cr multi block request          163         15     78
  2       2   FOREGROUND                   SELECT     On CPU / runqueue                  121         35      0
  3       2     FOREGROUND                 SELECT     gc cr multi block request           43         10    244
  3       2     FOREGROUND                 SELECT     On CPU / runqueue                   15          1      0

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

SQL> select distinct i.owner, i.index_name, i.degree, o.last_ddl_time
  2    from gv$sql_plan p, dba_indexes i, dba_objects o
  3   where p.operation = 'INDEX'
  4     and p.object_owner = i.owner
  5     and p.object_name = i.index_name
  6     and i.degree not in ('0', '1', 'DEFAULT')
  7     and i.owner = o.owner
  8     and i.index_name = o.object_name
  9     and o.object_type = 'INDEX'
 10     and (p.inst_id, p.sql_id, p.plan_hash_value) in
 11         (select inst_id, sql_id, sql_plan_hash_value
 12            from gv$active_session_history a
 13           where event = 'cursor: pin S wait on X'
 14             and program like 'oracle%(P0%')
 15  order by o.last_ddl_time desc
 16  /

no rows selected

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

Если присмотреться к проблемным курсорам:

SQL> select inst_id, sql_id, count(*)
  2    from gv$active_session_history a
  3   where event = 'cursor: pin S wait on X'
  4     and program like 'oracle%(P0%'
  5     and sample_time > trunc(sysdate)
  6   group by inst_id, rollup(sql_id)
  7  having count(*) > 200
  8   order by count(*) desc, inst_id
  9  /

INST_ID SQL_ID          COUNT(*)
------- ------------- ----------
      2                    41860 -- суммарное по инстансу кол-во таких ожиданий за текущие сутки
      1                    35373 -- --//--
      2 2arh7z09gq6a1        360 -- при выполнении этих запросов больше всего ожиданий
      2 btca9z55vkqrf        350 -- --//--
      1 369pqr0s3h02w        262 -- --//--

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('2arh7z09gq6a1'));

PLAN_TABLE_OUTPUT
...
Note
-----
   - dynamic sampling used for this statement (level=6)
   - Degree of Parallelism is 8 because of hint        -- may be, here be dragonz ?

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

SQL> select inst_id, sql_id, count(*)
  2    from gv$active_session_history a
  3   where event = 'cursor: pin S wait on X'
  4     and program like 'oracle%(P0%'
  5     and sample_time > trunc(sysdate)
  6     and not exists
  7   (select null
  8            from gv$sql_plan p
  9           where p.inst_id = inst_id
 10             and p.sql_id = sql_id
 11             and p.plan_hash_value = a.sql_plan_hash_value
 12             and other_xml like '%hint%')
 13   group by inst_id, rollup(sql_id)
 14   order by count(*) desc
 15  /

INST_ID SQL_ID          COUNT(*)
------- ------------- ----------
      2                      119 -- summary
      2 5kmd7vh3b2d8p         60
      2 dv8rqcfcmbsxm         45
      2 dqzw87txts8k6         14

— действительно, запросы без ссылки на подсказки в секции Note плана выполнения ждут на пару порядков реже, т.е. достаточно часто интересующие ожидания возникали именно при выполнении хинтованных запросов

К счастью обнаружилось, прямо в текстах почти всех таких запросов упоминаются 2 конкретных обзора, созданных с подсказкой /*+ PARALLEL(8)*/:

11.2.0.3.BALANCE1@SYS SQL> select inst_id, sql_id, sql_plan_hash_value, count(*)
  2    from gv$active_session_history a left join gv$sqlarea sa using (inst_id, sql_id)
  3   where event = 'cursor: pin S wait on X'
  4     and program like 'oracle%(P0%'
  5     and sample_time > trunc(sysdate)
  6     and UPPER(sa.sql_fulltext) not like '%V_UI_DEPENDENCES%'
  7     and UPPER(sa.sql_fulltext) not like '%V_UI_DEPS_OTHERS%'
  8   group by inst_id, rollup(sql_id, sql_plan_hash_value)
  9   order by count(*) desc
 10  /

no rows selected

— что значительно упростило локализацию проблемы (в случае множественной вложенности обзоров найти зависимость было бы немного сложнее). Попутно оказалось, что секция Note плана не всегда корректно отражает факт стимулирования DOP подсказками

Когда в последний раз менялись эти обзоры?

SQL> select to_char(last_ddl_time, 'dd.mm.yyyy hh24:mi:ss') as LAST_DDL_TIME
  2    from dba_objects
  3   where object_name in ('V_UI_DEPENDENCES', 'V_UI_DEPS_OTHERS')
  4     and object_type = 'VIEW'
  5  /

LAST_DDL_TIME
-------------------
09.08.2013 11:37:26
09.08.2013 11:37:26

До добавления хинтов а обзоры AWR выглядел вполне классически:

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:    278613 08-Aug-13 11:00:05       315       1.7
  End Snap:    278614 08-Aug-13 11:30:08       338       1.6
   Elapsed:               30.05 (mins)
   DB Time:              425.59 (mins)
...
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           12,125          47.5
db file sequential read             467,060       4,713     10   18.5 User I/O
db file scattered read               64,558         894     14    3.5 User I/O
db file parallel read                61,549         780     13    3.1 User I/O
direct path read temp                70,314         752     11    2.9 User I/O  

А после добавления, точнее, на следующий рабочий день, ибо изменения в обзоры были внесены 09-Aug-13, в пятницу — очевидно, в силу сакральных традиций ;)

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:    278805 12-Aug-13 11:00:19       525       1.5
  End Snap:    278806 12-Aug-13 11:30:23       539       1.5
   Elapsed:               30.07 (mins)
   DB Time:              495.10 (mins)
...
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                           11,830          39.8
cursor: pin S wait on X               2,809       7,027   2502   23.7 Concurrenc -- в AWR появилась "особенность"
db file sequential read             289,364       2,675      9    9.0 User I/O
db file scattered read               60,552         827     14    2.8 User I/O
db file parallel read                56,445         716     13    2.4 User I/O

При этом, например, для «топового» запроса sql_id=’2arh7z09gq6a1′ параллельное выполнение:

SQL> select
  2   count(*) cnt,
...
 92  /

1 row selected.

Elapsed: 00:00:00.78

Note
-----
   - dynamic sampling used for this statement (level=6)
   - Degree of Parallelism is 8 because of hint

Statistics
----------------------------------------------------------
         48  recursive calls                              --  dynamic sampling
          0  db block gets
      24493  consistent gets                              -- больше чтений
          0  physical reads
          0  redo size
        803  bytes sent via SQL*Net to client
        364  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         12  sorts (memory)                               -- больше сортировок
          0  sorts (disk)
          1  rows processed

— скорее замедляет выполнение запроса, в том числе за счёт dynamic sampling, автоматически запускаемого Oracle 11g при параллельном выполнении

В то время как непараллелельное выполнение:

SQL> select --+ NO_PARALLEL
  2   count(*) cnt,
...
 92  /

1 row selected.

Elapsed: 00:00:00.06

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
      20460  consistent gets
          0  physical reads
          0  redo size
        803  bytes sent via SQL*Net to client
        364  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          1  rows processed

показывает как минимум не худший результат. Точно так же и большинство запросов, изпользующих проблемные обзоры, являются быстрыми индексными запросами OLTP-типа и скорее проигрывают от форсирования параллельного выполнения

Пока существовала проблема — можно было наблюдать циклическую конкуренцию PX процессов за доступ к родительскому курсору  с, похоже, фиксированным таймаутом в online-режиме:

SQL> @mutex_waits

LVL WAITING_SID PROGRAM                   EVENT                   SECONDS_IN_WAIT BLOCKING_SESSION SQL_ID        SID_HOLDING_MUTEX MUTEX_TYPE  MUTEX_LOCATION
--- ----------- ------------------------- ----------------------- --------------- ---------------- ------------- ----------------- ----------- -------------------
  1           3 oracle@db-host.ru (P025)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1          80 oracle@db-host.ru (P020)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1         216 oracle@db-host.ru (P012)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1         268 oracle@db-host.ru (P017)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1         310 oracle@db-host.ru (P013)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1         363 oracle@db-host.ru (P014)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1         376 oracle@db-host.ru (P018)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1         797 oracle@db-host.ru (P010)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1         879 oracle@db-host.ru (P015)  library cache: mutex X                1                  a2na6hhpxap4q              1086
  1         999 oracle@db-host.ru (P021)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1        1080 oracle@db-host.ru (P019)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1        1086 oracle@db-host.ru (P022)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1        1104 oracle@db-host.ru (P023)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1        1149 oracle@db-host.ru (P011)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1        1277 oracle@db-host.ru (P024)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]
  1        1358 oracle@db-host.ru (P016)  cursor: pin S wait on X               1                  a2na6hhpxap4q               879 Cursor Pin  kkslce [KKSCHLPIN2]

— хорошо заметен mutex типа Cursor Pin / kkslce [KKSCHLPIN2], который с большим опережением возглавляет тройку лидеров на уровне всей системы:

SQL> select * from (select * from X$MUTEX_SLEEP order by sleeps desc) where rownum <= 3;

ADDR             INDX INST_ID MUTEX_TYPE    MUTEX_TYPE_ID LOCATION_ID LOCATION                 SLEEPS  WAIT_TIME
---------------- ---- ------- ------------- ------------- ----------- -------------------- ---------- ----------
00007F195F79D248   46       2 Cursor Pin                7           5 kkslce [KKSCHLPIN2]   280990843          0
00007F195F79DBB0    9       2 Library Cache             4          91 kglpnal2  91            3149172          0
00007F195F79DA30    6       2 Library Cache             4         106 kglhdgn2 106            2511514          0

, и отчётливо отражён в AWR:

 Mutex Sleep Summary            DB/Inst: -> ordered by number of sleeps desc

                                                                         Wait
Mutex Type            Location                               Sleeps    Time (ms)
--------------------- -------------------------------- ------------ ------------
Cursor Pin            kkslce [KKSCHLPIN2]                 1,399,866            0
Library Cache         kglpnal2  91                           20,906            0
...

Такого типа конкуренция описана в «Cursor: Pin S Wait On X» Contention Mutex Sleep Reason Primarily ‘ kkslce [KKSCHLPIN2]’ (Doc ID 1268724.1), но там речь идёт о проблеме high version count, которая в определённой степени присутствует в системе:

SQL> select sql_id, count(*)
  2    from v$sql_shared_cursor
  3   group by sql_id
  4  having count(*) > 40
  5   order by 2 desc;

SQL_ID          COUNT(*)
------------- ----------
c19vby4vk5kxv       2035
45u45mpanbatr       1010
01qms8fjs22uk         43
...

, но не имеет отношения к рассматриваемым запросам с  проблемными ожиданиями:

SQL> select inst_id,
  2         sql_id,
  3         count(distinct a.session_id || a.session_serial# || a.sample_time) as EVENT_COUNT,
  4         count(distinct sc.child_address) as VERSION_COUNT
  5    from gv$active_session_history a
  6    left join gv$sql_shared_cursor sc
  7   using (inst_id, sql_id)
  8   where a.event = 'cursor: pin S wait on X'
  9     and a.sample_time > trunc(sysdate)
 10   group by inst_id, sql_id
 11  having count(distinct a.session_id || a.session_serial# || a.sample_time) > 100
 12   order by 3 desc
 13  /

INST_ID SQL_ID        EVENT_COUNT VERSION_COUNT
------- ------------- ----------- -------------
      1 fa2ru89gtwux4         250             0 -- курсоры уже "вымыты" из Shared Pool, т.к. запрос делается за сутки
      2 558kbpm21wnw8         224             2
      2 2pcw3rbqy3909         199             2
      1 gb57c54288nty         154             0
      2 3pymk1q43cqbb         152             1
      1 1zfqh0gghszf3         150             2
      2 61h6pm28bmxjv         150             2
      2 cdh8ry1z6jgcc         145             2
      2 c7wksfw95jcuu         141             2
...

Как оказалось, подсказка /*+ PARALLEL(8)*/ была добавлена в частоиспользуемые обзоры с целью ускорить выполнение пары действительно тяжёлых запросов ;)

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

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

RSS feed for comments on this post. TrackBack URI

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

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

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

%d такие блоггеры, как: