Oracle mechanics

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 связано с насильственным прерыванием выполнения «зависшего» запроса)

Интерес представляет избыточное (по сравнению с типичным для этого запроса) потребление ЦПУ, в деталях израсходованное следующим образом:

SQL> select to_char(min(sql_exec_start), 'hh24:mi:ss') as sql_start,
  2         sql_opname,
  3         sql_plan_operation,
  4         sql_plan_options,
  5         session_state,
  6         event#,
  7         seq#,
  8         p2text,
  9         p2,
 10         to_char(min(sample_time), 'hh24:mi:ss') as min_time,
 11         to_char(max(sample_time), 'hh24:mi:ss') as max_time,
 12         count(*)
 13    from v$active_session_history
 14   where sql_id = 'acn3a69qq1shm'
 15     and sql_exec_id = 16780185
 16   group by sql_exec_start,
 17            sql_opname,
 18            sql_plan_operation,
 19            sql_plan_options,
 20            session_state,
 21            event#,
 22            seq#,
 23            p2text,
 24            p2
 25  /
 
SQL_START SQL_OPNAME  SQL_PLAN_OPERATION  SQL_PLAN_OPTIONS  SESSION_STATE EVENT# SEQ# P2TEXT                    P2 MIN_TIME MAX_TIME   COUNT(*)
--------- ----------- ------------------- ----------------- ------------- ------ ---- ----------------- ---------- -------- -------- ----------
10:47:03  INSERT      TABLE ACCESS        FULL              ON CPU                304 consumer group id      12553 10:47:05 10:47:05          1
10:47:03  INSERT      HASH JOIN           RIGHT OUTER       ON CPU                309 consumer group id      12553 10:47:06 12:27:03       5990

— в основном, процессорные мощности тратились на операцию HASH OUTER JOIN, что внешне выглядит непротиворечиво, кроме очевидно избыточно большого для этого запроса потребления ЦПУ

При этом поле P2TEXT неизменно содержало consumer group id, что характерно для единственного ожидания:

SQL> select * from v$event_name where parameter2 = 'consumer group id';
 
NAME                PARAMETER1  PARAMETER2         WAIT_CLASS
------------------- ----------- ------------------ ----------
resmgr:cpu quantum  location    consumer group id  Scheduler

, а значение P2 указывает на вполне осознанную, существующую в бд пользовательскую группу:

SQL> select OBJ#, NAME, DESCRIPTION, STATUS CATEGORY from RESOURCE_CONSUMER_GROUP$ where OBJ# = 12553;
 
 OBJ# NAME          DESCRIPTION                                                                                                CATEGORY
----- ------------- ---------------------------------------------------------------------------------------------------------- --------
12553 OTHER_GROUPS  Consumer group for users not included in any consumer group with a directive in the currently active plan  ACTIVE

Учитывая, что при выполнении v$session.event постоянно указывало на resmgr:cpu quantum (независимо от session_state), а Resource Plan в системе используется только в течение и по причине Maintenance Windows:

SQL> select window_name, resource_plan, repeat_interval, duration from dba_scheduler_windows where enabled = 'TRUE';
 
WINDOW_NAME      RESOURCE_PLAN              REPEAT_INTERVAL                                        DURATION      
---------------- -------------------------- ------------------------------------------------------ --------------
MONDAY_WINDOW    DEFAULT_MAINTENANCE_PLAN   freq=daily;byday=MON;byhour=22;byminute=0; bysecond=0  +000 04:00:00 
TUESDAY_WINDOW   DEFAULT_MAINTENANCE_PLAN   freq=daily;byday=TUE;byhour=22;byminute=0; bysecond=0  +000 04:00:00 
WEDNESDAY_WINDOW DEFAULT_MAINTENANCE_PLAN   freq=daily;byday=WED;byhour=22;byminute=0; bysecond=0  +000 04:00:00 
THURSDAY_WINDOW  DEFAULT_MAINTENANCE_PLAN   freq=daily;byday=THU;byhour=22;byminute=0; bysecond=0  +000 04:00:00 
FRIDAY_WINDOW    DEFAULT_MAINTENANCE_PLAN   freq=daily;byday=FRI;byhour=22;byminute=0; bysecond=0  +000 04:00:00 
SATURDAY_WINDOW  DEFAULT_MAINTENANCE_PLAN   freq=daily;byday=SAT;byhour=6;byminute=0; bysecond=0   +000 20:00:00 
SUNDAY_WINDOW    DEFAULT_MAINTENANCE_PLAN   freq=daily;byday=SUN;byhour=6;byminute=0; bysecond=0   +000 20:00:00

можно предположить, что причиной зависания запроса (произошедшего аккурат в SUNDAY_WINDOW — 11.05 12:00) была активность Resource Manager

Предположение о том, что ожидания класса Scheduler (типа ‘resmgr%’) можно и, возможно, правильнее идентифицировать по p2text вместо event / wait_class:

SQL> select SAMPLE_DAY, COUNT_BY_EVENT_NAME, COUNT_BY_P2TEXT from
  2  (select to_char(sample_time, 'DAY hh24') as SAMPLE_DAY,
  3         to_char(sample_time, 'D hh24'),
  4         sum(case when session_state = 'WAITING' and event like 'resmgr%' then 1 else 0 end) as COUNT_BY_EVENT_NAME,
  5         sum(case when session_state != 'WAITING' and p2text = 'consumer group id' then 1 else 0 end) as COUNT_BY_P2TEXT
  6    from dba_hist_active_sess_history
  7    where session_state =  'WAITING' and event like 'resmgr%'
  8       or session_state != 'WAITING' and p2text = 'consumer group id'
  9   group by to_char(sample_time, 'DAY hh24'), to_char(sample_time, 'D hh24')
 10   order by to_char(sample_time, 'D hh24'))
 11  where COUNT_BY_EVENT_NAME > 0 or COUNT_BY_P2TEXT > 0
 12  /
 
