Oracle mechanics

17.04.2013

Bug 10297948 High Version Count with PX_MISMATCH on Serial Queries in RAC

Filed under: bugs,Диагностика системы (instance),Oracle,RAC,shared pool — Игорь Усольцев @ 01:20
Tags: ,

Достаточно интересный для описания баг, с которым столкнулись в версии 11.2.0.2.0 Linux x86_64, практически выражается в периодическом «замирании» кластерных инстансов на ожиданиях, связанных с конкуренцией за shared pool, например, в таком виде:

11.2.0.2@ SQL> select event, count(*)
2    from dba_hist_active_sess_history
3   where snap_id = 135127
4     and session_state = 'WAITING'
5   group by event
6   order by count(*) desc
7  /

EVENT                                COUNT(*)
---------------------------------- ----------
library cache lock                       5311
cursor: pin S wait on X                  3800
db file sequential read                   119

или — в таком:

SQL> @ash_wait_tree "event = 'cursor: mutex S'"

LVL INST_ID BLOCKING_TREE       EVENT                    WAITS_COUNT AVG_WAIT_TIME_MS
--- ------- ------------------- ------------------------ ----------- ----------------
  1       1 FOREGROUND          cursor: mutex S                 4587      1
  2       1   FOREGROUND        cursor: mutex S                  304      0
  2       1   FOREGROUND        library cache lock                 8      5
  2       1   FOREGROUND        kksfbc child completion            2     51
  2       1   FOREGROUND        library cache: mutex X             1      0
  3       1     FOREGROUND      cursor: mutex S                   38      0
  4       1       FOREGROUND    cursor: mutex S                    8      0
  5       1         FOREGROUND  cursor: mutex S                    3      0
  1       2 FOREGROUND          cursor: mutex S                   27      0
  2       2   FOREGROUND        cursor: mutex S                    3      0
  3       2     FOREGROUND      cursor: mutex S                    2      0

При этом в последнем случае AWR показывает некоторые характерные признаки проблемы:

...
	   Elapsed:               15.12 (mins)
	   DB Time:              227.24 (mins)            -- повышенная нагрузка на систему
...
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.99       Redo NoWait %:   99.97
            Buffer  Hit   %:   99.96    In-memory Sort %:  100.00
            Library Hit   %:   69.59        Soft Parse %:   99.37
         Execute to Parse %:  -23.15         Latch Hit %:   99.99 -- характерный отрицательный Execute to Parse
Parse CPU to Parse Elapsd %:   84.67     % Non-Parse CPU:   27.00 -- низкий Non-Parse CPU ~ 3/4 CPU Time затрачено на разбор и конкуренцию за место в SGA
...
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                            7,384          54.2            -- большая часть этого времени - parsing
virtual circuit wait              4,739,200       3,588      1   26.3 Network    -- фактически idle wait event аналог SQL*Net message from client при использовании shared servers
cursor: mutex S                  21,382,242         681      0    5.0 Concurrenc -- ***
db file sequential read              33,357         327     10    2.4 User I/O
direct path read                     77,552         221      3    1.6 User I/O
...
Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
DB CPU                                                7,384.1         54.2
parse time elapsed                                    6,469.3         47.4 -- почти полоdина DB Time (47%)
sql execute elapsed time                              2,767.2         20.3
hard parse elapsed time                                  24.8           .2 -- не засчитывается как hard parse, что странно
...
Foreground Wait Events

                                                             Avg
                                        %Time Total Wait    wait    Waits   % DB
Event                             Waits -outs   Time (s)    (ms)     /txn   time
-------------------------- ------------ ----- ---------- ------- -------- ------
virtual circuit wait          4,739,200     0      3,588       1    426.8   26.3 -- idle
cursor: mutex S              21,382,242     0        681       0  1,925.8    5.0 -- 21 млн коротких ожиданий
db file sequential read          33,357     0        327      10      3.0    2.4
direct path read                 77,552     0        221       3      7.0    1.6
gc current block 2-way          301,183     0        201       1     27.1    1.5
kksfbc child completion           3,820    98        190      50      0.3    1.4 -- также отражает конкуренцию за shared pool
...
SQL ordered by Version Count

 Version
  Count   Executions     SQL Id
