Oracle is well known for its instrumentation: wait interface, log files and tracing capabilities.

Usually, lots of them are documented but the way you can trace binaries and tools are usually not. More, reading trace files is not an easy thing to do but some times you can find clues about the problem you face.

In this post, I will talk about how to enable tracing when you use some binaries.

RMAN

RMAN is the Oracle utility used to backup and recover your databases. To enable tracing is RMAN, you have to switch rman is “debug” mode.

This mode can be enabled directly in rman:

 

[oracle@oel7 ~]$ rman target /

Recovery Manager: Release 12.1.0.2.0 - Production on Wed Feb 24 15:45:13 2016

Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.

connected to target database: ORCL (DBID=1413029491)

RMAN> debug on

RMAN-03036: Debugging set to level=9[MEDIUM], types=ALL

DBGSQL: TARGET> begin dbms_rcvman.setDebugOn; dbms_rcvman.dumpPkgState('Debug On'); end;
DBGSQL: sqlcode = 0
DBGRCVMAN: ENTERING dumpPkgState Debug On

.../...

Or (much better) it can be enabled with the debug option in the rman command, and by specifying a trace file :

[oracle@oel7 ~]$ rman target / debug trace=tracefile.trc

Recovery Manager: Release 12.1.0.2.0 - Production on Wed Feb 24 15:22:10 2016

Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.

RMAN-06005: connected to target database: ORCL (DBID=1413029491)

RMAN> disconnect

All the debug stuff is then located in your “tracefile.trc” file.

You can enable tracing on specific component in rman :

• SQL: for tracing SQL queries generated by rman
• RESTORE: for tracing restore operation only
• RECOVER: for tracing recovery operation only
• RESYNC: for tracing synchronization operation only
• DUPLICATE: for tracing duplicate operation only

And for each or all of these component, you can set a verbosity level from 1 (lowest) to 10 (highest). 9 is the default verbosity level. Sometimes, you can change the verbosity level without any change in your tracefile.

Here are some examples (point that many components can be traced at the same time):

[oracle@oel7 ~]$ rman target / debug recover level=10 trace=tracefile.trc

[oracle@oel7 ~]$ rman target / debug sql level=1 trace=tracefile.trc

RMAN> debug restore,sql level=10

DGMGRL

DGMGRL is the tool used to control dataguard broker and operates some changes in your dataguard configuration: add config, initiate a switchover or a failover etc.

Dgmgrl can be switched to debug mode to get more information about a failed command.

[oracle@dg1 ~]$ dgmgrl -debug sys/oracle@prod_lille
DGMGRL for Linux: Version 11.2.0.4.0 - 64bit Production

Copyright (c) 2000, 2009, Oracle. All rights reserved.

Welcome to DGMGRL, type "help" for information.
[W000 02/24 16:14:15.62] Connecting to database using prod_lille.
[W000 02/24 16:14:15.65] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:14:15.65] Broker version is '11.2.0.4.0'
Connected.

This option can be very useful specially when you perform a switchover operation, all operations are logged and you can follow every connection, disconnection, tns errors, instance startup etc.

Below is an example of a successful switchover in debug mode:

DGMGRL> switchover to prod_arras;
Performing switchover NOW, please wait...
Operation requires a connection to instance "prod" on database "prod_arras"
Connecting to instance "prod"...
[W000 02/24 16:31:42.31] Connecting to database using (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=dg2.localdomain)(PORT=1521))(ADDRESS=(PROTOCOL=TCP)(HOST=dg1.localdomain)(PORT=1521)))(CONNECT_DATA=(SERVICE_NAME=prod_arras_DGB)(INSTANCE_NAME=prod))).
[W000 02/24 16:31:42.33] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:31:42.33] Broker version is '11.2.0.4.0'
Connected.
New primary database "prod_arras" is opening...
Operation requires startup of instance "prod" on database "prod_lille"
Starting instance "prod"...
[W000 02/24 16:31:50.20] Connecting to database using (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=dg1.localdomain)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=prod_lille_DGMGRL)(INSTANCE_NAME=prod)(SERVER=DEDICATED))).
[W000 02/24 16:31:50.21] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
ORA-01034: ORACLE not available
Process ID: 0
Session ID: 0 Serial number: 0

