Oracle mechanics

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

По частоте разбора (SQL ordered by Parse Calls) в том же отчёте AWR без явного лидера преобладали системные / рекурсивные запросы, в топе по кол-ву версий:

SQL ordered by Version Count
-> Only Statements with Version Count greater than 20 are displayed

 Version
  Count   Executions     SQL Id
-------- ------------ -------------
      99          286 bpv2838357n75
...

— интересным было только ярко выраженное верхнее ограничение количества дочерних курсоров на запрос, определяемое параметром _cursor_obsolete_threshold — см. Timur Akhmadeev. Obsolete cursors:

SQL> @param_ _cursor_obsolete_threshold

NAME                       VALUE  IS_DEF   DSC
-------------------------- ------ -------- -----------------------------------------------
_cursor_obsolete_threshold 100    TRUE     Number of cursors per parent before obsoletion.

Сами же запросы, указанные  в топе SQL ordered by Version Count показывали вполне предсказуемое для 11.2 поведение, характерное для Bind-Aware Cursor Sharing:

SQL> @shared_cu_sum bpv2838357n75
&1: bpv2838357n75

INST BIND_EQ_FAILURE  REASON                                                         COUNT(*)
---- ---------------- ------------------------------------------------------------ ----------
   1 Y                Bind mismatch(33)  |                                                 39
   1 Y                Rolling Invalidate Window Exceeded(2)  |  already_processed          12
   1 N                Rolling Invalidate Window Exceeded(2)  |  already_processed           8
   1 N                Bind mismatch(33)  |                                                  1
   1 N                Rolling Invalidate Window Exceeded(3)  |                              1

Значительно полезнее для определения причин cursor: pin S wait on X оказался топ AWR по использованию курсорами разделяемой памяти (Shared Pool SGA):

SQL ordered by Sharable Memory DB/Inst:
-> Only Statements with Sharable Memory greater than 1048576 are displayed

Sharable Mem (b)  Executions   % Total    SQL Id
---------------- ------------ -------- -------------
      79,363,336          360     0.90 1d6hyx1r5mswx
      78,873,208          360     0.89 1d6hyx1r5mswx
      15,982,594            3     0.18 9dhn1b8d88dpf

— где с большим отрывом лидирует sql_id 1d6hyx1r5mswx (упомянутый отчего-то дважды — но это мелкий недочёт). Параллельные процессы того же запроса значительно чаще других были замечены в ASH:

SQL> select sql_id,
  2         decode(instr(program, '(P0'), 0, 'FOREGROUND', 'PX Slave') TYPE,
  3         count(*)
  4    from v$active_session_history
  5   where event = 'cursor: pin S wait on X'
  6   group by sql_id,
  7            decode(instr(program, '(P0'), 0, 'FOREGROUND', 'PX Slave')
  8  having count(*) > 100
  9   order by count(*) desc
 10  /

SQL_ID        TYPE         COUNT(*)
------------- ---------- ----------
1d6hyx1r5mswx PX Slave         3858

А по суммарному количеству дочерних курсоров, включая «устаревшие» (v$sql.is_oblolete=’Y’), запрос оказался просто чемпионом:)

SQL> select sql_id, count(*)
  2    from v$sql
  3   group by sql_id
  4  having count(*) > 100
  5   order by count(*) desc
  6  /

SQL_ID          COUNT(*)
------------- ----------
1d6hyx1r5mswx       1034
2k9r3t70t9fxm        104
23nad9x295gkf        103

Вероятно, методика AWR подсчёта запросов с высоким high version count, основанная на количестве v$sql.child_number — не самая удачная и следует обращать внимание на общее количество дочерних курсоров — суммируя кол-во v$sql.child_address, что больше соответствует суммарному объёму памяти, занимаемому курсором в shared pool, и как следствие, возможным проблемам / ожиданиям при разборе очередного курсора

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

SQL> @shared_cu_sum 1d6hyx1r5mswx

INST IS_OBSOLETE PQ_SLAVE_MISMATCH TOP_LEVEL_RPI_CURSOR REASON1                                                      REASON2                                  COUNT(*)
---- ----------- ----------------- -------------------- ------------------------------------------------------------ ---------------------------------------- --------
   1 Y           Y                 N                    PQ Slave mismatch(2)  |                                      Top Level RPI Cursor(0)  |                    881
   1 Y           N                 N                    PQ Slave mismatch(2)  |                                      Top Level RPI Cursor(0)  |                    190
   1 Y           N                 Y                    PQ Slave mismatch(2)  |                                      NLS Settings(0)  |                             12
   1 Y           N                 N                    PQ Slave mismatch(2)  |                                      NLS Settings(0)  |                             10
   1 N           N                 N                    Optimizer mismatch(13)  |                                    Top Level RPI Cursor(0)  |                      4
   1 N           N                 N                    Rolling Invalidate Window Exceeded(2)  |  already_processed  Rolling Invalidate Window Exceeded(3)  |        3
   1 Y           N                 Y                    Rolling Invalidate Window Exceeded(2)  |  already_processed  Rolling Invalidate Window Exceeded(3)  |        2
   1 N           N                 N                    NLS Settings(0)  |                                           Top Level RPI Cursor(0)  |                      2
   1 N           N                 N                    Optimizer mismatch(13)  |                                    NLS Settings(0)  |                              1
   1 Y           N                 N                    Rolling Invalidate Window Exceeded(3)  |                     PQ Slave mismatch(2)  |                         1