-------- ------------ -------------
   4,096          N/A 8tduf68bwmwd5            -- число 4096 похоже на ограничение отображения в 11.2.0.2
SELECT ... WHERE task_id=:p1 FOR UPDATE NOWAIT

   3,955          N/A c749bc43qqfz3            -- этот запрос - просто шедевр
SELECT SYSDATE FROM DUAL
...
Mutex Sleep Summary
-> ordered by number of sleeps desc

                                                                         Wait
Mutex Type            Location                               Sleeps    Time (ms)
--------------------- -------------------------------- ------------ ------------
hash table            kkshGetNextChild [KKSHBKLOC1]      27,564,328      452,957 -- типичный набор mutex
Cursor Parent         kkscsPruneChild [KKSPRTLOC35]      11,889,113      174,713 -- , характерный для
Cursor Parent         kkscsAddChildNode [KKSPRTLOC34]     1,770,528       15,147 --   high version count
...

Проверяю как фиксировалось состояние запросов, выделяющихся в секции Version Count:

SQL> select sql_id,
  2         decode(session_state, 'WAITING', event, session_state),
  3         in_parse,
  4         count(*)
  5    from dba_hist_active_sess_history
  6   where snap_id = 132768
  7     and session_type = 'FOREGROUND'
  8     and sql_id in ('8tduf68bwmwd5', 'c749bc43qqfz3')
  9   group by sql_id,
 10            decode(session_state, 'WAITING', event, session_state),
 11            in_parse
 12   order by count(*) desc
 13  /
 