ORACLE instance started.
[W000 02/24 16:31:51.52] Connecting to database using (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=dg1.localdomain)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=prod_lille_DGMGRL)(INSTANCE_NAME=prod)(SERVER=DEDICATED))).
[W000 02/24 16:31:51.54] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:31:51.55] Broker version is '11.2.0.4.0'
alter database mount

Database mounted.
[W000 02/24 16:31:59.85] Connecting to database using (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=dg1.localdomain)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=prod_lille_DGMGRL)(INSTANCE_NAME=prod)(SERVER=DEDICATED))).
[W000 02/24 16:31:59.87] Checking broker version [BEGIN :version := dbms_drs.dg_broker_info('VERSION'); END;].
[W000 02/24 16:31:59.87] Broker version is '11.2.0.4.0'
Switchover succeeded, new primary is "prod_arras"

EXPDP / IMPDP

Datapump export and import operation can be traced too. But for these tools, Oracle published a note on how to enable tracing a datapump operation. The MOS note is “Export/Import DataPump Parameter TRACE – How to Diagnose Oracle Data Pump (Doc ID 286496.1)”.

To trace a datapump process, you can do it at different levels, client process (expdp/impdp), master process (DM), worker process (DW) and you can trace different services. That’s why Oracle used a TRACE parameter. This one in coded with a hexadecimal value that code for a type of services you want to trace, and this service will generate trace in different processes (DM, DW, etc.).

The Trace value depends on which service you want to trace:

-- Summary of Data Pump trace levels:
-- ==================================

  Trace   DM   DW  ORA  Lines
  level  trc  trc  trc     in
  (hex) file file file  trace                                         Purpose
------- ---- ---- ---- ------ -----------------------------------------------
  10300    x    x    x  SHDW: To trace the Shadow process (API) (expdp/impdp)
  20300    x    x    x  KUPV: To trace Fixed table
  40300    x    x    x  'div' To trace Process services
  80300    x            KUPM: To trace Master Control Process (MCP)      (DM)
 100300    x    x       KUPF: To trace File Manager
 200300    x    x    x  KUPC: To trace Queue services
 400300         x       KUPW: To trace Worker process(es)                (DW)
 800300         x       KUPD: To trace Data Package
1000300         x       META: To trace Metadata Package
------- 'Bit AND'
1FF0300    x    x    x  'all' To trace all components          (full tracing)

Here’s an example with full tracing:

[oracle@oel7 ~]$ expdp system/oracle directory=dpdir dumpfile=test.dmp logfile=test.log tables=HR.REGIONS REUSE_DUMPFILES=YES trace=FFF0300

In the trace files generated, you will find lots of very interesting stuff (for example below, the trace file of the expdp process)

*** 2016-02-24 18:25:33.740
*** SESSION ID:(135.7145) 2016-02-24 18:25:33.740
*** CLIENT ID:() 2016-02-24 18:25:33.740
*** SERVICE NAME:(SYS$USERS) 2016-02-24 18:25:33.740
*** MODULE NAME:(ude@oel7.localdomain (TNS V1-V3)) 2016-02-24 18:25:33.740
*** CLIENT DRIVER:() 2016-02-24 18:25:33.740
*** ACTION NAME:() 2016-02-24 18:25:33.740

