2018.07.12

Oracle Events

1. Flush Buffer Cache
2. 10053 Event (CBO Enable optimizer trace)
3. 10104 Event (dump hash join statistics to trace file)
4. 10195 Event (Disable generation of predicates from CHECK constraints)
5. 10200 Event(consistent read buffer status)
6. 10626 Event(specify timeout for online index rebuild to wait for DML)
7. 10629 Event(force online index build to backoff and retry DML lock upgrade)
8. 10704 Event(Print out information about what enqueues are being obtained)

Flush Buffer Cache

Oracle10gでは、次のコマンドを使用して、Buffer CacheをFlushします。

alter system flush buffer_cache;

Oracle9iでは、次のようなEventを利用してBuffer CacheをFlushします。

alter session set events= 'immediate trace name flush_cache';

または特定のTablespaceをOffline後、OnlineとTablespaceに属するBufferがFlushされます。

10053 Event (CBO Enable optimizer trace)

CBOのOptimizationプロセスをTraceファイルに出力します。Syntaxは以下の通りです。

alter session set events '10053 trace name context forever, level 1';

10104 Event (dump hash join statistics to trace file)

Hash Join実行過程をTraceファイルに出力します。Hash JoinをTroubleshootingする場合に主に使用されます。Syntaxは以下の通りです。

alter session set events '10104 trace name context forever, level 1';

10195 Event (Disable generation of predicates from CHECK constraints)

CHECK Constraintによる不必要なfiterting適用が発生することを防止する役割を行います。Syntaxは以下の通りです。

alter session set events '10195 trace name context off';

alter session set events '10195 trace name context forever, level 1';

10195 Eventの使用例は、次の通りです。

- Objectの作成
create table t_const1(id number, name varchar2(10), reg_date date);
create index t_const1_idx on t_const1(name);

- CHECK Constraintを追加
alter table t_const1 add constraint c1 check(name = trim(name));

- Plan確認

explain plan for select count(*) from t_const1
where name = '0987654321';

PLAN_TABLE_OUTPUT
Plan hash value: 225932663

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |     1 |     7 |     1   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE   |              |     1 |     7 |            |          |
|*  2 |   INDEX RANGE SCAN| T_CONST1_IDX |     1 |     7 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("NAME"='0987654321')
       filter(TRIM("NAME")='0987654321')  


alter session set events '10195 trace name context forever, level 1';

PLAN_TABLE_OUTPUT
Plan hash value: 225932663

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |     1 |     7 |     1   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE   |              |     1 |     7 |            |          |
|*  2 |   INDEX RANGE SCAN| T_CONST1_IDX |     1 |     7 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("NAME"='0987654321')

Check ConstraintによるFiltering追加は、一般的に性能に有利な場合が多くあります。Filteringによってデータが除外されると、その分仕事量が減る可能性があるからです。特定のクエリの条件では、これらのFilteringがむしろ副作用がありえるなら、このような特別な場合には、10195 Eventを利用してCheck ConstraintによるFiltering条件の追加を防止することができます。

10200 Event(consistent read buffer status)

OracleのLogical ReadsをTraceする機能を提供します。Logical Readsの動作メカニズムやバグによるLogical Reads異常を追跡する際に多く使用されます。Syntaxは以下の通りです。

alter session set events '10200 trace name context forever, level 1';
alter session set events '10200 trace name context off';

Logical ReadsのTrace結果は次の通りです。

SQL>  alter session set events '10200 trace name context forever, level 1';
SQL>  select count(*) from t;
SQL>  alter session set events '10200 trace name context off';

Consistent read started for block 0 : 00400a72
  env: (scn: 0x07df.1aadbf59  xid: 0x0004.009.0000054f  uba: 0x008002de.04ac.05 statement num=0
　　　　　　  parent xid: xid: 0x0000.000.00000000  scn: 0x07df.1aad99e4 0sch: scn: 0x0000.00000000)
CR exa ret 2 on:  03C44148  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  
　　　　　　　　　　uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 0 : 400a72
Consistent read started for block 0 : 00400a75
  env: (scn: 0x07df.1aadbf59  xid: 0x0004.009.0000054f  uba: 0x008002de.04ac.05 statement num=0
　　　　　　  parent xid: xid: 0x0000.000.00000000  scn: 0x07df.1aad99e4 0sch: scn: 0x0000.00000000)
CR exa ret 2 on:  03C44148  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000 
　　　　　　　　　  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 0 : 400a75

10626 Event(specify timeout for online index rebuild to wait for DML)

Online Rebuild作業が先行TransactionによってBlockingされた場合、待機時間（Timeout）の最大値を設定します。

Change the behaviour of an online index rebuild such that it will timeout, 
rather than wait indefinitely for existing DML to complete. 
The event level is the number of seconds the online index rebuild should wait. 
Values outside the legal range of 2 to 300 seconds will be adjusted automatically.

10629 Event(force online index build to backoff and retry DML lock upgrade)

Online Rebuild時DML Lock（TM Lock）Blockingを減らすためにTM LockをSS-> SでUpgradeする方法を制御します。Oracleが提供する説明は、次の通りです。

Change the behaviour of an online index rebuild such that it will backoff and retry 
a failed DML lock upgrade. The event level is the number of retries the online index 
rebuild should wait. Level 1 means backoff and retry indefinitely. 
Any other value less than 32 will be adjusted automatically to be 32.

つまり、Online Rebuildを実行するSessionがTM LockをS（4）で獲得していなければ、待機状態になるようにTM LockによるBlockingを回避します。使い方は以下の通りです。