SAMPLE_DAY                              COUNT_BY_EVENT_NAME COUNT_BY_P2TEXT
--------------------------------------- ------------------- ---------------
SUNDAY    00                                              0             163
SUNDAY    01                                              0              93
SUNDAY    06                                              0             122
SUNDAY    07                                              0             141
SUNDAY    08                                              0             133
SUNDAY    09                                              0             139
SUNDAY    10                                              0             113
SUNDAY    11                                              0             127
SUNDAY    12                                              0             105
SUNDAY    13                                              0             132
SUNDAY    14                                              5             121
SUNDAY    15                                              0             134
SUNDAY    16                                              0             104
SUNDAY    17                                              0             111
SUNDAY    18                                              0             119
SUNDAY    19                                              1             136
SUNDAY    20                                              0             102
SUNDAY    21                                              0             155
SUNDAY    22                                              0             143
SUNDAY    23                                              0             161
MONDAY    00                                              0             143
MONDAY    01                                              0             100
MONDAY    22                                              0             135
MONDAY    23                                              0             121
TUESDAY   00                                              0             162
TUESDAY   01                                              0              98
TUESDAY   22                                              0             266
TUESDAY   23                                              1             170
WEDNESDAY 00                                              0             278
WEDNESDAY 01                                              0             223
WEDNESDAY 22                                              0             300
WEDNESDAY 23                                              0             230
THURSDAY  00                                              0             312
THURSDAY  01                                              0             211
THURSDAY  22                                              0              92
THURSDAY  23                                              0              87
FRIDAY    00                                              0             137
FRIDAY    01                                              0              72
FRIDAY    22                                              0              54
FRIDAY    23                                              0             105
SATURDAY  00                                              0             155
SATURDAY  01                                              0             113
SATURDAY  06                                              0              63
SATURDAY  07                                              0             144
SATURDAY  08                                              1              83
SATURDAY  09                                              0             124
SATURDAY  10                                              0             132
SATURDAY  11                                              0             134
SATURDAY  12                                              0             106
SATURDAY  13                                              0             127
SATURDAY  14                                              0             113
SATURDAY  15                                              0             123
SATURDAY  16                                              0             130
SATURDAY  17                                              0             174
SATURDAY  18                                              0             133
SATURDAY  19                                              0             144
SATURDAY  20                                              0             120
SATURDAY  21                                              0             125
SATURDAY  22                                              0             145
SATURDAY  23                                              0             108

— скорее всего вполне разумно, причём метод определения по по P2TEXT даёт кратно большее кол-во событий Resource Manager, происходящих точно в пределах Maintenance Windows

Подсчитанный таким образом TOP запросов по максимальному кол-ву ожиданий, связанных с Resource Manager, на одно выполнение даёт ожидаемую картину:

SQL> select EVENT, p2, sql_id, sql_text, max(WAITS_PER_EXEC)
  2    from (
  3          select decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue') as EVENT,
  4                 count(distinct sample_id) over(partition by sql_id, sql_exec_id, session_state || EVENT) as WAITS_PER_EXEC,
  5                 p2,
  6                 sql_id,
  7                 trim(replace(replace(dbms_lob.substr(sql_text, 20), chr(10)), chr(9))) as sql_text
  8            from v$active_session_history ash
  9            join dba_hist_sqltext
 10           using (sql_id)
 11           where (session_state = 'WAITING' and event = 'resmgr:cpu quantum' or
 12                 session_state != 'WAITING' and p2text = 'consumer group id')
 13                 )
 14   group by EVENT, p2, sql_id, sql_text
 15  having max(WAITS_PER_EXEC) > 100
 16   order by max(WAITS_PER_EXEC) desc
 17  /
 
EVENT                                P2 SQL_ID        SQL_TEXT             MAX(WAITS_PER_EXEC)
---------------------------- ---------- ------------- -------------------- -------------------
On CPU / runqueue                 12553 acn3a69qq1shm INSERT INTO SHOPDATA                5991 -- на первом месте проблемный запрос
On CPU / runqueue                 12550 gdphfkw4kk386 /* SQL Analyze(1) */                1697 -- *
On CPU / runqueue                 12553 0dnqcadzdrfs1 select result, descr                 169 -- с большим отставанием

*) — на 2-м месте, судя по комментарию в тексте, запрос автоматического сбора статистики с указанием в P2 соответствующей Resource Consumer Group:

SQL> select OBJ#, NAME, DESCRIPTION, STATUS CATEGORY from RESOURCE_CONSUMER_GROUP$ where OBJ# = 12550
  2  /
 
 OBJ# NAME                      DESCRIPTION                                      
----- ------------------------- -------------------------------------------------
12550 ORA$AUTOTASK_STATS_GROUP  Consumer group for gathering optimizer statistics

Завести SR (точнее, довести до результата) для таких редковоспроизводимых случаев проблематично, в качестве профилактики подобных инциндентов можно накатить Recommended Patches for CPU Resource Manager (Doc ID 1339803.1), хотя единственный из подходящих по симптомам Bug 16392079 Sessions hang waiting for ‘resmgr:cpu quantum’ with Resource Manager проявляется при временном отсутствии в системе процесса VKRM, который в нашем случае исправно функционировал на протяжении проблемного периода (согласно трейсу); либо вообще отключить использование Resource Manager как рекомендуется в качестве last resort:

SQL> execute dbms_scheduler.set_attribute('<window name>','RESOURCE_PLAN','');

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

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

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