SHDW: *** GET_STATUS_VERSION call ***
SHDW: Version = 9999
KUPP:18:25:33.741: Input trace/debug flags: 0FFF0300 = 268370688
KUPP:18:25:33.741: Current trace/debug flags: 0FFF0300 = 268370688
SHDW:18:25:33.741: Current user = SYSTEM
SHDW:18:25:33.741: Current schema = SYSTEM
SHDW:18:25:33.741: Current language = AMERICAN_AMERICA.AL32UTF8
SHDW:18:25:33.742: Current session address = 00000001B7D050F8
SHDW:18:25:33.742: *** OPEN call ***
SHDW:18:25:33.742: operation = EXPORT
SHDW:18:25:33.742: job_mode = table
SHDW:18:25:33.742: remote_link =
SHDW:18:25:33.742: job_name =
SHDW:18:25:33.742: version =
SHDW:18:25:33.742: compression = 2
KUPV:18:25:33.743: Open request for job: SYSTEM.SYS_EXPORT_TABLE_01
KUPV:18:25:33.745: Master Table create statement: CREATE TABLE "SYSTEM"."SYS_EXPORT_TABLE_01" (abort_step NUMBER,ancestor_process_order NUMBER,base_object_name VARCHAR2(30),base_object_schema VARCHAR2(30),base_object_type VARCHAR2(30),base_process_order NUMBER,block_size NUMBER,cluster_ok NUMBER,completed_bytes NUMBER,completed_rows NUMBER,completion_time DATE,control_queue VARCHAR2(30),creation_level NUMBER,cumulative_time NUMBER,data_buffer_size NUMBER,data_io NUMBER,dataobj_num NUMBER,db_version VARCHAR2(60),degree NUMBER,domain_process_order NUMBER,dump_allocation NUMBER,dump_fileid NUMBER,dump_length NUMBER,dump_orig_length NUMBER,dump_position NUMBER,duplicate NUMBER,elapsed_time NUMBER,error_count NUMBER,extend_size NUMBER,file_max_size NUMBER,file_name VARCHAR2(4000),file_type NUMBER,flags NUMBER,grantor VARCHAR2(30),granules NUMBER,guid RAW(16),in_progress CHAR(1),instance VARCHAR2(60),instance_id NUMBER,is_default NUMBER,job_mode VARCHAR2(21),job_version VARCHAR2(60),last_file NUMBER,last_update DA
TE,load_method NUMBER,metadata_buffer_size NUMBER,metadata_io NUMBER,name VARCHAR2(30),object_int_oid VARCHAR2(32),object_long_name VARCHAR2(4000),object_name VARCHAR2(200),object_number NUMBER,object_path_seqno NUMBER,object_row NUMBER,object_schema VARCHAR2(30),object_tablespace VARCHAR2(30),object_type VARCHAR2(30),object_type_path VARCHAR2(200),old_value VARCHAR2(4000),operation VARCHAR2(8),option_tag VARCHAR2(30),orig_base_object_schema VARCHAR2(30),original_object_name VARCHAR2(128),original_object_schema VARCHAR2(30),packet_number NUMBER,parallelization NUMBER,parent_process_order NUMBER,partition_name VARCHAR2(30),phase NUMBER,platform VARCHAR2(101),process_name VARCHAR2(30),process_order NUMBER,processing_state CHAR(1),processing_status CHAR(1),property NUMBER,queue_tabnum NUMBER,remote_link VARCHAR2(128),scn NUMBER,seed NUMBER,service_name VARCHAR2(64),size_estimate NUMBER,start_time DATE,state VARCHAR2(12),status_queue VARCHAR2(30),subpartition_name VARCHAR2(30),target_xml_clob CLOB,tde_rewrapped_
key RAW(2000),template_table VARCHAR2(30),timezone VARCHAR2(64),total_bytes NUMBER,trigflag NUMBER,unload_method NUMBER,user_directory VARCHAR2(4000),user_file_name VARCHAR2(4000),user_name VARCHAR2(30),value_n NUMBER,value_t VARCHAR2(4000),version NUMBER,work_item VARCHAR2(21),xml_clob CLOB) SEGMENT CREATION IMMEDIATE INITRANS 10
KUPV:18:25:33.780: (Re)Creating job: SYSTEM.SYS_EXPORT_TABLE_01

.../...

SRVCTL

srvctl is the program that control clusterware resources. You can use it in a RAC configuration, or with Oracle Restart.

If, for example, a ressource doesn’t start in your cluster, or you would like to have more information about the process. You can set a specific environment variable named SRVM_TRACE to the value you want and then run your command. srvctl just look if the variable is defined and then it traces. The debug information is written in the standard output.