alter session set events '10629 trace name context forever, level 1';
alter session set events '10629 trace name context forever, level 32';

Online Rebuild作業が途中で終了した場合、Indexの状態がクリーンにならない場合これ以降はIndexのDDLが実行されないことがあります。この場合、ORA-8014 Errorが発生します。Oracle10’gからdbms_repair.online_index_clean関数を利用してOnline Rebuildに失敗したIndexの状態を整理することができます。

10704 Event(Print out information about what enqueues are being obtained)

Enqueue獲得と解除のDebugging情報を出力します。特定のOperationがどのようなEnqueueを必要とし、どのくらいの時間占有していることがわかります。Enqueue Blocking現象をTroubleshootingするときに使用することができます。Syntaxは以下の通りです。

alter session set events '10704 trace name context forever, level 10';
alter session set events '10704 trace name context off';

ventレベルは次の通りです。

1. 1-4: print out basic info for ksqlrl, ksqcmi
2. 5-9: also print out stuff in callbacks: ksqlac, ksqlop
3. 10+: also print out time for each line

簡単なDMLのTrace結果は以下の通りです。CU、FB、HW、TM、TX Lockを占有して解除する一連の作業をDebuggingすることができます。

alter session set events '10704 trace name context forever, level 10';
insert into t1 values(1);
alter session set events '10704 trace name context off';

 *** 2008-08-04 10:48:42.962
ksqgtl *** CU-6c2dd874-00000000 mode=6 flags=0x10 timeout=300 ***
ksqgtl: no transaction
ksqgtl: use existing ksusetxn DID
ksqgtl:
	ksqlkdid: 0001-001C-0000000A
*** 2008-08-04 10:48:43.008
*** ksudidTrace: ksqgtl
	ksusesdi:   0000-0000-00000000
	ksusetxn:   0001-001C-0000000A
ksqgtl: RETURNS 0
*** 2008-08-04 10:48:43.008
ksqrcl: CU,6c2dd874,0
ksqrcl: returns 0
*** 2008-08-04 10:48:43.008
ksqgtl *** TM-0000ff46-00000000 mode=3 flags=0x401 timeout=21474836 ***
ksqgtl: xcb=0x6F2014CC, ktcdix=2147483647, topxcb=0x6F2014CC
	ktcipt(topxcb)=0x0
*** 2008-08-04 10:48:43.008
ksucti: init txn DID from session DID 0001-001C-0000000A
ksqgtl:
	ksqlkdid: 0001-001C-0000000A
*** 2008-08-04 10:48:43.024
*** ksudidTrace: ksqgtl
	ktcmydid(): 0001-001C-0000000A
	ksusesdi:   0000-0000-00000000
	ksusetxn:   0001-001C-0000000A
ksqgtl: RETURNS 0
*** 2008-08-04 10:48:43.024
ksqgtl *** HW-00000007-03000a33 mode=6 flags=0x11 timeout=21474836 ***
ksqgtl: xcb=0x6F2014CC, ktcdix=2147483647, topxcb=0x6F2014CC
	ktcipt(topxcb)=0x0
*** 2008-08-04 10:48:43.024
ksucti: init session DID from txn DID: 0001-001C-0000000A
ksqgtl:
	ksqlkdid: 0001-001C-0000000A
*** 2008-08-04 10:48:43.040
*** ksudidTrace: ksqgtl
	ktcmydid(): 0001-001C-0000000A
	ksusesdi:   0000-0000-00000000
	ksusetxn:   0001-001C-0000000A
ksqgtl: RETURNS 0
*** 2008-08-04 10:48:43.040
ksqrcl: HW,7,3000a33
ksqrcl: returns 0
*** 2008-08-04 10:48:43.040
ksqgtl *** FB-00000007-03000a31 mode=6 flags=0x11 timeout=21474836 ***
ksqgtl: xcb=0x6F2014CC, ktcdix=2147483647, topxcb=0x6F2014CC
	ktcipt(topxcb)=0x0
*** 2008-08-04 10:48:43.055
ksucti: init session DID from txn DID: 0001-001C-0000000A
ksqgtl:
	ksqlkdid: 0001-001C-0000000A
*** 2008-08-04 10:48:43.055
*** ksudidTrace: ksqgtl
	ktcmydid(): 0001-001C-0000000A
	ksusesdi:   0000-0000-00000000
	ksusetxn:   0001-001C-0000000A
ksqgtl: RETURNS 0
*** 2008-08-04 10:48:43.055
ksqrcl: FB,7,3000a31
ksqrcl: returns 0
*** 2008-08-04 10:48:43.055
ksqgtl *** TX-0009002d-000015a9 mode=6 flags=0x401 timeout=0 ***
ksqgtl: xcb=0x6F2014CC, ktcdix=2147483647, topxcb=0x6F2014CC
	ktcipt(topxcb)=0x0
*** 2008-08-04 10:48:43.071
ksucti: init session DID from txn DID: 0001-001C-0000000A
ksqgtl:
	ksqlkdid: 0001-001C-0000000A
*** 2008-08-04 10:48:43.071
*** ksudidTrace: ksqgtl
	ktcmydid(): 0001-001C-0000000A
	ksusesdi:   0000-0000-00000000
	ksusetxn:   0001-001C-0000000A
ksqgtl: RETURNS 0
*** 2008-08-04 10:48:43.071
ksqrcl: TX,9002d,15a9
ksqrcl: returns 0
*** 2008-08-04 10:48:43.087
ksqrcl: TM,ff46,0
ksqrcl: returns 0

Back to index