Thursday, July 29, 2010

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

3 comments:

Frits Hoogland said...

It would be handy to point out 'oradebug unlimit', which resets the limit imposed by 'max_dump_file_size'. Traces often explode in size, so hitting the limit is not unthinkable.

Kumar Madduri said...

Hello
Can you explain or elaborate more on this last sentence
" You can still use the _px_trace underscore parameter to determine why queries are not running in parallel"

Fairlie Rego said...

Please check the below note on MOS

How to Use _PX_TRACE to Check Whether Parallelism is Used [ID 400886.1]