SQL_ID        DECODE(SESSION_STATE,'WAITING'                                   IN_PARSE   COUNT(*)
------------- ---------------------------------------------------------------- -------- ----------
8tduf68bwmwd5 ON CPU                                                           Y               444 -- на CPU в состоянии parse
c749bc43qqfz3 ON CPU                                                           Y               115 -- аналогично
8tduf68bwmwd5 cursor: mutex S                                                  Y                38
c749bc43qqfz3 cursor: mutex S                                                  Y                29
8tduf68bwmwd5 cursor: mutex S                                                  N                25
8tduf68bwmwd5 ON CPU                                                           N                13
8tduf68bwmwd5 kksfbc child completion                                          Y                12
c749bc43qqfz3 kksfbc child completion                                          Y                 5
8tduf68bwmwd5 library cache lock                                               Y                 1
8tduf68bwmwd5 cursor: pin S wait on X                                          Y                 1

— эти же запросы, естественно, занимают большую часть ASH по количеству упоминаний

По версиям, рекомендуемая Oracle функция VERSION_RPT показывает:

SQL> SELECT * FROM TABLE(version_rpt('8tduf68bwmwd5'));
 
COLUMN_VALUE
--------------------------------------------------------------------------------
Version Count Report Version 3.2.1 -- Today's Date 21-mar-13 14:55
RDBMS Version :11.2.0.2.0 Host:
==================================================================
Addr: 00000010BBFCAAE8  Hash_Value: 399110565  SQL_ID 8tduf68bwmwd5
Sharable_Mem: 318588516 bytes   Parses: 287860                      -- 300 МБ в Shared Pool, почти 300,000 parses
Stmt:
0 SELECT t.*,       TO_CHAR(start_time, 'YYYY-MM-DD HH24:MI:SS') s
1 ...
2 1 FOR UPDATE NOWAIT
3
Versions Summary
----------------
USER_BIND_PEEK_MISMATCH :1
PX_MISMATCH :14650                    -- основная причина
Versions with ALL Columns as "N" :131
Total Versions:14782
Plan Hash Value Summary
-----------------------
Plan Hash Value Count
=============== =====
     3317302341 14786
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for USER_BIND_PEEK_MISMATCH : -- неинтересно в этом случае
...
~~~~~~~~~~~~~~~~~~~~~~~~~
Details for PX_MISMATCH :             -- интересно, но ничего нет
No details available
####

Также может наблюдаться в качестве причины Optimizer mismatch:

SQL> @v$sql_shared_cursor_sum 8tduf68bwmwd5
 
REASON#1                             REASON#2                              COUNT(*)
------------------------------------ ----------------------------------- ----------
Optimizer mismatch(4)                User Bind Peek settings mismatch(0)      13912
User Bind Peek settings mismatch(0)                                               1
Optimizer mismatch(4)                Bind mismatch(6)                             1

При этом план запроса — только один и не предполагает параллельного выполнения:

SQL> SELECT * FROM TABLE(dbms_xplan.display_awr('8tduf68bwmwd5'));

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------
SQL_ID 8tduf68bwmwd5
--------------------

Plan hash value: 3317302341

------------------------------------------------------------------------------
| Id  | Operation                    | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |       |       |     1 (100)|          |
|   1 |  FOR UPDATE                  |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID|     1 |    53 |     1   (0)| 00:00:01 |
|   3 |    INDEX UNIQUE SCAN         |     1 |       |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------

— аналогичная картина наблюдается для sql_id=c749bc43qqfz3, который SELECT SYSDATE FROM DUAL

По описанию бага проблема характерна для версий 11.1.0.7 — 11.2.0.3, исправление доступно в виде как отдельных патчей, так и в составе PSU
Как временный workaround может быть использовано удаление проблемных курсоров с помощью dbms_shared_pool.purge или flush shared pool

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

INST#1 SQL> select inst_id, sql_id, count(*)
  2    from gv$sql_shared_cursor
  3   group by inst_id, sql_id
  4   having count(*) > 10
  5   order by count(*) desc
  6  /
 
INST_ID SQL_ID          COUNT(*)
------- ------------- ----------
..
      1 91nujtwmxa3gj         12 -- запрос с несколькими версиями
...

INST#1 SQL> @shared_cu_sum 91nujtwmxa3gj
 
INST   COUNT(*) IS_OBSOLETE PQ_SLAVE_MISMATCH TOP_LEVEL_RPI_CURSOR REASON1
---- ---------- ----------- ----------------- -------------------- ------------------------------------------------------------
   1          8 N           Y                 N                    PQ Slave mismatch(5)  | -- попадающими под определение бага
   1          3 N           N                 N                    PQ Slave mismatch(5)  |
   1          1 N           Y                 N                    Optimizer mismatch(2)  |

INST#1 SQL> @purge_cu 91nujtwmxa3gj -- удаляю курсор из памяти

PL/SQL procedure successfully completed.

SQL> @shared_cu_sum 91nujtwmxa3gj -- проверяю

no rows

INST#1 SQL> SELECT 5 FROM DBA_SCHEDULER_RUNNING_JOBS WHERE JOB_NAME='MAIN_EXECUTOR'
  2  /

         5
----------
         5

1 row selected.                          -- выполняю

INST#1 SQL> @shared_cu_sum 91nujtwmxa3gj -- получаю
 
INST   COUNT(*) IS_OBSOLETE PQ_SLAVE_MISMATCH TOP_LEVEL_RPI_CURSOR REASON1
---- ---------- ----------- ----------------- -------------------- -----------------------
   2          2 N           Y                 N                    PQ Slave mismatch(5)  |
   1          2 N           Y                 N                    PQ Slave mismatch(5)  |
   1          1 N           N                 N                    PQ Slave mismatch(5)  |
   2          1 N           N                 N                    PQ Slave mismatch(5)  |

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

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

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