Oracle mechanics

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


Соответствующий типу SQL ordered by Cluster Wait из AWR список запросов по всем нодам можно получить из таблицы ash_201408071200 (своевременно сделанной копии GV$ACTIVE_SESSION_HISTORY за проблемный период):

SQL> select inst_id, sql_id, count(*)
  2  from ash_201408071200
  3  where wait_class = 'Cluster' and session_state = 'WAITING'
  4  group by inst_id, sql_id
  5  order by count(*) desc
  6  /

INST_ID SQL_ID          COUNT(*)
------- ------------- ----------
      1 43kfr3uthbugg      26188 -- SELECT ... FROM T_EXPORT WHERE ... FOR UPDATE SKIP LOCKED
      1 5cbp4s5jq04xg      21691 -- select  /*+ INDEX(TAB AQ$_TQ1_I) */   tab.rowid, tab.msgid, ... "U1"."TQ1" tab  where ... for update skip locked
      2 1y8zrwnuam2py      17423 -- SELECT ... FROM T_EXPORT WHERE ... FOR UPDATE SKIP LOCKED
      1 du560n5czuzb3       5508 -- INSERT INTO t_invoice ..., не рассматривается

или, вместе с объектами межнодовой конкуренции:

SQL> select inst_id, sql_id, current_obj#, o.object_type, o.object_name, count(*)
  2    from ash_201408071200 ash join dba_objects o on current_obj# = object_id
  3   where wait_class = 'Cluster'
  4     and session_state = 'WAITING'
  5   group by inst_id, sql_id, current_obj#, o.object_type, o.object_name
  6   order by count(*) desc
  7  /

INST_ID SQL_ID        CURRENT_OBJ# OBJECT_TYPE  OBJECT_NAME                    COUNT(*)
------- ------------- ------------ ------------ ---------------------------- ----------
      2 1y8zrwnuam2py       188547 TABLE        T_EXPORT                          17200
      1 43kfr3uthbugg       195691 INDEX        T_EXPORT_INDEX_STATE              14660
      1 43kfr3uthbugg       188547 TABLE        T_EXPORT                          10565
      1 5cbp4s5jq04xg         6456 TABLE        TQ1                                6555
      1 5cbp4s5jq04xg         6459 INDEX        AQ$_TQ1_I                          5759
...

— из которого, казалось бы, очевидно, что запросы 1y8zrwnuam2py и 43kfr3uthbugg блокируют друг друга на табличке T_EXPORT с разных нод, однако формально для кластерных ожиданий этих запросов в качестве блокирующего в ASH указывается лишь собственный инстанс, что затрудняет понимание проблемы:

SQL> select sql_id, inst_id, blocking_inst_id, blocking_session_status, count(*)
  2    from ash_201408071200
  3   where wait_class = 'Cluster'
  4     and session_state = 'WAITING'
  5     and sql_id in ('43kfr3uthbugg', '1y8zrwnuam2py')
  6   group by sql_id, inst_id, blocking_session_status, blocking_inst_id
  7   order by count(*) desc
  8  /

SQL_ID        INST_ID BLOCKING_INST_ID BLOCKING_SESSION_STATUS   COUNT(*)
------------- ------- ---------------- ----------------------- ----------
43kfr3uthbugg       1                1 VALID                        17825 -- 1-й блокирует 1-й
1y8zrwnuam2py       2                2 VALID                        11971 -- --//--
43kfr3uthbugg       1                  UNKNOWN                       8234 -- блокер либо неизвестен,
1y8zrwnuam2py       2                  GLOBAL                        5203 -- либо абстрактно-глобальный, без указания inst_id, sid, etc.
1y8zrwnuam2py       1                1 VALID                         2169
1y8zrwnuam2py       1                  UNKNOWN                       1556
...

Но если, не полагаясь на указанные в ASH значения blocking_inst_id, blocking_session, blocking_session_serial#, сравнить одновременные кластерные ожидания для конкретных блоков бд (current_file#, current_block#):