See demonstration below:

[oracle@rac1 ~]$ env|grep SRVM
[oracle@rac1 ~]$ srvctl status database -db cdb
Instance cdb1 is running on node rac1
Instance cdb2 is not running on node rac2
[oracle@rac1 ~]$ export SRVM_TRACE=laurent
[oracle@rac1 ~]$ srvctl status database -db cdb
[main] [ 2016-02-24 18:43:08.601 CET ] [OPSCTLDriver.setInternalDebugLevel:325] tracing is true at level 2 to file null
[main] [ 2016-02-24 18:43:08.607 CET ] [OPSCTLDriver.main:162] SRVCTL arguments : args[0]=status args[1]=database args[2]=-db args[3]=cdb
[main] [ 2016-02-24 18:43:08.608 CET ] [SRVMContext.init:114] Performing SRVM Context init. Init Counter=1
[main] [ 2016-02-24 18:43:08.622 CET ] [Library.load:194] library.load
[main] [ 2016-02-24 18:43:08.623 CET ] [sPlatform.isHybrid:66] osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2016-02-24 18:43:08.624 CET ] [sPlatform.isHybrid:66] osName=Linux osArch=amd64 JVM=64 rc=false
[main] [ 2016-02-24 18:43:08.624 CET ] [Library.load:271] Loading library /u01/app/oracle/product/12.1.0/dbhome_1/lib/libsrvmhas12.so
[main] [ 2016-02-24 18:43:08.635 CET ] [SRVMContext.init:131] SRVM Context init-ed
[main] [ 2016-02-24 18:43:08.648 CET ] [Version.isPre:610] version to be checked 12.1.0.2.0 major version to check against 10
[main] [ 2016-02-24 18:43:08.648 CET ] [Version.isPre:621] isPre.java: Returning FALSE
[main] [ 2016-02-24 18:43:08.651 CET ] [OCR.loadLibrary:328]
Inside constructor of OCR
[main] [ 2016-02-24 18:43:08.652 CET ] [OCR.loadLibrary:336] Going to load the ocr library

.../...

[oracle@rac1 ~]$ unset SRVM_TRACE
[oracle@rac1 ~]$ srvctl status database -db cdb
Instance cdb1 is running on node rac1
Instance cdb2 is not running on node rac2

OPATCH

Opatch can be traced with an environment variable positioned like srvctl. This variable is OPATCH_DEBUG and it has to be set to TRUE. As for srvctl, information is written to standard output:

[oracle@rac1 ~]$ export OPATCH_DEBUG=TRUE
[oracle@rac1 ~]$ $ORACLE_HOME/OPatch/opatch lsinv
OPatch was not able to set FMW_COMPONENT_HOME by itself.
Machine Info: Linux rac1.localdomain 3.8.13-44.1.1.el6uek.x86_64 #2 SMP Wed Sep 10 06:10:25 PDT 2014 x86_64 x86_64 x86_64 GNU/Linux
_osArch is amd64
_javaVMSpecVersion is 1.0
_javaVMSpecVendor is Sun Microsystems Inc.
_javaVMSpecName is Java Virtual Machine Specification
_javaVMVendor is Sun Microsystems Inc.
_javaJRESpecVersion is 1.6
_javaJRESpecVendor is Sun Microsystems Inc.
_javaJRESpecName is Java Platform API Specification
_javaSupportedClassVersion is 50.0
OPatch compiled with major version: 50, minor version: 0
_osArch (from OCM API) is
/u01/app/oracle/product/12.1.0/dbhome_1/jdk/bin/java -Xms150m -Xmx256m -XX:MaxPermSize=128M -cp /u01/app/oracle/product/12.1.0/dbhome_1/OPatch/ocm/lib/emocmclnt.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/OraInstaller.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/OraPrereq.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/OraCheckPoint.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/share.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/orai18n-mapping.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/xmlparserv2.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/emCfg.jar:/u01/app/oracle/product/12.1.0/dbhome_1/oui/jlib/ojmisc.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/jlib/opatch.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/jlib/opatchsdk.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/automation.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/apache-commons/commons-cli-1.0.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/jlib/oracle.opatch.classpath.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/activation.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/jaxb-api.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/jaxb-impl.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/jaxb/jsr173_1.0_api.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/OsysModel.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/osysmodel-utils.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/CRSProductDriver.jar:/u01/app/oracle/product/12.1.0/dbhome_1/OPatch/oplan/jlib/oracle.oplan.classpath.jar -DOPatch.ORACLE_HOME=/u01/app/oracle/product/12.1.0/dbhome_1 -DOPatch.DEBUG=true -DOPatch.RUNNING_DIR=/u01/app/oracle/product/12.1.0/dbhome_1/OPatch -DOPatch.MW_HOME= -DOPatch.WL_HOME= -DOPatch.COMMON_COMPONENTS_HOME= -DOPatch.OUI_LOCATION= -DOPatch.FMW_COMPONENT_HOME= -DOPatch.OPATCH_CLASSPATH= -DOPatch.WEBLOGIC_CLASSPATH= oracle/opatch/OPatch lsinv -invPtrLoc /u01/app/oracle/product/12.1.0/dbhome_1/oraInst.loc
Oracle Interim Patch Installer version 12.1.0.1.3
Copyright (c) 2016, Oracle Corporation. All rights reserved.

