RDBMS events

RDBMS events are often used to do additional tracing and for debug purposes.
Most of them are listed in $ORACLE_HOME/rdbms/mesg/oraus.msg
One such event I use quite often to determine which locks/enqueues a session is requesting is the following.
For example the below trace indicates that an innocuous looking query on v$flash_recovery_area_usage takes a controlfile lock in mode 4 which might not be the best thing to happen on a high throughput multi node RAC environment with a huge number of flashback logs.
SQL> alter session set events '10704 trace name context forever, level 10';

Session altered.

SQL> oradebug setmypid
Statement processed.
SQL> oradebug
tracefile_name /u01/app/oracle/diag/rdbms/TEST/TEST1/trace/TEST1_ora_600.trc
SQL> select * from v$flash_recovery_area_usage;


*** 2010-07-30 10:07:33.978
ksqgtl *** CF-00000000-00000000 mode=4 flags=0x1a011 timeout=900 ***
ksqgtl: no transaction
ksqgtl: use existing ksusetxn DID
ksqgtl:
ksqlkdid: 0001-0036-00000169

*** 2010-07-30 10:07:33.978
*** ksudidTrace: ksqgtl
ksusesdi: 0001-0036-00000168
ksusetxn: 0001-0036-00000169

*** 2010-07-30 10:07:33.978
ksqcmi: CF,0,0 mode=4 timeout=900
ksqcmi: returns 0
ksqgtl: RETURNS 0

*** 2010-07-30 10:07:33.978
ksqgtl *** CF-00000000-00000004 mode=4 flags=0x10010 timeout=0 ***
ksqgtl: no transaction
ksqgtl: use existing ksusetxn DID
ksqgtl:
ksqlkdid: 0001-0036-00000169



Another event I have used in the past is related to parallel query to determine why PQ slaves do not get spawned
But to my surprise this event does not work anymore in 11.2

SQL> alter session set events '10392 trace name context forever, level 1';
Session altered.

SQL> oradebug setmypid
Statement processed.

SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/TEST/TEST1/trace/TEST1_ora_14748.trc

SQL> select /*+ parallel(a,8) */ count(*) from sys.obj$ a;

COUNT(*)
----------
231692

SQL> !cat /u01/app/oracle/diag/rdbms/TEST/TEST1/trace/TEST1_ora_14748.trc

*** 2010-07-30 14:41:02.547
*** SESSION ID:(316.58074) 2010-07-30 14:41:02.547
*** CLIENT ID:() 2010-07-30 14:41:02.547
*** SERVICE NAME:(SYS$USERS) 2010-07-30 14:41:02.547
*** MODULE NAME:(sqlplus@bart.au (TNS V1-V3)) 2010-07-30 14:41:02.547
*** ACTION NAME:() 2010-07-30 14:41:02.547

Processing Oradebug command 'setmypid'

*** 2010-07-30 14:41:02.547
Oradebug command 'setmypid' console output:

*** 2010-07-30 14:41:08.598
Processing Oradebug command 'tracefile_name'

*** 2010-07-30 14:41:08.598
Oradebug command 'tracefile_name' console output:

The trace does not contain any information

Feedback from Oracle was that “not many people use the px numeric ones and so they removed the code.”…
You can still use the _px_trace underscore parameter to determine why queries are not running in parallel

Dynamic Re-Mastering in 11g

This is a follow-up on a post from last year

http://el-caro.blogspot.com/search/label/10g%20RAC%20DRM

Node 1
========
SQL> create table obj as select * from sys.obj$;

Table created.

SQL> select object_id,owner,object_type from dba_objects where object_name='OBJ' and object_type='TABLE';

OBJECT_ID OWNER OBJECT_TYPE
---------- ------------------------------ -------------------
136388 REGOFA TABLE


SQL> select * from V$GCSPFMASTER_INFO where DATA_OBJECT_ID=136388;

no rows selected


Now we go to node 2 and manually master the object there...

Node 2
=========
SQL> oradebug setmypid
Statement processed.
SQL> oradebug lkdebug -m pkey 136388
Statement processed.
SQL> select * from V$GCSPFMASTER_INFO where data_object_id=136388;

FILE_ID DATA_OBJECT_ID GC_MASTERIN CURRENT_MASTER PREVIOUS_MASTER
---------- -------------- ----------- -------------- ---------------
REMASTER_CNT
------------
0 136388 Affinity 1 32767
1


Node 1
======

SQL> oradebug setmypid
Statement processed.
SQL> oradebug lkdebug -m pkey 136388
Statement processed.

Also Bug 5649377: REMASTER_CNT IN V$GCSPFMASTER_INFO IS NOT GETTING UPDATED
which I logged in 2006 is fixed in 11g

SQL> /

FILE_ID DATA_OBJECT_ID GC_MASTERIN CURRENT_MASTER PREVIOUS_MASTER
---------- -------------- ----------- -------------- ---------------
REMASTER_CNT
------------
0 136388 Affinity 0 1
2

As you can see the remaster_cnt is correctly set to 2 above
SQL> select * from X$KJDRMAFNSTATS;


ADDR INDX INST_ID DRMS AVG_DRM_TIME OBJECTS_PER_DRM
---------------- ---------- ---------- ---------- ------------ ---------------
QUIESCE_T FRZ_T CLEANUP_T REPLAY_T FIXWRITE_T SYNC_T RES_CLEANED
---------- ---------- ---------- ---------- ---------- ---------- -----------
REPLAY_S REPLAY_R MY_OBJECTS
---------- ---------- ----------
0000000060016FC0 0 1 104 11291 186
3219 28 1622 1302 4589 510 0
26 191959 2


SQL> select count(*) from V$GCSPFMASTER_INFO where current_master=0;

COUNT(*)
----------
2


DRM info is now also available in AWR tables via DBA_HIST_DYN_REMASTER_STATS

Also the following event can be used to trace DRM information

Event can be turned ON dynamically

SQL> alter system set events '10430 trace name context forever, level 10';

System altered.


*** 2010-04-07 21:02:23.831
Begin DRM(245) (swin 0) - AFFINITY transfer pkey 136388.0 to 2 oscan 1.1
kjiobjscn 1
ftd (30) received from node 1 (8/0.0.0)
all ftds received

* kjxftdn: break from kjxftdn, post lmon later

Event can be turned off
SQL> alter system set events '10430 trace name context off';

System altered.


Also the LMON and LMS trace files contains DRM related info

Although I have seen a lot of issues in 10G and turned off DRM in many cases I haven't seen any such issues
in 11.2 so far