Also see these
other notes on using oradebug.
Quick tips for Oracle debugging and tracing with
the Oradebug utility
By Ben Prusinski,
Senior Oracle DBA and Consultant
May 2015:
Oracle provides an internal and poorly documented utility
called oradebug.
The oradebug utility provides useful functions for
debugging and tracing Oracle database errors and can also be quite handy for
tracing SQL statements to output to the tkprof utility for analysis by Oracle
technicians. However, there are some caveats with the use of the oradebug tool
and it should be used only under the careful guidance of Oracle support to avoid
potential damage to production and other critical Oracle databases.
Here are a few of the many
functions available for the expert Oracle DBA with oradebug.
C:\oradebug>sqlplus /nolog
SQL*Plus: Release 10.2.0.1.0 - Production on Mon
May 19 14:46:19 2015
Copyright (c) 1982, 2005, Oracle.
All rights reserved.
SQL> connect / as sysdba
Connected.
SQL> oradebug help
HELP
[command]
Describe one or all commands
SETMYPID
Debug current process
SETOSPID
<ospid>
Set OS pid of process to debug
SETORAPID <orapid>
['force'] Set Oracle pid of
process to debug
SHORT_STACK
Dump abridged OS stack
DUMP
<dump_name> <lvl> [addr]
Invoke named dump
DUMPSGA
[bytes]
Dump fixed SGA
DUMPLIST
Print a list of available dumps
EVENT
<text>
Set trace event in process
SESSION_EVENT <text>
Set trace event in session
DUMPVAR
<p|s|uga> <name> [level]
Print/dump a fixed PGA/SGA/UGA DUMPTYPE
<address> <type> <count>
Print/dump an address with type info
SETVAR
<p|s|uga> <name> <value>
Modify a fixed PGA/SGA/UGA PEEK
<addr> <len> [level]
Print/Dump memory
POKE <addr> <len> <value>
Modify memory
WAKEUP
<orapid>
Wake up Oracle process
SUSPEND
Suspend execution
RESUME
Resume execution
FLUSH
Flush pending writes to trace CLOSE_TRACE
Close trace file
TRACEFILE_NAME
Get name of trace file
LKDEBUG
Invoke global enqueue service
SGATOFILE
<SGA dump dir>
Dump SGA to file
DMPCOWSGA
<SGA dump dir> Dump & map SGA as
COW
MAPCOWSGA
<SGA dump dir>
Map SGA as COW
HANGANALYZE [level] [syslevel]
Analyze system hang
FFBEGIN Flash
Freeze the Instance
FFDEREGISTER
FF deregister instance from cluster
FFTERMINST
Call exit and terminate instance
FFRESUMEINST
Resume the flash frozen instance
FFSTATUS Flash
freeze status of instance
UNLIMIT
Unlimit the size of the trace file
PROCSTAT Dump
process statistics
As you can see, there are quite a few options
to the oradebug utility.
The most useful
features of the oradebug utility are for hang and crash analysis for Oracle
database environments. If there is a core dump or bug that must be resolved with
the help of Oracle support, the Oracle DBA can generate the crash dump analysis
and work through the crisis with confidence and less delay by dumping the memory
contents of the SGA to the trace file and handing this off to the advanced
Oracle internal support engineer for quick analysis
and problem resolution.
Another use for oradebug is for performance
analysis and tuning. SQL statements can be traced at the kernel level with
oradebug which aids in the tuning of SQL for the Oracle database environment.
We will next cover a quick example of how to
use oradebug utility to trace a user SQL session.
Oradebug requires the SYSDBA level privileges account ie)
SYS to run from within a new SQL*Plus session.
First we will set our oradebug to trace the current user
session with the setmypid command.
SQL> oradebug setmypid
Statement processed.
SQL>
Now lets use an ALTER SESSION command to tidy up the name
for the oradebug file to make things easier when we need to locate the trace
file.
SQL> alter session set tracefile_identifier='mytrace';
Session altered.
Now, let's check where our trace file is stored with the
following oradebug command:
SQL> oradebug tracefile_name
c:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_1348_mytrace.trc
By default, oradebug writes out the trace file to the
USER_DUMP_DESTINATION directory.
Now lets setup our SQL trace for our current user session
and generate some database activity to capture with oradebug.
Oradebug uses events to capture various database events for
Oracle. For a SQL trace, the specific event is 10046. In addition to these
events for capturing low level Oracle database activity, oradebug also has many
levels available for setting the trace.
Some of these trace levels with oradebug include:
Level 1 - contains the basic level of trace information. For example, this trace level
will display the bind variables in PL/SQL and SQL statements.
Level 8 -
provides the trace details from Level 1 plus the wait events for elapsed
times that are more than current CPU timings.
Level 12- adds
in all the previous trace level information in addition to all wait event
information.
Since we are using oradebug in a test environment, let's
enable a full trace to capture as much detail as possible for SQL activity with
our user session. We also want to set the trace file to be unlimited in size so
no errors occur during the tracing activity.
SQL> oradebug unlimit
Statement processed.
SQL> oradebug event 10046 trace name context forever, level 12
Statement processed.
Now that we have the trace enabled for SQL statements with
oradebug, lets generate some activity.
SQL> create table t1 (a number, b varchar2(100));
Table created.
SQL> insert into t1
2 values (1,'A');
1 row created.
SQL> commit;
Commit complete.
SQL> insert into t1
2 values (2,'B');
1 row created.
SQL> commit;
Commit complete.
SQL> insert into t1
2 values (3,'C');
1 row created.
SQL> commit;
Commit complete.
SQL> insert into t1
2 values (3,'C');
1 row created.
Now let's end our trace session for oradebug and review the
new trace file.
SQL> oradebug event 10046 trace name context off
Statement processed.
SQL> oradebug tracefile_name
c:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_1348_mytrace.trc
We can format our trace file with tkprof or review the raw
data generated by oradebug in the trace file. First, we will look at the raw
trace dump that we generated with oradebug and then we will conclude our brief
visit to oradebug with a tkprof formatted trace output.
Our raw dump in the trace file reviews many low level
details for Oracle as shown below.
*** TRACE DUMP CONTINUED FROM FILE
***
Dump file
c:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_1348_mytrace.trc
Mon May 19 15:12:22 2015
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release
10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU
: 2 - type 586
Process Affinity :
0x00000000
Memory (Avail/Total): Ph:856M/2037M, Ph+PgF:2240M/3934M, VA:979M/2047M
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 26
Windows thread id: 1348, image: ORACLE.EXE (SHAD)
*** 2015-05-19 15:12:22.218
*** SERVICE NAME:(SYS$USERS) 2015-05-19 15:12:22.187
*** SESSION ID:(135.279) 2015-05-19 15:12:22.187
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1
p3=0 obj#=-1 tim=18507445018
*** 2015-05-19 15:13:20.187
WAIT #0: nam='SQL*Net message from client' ela= 57993544 driver id=1111838976
#bytes=1 p3=0 obj#=-1 tim=18565462754
XCTEND rlbk=0, rd_only=1
=====================
PARSING IN CURSOR #4 len=42 dep=0 uid=0 oct=1 lid=0 tim=18565469559 hv=4239432121
ad='40adba98'
create table t1(a number, b varchar2(100))
END OF STMT
PARSE #4:c=0,e=3292,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=18565469553
BINDS #4:
=====================
PARSING IN CURSOR #3 len=51 dep=1 uid=0 oct=3 lid=0 tim=18565479916 hv=1523794037
ad='46295e4c'
select audit$,options from procedure$ where obj#=:1
END OF STMT
PARSE #3:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=18565479911
BINDS #3:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=00 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0a2dbffc bln=22
avl=03 flg=05
value=10200
EXEC #3:c=15625,e=11817,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=18565499761
FETCH #3:c=0,e=59,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=18565501551
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY INDEX ROWID PROCEDURE$
(cr=3 pr=0 pw=0 time=64 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=109 op='INDEX UNIQUE SCAN I_PROCEDURE1 (cr=2
pr=0 pw=0 time=32 us)'
=====================
PARSING IN CURSOR #1 len=179 dep=1 uid=0 oct=3 lid=0 tim=18565507100 hv=2812844157
ad='462ee788'
select owner#,name,namespace,remoteowner,linkname,p_timestamp,p_obj#, nvl(property,0),subname,d_attrs
from dependency$ d, obj$ o where d_obj#=:1 and p_obj#=obj#(+) order by order#
END OF STMT
PARSE #1:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=18565507094
BINDS #1:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=0a2dc1d8 bln=22
avl=03 flg=05
value=10200
EXEC #1:c=15625,e=13251,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=18565529339
FETCH #1:c=0,e=545,p=0,cr=20,cu=0,mis=0,r=1,dep=1,og=4,tim=18565531768
FETCH #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=18565533741
FETCH #1:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=18565535668
FETCH #1:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=18565537698
FETCH #1:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=18565539607
FETCH #1:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=18565541509
FETCH #1:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=18565543419
FETCH #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=18565545385
STAT #1 id=1 cnt=7 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=20 pr=0 pw=0 time=654
us)'
STAT #1 id=2 cnt=7 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=20 pr=0 pw=0
time=495 us)'
STAT #1 id=3 cnt=7 pid=2 pos=1 obj=92 op='TABLE ACCESS BY INDEX ROWID
DEPENDENCY$ (cr=4 pr=0 pw=0 time=136 us)'
STAT #1 id=4 cnt=7 pid=3 pos=1 obj=122 op='INDEX RANGE SCAN I_DEPENDENCY1 (cr=2
pr=0 pw=0 time=62 us)'
STAT #1 id=5 cnt=7 pid=2 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=16
pr=0 pw=0 time=257 us)'
STAT #1 id=6 cnt=7 pid=5 pos=1 obj=36 op='INDEX UNIQUE SCAN I_OBJ1 (cr=9 pr=0
pw=0 time=116 us)'
In the header section of the trace file, oradebug has
provided us with useful configuration information on the system and database
environment. Next, we see the dump output for wait events and SQL statements for
our Oracle 10g database instance.
Now we will conclude our brief visit to the world of
oradebug with a brief example of using tkprof with the trace file for database
tuning analysis.
To format our trace file generated from our recent oradebug
session we need to execute the tkprof command from the trace file default
directory as follows.
C:\oradebug>cd c:\oracle\product\10.2.0\admin\orcl\udump
C:\oracle\product\10.2.0\admin\orcl\udump>
tkprof orcl_ora_1348_mytrace.trc trace_sql.txt
explain=system/oracle
sys=no waits=yes
TKPROF: Release 10.2.0.1.0 - Production on Mon May 19 15:24:23 2015
Copyright (c) 1982, 2005, Oracle.
All rights reserved.
Now, let's review
the contents of our newly formatted trace file:
TKPROF: Release 10.2.0.1.0 - Production on Mon May 19 15:24:23 2015
Copyright (c) 1982, 2005, Oracle.
All rights reserved.
Trace file: orcl_ora_1348_mytrace.trc
Sort options: default
***********************************************************************
count = number of times
OCI procedure was executed
cpu = cpu
time in seconds executing
elapsed = elapsed time in seconds
executing
disk = number of
physical reads of buffers from disk
query = number of
buffers gotten for consistent read
current = number of buffers gotten
in current mode (usually for update)
rows = number of
rows processed by the fetch or execute call
***********************************************************************
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 38 (XDB)
(recursive depth: 1)
**********************************************************************
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 38 (XDB)
(recursive depth: 2)
Rows
Execution Plan
-------
---------------------------------------------------
0
SELECT STATEMENT MODE:
ALL_ROWS
0
NESTED LOOPS
0
NESTED LOOPS
0
TABLE ACCESS MODE:
ANALYZED (BY INDEX ROWID) OF 'USER$'
(CLUSTER)
0
INDEX MODE: ANALYZED
(UNIQUE SCAN) OF 'I_USER1' (INDEX
(UNIQUE))
0
TABLE ACCESS MODE:
ANALYZED (CLUSTER) OF 'TS$' (CLUSTER)
0
INDEX MODE: ANALYZED
(UNIQUE SCAN) OF 'I_TS#' (INDEX
SELECT /*+ ALL_ROWS */ COUNT(*)
FROM
ALL_POLICIES V WHERE V.OBJECT_OWNER = :B3 AND V.OBJECT_NAME = :B2 AND
(POLICY_NAME LIKE '%xdbrls%' OR POLICY_NAME LIKE '%$xd_%') AND
V.FUNCTION =
:B1
call
count
cpu elapsed
disk
query current
rows
Rows Row Source
Operation
-------
---------------------------------------------------
1
FILTER (cr=3 pr=0 pw=0
time=148 us)
1
TABLE ACCESS FULL DUAL (cr=3 pr=0 pw=0 time=43 us)
Rows
Execution Plan
-------
---------------------------------------------------
0
SELECT STATEMENT MODE:
ALL_ROWS
1
FILTER
1
TABLE ACCESS MODE:
ANALYZED (FULL) OF 'DUAL' (TABLE)
***********************************************************************
Misses in library cache during parse: 6
Elapsed times include waiting on following events:
Event waited on
Times Max. Wait
Total Waited
----------------------------------------
Waited ----------
--------SQL*Net message to client
28
0.00
0.00
SQL*Net message from client
28
178.60
331.48
SQL*Net break/reset to client
2
0.00
0.00
db file sequential read
2
0.00 0.00
reliable message
1
0.00
0.00
enq: RO - fast object reuse
1
0.00
0.00
rdbms ipc reply
1
0.00
0.00
log file sync
6
0.00
0.00
As you can see the oradebug utility provides a wealthy of
information and serves as a goldmine of resources for the Oracle expert
practitioner who must resolve the toughest Oracle problems. It will allow you to
develop insight into the Oracle database engine on how the nuts and bolts of the
Oracle database really works.
and include the URL for the page.
