10 Replies Latest reply on Mar 17, 2010 4:19 AM by InquisitiveDBA

    How do  I read/interpret spreport.sql output?

    640410
      Hi Friends,

      I have run the spreport.sql and the following is my output.
      How do I locate my problem? I just have a program that is running for a long time. I believe it hits a lock.

      Is the following output show anything? Thanks a lot in advance.
      STATSPACK report for
      
      Database    DB Id    Instance     Inst Num Startup Time    Release     RAC
      ~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
                3599100408 DEV2                1 17-Jun-09 22:20 10.2.0.3.0  NO
      
      Host  Name:   orafin.philweb.c Num CPUs:    8        Phys Memory (MB):        0
      ~~~~
      
      Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
      ~~~~~~~~    ---------- ------------------ -------- --------- -------------------
      Begin Snap:         26 26-Jun-09 11:00:01      109      50.4
        End Snap:         27 26-Jun-09 12:00:04      102      53.8
         Elapsed:               60.05 (mins)
      
      Cache Sizes                       Begin        End
      ~~~~~~~~~~~                  ---------- ----------
                     Buffer Cache:       388M             Std Block Size:         8K
                 Shared Pool Size:       604M                 Log Buffer:    10,878K
      
      Load Profile                            Per Second       Per Transaction
      ~~~~~~~~~~~~                       ---------------       ---------------
                        Redo size:             32,391.88             26,167.70
                    Logical reads:             18,860.59             15,236.48
                    Block changes:                345.46                279.08
                   Physical reads:                  7.10                  5.74
                  Physical writes:                  1.81                  1.46
                       User calls:                681.15                550.26
                           Parses:                 44.98                 36.34
                      Hard parses:                  0.42                  0.34
                            Sorts:                153.57                124.06
                           Logons:                  0.11                  0.09
                         Executes:                527.44                426.09
                     Transactions:                  1.24
      
        % Blocks changed per Read:    1.83    Recursive Call %:    49.08
       Rollback per transaction %:   39.89       Rows per Sort:     2.75
      
      Instance Efficiency Percentages
      ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                  Buffer Nowait %:   99.77       Redo NoWait %:  100.00
                  Buffer  Hit   %:   99.96    In-memory Sort %:  100.00
                  Library Hit   %:   99.61        Soft Parse %:   99.06
               Execute to Parse %:   91.47         Latch Hit %:   97.91
      Parse CPU to Parse Elapsd %:   66.56     % Non-Parse CPU:   97.62
      
       Shared Pool Statistics        Begin   End
                                     ------  ------
                   Memory Usage %:   62.92   55.55
          % SQL with executions>1:   81.49   86.47
        % Memory for SQL w/exec>1:   71.51   81.25
      
      Top 5 Timed Events                                                    Avg %Total
      ~~~~~~~~~~~~~~~~~~                                                   wait   Call
      Event                                            Waits    Time (s)   (ms)   Time
      ----------------------------------------- ------------ ----------- ------ ------
      CPU time                                                       353          40.1
      log file sync                                  565,769         218      0   24.8
      enq: TX - row lock contention                       34          97   2852   11.0
      log file parallel write                        238,536          95      0   10.8
      db file sequential read                         17,795          54      3    6.1
                -------------------------------------------------------------
       
      Host CPU  (CPUs: 8)
      ~~~~~~~~              Load Average
                            Begin     End      User  System    Idle     WIO     WCPU
                          ------- -------   ------- ------- ------- ------- --------
                             0.15    0.12      1.78    0.64   97.57    0.90
      
      Instance CPU
      ~~~~~~~~~~~~
                    % of total CPU for Instance:    1.90
                    % of busy  CPU for Instance:   78.33
        %DB time waiting for CPU - Resource Mgr:
      
      Memory Statistics                       Begin          End
      ~~~~~~~~~~~~~~~~~                ------------ ------------
                        Host Mem (MB):           .1           .0
                         SGA use (MB):      1,024.0      1,024.0
                         PGA use (MB):        367.1        461.1
          % Host Mem used for SGA+PGA:    1055896.8    4582779.7
                -------------------------------------------------------------
      
      Time Model System Stats  DB/Inst: DEV2/DEV2  Snaps: 26-27
      -> Ordered by % of DB time desc, Statistic name
      
      Statistic                                       Time (s) % of DB time
      ----------------------------------- -------------------- ------------
      DB CPU                                             514.1         72.4
      sql execute elapsed time                           423.0         59.6
      parse time elapsed                                 110.8         15.6
      hard parse elapsed time                            109.3         15.4
      inbound PL/SQL rpc elapsed time                     24.6          3.5
      PL/SQL execution elapsed time                        9.7          1.4
      hard parse (sharing criteria) elaps                  3.8           .5
      PL/SQL compilation elapsed time                      2.9           .4
      connection management call elapsed                   0.7           .1
      repeated bind elapsed time                           0.7           .1
      failed parse elapsed time                            0.1           .0
      Java execution elapsed time                          0.1           .0
      hard parse (bind mismatch) elapsed                   0.1           .0
      sequence load elapsed time                           0.0           .0
      DB time                                            710.3
      background elapsed time                            134.7
      background cpu time                                 34.0
                -------------------------------------------------------------
       
      Wait Events  DB/Inst: DEV2/DEV2  Snaps: 26-27
      -> s - second, cs - centisecond,  ms - millisecond, us - microsecond
      -> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
      -> Only events with Total Wait Time (s) >= .001 are shown
      -> ordered by Total Wait Time desc, Waits desc (idle events last)
      
                                                                          Avg
                                                      %Time Total Wait   wait    Waits
      Event                                    Waits  -outs   Time (s)   (ms)     /txn
      --------------------------------- ------------ ------ ---------- ------ --------
      log file sync                          565,769      0        218      0    126.9
      enq: TX - row lock contention               34     97         97   2852      0.0
      log file parallel write                238,536      0         95      0     53.5
      db file sequential read                 17,795      0         54      3      4.0
      SQL*Net break/reset to client          940,790      0         19      0    210.9
      log file sequential read                 1,000      0         16     16      0.2
      PL/SQL lock timer                            1    100         10   9767      0.0
      inactive session                             6    100          6    978      0.0
      Log archive I/O                          1,092      0          2      2      0.2
      db file scattered read                   1,170      0          2      2      0.3
      buffer busy waits                      159,024      0          2      0     35.7
      control file parallel write              1,348      0          1      1      0.3
      os thread startup                           62      0          1     21      0.0
      SQL*Net more data to client              6,236      0          1      0      1.4
      cursor: pin S wait on X                     73     97          1     11      0.0
      control file sequential read             3,541      0          0      0      0.8
      latch: cache buffers chains             46,233      0          0      0     10.4
      latch: shared pool                          17      0          0     15      0.0
      log file switch completion                   4      0          0     46      0.0
      read by other session                       20      0          0      8      0.0
      latch: enqueue hash chains                  12      0          0      7      0.0
      latch free                                  60      0          0      1      0.0
      wait list latch free                         2      0          0     11      0.0
      LGWR wait for redo copy                  1,763      0          0      0      0.4
      rdbms ipc reply                             40      0          0      0      0.0
      latch: In memory undo latch                 10      0          0      0      0.0
      SQL*Net message from client          2,437,594      0    201,711     83    546.5
      Streams AQ: waiting for messages         2,236     99     17,752   7939      0.5
      pipe get                                 3,471     99     14,059   4051      0.8
      Streams AQ: waiting for time mana           32     53      3,835 ######      0.0
      Streams AQ: qmn coordinator idle         1,615     37      3,515   2177      0.4
      Streams AQ: qmn slave idle wait          1,014      0      3,515   3467      0.2
      jobq slave wait                            609    100      1,783   2927      0.1
      SQL*Net message to client            2,437,588      0          3      0    546.5
      SQL*Net more data from client            2,417      0          0      0      0.5
                -------------------------------------------------------------
       
      Background Wait Events  DB/Inst: DEV2/DEV2  Snaps: 26-27
      -> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
      -> Only events with Total Wait Time (s) >= .001 are shown
      -> ordered by Total Wait Time desc, Waits desc (idle events last)
      
                                                                          Avg
                                                      %Time Total Wait   wait    Waits
      Event                                    Waits  -outs   Time (s)   (ms)     /txn
      --------------------------------- ------------ ------ ---------- ------ --------
      log file parallel write                238,537      0         95      0     53.5
      log file sequential read                 1,000      0         16     16      0.2
      Log archive I/O                          1,092      0          2      2      0.2
      control file parallel write              1,348      0          1      1      0.3
      os thread startup                           62      0          1     21      0.0
      db file scattered read                     997      0          1      1      0.2
      control file sequential read             1,469      0          0      0      0.3
      db file sequential read                    406      0          0      0      0.1
      events in waitclass Other                1,833      0          0      0      0.4
      rdbms ipc message                      221,096      5     38,295    173     49.6
      Streams AQ: waiting for time mana           32     53      3,835 ######      0.0
      smon timer                                 186      1      3,592  19313      0.0
      pmon timer                               1,267     99      3,519   2777      0.3
      Streams AQ: qmn coordinator idle         1,615     37      3,515   2177      0.4
      Streams AQ: qmn slave idle wait          1,014      0      3,515   3467      0.2
                -------------------------------------------------------------
        • 1. Re: How do  I read/interpret spreport.sql output?
          640410
          Wait Event Histogram  DB/Inst: DEV2/DEV2  Snaps: 26-27
          -> Total Waits - units: K is 1000, M is 1000000, G is 1000000000
          -> % of Waits - column heading: <=1s is truly <1024ms, >1s is truly >=1024ms
          -> % of Waits - value: .0 indicates value was <.05%, null is truly 0
          -> Ordered by Event (idle events last)
          
                                     Total ----------------- % of Waits ------------------
          Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s
          -------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
          LGWR wait for redo copy    1763  100.0
          Log archive I/O            1092    9.2  73.7  14.5    .5   1.2    .7    .2
          PL/SQL lock timer             1                                            100.0
          SQL*Net break/reset to cli  940K 100.0    .0    .0    .0    .0          .0
          SQL*Net more data to clien 6236  100.0                                  .0
          buffer busy waits           159K 100.0    .0    .0                      .0
          control file parallel writ 1348   94.7   4.2    .3    .1    .4    .1    .1
          control file sequential re 3541   99.9                            .0    .0
          cursor: pin S               283  100.0
          cursor: pin S wait on X      73    2.7                    97.3
          db file scattered read     1170   86.2    .7   1.5   3.7   5.6   1.6    .7
          db file sequential read      17K  68.7    .7   3.2  10.9  13.4   3.0    .1
          direct path read             83  100.0
          direct path write            80  100.0
          enq: TX - row lock content   34                                        2.9  97.1
          inactive session              6                                      100.0
          latch free                   56   71.4  19.6   8.9
          latch: In memory undo latc    9  100.0
          latch: cache buffers chain   42K  99.9    .0    .0
          latch: enqueue hash chains   11   54.5   9.1                    36.4
          latch: library cache         12  100.0
          latch: messages               1  100.0
          latch: redo allocation       26  100.0
          latch: redo writing           1  100.0
          latch: session allocation     1  100.0
          latch: shared pool           14   21.4  14.3         7.1  14.3  21.4  21.4
          log file parallel write     238K  98.7    .5    .3    .1    .3    .1    .0
          log file sequential read   1000   11.7   4.7    .4   8.3  34.9  28.5  11.5
          log file single write         4  100.0
          log file switch completion    4   50.0                                50.0
          log file sync               565K  97.6   1.1    .6    .2    .4    .1    .0
          os thread startup            62                           16.1  80.6   3.2
          rdbms ipc reply              40   97.5         2.5
          read by other session        20   45.0                    35.0  20.0
          undo segment extension        8  100.0
          wait list latch free          2                          100.0
          SQL*Net message from clien 2437K  99.2    .3    .1    .0    .0    .0    .0    .3
          SQL*Net message to client  2437K 100.0    .0
          SQL*Net more data from cli 2417   99.9          .0    .1
          Streams AQ: qmn coordinato 1615   62.8                                      37.2
          Streams AQ: qmn slave idle 1014   49.7                                      50.3
          Streams AQ: waiting for me 2230                                        1.8  98.2
          Streams AQ: waiting for ti   32   15.6                                 9.4  75.0
          class slave wait              2  100.0
          jobq slave wait             609                                         .2  99.8
          pipe get                   3471                                        8.4  91.6
          pmon timer                 1267    5.1                .1                    94.8
          rdbms ipc message           221K  93.0    .8    .2    .1    .1    .1   2.0   3.7
          smon timer                  186   49.5                .5               4.3  45.7
                    -------------------------------------------------------------
          
          Wait Event Histogram  DB/Inst: DEV2/DEV2  Snaps: 26-27
          -> Total Waits - units: K is 1000, M is 1000000, G is 1000000000
          -> % of Waits - column heading: <=1s is truly <1024ms, >1s is truly >=1024ms
          -> % of Waits - value: .0 indicates value was <.05%, null is truly 0
          -> Ordered by Event (idle events last)
          
                                     Total ----------------- % of Waits ------------------
          Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s
          -------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
          LGWR wait for redo copy    1763  100.0
          Log archive I/O            1092    9.2  73.7  14.5    .5   1.2    .7    .2
          PL/SQL lock timer             1                                            100.0
          SQL*Net break/reset to cli  940K 100.0    .0    .0    .0    .0          .0
          SQL*Net more data to clien 6236  100.0                                  .0
          buffer busy waits           159K 100.0    .0    .0                      .0
          control file parallel writ 1348   94.7   4.2    .3    .1    .4    .1    .1
          control file sequential re 3541   99.9                            .0    .0
          cursor: pin S               283  100.0
          cursor: pin S wait on X      73    2.7                    97.3
          db file scattered read     1170   86.2    .7   1.5   3.7   5.6   1.6    .7
          db file sequential read      17K  68.7    .7   3.2  10.9  13.4   3.0    .1
          direct path read             83  100.0
          direct path write            80  100.0
          enq: TX - row lock content   34                                        2.9  97.1
          inactive session              6                                      100.0
          latch free                   56   71.4  19.6   8.9
          latch: In memory undo latc    9  100.0
          latch: cache buffers chain   42K  99.9    .0    .0
          latch: enqueue hash chains   11   54.5   9.1                    36.4
          latch: library cache         12  100.0
          latch: messages               1  100.0
          latch: redo allocation       26  100.0
          latch: redo writing           1  100.0
          latch: session allocation     1  100.0
          latch: shared pool           14   21.4  14.3         7.1  14.3  21.4  21.4
          log file parallel write     238K  98.7    .5    .3    .1    .3    .1    .0
          log file sequential read   1000   11.7   4.7    .4   8.3  34.9  28.5  11.5
          log file single write         4  100.0
          log file switch completion    4   50.0                                50.0
          log file sync               565K  97.6   1.1    .6    .2    .4    .1    .0
          os thread startup            62                           16.1  80.6   3.2
          rdbms ipc reply              40   97.5         2.5
          read by other session        20   45.0                    35.0  20.0
          undo segment extension        8  100.0
          wait list latch free          2                          100.0
          SQL*Net message from clien 2437K  99.2    .3    .1    .0    .0    .0    .0    .3
          SQL*Net message to client  2437K 100.0    .0
          SQL*Net more data from cli 2417   99.9          .0    .1
          Streams AQ: qmn coordinato 1615   62.8                                      37.2
          Streams AQ: qmn slave idle 1014   49.7                                      50.3
          Streams AQ: waiting for me 2230                                        1.8  98.2
          Streams AQ: waiting for ti   32   15.6                                 9.4  75.0
          class slave wait              2  100.0
          jobq slave wait             609                                         .2  99.8
          pipe get                   3471                                        8.4  91.6
          pmon timer                 1267    5.1                .1                    94.8
          rdbms ipc message           221K  93.0    .8    .2    .1    .1    .1   2.0   3.7
          smon timer                  186   49.5                .5               4.3  45.7
                    -------------------------------------------------------------
          • 2. Re: How do  I read/interpret spreport.sql output?
            662087
            best way is to read docs for statspack , check your email

            have sent you some
            1 person found this helpful
            • 3. Re: How do  I read/interpret spreport.sql output?
              Charles Hooper
              It might have been helpful to see more of the report.

              Hard parses = 0.42 per second, with 109.3 seconds spent hard parsing SQL statements compared to only 423.0 seconds executing SQL statements. This might indicate that there was a brief period in the 60 minute time period where a lot of SQL statements were hard parsed.

              enq: TX - row lock contention: 34 waits for 97 seconds - this wait event has a 3 second timeout, meaning that this could have been a single session waiting 97 seconds for a single row. Possibly indicates a potential primary key violation (if the first session commits), a potential unique key violation (if the first session commits), or a situation where a second session attempts to modify a row that was already modified (but not committed) by the first session.

              SQL*Net break/reset to client: 940,790 waits for 19 seconds. Close to a million error messages were sent back to the clients in the 60 minutes - about 278 per second. The failed parse elapsed time indicates that only 0.1 seconds were lost to failed parses, but I would venture a guess that the actual amount of time lost due to failed parses was a bit higher.

              cursor: pin S wait on X: 73 waits for 97 (edit read the wrong column) timeouts (Metalink bug 7462072 indicates the possibility of a 10ms/ 0.01 second wait). My notes indicate the following on this wait event: A session waits for this event when it is requesting a shared mutex pin and another session is holding an exclusive mutex pin on the same cursor object. On Oracle 10.2.0.1 through 10.2.0.3 and 11.1.0.6, this wait event may be caused by Metalink bug 5485914 (Metalink Note:5485914.8) when activating session tracing or explain plans.

              The time spent on log file sync (the foreground wait on a commit) time of 218 seconds is more than twice the time spent on log file parallel write (the background wait on a commit) of 95 seconds. This might indicate that there was a brief period of heavy CPU utilization.

              You might want to pick one or two sessions that are experiencing slow performance and enable a 10046 trace at level 12 for those sessions. Also, take a look at Metalink note 5485914.8. One of the problems with Statspack/AWR reports is that short duration performance problems may be lost in the averages for the time period. The detail contained in a raw 10046 trace file eliminates the lost detail and focuses on a specific problem.

              Edit:
              Search Metalink for the exact phrase of:
              cursor: pin S wait on X

              There are several recent articles written/updated in 2009 which indicate additional causes of the cursor: pin S wait on X wait event, including a couple additional bugs.

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

              Edited by: Charles Hooper on Jun 26, 2009 7:43 AM
              Added suggestion for the Metalink search, typo.

              Edited by: Charles Hooper on Jun 26, 2009 7:58 AM
              1 person found this helpful
              • 4. Re: How do  I read/interpret spreport.sql output?
                Gerwin Hendriksen
                The above post gives a good description, I think in your case that it will be smart to upload your file to the website from http://oraperf.com/. At this website from Anjo Kolk you are able to upload the file, after creating your own account and get an html formatted output with technical comments.

                Regards, Gerwin
                1 person found this helpful
                • 5. Re: How do  I read/interpret spreport.sql output?
                  640410
                  Thanks to all of you Meakin,Charles,Gerwin :)


                  I am expecting someting like .....I can see from the output...something like....that I have to change something in the init.ora ....that some sql statements are
                  slow and earting lots of CPU...that there are deadlocks....some clear thoughts ....
                  • 6. Re: How do  I read/interpret spreport.sql output?
                    Charles Hooper
                    ytterp2009 wrote:
                    Thanks to all of you Meakin,Charles,Gerwin :)


                    I am expecting someting like .....I can see from the output...something like....that I have to change something in the init.ora ....that some sql statements are
                    slow and earting lots of CPU...that there are deadlocks....some clear thoughts ....
                    From what you posted in this thread, there is insufficient information to state that you really should consider changing, for instance, the pga_aggregate_target so that it is not set to 2,500 GB. You did not include the full statspack report, so we are not able to offer much in the way of suggestions for changes to the initialization parameters, nor offer suggestions of problematic SQL statements. From what you posted it looks like there is a clear problem with parsing (mostly a problem during hard parsing) and an average of 200+ error messages returned to the client computers per second. If this is the same database instance as you have previously described in the forums, you might want to look at prior comments made by myself and others. For instance, in this thread:
                    DB Performance problem

                    What I am suggesting is that you understand the problem before just trying to change things. Switch to a 10046 trace at level 12 - I first suggested this to you 16 days ago.

                    Charles Hooper
                    IT Manager/Oracle DBA
                    K&M Machine-Fabricating, Inc.
                    1 person found this helpful
                    • 7. Re: How do  I read/interpret spreport.sql output?
                      Srini Chavali-Oracle
                      Pl see if MOS Doc 842884.1 (How To Understand AWR Report / Statspack Report) can help

                      HTH
                      Srini
                      1 person found this helpful
                      • 8. Re: How do  I read/interpret spreport.sql output?
                        640410
                        Thanks again Charles, Srini.

                        By the way Charles this is another Oracle server instance. The problem here is that submitted 1 batch job, and usually it just took 1 minute before to complete, but now it is running forever.
                        It seems encountering deadlock and waits.
                        My question is how can a statspack report help here? Which part of the statspack report tells me that my sql statements is encountering deadlocks and waits?
                        • 9. Re: How do  I read/interpret spreport.sql output?
                          Charles Hooper
                          ytterp2009 wrote:
                          Thanks again Charles, Srini.

                          By the way Charles this is another Oracle server instance. The problem here is that submitted 1 batch job, and usually it just took 1 minute before to complete, but now it is running forever.
                          It seems encountering deadlock and waits.
                          My question is how can a statspack report help here? Which part of the statspack report tells me that my sql statements is encountering deadlocks and waits?
                          Statspack has its limits. Let's take a look at what a 10046 trace enabled for a session will do for us. First, we need to know how to enable a 10046 trace, and there are several ways. For example, in a logon trigger when someone starts a program named WSALES:
                          CREATE OR REPLACE TRIGGER LOGON_CAPTURE_TRACE AFTER LOGON ON DATABASE
                          DECLARE
                            SHOULD_EXECUTE INTEGER;
                            TRACEFILE VARCHAR2(150);
                          BEGIN
                            SELECT DECODE(SUBSTR(UPPER(PROGRAM),1,6),'WSALES',1,0) INTO SHOULD_EXECUTE FROM V$SESSION WHERE SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1);
                            IF SHOULD_EXECUTE > 0 THEN
                              TRACEFILE := 'ALTER SESSION SET TRACEFILE_IDENTIFIER ='''||USER||TO_CHAR(SYSDATE,'YYMMDDHH24MI')||'''';
                              EXECUTE IMMEDIATE TRACEFILE;
                              EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE=UNLIMITED';
                              EXECUTE IMMEDIATE 'ALTER SESSION SET TIMED_STATISTICS=TRUE';
                              EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
                            END IF;
                          END;
                          /
                          The above first checks the name of the program/module which is connecting to the database. If the first eight characters are WSALES, then the session's trace file identifier is set to the user ID followed by the current date/time. Next, the maximum trace file size for the session is set to allow unlimited growth. Timed statistics are enabled to provide timing information in the trace files, and then trace event 10046 is enabled at level 12, capturing bind variables submitted by the client computers, as well as the wait events which indicate the source of delays during the execution of SQL statements.

                          When finished with the extended tracing, make certain to remove the trigger when logged into SQL*Plus as the SYS user:
                          DROP TRIGGER LOGON_CAPTURE_TRACE;
                          Other methods:
                          If you have access to the source code, it should be possible to execute a SQL statement like this to enable a 10046 extended trace at level 12 (waits and binds):
                          ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
                          If you do not have access to the source code, you can remotely enable an extended trace for another session with:
                          * Logon trigger that executes the above SQL statement for a specific user/application.
                          * System wide 10046 extended trace (change SESSION in the above SQL statement to SYSTEM).
                          * Session specific 10046 trace remotely enabled using:
                            EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,12,'');
                          -or-
                            EXEC SYS.DBMS_SUPPORT.START_TRACE_IN_SESSION(SID,SERIAL#,WAITS=>TRUE,BINDS=>FALSE);
                          -or-
                            EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>sid,SERIAL_NUM=>serial#,WAITS=>TRUE,BINDS=>TRUE)
                          -or-
                            EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);
                          The SID and SERIAL# may be retrieved from V$SESSION.

                          The SYS.DBMS_SYSTEM.SET_EV method is unsupported, but it works fine on older versions of Oracle where the other methods do not exist.

                          Oracle will create the trace files in the server's udump directory.

                          Before executing any of the above (especially the system wide method), determine how to disable a 10046 trace, depending on how it was started:
                            ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
                          -or-
                            EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,0,'');
                          -or-
                            EXEC SYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION(SID,SERIAL#);
                          -or-
                            EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,FALSE);
                          --

                          A short summary of the contents of an extended Trace file:
                          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)
                          The suggestion is to use the right tool for the job. Just continually increasing the value of the initialization parameters is usually not the right course of action.

                          Charles Hooper
                          IT Manager/Oracle DBA
                          K&M Machine-Fabricating, Inc.
                          • 10. Re: How do  I read/interpret spreport.sql output?
                            InquisitiveDBA
                            hi can us send me the email as well so that i will be able to learn how to interpret spauto.sql reports. thanks a lot!!

                            gsdelcru@yahoo.com.ph