SQL> select ash1.inst_id          as INST_ID1,
  2         ash1.sql_id           as SQL_ID1,
  3         ash1.event            as EVENT1,
  4         ash1.blocking_inst_id as ASH_BLOCKING_INST,
  5         ash2.inst_id          as REMOTE_BLOCKING_INST,
  6         ash2.sql_id           as SQL_ID2,
  7         ash2.event            as EVENT2,
  8         o.object_type,
  9         o.object_name,
 10         count(*)              as WAITS_COUNT,
 11         count(distinct ash1.current_file#||ash1.current_block#) as BLOCK_COUNT
 12  from ash_201408071200 ash1
 13  join ash_201408071200 ash2  on ash1.current_file#  = ash2.current_file#
 14                             and ash1.current_block# = ash2.current_block#
 15                             and ash1.wait_class     = ash2.wait_class
 16                             and ash1.session_state  = ash2.session_state
 17                             and ash1.p1text         = ash2.p1text
 18                             and ash1.inst_id       <> ash2.inst_id                       -- работающие на разных нодах
 19                             and (ash1.sql_id in ('43kfr3uthbugg', '1y8zrwnuam2py') or
 20                                  ash2.sql_id in ('43kfr3uthbugg', '1y8zrwnuam2py'))
 21                             and ash2.sample_time    > ash1.sample_time                   -- недублированные
 22  join dba_objects o on ash1.current_obj# = object_id
 23  where to_char(ash2.sample_time,'SSSSS') - to_char(ash1.sample_time,'SSSSS') <= 1 -- почти одновременные
 24    and ash1.wait_class    = 'Cluster' -- кластерные
 25    and ash1.p1text        = 'file#'   -- блок-ориентированные
 26    and ash1.session_state = 'WAITING' -- ожидания
 27  group by ash1.inst_id,
 28           ash1.sql_id,
 29           ash1.event,
 30           ash1.blocking_inst_id,
 31           ash2.inst_id,
 32           ash2.sql_id,
 33           ash2.event,
 34           o.object_type,
 35           o.object_name
 36  order by count(*) desc
 37  /

INST_ID1 SQL_ID1       EVENT1                  ASH_BLOCKING_INST REMOTE_BLOCKING_INST SQL_ID2       EVENT2                  OBJECT_TYPE OBJECT_NAME WAITS_COUNT BLOCK_COUNT
-------- ------------- ----------------------- ----------------- -------------------- ------------- ----------------------- ----------- ----------- ----------- -----------
       2 1y8zrwnuam2py gc buffer busy acquire                  2                    1 43kfr3uthbugg gc buffer busy acquire  TABLE       T_EXPORT           3398         128
       1 43kfr3uthbugg gc buffer busy acquire                  1                    2 1y8zrwnuam2py gc buffer busy acquire  TABLE       T_EXPORT           1224          28
       1 1y8zrwnuam2py gc buffer busy acquire                  1                    2 d3sgu8r801msz gc buffer busy acquire  TABLE       T_EXPORT            731           4
       1 1y8zrwnuam2py gc buffer busy acquire                  1                    2 1y8zrwnuam2py gc buffer busy acquire  TABLE       T_EXPORT            590          26
       2 1y8zrwnuam2py gc buffer busy acquire                  2                    1 1y8zrwnuam2py gc buffer busy acquire  TABLE       T_EXPORT            570          42
       2 d3sgu8r801msz gc buffer busy acquire                  2                    1 1y8zrwnuam2py gc buffer busy acquire  TABLE       T_EXPORT            432           4
       2 d3sgu8r801msz gc buffer busy acquire                  2                    1 43kfr3uthbugg gc buffer busy acquire  TABLE       T_EXPORT            401           6
       1 43kfr3uthbugg gc buffer busy acquire                  1                    2 d3sgu8r801msz gc buffer busy acquire  TABLE       T_EXPORT            327           4
       1 d3sgu8r801msz gc buffer busy release                  1                    2 1y8zrwnuam2py gc buffer busy acquire  TABLE       T_EXPORT            201           2
       2 1y8zrwnuam2py gc buffer busy acquire                  2                    1 d3sgu8r801msz gc buffer busy release  TABLE       T_EXPORT             97           2
       1 43kfr3uthbugg gc buffer busy acquire                  1                    2 1y8zrwnuam2py gc buffer busy release  TABLE       T_EXPORT             85           3
       2 d3sgu8r801msz gc buffer busy acquire                  2                    1 43kfr3uthbugg gc buffer busy release  TABLE       T_EXPORT             72           4
       1 43kfr3uthbugg gc buffer busy release                  1                    2 d3sgu8r801msz gc buffer busy acquire  TABLE       T_EXPORT             60           2
...

— легко видеть как на конкретных блоках таблицы T_EXPORT идёт плотная конкурентная борьба между запросом 43kfr3uthbugg на 1-м инстансе и 1y8zrwnuam2py на 1-м и 2-м. Кроме этих 2-х в качестве блокирующего заметен d3sgu8r801msz (insert into T_EXPORT…), но вклад этого быстрого запроса/однострочной вставки:

SQL> @v$sqlstats d3sgu8r801msz

INST_ID      EXECS SQL_ID              PLAN ELA_PER_EXEC CPU_PER_EXEC CONCURRENCY_PER_EXEC CLUSTER_PER_EXEC ROWS_PER_EXEC
------- ---------- ------------- ---------- ------------ ------------ -------------------- ---------------- -------------
      1      94234 d3sgu8r801msz          0         2400          809                    5              996             1
      2     293687 d3sgu8r801msz          0        20495          737                 6952            12633             1

не отражён ни в AWR, ни в статистике:

SQL> select * from dba_hist_sqlstat where sql_id = 'd3sgu8r801msz' and  snap_id between 296083 and 296093
  2  /

no rows selected

Пара проблемных запросов к T_EXPORT показывают заметное замедление во время проблемного снапшота за счёт кластерных ожиданий:

SQL> @dba_hist_sqlstat "sql_id = '1y8zrwnuam2py' and  snap_id between 296083 and 296093"

INST BEGIN_SNAP_ID BEGIN_SNAP_TIME      EXECS       PLAN ELA_PER_EXEC CLWAITS_PER_EXEC_US CLWAITS_SEC
---- ------------- --------------- ---------- ---------- ------------ ------------------- -----------
   2        296092 07.08 14:30           2251  924785236        11274                9744          22
   2        296091 07.08 14:00           3413  924785236         8657                6209          21
   1        296088 07.08 12:30           4246  924785236       346503              333124        1414
   2        296088 07.08 12:30          19276  924785236       189733              163824        3158
   1        296087 07.08 12:00            918  924785236      2612880             2551953        2343 -- на обоих
   2        296087 07.08 12:00           9409  924785236      1352847             1258593       11842 -- инстансах
   2        296086 07.08 11:30          16007  924785236       234892              131965        2112
   2        296085 07.08 11:00          16262  924785236       157679                2050          33
   2        296084 07.08 10:30          17162  924785236       222980                1041          18
   2        296083 07.08 10:00          16824  924785236       279140                 881          15
   2        296082 07.08 09:30           1446  924785236        46841                 275           0

SQL> @dba_hist_sqlstat "sql_id = '43kfr3uthbugg' and  snap_id between 296083 and 296093"

INST BEGIN_SNAP_ID BEGIN_SNAP_TIME      EXECS       PLAN ELA_PER_EXEC CLWAITS_PER_EXEC_US CLWAITS_SEC
---- ------------- --------------- ---------- ---------- ------------ ------------------- -----------
   1        296090 07.08 13:30           3159 3614497239        17756                1775           6
   1        296088 07.08 12:30           3214 3614497239      1716027             1655945        5322
   1        296087 07.08 12:00           3432 3614497239      6298406             6091114       20905 -- только на 1-й ноде
   1        296086 07.08 11:30           4305 3614497239      1343439             1205333        5189
   1        296085 07.08 11:00           3589 3614497239       205309                9755          35
   1        296084 07.08 10:30           3739 3614497239       265640               25359          95
   1        296083 07.08 10:00           3970 3614497239       316476                8825          35
   1        296082 07.08 09:30           3387 3614497239       282055                1161           4

— при этом кол-во выполнений EXECS 1-го запроса 1y8zrwnuam2py перед интересующим снапшотом росло и распостранилось на оба инстанса (что и спровоцировало проблемы), второй же 43kfr3uthbugg стабильно выполнялся на одной 1-й ноде

Кроме 2-х вышеперечисленных в топе кластерных запросов присутствует примечательный запрос 5cbp4s5jq04xg (select /*+ INDEX(TAB AQ$_TQ1_I) */ tab.rowid, tab.msgid,… from «U1».»TQ1″ tab … for update skip locked), также показывающий замедление в проблемный период:

SQL> @dba_hist_sqlstat "sql_id = '5cbp4s5jq04xg' and  snap_id between 296083 and 296093"

INST BEGIN_SNAP_ID BEGIN_SNAP_TIME    EXECS       PLAN ELA_PER_EXEC CLWAITS_PER_EXEC_US CLWAITS_SEC
---- ------------- --------------- -------- ---------- ------------ ------------------- -----------
   1        296092 07.08 14:30       128771  282845214         4083                1551         200
   1        296091 07.08 14:00       146023  282845214         4879                2003         293
   1        296090 07.08 13:30       121812  282845214         3668                1600         195
   1        296089 07.08 13:00       117644  282845214         4400                2343         276
   1        296088 07.08 12:30       168710  282845214        27556               20417        3445
   1        296087 07.08 12:00        70732  282845214       307021              257590       18220 -- тут, и также с большими кластерными ожиданиями
   1        296086 07.08 11:30       157953  282845214        47712               36245        5725
   1        296085 07.08 11:00       155581  282845214         3467                1083         168
   1        296084 07.08 10:30       187893  282845214         3589                1326         249
   1        296083 07.08 10:00       165008  282845214         2970                 724         119
   1        296082 07.08 09:30       129596  282845214         3252                1273         165

Собственно этот запрос рекурсивно вызывается процедурой DBMS_AQ.DEQUEUE из области Oracle Advanced Queuing (AQ)* и успевает выполняться в проблемный период даже реже, чем обычно, также без видимых кросс-инстансных блокировок:

SQL> select sql_id, inst_id, blocking_inst_id, blocking_session_status, count(*)
  2    from ash_201408071200
  3   where wait_class = 'Cluster'
  4     and session_state = 'WAITING'
  5     and sql_id in '5cbp4s5jq04xg'
  6   group by sql_id, inst_id, blocking_session_status, blocking_inst_id
  7   order by count(*) desc
  8  /

SQL_ID        INST_ID BLOCKING_INST_ID BLOCKING_SESSION_STATUS   COUNT(*)
------------- ------- ---------------- ----------------------- ----------
5cbp4s5jq04xg       1                1 VALID                        20553
5cbp4s5jq04xg       1                  UNKNOWN                       1115
5cbp4s5jq04xg       1                  GLOBAL                          23

Запрос же с анализом «одномоментных» кластерных ожиданий совпадающих блоков бд показывает дополняет картину конкуренции:

SQL> select ash1.inst_id          as INST_ID1,
  2         ash1.sql_id           as SQL_ID1,
  3         ash1.event            as EVENT1,
  4         ash1.blocking_inst_id as ASH_BLOCKING_INST,
  5         ash2.inst_id          as REMOTE_BLOCKING_INST,
  6         ash2.sql_id           as SQL_ID2,
  7         ash2.event            as EVENT2,
  8         o.object_type,
  9         o.object_name,
 10         count(*)              as WAITS_COUNT,
 11         count(distinct ash1.current_file#||ash1.current_block#) as BLOCK_COUNT
 12  from ash_201408071200 ash1
 13  join ash_201408071200 ash2  on ash1.current_file#  = ash2.current_file#
 14                             and ash1.current_block# = ash2.current_block#
 15                             and ash1.wait_class     = ash2.wait_class
 16                             and ash1.session_state  = ash2.session_state
 17                             and ash1.p1text         = ash2.p1text
 18                             and ash1.inst_id       <> ash2.inst_id                       -- работающие на разных нодах
 19                             and (ash1.sql_id = '5cbp4s5jq04xg' or ash2.sql_id = '5cbp4s5jq04xg')
 20                             and ash2.sample_time    > ash1.sample_time                   -- недублированные
 21  join dba_objects o on ash1.current_obj# = object_id
 22  where to_char(ash2.sample_time,'SSSSS') - to_char(ash1.sample_time,'SSSSS') <= 1 -- почти одновременные
 23    and ash1.wait_class    = 'Cluster' -- кластерные
 24    and ash1.p1text        = 'file#'   -- блок-ориентированные
 25    and ash1.session_state = 'WAITING' -- ожидания
 26  group by ash1.inst_id,
 27           ash1.sql_id,
 28           ash1.event,
 29           ash1.blocking_inst_id,
 30           ash2.inst_id,
 31           ash2.sql_id,
 32           ash2.event,
 33           o.object_type,
 34           o.object_name
 35  order by count(*) desc
 36  /
INST_ID1 SQL_ID1       EVENT1                  ASH_BLOCKING_INST REMOTE_BLOCKING_INST SQL_ID2       EVENT2                  OBJECT_TYPE OBJECT_NAME WAITS_COUNT BLOCK_COUNT
-------- ------------- ----------------------- ----------------- -------------------- ------------- ----------------------- ----------- ----------- ----------- -----------
       1 5cbp4s5jq04xg gc buffer busy acquire                  1                    2 cc5n5w1r8sc3a gc buffer busy acquire  INDEX       AQ$_TQ1_I           873           3
       2 cc5n5w1r8sc3a gc buffer busy acquire                  2                    1 5cbp4s5jq04xg gc buffer busy release  TABLE       TQ1                 531           4
       1 5cbp4s5jq04xg gc buffer busy acquire                  1                    2 cc5n5w1r8sc3a gc buffer busy acquire  TABLE       TQ1                 444           1
       2 cc5n5w1r8sc3a gc buffer busy acquire                  2                    1 5cbp4s5jq04xg gc buffer busy acquire  INDEX       AQ$_TQ1_I           441           3
       2 cc5n5w1r8sc3a gc buffer busy acquire                  2                    1 5cbp4s5jq04xg gc buffer busy acquire  TABLE       TQ1                 223           2
       1 5cbp4s5jq04xg gc buffer busy release                  1                    2 cc5n5w1r8sc3a gc buffer busy acquire  TABLE       TQ1                 198           2
       1 5cbp4s5jq04xg gc buffer busy acquire                  1                    2 cc5n5w1r8sc3a gc buffer busy release  TABLE       TQ1                 138           1
       2 cc5n5w1r8sc3a gc buffer busy release                  2                    1 5cbp4s5jq04xg gc buffer busy acquire  TABLE       TQ1                  69           1
       2 cc5n5w1r8sc3a gc buffer busy release                                       1 5cbp4s5jq04xg gc buffer busy acquire  INDEX       AQ$_TQ1_I            68           2
       1 5cbp4s5jq04xg gc buffer busy acquire                  1                    2 cc5n5w1r8sc3a gc buffer busy release  INDEX       AQ$_TQ1_I            49           2
...

, включая важные детали типа:

  • циклических ожиданий gc buffer busy acquire и пар gc buffer busy acquire gc buffer busy release
  • небольшого кол-ва блоков AQ таблицы и индекса — от 1 до 4-х, задействованных в «конкурентной борьбе»

Блокирующим при этом ожидаемо является короткий DBMS_AQ.ENQUEUE запрос cc5n5w1r8sc3a (insert into «U1».»TQ1″…), не отражённый в AWR

Причиной последних (AQ-related) блокировок является одновременное заполнение очереди с 2-х нод, несмотря на то, что очистка очереди(dequeue) выполняется грамотно только с 1-й ноды:

SQL> select * from gv$persistent_queues where queue_name = 'QON';

INST_ID   QUEUE_ID QUEUE_TABLE_ID QUEUE_NAME  ENQUEUED_MSGS DEQUEUED_MSGS BROWSED_MSGS ELAPSED_ENQUEUE_TIME ELAPSED_DEQUEUE_TIME
------- ---------- -------------- ----------- ------------- ------------- ------------ -------------------- --------------------
      2     187099           6456 QON                632897             0            0          994917,7375                    0
      1     187099           6456 QON               1148078       1780967       186239          205042,2942      1228425745,7701

что несколько противоречит рекомендациях производителя Oracle Streams AQ and RAC Scalability and Performance Guidelines, однако сами по себе AQ запросы типа 5cbp4s5jq04xg проблем в системе (пока) не создают, а попадают в топ кластерных ожиданий попутно при увеличении нагрузки на Global Cache, сопровождая возникновения кластерных проблем

*) Структура AQ объектов хорошо описана в Julian Dyke. Advanced Queuing Internals, за исключением того, что в качестве хинта dequeue запроса в Oracle 10g использовался /*+ FIRST_ROWS(1) */, а в 11g используется прямое указание автоматически создаваемого индекса о 6-ти полях /*+ INDEX(TAB AQ$_TQ1_I) */

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

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

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