, хотя столбцы с указанием причин PQ_SLAVE_MISMATCH, TOP_LEVEL_RPI_CURSOR часто не совпадают с первыми 2-мя значениями из поля v$sql_shared_cursor.reason — что очень похоже на Bug 12539487 : V$SQL_SHARED_CURSOR.REASON DIFFERENT FROM BITMAP FLAGS

Интересно также то, что в поле v$sql_shared_cursor.reason для каждого дочернего курсора указывается целый ряд причин повторного неиспользования — иногда довольно длинный:

SQL> SELECT INST,
  2         count(*),
  3         is_obsolete,
  4         pq_slave_mismatch,
  5         top_level_rpi_cursor,
  6         Reason
  7  from (
  8  SELECT INST,
  9         is_obsolete,
 10         pq_slave_mismatch,
 11         top_level_rpi_cursor,
 12         LISTAGG(Reason, '; ') WITHIN GROUP (ORDER BY to_number(rid)) AS Reason
 13  FROM (select sc.sql_id,
 14               sc.child_address,
 15               sc.inst_id as INST,
 16               is_obsolete,
 17               pq_slave_mismatch,
 18               top_level_rpi_cursor,
 19               xt.rid || ' |' || xt.Reasons || ' |' || xt.Details as Reason,
 20               xt.rid
 21               from gv$sql_shared_cursor sc, gv$sql s,
 22                 xmltable('/Reasonz/ChildNode' passing xmltype('<Reasonz>'||sc.reason||'</Reasonz>')
 23                          columns
 24                          RID varchar2(60) path 'ID',
 25                          Reasons varchar2(60) path 'reason',
 26                          Details varchar2(60) path 'details') xt
 27                            where dbms_lob.substr(reason, 256) <> ' '
 28                              and '1d6hyx1r5mswx' = sc.sql_id
 29                              and s.sql_id = sc.sql_id
 30                              and s.child_address = sc.child_address
 31                              and 1 = sc.inst_id)
 32  GROUP BY INST,
 33           is_obsolete,
 34           pq_slave_mismatch,
 35           top_level_rpi_cursor,
 36           child_address)
 37  GROUP BY INST,
 38           is_obsolete,
 39           pq_slave_mismatch,
 40           top_level_rpi_cursor,
 41           Reason
 42  order by count(*) desc
 43  /

INST   COUNT(*) IS_OBSOLETE PQ_SLAVE_MISMATCH TOP_LEVEL_RPI_CURSOR REASON
---- ---------- ----------- ----------------- -------------------- ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   1        813 Y           Y                 N                    7 |Top Level RPI Cursor(0) |; 9 |PQ Slave mismatch(2) |
   1        179 Y           N                 N                    7 |Top Level RPI Cursor(0) |; 9 |PQ Slave mismatch(2) |
   1         11 Y           N                 Y                    9 |PQ Slave mismatch(2) |; 45 |NLS Settings(0) |
   1          9 Y           N                 N                    9 |PQ Slave mismatch(2) |; 45 |NLS Settings(0) |
   1          6 N           N                 N                    3 |Optimizer mismatch(13) |; 7 |Top Level RPI Cursor(0) |; 9 |PQ Slave mismatch(2) |
   1          5 N           N                 N                    7 |Top Level RPI Cursor(0) |; 9 |PQ Slave mismatch(2) |; 34 |Rolling Invalidate Window Exceeded(2) |already_processed; 34 |Rolling Invalidate Window Exceeded(3) |; 45 |NLS Settings(0) |
   1          2 Y           N                 Y                    9 |PQ Slave mismatch(2) |; 34 |Rolling Invalidate Window Exceeded(2) |already_processed; 34 |Rolling Invalidate Window Exceeded(3) |; 45 |NLS Settings(0) |
   1          2 N           N                 N                    7 |Top Level RPI Cursor(0) |; 9 |PQ Slave mismatch(2) |; 45 |NLS Settings(0) |
   1          1 N           N                 N                    3 |Optimizer mismatch(13) |; 7 |Top Level RPI Cursor(0) |; 9 |PQ Slave mismatch(2) |; 45 |NLS Settings(0) |
   1          1 N           N                 N                    9 |PQ Slave mismatch(2) |; 34 |Rolling Invalidate Window Exceeded(2) |already_processed; 34 |Rolling Invalidate Window Exceeded(3) |; 45 |NLS Settings(0) |; 45 |NLS Settings(0) |
   1          1 Y           N                 N                    9 |PQ Slave mismatch(2) |; 34 |Rolling Invalidate Window Exceeded(3) |; 45 |NLS Settings(0) |
   1          1 N           N                 N                    3 |Optimizer mismatch(13) |; 9 |PQ Slave mismatch(2) |; 45 |NLS Settings(0) |

