pseudo AWR bug

Сегодня обнаружилась интересная картина: AWR перестал делать снапшоты. Т.е. не то чтобы совсем перестал, а просто долго делает снапшот.  Для удобства анализа сделали так:

SQL> select sid from v$mystat where rownum<2;

       SID

----------

       614

SQL> alter session set events '10046 trace name context forever, level 12';

Session altered.

SQL> exec dbms_workload_repository.create_snapshot;

и стали смотреть в трейс файл :

[oracle@ODA01-pub1 trace]$ tail -100f ODA01DB1_ora_12958.trc

WAIT #46931816430624: nam='control file sequential read' ela= 179 file#=0 block#=1 blocks=1 obj#=-1 tim=1324627288235588

WAIT #46931816430624: nam='control file sequential read' ela= 185 file#=0 block#=40 blocks=1 obj#=-1 tim=1324627288235898

WAIT #46931816430624: nam='control file sequential read' ela= 182 file#=0 block#=42 blocks=1 obj#=-1 tim=1324627288236178

WAIT #46931816430624: nam='control file sequential read' ela= 183 file#=0 block#=113 blocks=1 obj#=-1 tim=1324627288236456

WAIT #46931816430624: nam='control file sequential read' ela= 179 file#=0 block#=1 blocks=1 obj#=-1 tim=1324627288236791

WAIT #46931816430624: nam='control file sequential read' ela= 183 file#=0 block#=40 blocks=1 obj#=-1 tim=1324627288237131

WAIT #46931816430624: nam='control file sequential read' ela= 185 file#=0 block#=42 blocks=1 obj#=-1 tim=1324627288237413

WAIT #46931816430624: nam='control file sequential read' ela= 181 file#=0 block#=113 blocks=1 obj#=-1 tim=1324627288237716

WAIT #46931816430624: nam='control file sequential read' ela= 182 file#=0 block#=1 blocks=1 obj#=-1 tim=1324627288238056

WAIT #46931816430624: nam='control file sequential read' ela= 184 file#=0 block#=40 blocks=1 obj#=-1 tim=1324627288238361

WAIT #46931816430624: nam='control file sequential read' ela= 187 file#=0 block#=42 blocks=1 obj#=-1 tim=1324627288238644

WAIT #46931816430624: nam='control file sequential read' ela= 184 file#=0 block#=113 blocks=1 obj#=-1 tim=1324627288238924

WAIT #46931816430624: nam='control file sequential read' ela= 177 file#=0 block#=1 blocks=1 obj#=-1 tim=1324627288239256

WAIT #46931816430624: nam='control file sequential read' ela= 178 file#=0 block#=40 blocks=1 obj#=-1 tim=1324627288239557

WAIT #46931816430624: nam='control file sequential read' ela= 176 file#=0 block#=42 blocks=1 obj#=-1 tim=1324627288239857

WAIT #46931816430624: nam='control file sequential read' ela= 180 file#=0 block#=113 blocks=1 obj#=-1 tim=1324627288240135

В общем, что-то зациклилось...

Металинк предлагает отгадку:  AWR Snapshot Causes Many Control File Sequential Read Waits [ID 941761.1]  ... AWR snapshots are taking a lot of time flushing WRH$_THREAD ...

В доке рекомендовано:

alter system set "_awr_disabled_flush_tables"='wrh$_thread';

Однако эта рекомендация "в лоб" не помогла. События 'control file sequential read' продолжались, и снапшот собирался долго. Поэтому пришлось еще немного покопаться: Смотрим

WAIT #46931816430624: nam='control file sequential read' ela= 260 file#=0 block#=1 blocks=1 obj#=-1 tim=1324626633244332

Событие ожидания относится к курсору  #46931816430624

Ищем в трейсе этот курсор: 

PARSING IN CURSOR #46931816430624 len=881 dep=1 uid=0 oct=2 lid=0 tim=1324626633222179 hv=2600278305 ad='c57822e90' sqlid='6vntx5ydgu691'
insert into wrh$_tempstatxs   (snap_id, dbid, instance_number, file#, creation_change#, phyrds,    phywrts, singleblkrds, readtim, writet
im, singleblkrdtim, phyblkrd,    phyblkwrt, wait_count, time)  select    :snap_id, :dbid, :instance_number,    tf.tfnum, to_number(tf.tfc
rc_scn) creation_change#,    ftio.kcftiopyr, ftio.kcftiopyw, ftio.kcftiosbr,    floor(ftio.kcftioprt / 10000), floor(ftio.kcftiopwt / 100
00),    floor(ftio.kcftiosbt / 10000), ftio.kcftiopbr, ftio.kcftiopbw,    fw.count, fw.time  from    x$kcftio ftio, x$kcctf tf, x$kcbfwai
t 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)
 

Оказывается, он относится к таблице wrh$_tempstatxs.

Поэтому переписываем alter system:

alter system set "_awr_disabled_flush_tables"='wrh$_tempstatxs';    

Во первых: ТОЖЕ НЕ ПОМОГЛО !

Во-вторых: эта команда затерла значение предыдущей: "_awr_disabled_flush_tables"='wrh$_thread'

Возникла мысль - что это за беда, если для каждой таблички WR* надо руками включать специфические свойства? Не является ли причина более общей?



Поэтому дальше сделал так:

exec dbms_stats.gather_fixed_objects_stats;
exec dbms_stats.gather_dictionary_stats;



И - вуаля - результат налицо :


SQL> alter system reset "_awr_disabled_flush_tables" ;
System altered.

SQL> /
alter system reset "_awr_disabled_flush_tables"
*
ERROR at line 1:
ORA-32010: cannot find entry to delete in SPFILE

SQL> set timing on
SQL> exec dbms_workload_repository.create_snapshot;
PL/SQL procedure successfully completed.

Elapsed: 00:00:06.77




Отсюда вывод - СОБИРАЙТЕ СТАТИСТИКУ НА СЛОВАРЬ И НА FIXED TABLES!!!