Friday, March 6, 2009

Oracle Trace Files

     Guys ! as a software engineer you need to know how to work round the clock and also to be idle for weeks, even months. Though I have experienced the former for most part of my career, last couple of months I was bound to undergo the second and most boring phase. Fortunately, I have identified this within a couple of days and also figured out a possible remedy for this monotonous phase I was heading towards. That is my friends… “Installation and configuration of Metasolv” . I have to agree that it was really challenging to install M6 from scratch. Amid my new learning, the notable one is Trace files in Oracle. Despite the trace option in Metasolv, I had to avail Oracle trace option to troubleshoot some privilege issue.

       Trace is a feature in oracle which enables you to log minute details of a session. Enabling trace for a session will make oracle to log the session details in a file called trace file with extension “.trc”. A proper naming convention has been followed by oracle for these trace files.


  • DB_NAME – Global database name
  • SID- Session id
  • Example: mssdev_ora_2308.trc

    Enabling trace

        Trace can be enabled session wise. We can enable session using a simple alter statement from a particular session or using DBMS_SUPPORT package provided by oracle.

    • ALTER SYSTEM SET trace_enabled = TRUE; for enabling trace.
    • ALTER SYSTEM SET trace_enabled = FALSE;for disabling trace.

    If you would like to enable trace for another session apart from your current session, you can use DBMS_SUPPORT package.

    SQL> desc dbms_support
    Element         Type 
    ---------------------- ---------
    MYSID                                FUNCTION
    START_TRACE                     PROCEDURE
    STOP_TRACE                      PROCEDURE

    Last two procedures described above are used for starting and stopping tracing for any session that currently exists in the database. Lets see a method for enabling trace for all active sessions for a particular user using a simple BEGIN-END block.

      for c in (select s.sid     sid,
                       s.serial# serial
                from   v$session s
                where  s.USERNAME = 'ASAP' and
                       s.status = ’ACTIVE’)
        dbms_support.start_trace_in_session(c.sid, c.serial);
      end loop;

    Use dbms_support.stop_trace_in_session  (c.sid,c.serial); for stopping the tracing. Trace file provides each and every details of the session. A sample trace file will be like this.


    Dump file c:\oracle\admin\mssdev\udump\mssdev_ora_2308.trc
    Wed Feb 18 13:01:42 2009
    ORACLE V9. - Production vsnsta=0
    vsnsql=12 vsnxtr=3
    Windows 2000 Version 5.1 Service Pack 2, CPU type 586
    Oracle9i Enterprise Edition Release - Production
    With the Partitioning, OLAP and Oracle Data Mining options
    JServer Release - Production
    Windows 2000 Version 5.1 Service Pack 2, CPU type 586
    Instance name: mssdev

    Redo thread mounted by this instance: 1

    Oracle process number: 15

    Windows thread id: 2308, image: ORACLE.EXE

    *** 2009-02-18 13:01:42.000
    *** SESSION ID:(9.23) 2009-02-18 13:01:42.000

    PARSING IN CURSOR #2 len=79 dep=0 uid=73 oct=3 lid=73 tim=259898785365 hv=4060294543 ad='1cd62f00'

    SELECT global_name FROM global_name
    PARSE #8:c=15625,e=17422,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=4,tim=2592960232
    BINDS #8:
    EXEC #8:c=0,e=1358,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2592968343
    WAIT #8: nam='SQL*Net message to client' ela= 3 p1=1952673792 p2=1 p3=0
    WAIT #8: nam='SQL*Net message from client' ela= 3338 p1=1952673792 p2=1 p3=0
    WAIT #8: nam='SQL*Net message to client' ela= 1 p1=1952673792 p2=1 p3=0
    FETCH #8:c=0,e=1422,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=2592977265
    WAIT #8: nam='SQL*Net message from client' ela= 36895 p1=1952673792 p2=1 p3=0


             Every line in the trace file has statistics embedded in it, we have to decipher the trace file to understand the details of the session. For example PARSE line shows, the length of the cursor (len=79), the user id of the person parsing the cursor (uid=73), the time the parse began (tim=) and the SQL address of the cursor (ad=). As you will see shortly, we can reference the ad= line to v$sqlarea and get the text of this cursor.

    Some commonly used variable in the trace file are

    C= cpu time, e=elapsed time, p=number of database blocks read, cr=number of consistent mode blocks read. cu=number of current mode blocks read, mis=number of library cache misses, r=number of rows, og=optimizer goal (1=all_rows, 2=first_rows, 3=rule and 4=choose)

            It shows values of these variables for each each section like parsing, binding with variable values, executing, waiting and fetching the records. Reading this file would gives us the understanding of

    • Client used for execution
    • Time and resource involved in executing the query
    • Number of rows fetched along with optimizer goal

    You can read more on Output format of Trace file.


    Guru said...

    The post looks interesting. So, finding enough time at last.

    Unknown said...

    nice article.

    I read the other link you mentioned and i noticed this statment.

    "If there are TIMESTAMPS in the file you can use the difference between 'tim' values to determine an absolute time."

    This is what i am trying to achieve..basically the absolute times between all the query's shown in the trace. Would you know what query or technique I could use extract that output?