4 Replies Latest reply: May 27, 2008 9:08 AM by 428027 RSS

    some 10046 traceing questions.....

    user00726
      when i enbale 10046 tracing event,then in the dump file...i got the below information....

      i want to know in the first line i.e
      what is len,dep,uid,oct,lid,tim

      and what is ela (is it elapsed),c,e,p,cr,cu,mis etc.

      i know the meaning of sql net message to or from client....
      but how would i know at what time DB get a data or at what time user get a data from the DB......

      above are some of the queries whick i am looking for.....

      PARSING IN CURSOR #7 len=73 dep=0 uid=27 oct=3 lid=27 tim=618157870 hv=1879765364 ad='3f0b34c8'
      select sum(returnamt) as amt from cancellationhdr where reqid = 'R222729'
      END OF STMT
      PARSE #7:c=0,e=727,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=618157865
      WAIT #7: nam='SQL*Net message to client' ela= 3 p1=1297371904 p2=1 p3=0
      WAIT #0: nam='SQL*Net message from client' ela= 2 p1=1297371904 p2=1 p3=0
      WAIT #7: nam='SQL*Net message to client' ela= 1 p1=1297371904 p2=1 p3=0
      WAIT #0: nam='SQL*Net message from client' ela= 2 p1=1297371904 p2=1 p3=0
      BINDS #7:
      XCTEND rlbk=0, rd_only=1
      EXEC #7:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=618158815
      WAIT #7: nam='SQL*Net message to client' ela= 2 p1=1297371904 p2=1 p3=0
      WAIT #0: nam='SQL*Net message from client' ela= 2 p1=1297371904 p2=1 p3=0
      WAIT #7: nam='SQL*Net message to client' ela= 2 p1=1297371904 p2=1 p3=0
      FETCH #7:c=0,e=49,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=4,tim=618159398
      WAIT #0: nam='SQL*Net message from client' ela= 2 p1=1297371904 p2=1 p3=0
      STAT #7 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE '
      STAT #7 id=2 cnt=0 pid=1 pos=1 obj=7421 op='TABLE ACCESS BY INDEX ROWID CANCELLATIONHDR '
      STAT #7 id=3 cnt=0 pid=2 pos=1 obj=7425 op='INDEX RANGE SCAN CANCELLATIONDHRREQID '
      WAIT #7: nam='SQL*Net message to client' ela= 1 p1=1297371904 p2=1 p3=0
      WAIT #0: nam='SQL*Net message from client' ela= 1 p1=1297371904 p2=1 p3=0
      STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE '
      STAT #5 id=2 cnt=1 pid=1 pos=1 obj=7504 op='TABLE ACCESS BY INDEX ROWID MONEYRECIEPT '
      STAT #5 id=3 cnt=1 pid=2 pos=1 obj=7506 op='INDEX RANGE SCAN MOENEYRECEIPTID '
      WAIT #5: nam='SQL*Net message to client' ela= 1 p1=1297371904 p2=1 p3=0
      WAIT #0: nam='SQL*Net message from client' ela= 2 p1=1297371904 p2=1 p3=0
      WAIT #5: nam='SQL*Net message to client' ela= 2 p1=1297371904 p2=1 p3=0
      WAIT #0: nam='SQL*Net message from client' ela= 2 p1=1297371904 p2=1 p3=0
        • 1. Re: some 10046 traceing questions.....
          Aman....
          Read this page for the starting for readng 10046 trace file.
          http://groups.google.com/group/comp.databases.oracle.server/browse_thread/thread/4f346646832c2a87/c1de2270c4da7c64?lnk=gst&q=charles+hooper+%2B+10046#c1de2270c4da7c64
          Aman....
          • 2. Re: some 10046 traceing questions.....
            153119
            Please buy Cary Millsap, Optimizing Oracle Performance, ISBN 0-596-00527-X

            This book contains a complete walkthrough of a trace files, plus tools to 'parse' it.
            It also explains the time unit has not been always the same.
            In 8i ela (elapsed, obviously) is in milliseconds, in 9i and higher in microseconds.
            Yet another reason to always include those 4 digits.


            --
            Sybrand Bakker
            Senior Oracle DBA
            • 3. Re: some 10046 traceing questions.....
              Charles Hooper
              I second Sybrand's recommendation of Cary Millsap's book for learning how to read 10046 trace files. That book is likely the best source for understanding these trace files.

              If you search for information on 10046 trace files, you will likely find a couple other writeups that I created for reading 10046 trace files in addition to the one posted by Aman. One of those posts is here:
              http://groups.google.com/group/ORACLE_DBA_EXPERTS/browse_thread/thread/520793f76f5d40d3

              In short summary:
              len= the number of characters in the SQL statement
              dep= tells the application/trigger depth at which the SQL statement was executed. dep=0 indicates that it was executed by the client application. dep=1 indicates that the SQL statement was executed by a trigger, the Oracle optimizer, or a space management call. dep=2 indicates that the SQL statement was called from a trigger, dep=3 indicates that the SQL statement was called from a trigger that was called from a trigger.
              tim= is a time stamp measured in 1/1,000,000 of a second that may be used for tracking the progress in the 10046 trace file - take the delta value of the most recent tim=, subtract the first tim=, divide the result by 1,000,000 - equals the number of seconds into the trace file.
              c= CPU seconds - amount of CPU resources required at that point in the execution. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
              e= Elapsed seconds - number of seconds as measured by a high precision clock at that point in the execution. This may be significantly different from CPU seconds. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
              p= Physical blocks read from disk.
              cr= Consistent reads
              cu= Consistent reads in current mode
              mis= Number of shared pool misses at that stage of execution.
              r= Number of rows returned by the call
              og= Optimizer goal - 1=ALL_ROWS, 2=FIRST_ROWS, 3=RULE, 4=CHOOSE
              XCTEND rlbk=0 indicates that the client issued a COMMIT, rd_only=1 indicates that no information changed in the database as a result of the COMMIT
              ela= is the elapsed time in 1/100 of a second on 8.1.7.4 and earlier, and in 1/1,000,000 of a second on versions after 8.1.7.4.
              p1= meaning depends on the wait event
              p2= meaning depends on the wait event
              p3= meaning depends on the wait event

              STAT lines - the row source execution plan:
              id= line identifier
              cnt= number of rows returned or processed
              pid= parent operation identifier - used to determine indentation of the plan
              obj= object id (or possibly data object id - I will have to verify) of the object referenced at that stage of the plan

              Search for additional details.

              Putting the pieces together, it is possible to do the following analysis:
              (Raw Trace)
              =====================
              PARSING IN CURSOR #76 len=712 dep=0 uid=535 oct=3 lid=535 tim=4085083825 hv=2470216549 ad='488f714c'

              select currency_id, sell_rate, buy_rate,  act_material_cost, act_labor_cost, act_burden_cost, act_service_cost,
              tracking_currency,
              s_currency, s_thousand, i_currency, i_neg_curr, i_curr_digits,
              rnd_acct_id, real_gn_acct_id, real_ls_acct_id, unreal_gn_acct_id, unreal_ls_acct_id
              from LABOR_TICKET_CURR t, currency c
              where TRANSACTION_ID = 1257288
              and t.currency_id = c.id
              order by c.id asc                                                       END OF STMT
              PARSE #76:c=15625,e=3997,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4085083815
              WAIT #76: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085086655
              WAIT #76: nam='SQL*Net message from client' ela= 806 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085087815
              BINDS #76:
              EXEC #76:c=0,e=425,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4085088645
              FETCH #76:c=0,e=97,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,tim=4085089011
              WAIT #76: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085089369
              WAIT #76: nam='SQL*Net message from client' ela= 15705 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085105370
              STAT #76 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=1 pr=0 pw=0 time=112 us)'
              STAT #76 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=1 pr=0 pw=0 time=70 us)'
              STAT #76 id=3 cnt=0 pid=2 pos=1 obj=38654 op='TABLE ACCESS BY INDEX ROWID LABOR_TICKET_CURR (cr=1 pr=0 pw=0 time=59 us)'
              STAT #76 id=4 cnt=0 pid=3 pos=1 obj=39858 op='INDEX RANGE SCAN SYS_C0035887 (cr=1 pr=0 pw=0 time=46 us)'
              STAT #76 id=5 cnt=0 pid=2 pos=2 obj=38537 op='TABLE ACCESS BY INDEX ROWID CURRENCY (cr=0 pr=0 pw=0 time=0 us)'
              STAT #76 id=6 cnt=0 pid=5 pos=1 obj=39751 op='INDEX UNIQUE SCAN SYS_C0035752 (cr=0 pr=0 pw=0 time=0 us)'
              =====================
              (End of Raw Trace)

              Analysis:
              Cursor 76   Ver 3   Parse at 0.067149  (0.027692)
              Statement Depth 0 (Application Code)

              select currency_id, sell_rate, buy_rate,  act_material_cost, act_labor_cost, act_burden_cost, act_service_cost,
              tracking_currency,
              s_currency, s_thousand, i_currency, i_neg_curr, i_curr_digits,
              rnd_acct_id, real_gn_acct_id, real_ls_acct_id, unreal_gn_acct_id, unreal_ls_acct_id
              from LABOR_TICKET_CURR t, currency c
              where TRANSACTION_ID = 1257288
              and t.currency_id = c.id
              order by c.id asc

              Cursor 76   Ver 3 Parse at 0.067139 (Parse to Parse  -0.000010),CPU Time 0.015625,Elapsed Time 0.003997,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,**Shared Pool Misses** 1,Goal=ALL_ROWS
              Cursor 76   Ver 3            0.069979  0.000007   SQL*Net message to client
              Cursor 76   Ver 3            0.071139  0.000806   SQL*Net message from client
              Bind Variables:BINDS #76:  0.071139

              Cursor 76   Ver 3 Execute at 0.071969 (Parse to Exec  0.004820),CPU Time 0.000000,Elapsed Time 0.000425,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
              Cursor 76   Ver 3   Fetch at 0.072335 (Parse to Fetch 0.005186),CPU Time 0.000000,Elapsed Time 0.000097,Rows Retrievd 0,Blks from Buff 1,Blks from Disk 0
              Cursor 76   Ver 3   Fetch at 0.072335 (Parse to Fetch 0.005186),CPU Time 0.000000,Elapsed Time 0.000097,Rows Retrievd 0,Blks from Buff 1,Blks from Disk 0
              Cursor 76   Ver 3            0.072693  0.000007   SQL*Net message to client
              Cursor 76   Ver 3            0.088694  0.015705   SQL*Net message from client

                     (Rows 0)   SORT ORDER BY (cr=1 pr=0 pw=0 time=102 us)
                     (Rows 0)    NESTED LOOPS  (cr=1 pr=0 pw=0 time=67 us)
                     (Rows 0)     TABLE ACCESS BY INDEX ROWID LABOR_TICKET_CURR (cr=1 pr=0 pw=0 time=57 us)
                     (Rows 0)      INDEX RANGE SCAN SYS_C0035887 (cr=1 pr=0 pw=0 time=45 us)
                     (Rows 0)     TABLE ACCESS BY INDEX ROWID CURRENCY (cr=0 pr=0 pw=0 time=0 us)
                     (Rows 0)      INDEX UNIQUE SCAN SYS_C0035752 (cr=0 pr=0 pw=0 time=0 us)
              For more information (for example, cr=0 pr=0 pw=0 time=0 us on STAT lines), try the following search:
              http://books.google.com/books?hl=en&q=STAT%3D%20OBJ%20millsap&um=1&ie=UTF-8&sa=N&tab=wp

              Charles Hooper
              IT Manager/Oracle DBA
              K&M Machine-Fabricating, Inc.

              Finished the line describing ela=, added sample of analysis results.
              Message was edited by:
              Charles Hooper
              • 4. Re: some 10046 traceing questions.....
                428027
                Do you know how to use tkprof ?

                Regards
                Helio Dias
                http://heliodias.com