Проблема при создании AWR снапшотов в Oracle 11g

Как известно, начиная с Oracle 11g, для избежания длительного блокирования ресурсов и/или создания избыточной нагрузки на систему как только создание AWR снапшота занимает больше 15 минут процессы M00X (MMON slaves) самоуничтожаются и MMON приостанавливает генерацию снимков AWR на 23 часа, в отличие от 10g, в которой процессы создания снимков выполнялись без ограничений по времени

В этом месте возникает практический вопрос: как восстановить генерацию AWR снапшотов? Например, если после обновления на 11.2 ситуация повторяется изо дня в день и AWR снимки не генерируются?

При возникновении проблемы Oracle пишет след.отладочную информацию

1) в alert.log:

Mon Jan 30 01:53:50 2012
Suspending MMON slave action kewrmafsa_ for 82800 seconds

2) в лог MMON (inst1_mmon_22577.trc):

Unable to schedule a MMON slave at: Auto Flush Main 1
  Slave action has been temporarily suspended
    - Slave action had prior policy violations.
  Unknown return code: 101

3) в лог M000 (inst1_m000_14220.trc):

*** KEWROCISTMTEXEC - encountered error: (ORA-12751: cpu time or run time policy violation)
  *** SQLSTR: total-len=894, dump-len=240,
      STR={insert into wrh$_tempstatxs   (snap_id, dbid, instance_number, file#, creation_change#, phyrds,    phywrts, singleblkrds, readtim, writetim, singleblkrdtim, phyblkrd,    phyblkwrt, wait_count, time)  select    :snap_id, :dbid, :instance_num}
...
Runtime exceeded 900 seconds

либо:

*** KEWROCISTMTEXEC - encountered error: (ORA-12751: cpu time or run time policy violation
)
  *** SQLSTR: total-len=1340, dump-len=240,
      STR={insert into WRH$_IOSTAT_FILETYPE    (snap_id, dbid, instance_number,     filetype_id,     small_read_meg
abytes, small_write_megabytes,     large_read_megabytes, large_write_megabytes,     small_read_reqs, small_write_re
qs, small_sync_read_r}

Проблемный запрос, на котором сессия провисела 900 секунд при попытке выполнить AWR снапшот:

insert into wrh$_tempstatxs
  (...)
  select :snap_id,
         :dbid,
         :instance_number,
         tf.tfnum,
         to_number(tf.tfcrc_scn) creation_change#,
         ftio.kcftiopyr,
         ftio.kcftiopyw,
         ftio.kcftiosbr,
         floor(ftio.kcftioprt / 10000),
         floor(ftio.kcftiopwt / 10000),
         floor(ftio.kcftiosbt / 10000),
         ftio.kcftiopbr,
         ftio.kcftiopbw,
         fw.count,
         fw.time
    from x$kcftio ftio, x$kcctf tf, x$kcbfwait fw, x$kccfn fn, x$kccts ts
   where ts.tstsn = tf.tftsn
     and ftio.kcftiofno = fn.fnfno
     and tf.tfnum = fn.fnfno
     and tf.tffnh = fn.fnnum
     and tf.tfdup <> 0
     and fn.fntyp = 7
     and fn.fnnam is not null
     and bitand(tf.tfsta, 32) <> 32
     and fw.indx + 1 = (fn.fnfno + :db_files)

Статистика запроса:

SQL> select * from v$sql where sql_text like 'insert into wrh$_tempstatxs%';

FETCHES EXECUTIONS DISK_READS BUFFER_GETS USER_IO_WAIT_TIME ROWS_PROCESSED PHYSICAL_READ_BYTES
------- ---------- ---------- ----------- ----------------- -------------- -------------------
      0          1          2         193              6301              0         64565551104

– показывает что за 15 минут выполнения не было вставлено ни одной строки при огромном количестве физических чтений, т.е. проблема с медленным выполнением|плохим планом подзапроса.

V$SESSION_EVENT показывает

EVENT                            WAIT_CLASS    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT
-------------------------------- ------------- ----------- -------------- ----------- ------------
control file sequential read     System I/O         209172              0       31966         0,15
SQL*Net message from client      Idle                    8              0        1226       153,19
db file sequential read          User I/O              114              0          65         0,57
...

, что время основного для запроса ожидания control file sequential read не учитывается в V$SQL.USER_IO_WAIT_TIME – очевидно, поскольку операция не пользовательская)

Недорогой план запроса:

Plan hash value: 1263745846

---------------------------------------------------------------------------------------------
| Id  | Operation                 | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |                 |     1 |   143 |     1 (100)| 00:00:01 |
|*  1 |  HASH JOIN                |                 |     1 |   143 |     1 (100)| 00:00:01 |
|   2 |   NESTED LOOPS            |                 |     1 |   139 |     0   (0)| 00:00:01 |
|   3 |    MERGE JOIN CARTESIAN   |                 |   150 | 13950 |     0   (0)| 00:00:01 |
|   4 |     MERGE JOIN CARTESIAN  |                 |     1 |    83 |     0   (0)| 00:00:01 |
|*  5 |      FIXED TABLE FULL     | X$KCCTF         |     1 |    56 |     0   (0)| 00:00:01 |
|   6 |      BUFFER SORT          |                 |   100 |  2700 |     0   (0)| 00:00:01 |
|   7 |       FIXED TABLE FULL    | X$KCFTIO        |   100 |  2700 |     0   (0)| 00:00:01 |
|   8 |     BUFFER SORT           |                 |   200 |  2000 |     0   (0)| 00:00:01 |
|   9 |      FIXED TABLE FULL     | X$KCBFWAIT      |   200 |  2000 |     0   (0)| 00:00:01 |
|* 10 |    FIXED TABLE FIXED INDEX| X$KCCFN (ind:1) |     1 |    46 |     0   (0)| 00:00:01 |
|  11 |   FIXED TABLE FULL        | X$KCCTS         |    20 |    80 |     0   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

включает два CARTESIAN JOIN‘а с таблицами:

• X$KCCTF – список временных файлов, хранится в controlfile => control file sequential read
• X$KCFTIO – статистика временных файлов (V$TEMPSTAT)
• X$KCBFWAIT – block|buffer file wait – статистика ожиданий по всем файлам бд

Судя по тому, что с подсказкой /*+ DYNAMIC_SAMPLING(5)*/ тот же запрос выполняется мгновенно, проблема может быть в отсутствии статистики по фиксированным таблицам:

SQL> select rowcnt, blkcnt, analyzetime, samplesize
 2 from tab_stats$
 3 where obj# in (select OBJECT_ID from V$FIXED_TABLE)
 4 /

no rows selected

После сбора статистики:

11.2.0.3.@SYS SQL> BEGIN
 2 DBMS_STATS.GATHER_FIXED_OBJECTS_STATS;
 3 END;
 4 /

PL/SQL procedure successfully completed.

Elapsed: 00:07:20.01

план запроса меняется:

Plan hash value: 863936232

----------------------------------------------------------------------------------------------
| Id  | Operation                  | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |                 |    22 |  2948 |     1 (100)| 00:00:01 |
|   1 |  HASH JOIN                 |                 |    22 |  2948 |     1 (100)| 00:00:01 |
|   2 |   HASH JOIN                |                 |     1 |   124 |     1 (100)| 00:00:01 |
|   3 |    NESTED LOOPS            |                 |     1 |    96 |     0   (0)| 00:00:01 |
|   4 |     MERGE JOIN CARTESIAN   |                 |    70 |  4690 |     0   (0)| 00:00:01 |
|   5 |      FIXED TABLE FULL      | X$KCCFN         |     3 |   189 |     0   (0)| 00:00:01 |
|   6 |      BUFFER SORT           |                 |    28 |   112 |     0   (0)| 00:00:01 |
|   7 |       FIXED TABLE FULL     | X$KCCTS         |    28 |   112 |     0   (0)| 00:00:01 |
|   8 |     FIXED TABLE FIXED INDEX| X$KCCTF (ind:1) |     1 |    29 |     0   (0)| 00:00:01 |
|   9 |    FIXED TABLE FULL        | X$KCFTIO        |   500 | 14000 |     0   (0)| 00:00:01 |
|  10 |   FIXED TABLE FULL         | X$KCBFWAIT      |  1000 | 10000 |     0   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

- меняется порядок доступа и оценка кол-ва строк таблиц + остаётся одно картезианское произведение менее объёмных таблиц. Стоимость выполнения всего запроса по-прежнему остаётся низкой Cost=1, для доступа к трём строкам X$KCCTF теперь используется индекс:

SQL> select * from v$indexed_fixed_column where table_name = 'X$KCCTF';

    TABLE_NAME  INDEX_NUMBER COLUMN_NAME  COLUMN_POSITION
    ----------- ------------ ------------ ---------------
    X$KCCTF                1 TFNUM                      0

AWR снапшот успешно создаётся на 2-й ноде кластера:

11.2.0.3@SQL> exec DBMS_WORKLOAD_REPOSITORY.create_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:15:16.90

– при этом из 15+ минут 892 секунд тратится на ожидание reliable message – ожидание ответа от другой ноды кластера, которое имеет как раз 15-ти минутный таймаут

Причиной является небыстрая инвалидация проблемного курсора на другой ноде несмотря на появившуюся статистику фиксированных таблиц:

SQL> select inst_id,
  2         sql_id,
  3         child_number,
  4         plan_hash_value,
  5         users_opening,
  6         users_executing,
  7         kept_versions
  8    from gv$sql
  9   where sql_id = '1cd2krbdzrhvq';

INST_ID SQL_ID        CHILD_NUMBER PLAN_HASH_VALUE USERS_OPENING USERS_EXECUTING KEPT_VERSIONS
------- ------------- ------------ --------------- ------------- --------------- -------------
      1 1cd2krbdzrhvq            0      1263745846             0               0             0
      1 1cd2krbdzrhvq            1       863936232             0               0             0
      2 1cd2krbdzrhvq            0       863936232             0               0             0

– курсор с «правильным» планом (PLAN_HASH_VALUE 863936232) появляется на другой ноде (INST_ID=1) не сразу, что не мешает ночным AWR снапшотам с этого момента собираются автоматически и без ошибок

Как вариант решения описанных проблем или с целью экономии места в SYSAUX можно отключить сбор отдельных статистик AWR – Miladin Modrakovic: How to disable flush of ASH data to AWR?:

SQL> alter system set “_awr_disabled_flush_tables”=’WRH$_TEMPSTATXS,WRH$_IOSTAT_FILETYPE’;

P.S. После решения проблемы нашёл по ключевому слову X$KCCTF на Metalink’е свежий (10-JAN-2012) документ AWR or STATSPACK Snapshot collection extremely slow in 11gR2 [ID 1392603.1] с описанием аналогичного решения проблемы. Проблема при этом справедливо именуется багом – автоматическая процедура должна работать из коробки

P.P.S. А 09.01.2012 Maria Colgan в официальном блоге описывает преимущества сбора статистики фиксированных таблиц – Fixed Objects Statistics and why they are important – без упоминания проблем AWR, но подозрительно своевременно)