— похоже на отладочную информацию?)

Возвратившись к проблемному запросу, проверил насколько параллельное выполнение вообще имеет смысл:

SQL> set arraysize 5000
SQL> set autotrace on
SQL> SELECT--+ noparallel
...
 17  /

55686 rows selected.

Elapsed: 00:00:03.00
...
Statistics
----------------------------------------------------------
         85  recursive calls
         22  db block gets
      43610  consistent gets
          0  physical reads
          0  redo size
    4109554  bytes sent via SQL*Net to client
        596  bytes received via SQL*Net from client
         13  SQL*Net roundtrips to/from client
          4  sorts (memory)
          0  sorts (disk)
      55686  rows processed

— запрос вполне удовлетворительно выполняется непараллельно по сравнению с 20+ секундами DB time при параллельном выполнении

Осталось найти и устранить причину непредумышленного (в смысле нестимулированного хинтами и outline-нами — baseline-нами, параметры параллельного выполнения в системе установлены по умолчанию) параллелизма:

SQL> select owner, index_name, degree
  2    from dba_indexes
  3   where (owner, index_name) in
  4         (select distinct object_owner, object_name
  5            from v$sql_plan
  6           where sql_id = '1d6hyx1r5mswx')
  7     and degree > 1
  8  /

OWNER      INDEX_NAME                     DEGREE
---------- ------------------------------ ------
INDEXER    IDX_TESTING_DID                     8 -- последствия перестройки
INDEXER    IDX_PARAM_TYPE_ENTITY               8

SQL> alter index INDEXER.IDX_TESTING_DID noparallel
  2  /

Index altered.

SQL> alter index INDEXER.IDX_PARAM_TYPE_ENTITY noparallel
  2  /

Index altered.

И проверить как изменилась статистика реального выполнения запроса:

SQL> select
  2      sn.begin_interval_time,
  3      sum(st.executions_delta) as execs,
  4      round(avg(st.elapsed_time_delta/decode(st.executions_delta,0,1,st.executions_delta))) as ela_per_exec,
  5      max(round(st.px_servers_execs_delta/decode(st.executions_delta,0,1,st.executions_delta))) as px_per_exec,
  6      round(avg((st.rows_processed_delta/decode(st.executions_delta,0,1,st.executions_delta)))) as rows_per_exec,
  7      round(avg((st.fetches_delta/decode(st.executions_delta,0,1,st.executions_delta)))) as fetches_per_exec
  8  from dba_hist_sqlstat st, dba_hist_snapshot sn
  9  where sql_id in ('1d6hyx1r5mswx')
 10        and st.snap_id = sn.snap_id
 11        and st.instance_number = sn.instance_number
 12        and st.executions_delta > 0
 13        and sn.begin_interval_time between sysdate - 8/24 and sysdate - 2/24
 14  group by sn.begin_interval_time
 15  order by sn.begin_interval_time
 16  /

BEGIN_INTERVAL_TIME       EXECS ELA_PER_EXEC PX_PER_EXEC ROWS_PER_EXEC FETCHES_PER_EXEC
---------------------- -------- ------------ ----------- ------------- ----------------
28-FEB-13 13.00.42.303      360     23792121          16         55672                3 -- было - параллельно и медленно - PX_PER_EXEC > 0
28-FEB-13 14.00.48.991      360     23888670          16         55679                3 -- --//--
28-FEB-13 15.00.51.815      224     38860586          26         55686                3 -- --//--
28-FEB-13 16.00.56.239      272      1974574           0         55689                3 -- после отключения параллельного выполнения
28-FEB-13 17.00.58.732      297      1547864           0         55692                3 --   затраченное время ELA_PER_EXEC сократилось
28-FEB-13 18.00.03.103      324      1510308           0         55695                3 --   более чем на порядок

И убедиться чтоожидание cursor: pin S wait on X исчезло из стандартного отчёта AWR

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

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

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