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 2008
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
SETORAPID
SHORT_STACK Dump abridged OS stack
DUMP
DUMPSGA [bytes] Dump fixed SGA
DUMPLIST Print a list of available dumps
EVENT
SESSION_EVENT
DUMPVAR
DUMPTYPE
SETVAR
POKE
WAKEUP
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
DMPCOWSGA
MAPCOWSGA
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.
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.
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 2008
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g
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)
*** 2008-05-19 15:12:22.218
*** SERVICE NAME:(SYS$USERS) 2008-05-19 15:12:22.187
*** SESSION ID:(135.279) 2008-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
*** 2008-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 2008
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 2008
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.
No comments:
Post a Comment