OPatchSession::parse() on "lsinv","-invPtrLoc","/u01/app/oracle/product/12.1.0/dbhome_1/oraInst.loc",

Argument is "lsinv"
Add commands for Help
add command "apply"

.../...

Oracle Kernel Tracing

Oracle Kernel tracing can be done by enabling some events.

Event is a number between 10000 and 10999. It’s very similar to an error code … but it’s not a real one.

The most popular events are 10046 (SQL Trace) and 10053 (CBO debug trace) …but there are plenty of other ones and you can find details in oraus.msg file (or you can plan with oerr utility).

Events can be positioned by many ways :

• With an ALTER SESSION (It’s not recommended to use ALTER SYSTEM when you enable events)

SQL> alter session set events '10046 trace name context forever, level 12';
SQL> alter session set events '10046 trace name context off';

• With an oradebug command. This method offers the possibility to set an event in another session

For example, if you want to enable 10053 event in the session that have the OS PID 5683 (You can use SETMYPID for debugging your own session, or SETORAPID to target a session with a specific Oracle PID)

SQL> oradebug setospid 5683; 
SQL> oradebug event 10053 trace name context forever, level 1;
SQL> oradebug event 10053 trace name context off;

• With DBMS_SYSTEM.SET_EV. Like ORADEBUG, you can set an event in another session

 

SQL> -- Enable SQL Trace in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10046, le=>12, nm=>'');
SQL> -- Disable SQL Trace in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10046, le=>0, nm=>'');

SQL> -- Enable CBO debug in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10053, le=>1, nm=>'');
SQL> -- Disable CBO debug in session with SID 6278 and Serial 71077
SQL> execute dbms_system.set_ev(si=>6278, se=>71077, ev=>10046, le=>0, nm=>'');

For all of these commands, the trace file will be available in the folder referenced by user_dump_dest.

Starting with Oracle 11.2, Oracle come with a new way to trace its components. This is named UTS (Unified Tracing System).

UTS offers the possibility to trace some components (like with events) but you can combine it with filters (for example, trace CBO computation when a specific SQL_ID is parsed etc.)

Note: Events are still available and they have’nt been replaced by UTS … UTS completes them.

The component list can be get with “oradebug doc component” command.

I will not write some detailed stuff about UTS because very interesting guys in the community have already written blog posts and articles on this.

You can visit them by following these URLs :

• Tanel Pöder: http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc
• Miladin Modrakovic: https://oraclue.files.wordpress.com/2011/03/oracle_diagnostic_events_in_11g1.pdf

 

Last but not least, tracing everything without knowing what you are doing can be dangerous (Filesystem full filling, database hangs and/or crash), so it’s recommended to use tracing very carefully.

 

Thanks to my friend Pierre Labrousse who helped me for parts of this post.