This discussion is archived
1 2 3 4 5 6 8 Previous Next 117 Replies Latest reply: May 5, 2008 10:19 AM by 181444 Go to original post RSS
  • 45. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Charles,
    when I am giving /*LEADING(CS)*/ it's giving error. It shows each and every condition which is defined in the query and displays the message as " Data not found".

    thank you
  • 46. Re: query tuning
    153119 Pro
    Currently Being Moderated
    The + is missing.
    Please compare your post with Charles answer.

    --
    Sybrand Bakker
    Senior Oracle DBA
  • 47. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Here I missed the + sign but in the script I have given..
  • 48. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    hi when I have added this "Leading" it was taking same time. There is no increase in performance. give me any other idea to resolve this.

    Thank you
  • 49. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    hi when I have added this "Leading" it was taking
    same time. There is no increase in performance. give
    me any other idea to resolve this.

    Thank you
    Please, re-read my first post from today. You will find the following comment

    "One of the problems with the CASE_SIZE view is that you have views that depend on views, and those views depend on other views - the predicates from the tables in the query may not be pushing deep enough into the multiple levels of views. You may need to rewrite the CASE_SIZE view to improve performance, and better yet include the logic of the optimized version of the view as an inline view in your SQL statement."


    I then explained how to change the view into an inline view. You need to optimize the SQL statement in the view definition!

    The view is likely the source of the two sorts to disk that you indicated that you received in the response to deepa_t - I mentioned the potential for these sorts to disk in my first reponse to you in this thread. I suggested that you run a 10046 trace at level 8, provided you a link that shows how to enable it, and indicated what to look for in the 10046 trace to identify what exactly in the query is causing the slow performance. In one of my last posts I suggested that you may need the assistance of the DBA for some of this tuning.

    I have offered you advice, and the only thing that you have tried so far is to add a hint. There is a chance that you typed the hint incorrectly - you can check by generating a new explain plan for the hinted version of the query. If the view is still at the bottom of the explain plan, you likely typed the hint incorrectly.

    Sybrand, thanks for the assistance.

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 50. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Hi Charles,
    I have followed as per ur guidance. I got trace file and I got tkporf. I gave the command as follows for TKPROF
       tkprof g_ora_14292.trc output.txt explain= /  insert=store.sql sys=no 
    the output as follows
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       2        0.00          0.00
      direct path write                            5506        0.22          4.39
      direct path read                               42        0.00          0.06
      db file sequential read                     73643        0.32         47.06
      db file scattered read                     123335        0.93        318.67
      latch free                                      3        0.00          0.00
      SQL*Net break/reset to client                   1        0.00          0.00
      SQL*Net message from client                     1      181.03        181.03
    ********************************************************************************
    <select statement>
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.32       0.29          0        593          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch   819704    874.76    1529.15    3879188   12619996          5    12295541
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   819706    875.08    1529.45    3879188   12620589          5    12295541

    Misses in library cache during parse: 1
    Optimizer goal: ALL_ROWS
    Parsing user id: 315  (DEVEL)

    Rows     Row Source Operation
    -------  ---------------------------------------------------
    12295541  HASH JOIN  (cr=12619996 r=3879188 w=2408 time=1503903336 us)
    212315   VIEW  (cr=7553336 r=2408 w=2408 time=82297538 us)
    <as per my prevous post >

    Rows     Execution Plan
    -------  ---------------------------------------------------
    <as per  my previous post>

    Elapsed times include waiting on following events:

      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                  819704        0.00          0.45
      direct path write                               4        0.00          0.00
      direct path read                               51        0.00          0.07
      db file sequential read                     94884        0.41         60.91
      db file scattered read                     222696     2302.70       4675.10
      SQL*Net message from client                819704     3672.87       6299.98
      latch free                                      2        0.00          0.00



    ********************************************************************************

    OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse       30      0.66       3.81          0       1209          0           0
    Execute 359369     80.45     157.24       2373     685165    1421669      287451
    Fetch   1179026   1243.52    2250.98    5638169   23437045         14    12654850
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total   1538425   1324.63    2412.03    5640542   24123419    1421683    12942301

    Misses in library cache during parse: 5

    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                 1179098        0.00          0.77
      SQL*Net message from client               1179097     3672.87       8511.63
      library cache pin                               2        3.00          3.00
      SQL*Net break/reset to client                   5        0.01          0.01
      log file sync                                  37        1.00          4.11
      db file sequential read                    170903        0.41        150.29
      latch free                                    314        0.29          2.38
      direct path write                            5514        0.22          4.41
      direct path read                              107        0.14          0.43
      SQL*Net more data to client                  1350        0.02          0.24
      buffer busy waits                             212        0.49          4.02
      SQL*Net more data from client                3715        0.04          0.23
      log buffer space                              203        1.00         26.34
      enqueue                                        24        0.31          0.90
      buffer deadlock                                 3        0.00          0.00
      log file switch completion                      4        0.11          0.18
      db file scattered read                     346031     2302.70       4993.78


    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse      669      0.00       0.01          0          0          0           0
    Execute    676      0.02       0.06          0          4          1           1
    Fetch      947      0.01       0.13          3       1837          0         874
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total     2292      0.03       0.22          3       1841          1         875

    Misses in library cache during parse: 5

    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                         3        0.01          0.03

       33  user  SQL statements in session.
      668  internal SQL statements in session.
      701  SQL statements in session.
       25  statements EXPLAINed in this session.
    ********************************************************************************
    Trace file: g_ora_14292.trc
    Trace file compatibility: 9.00.01
    Sort options: default

           2  sessions in tracefile.
          63  user  SQL statements in trace file.
         739  internal SQL statements in trace file.
         701  SQL statements in trace file.
          41  unique SQL statements in trace file.
          25  SQL statements EXPLAINed using schema:
               DEVEL.prof$plan_table
                 Default table was used.
                 Table was created.
                 Table was dropped.
    6446643  lines in trace file.
    So please guide me for the next step.

    Thank you
  • 51. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    Thanks for posting the output of TKPROF.

    However, there are a couple problems:
    * Is this the TKPROF output for your query WITH the hint? Or is it the original query WITHOUT the hint?
    * You have removed certain portions of the TKPROF output, replacing those with <select statement> and <as per my prevous post>. It is fine that you do not post the SQL statement, but one of the goals of generating a 10046 trace was to view the "Row Source Operation" section (from the STAT lines in the 10046 trace), and you have deleted those lines.
    * I asked for the STAT lines directly from the 10046 trace file - I normally use the 10046 trace directly and not TKPROF.

    Let's see if we can identify anything helpful from what is posted.
    * 875.08 seconds (14.58 minutes) of CPU time with an elapsed time of 1,529.45 seconds (25.49 minutes).
    * The two sorts to disk seem to have had very little impact on the total execution time (about 4.5 seconds).
    * Single block reads (likely index reads) contributed about 47 seconds.
    * Multiblock reads (likely full table scans) contributed about 319 seconds.
    * Client think time (Oracle waiting for another request from the client and network latency) is 181 seconds - it may be important to know if these "SQL*Net message from client" waits occur between fetch calls.
    * There were 819,704 fetch calls to retrieve the 12,295,541 rows from the query, indicating that you are fetching roughly 15 rows at a time.
    * There were at least 819,706 round trips between the server and the client, and if each round trip required 0.0002 seconds due to network latency, you lost 163.94 seconds to round trip communication between the client and server. (Odd that this is close to the statistic for SQL*Net message from client).
    * Through the last hash join, there were 12,619,996 consistent reads, of those 7,553,336 came directly from the view.
    * Excessive logical IO, excessive parsing, and excessive/inefficient recursive calls may contribute to CPU time. Parse time was apparently not a problem, there were 739 recursive calls (which may or may not have been a significant contributor), and there were at least 12,619,996 consistent reads. Decreasing the number of consistent reads would be a good starting point, and to do that you need to optimize the view.

    Sorry, not much to offer you yet.

    Please post the STAT lines directly from the 10046 trace file. You can find them by searching through the trace file for your SQL statement. Above the SQL statement you will find "PARSING IN CURSOR # " and a number (for instance 2). Search down the trace file for the first line that reads "STAT #" and the same number you just found (for instance 2). Copy all lines starting at that point down to the last "STAT #" with the same number you found for the SQL statement.

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 52. Re: query tuning
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    Charles,

    I think you need to be analyzing the wait stats BELOW the summary work stats, and after the curtailed rowsource operation listing.

    This shows 800,000 SQL*Net roundtrips, which is consistent with the fetch calls, and 2.2M db file scattered reads, which is roughly consistent with the 38M disk reads if you assume a value of 16 for the db_file_multiblock_read_count.

    There is an interesting anomaly with the max wait for a scattered read taking 2,400 seconds - and a strange inconsistency between the wait stats and the total cpu and elapsed time; but apart from that, the general indication is that it takes a lot of time (CPU and elapsed) to do lots of tablescans, and a lot of time to shift 12M rows across a network.

    I agree fully with your comment about the importance of the full listing from the rowsource operation - that might give us some idea of where most of the work was done.

    Regards
    Jonathan Lewis
    http://jonathanlewis.wordpress.com
    http://www.jlcomp.demon.co.uk
  • 53. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    Jonathan,

    Thanks for the assistance with the analysis. I need to spend a little more time looking through the summarized output produced by TKPROF, and your suggestions are very helpful.

    I noticed the large max wait time for db file scattered read of 2,303 seconds, but was not certain what generated that number. Is there a possibility of an odd calculation problem related to delayed block cleanout, possibly when block reads are queuing behind redo writes?

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 54. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Charles,
    please find the following
    Trace file: g_ora_14292.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
    ********************************************************************************

    alter SESSION SET EVENTS '10046 trace name context forever, level 12'


    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        0      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        1      0.00       0.00          0          0          0           0

    Misses in library cache during parse: 0
    Optimizer goal: CHOOSE
    Parsing user id: 315  (RMSBATQ)

    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************

    alter SESSION SET TIMED_STATISTICS = TRUE


    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.02          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.00       0.02          0          0          0           0
    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: 315  (DEVEL)

    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************

    alter SESSION SET NLS_NUMERIC_CHARACTERS = '.,'


    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.00       0.00          0          0          0           0

    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: 315  (DEVEL)

    alter SESSION SET NLS_DATE_FORMAT = 'YYYYMMDD'


    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.01       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.01       0.00          0          0          0           0

    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: 315  (DEVEL)

    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
      library cache pin                               2        3.00          3.00
    ********************************************************************************

    select  /*+  INDEX(rc pk_restart_control)  +*/ process_flag ,driver_name ,
      num_threads ,commit_max_ctr
    from
    restart_control rc where program_name=LOWER(:b0)
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       3.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        1      0.00       0.00          0          2          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       3.00          0          2          0           1

    Misses in library cache during parse: 0
    Optimizer goal: CHOOSE
    Parsing user id: 315  (DEVEL)

    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  TABLE ACCESS BY INDEX ROWID OBJ#(28470) (cr=2 r=0 w=0 time=14 us)
          1   INDEX UNIQUE SCAN OBJ#(28471) (cr=1 r=0 w=0 time=8 us)(object id 28471)


    Rows     Execution Plan
    -------  ---------------------------------------------------
          0  SELECT STATEMENT   GOAL: CHOOSE
          1   TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
                  'RESTART_CONTROL'
          1    INDEX   GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_RESTART_CONTROL'
                   (UNIQUE)


    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************

    select sid
    from
    v$session where process=to_char(:b0)


    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0


    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       3.00          0          0          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        1      0.00       0.00          0          2          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    ----
    ---
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  FIXED TABLE FULL X$KSUSE (cr=0 r=0 w=0 time=71 us)

    error during execute of EXPLAIN PLAN statement
    ORA-01039: insufficient privileges on underlying objects of the view

    parse error offset: 91

    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
    ********************************************************************************
    if u need more information pls let me know.
  • 55. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    I appreciate the effort, but it looks like you may have sent a 10046 trace file through TKPROF that did not include your query.

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 56. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    charles,
    Here I am posting Query as well as explain plan
    SELECT  IM.LOCATION, 
            IM.ITEM, 
            CS.CASE_SIZE, 
            IM.ONDATE, 
            IM.OFFDATE, 
            MAS.STATUS
    FROM  CASE_SIZE CS,
          ITEM IM,
          MASTER MAS,
          WAREHOUSE WH
    WHERE  MAS.PACK_IND = 'N' 
    AND    MAS.ITEM_LEVEL = MAS.TRNS_LEVEL 
    AND    MAS.STATUS = 'A' 
    AND    MAS.FOREIND = 'Y' 
    AND    MAS.ITEM = IM.ITEM 
    AND    IM.LOCATION_TYPE = 'S' 
    AND    MAS.ITEM = CS.ITEM 
    AND    CS.SUPPLY_INDICATOR = 'Y' 
    AND    CS.COUNTRY_INDICATOR = 'Y' 
    AND    IM.LOCATION =WH.WAREHOSE_NO  
    AND    NVL(WH.CLOSE_DATE,'04-APR-9999')>=TO_DATE
         (&VERSDATE}, 'YYYYMMDD')
    Execution Plan
    ----------------------------------------------------------  
    0      SELECT STATEMENT Optimizer=CHOOSE (Cost=15085 Card=1139512 Bytes=134462416)  
    1    0   HASH JOIN (Cost=15085 Card=1139512
                        bytes=134462416)  
    2    1   HASH JOIN (Cost=580 Card=30772 Bytes=1569372)   3    2   TABLE ACCESS (FULL) OF 'MASTER' (Cost=63
    Card=1306 Bytes=18284)  
    4    2       TABLE ACCESS (BY GLOBAL INDEX ROWID) OF 'ITEM' (Cost=2 Card=105311 Bytes=3369952)  
    5    4    NESTED LOOPS (Cost=86 Card=4296685 Bytes=158977345)  
    6    5    TABLE ACCESS (FULL) OF 'WAREHOUSE' (Cost=4 Card=41 Bytes=205)  
    7    5    INDEX (RANGE SCAN) OF 'PK_LOCATION' (UNIQUE) (Cost=1 Card=210622)  
    8    1     VIEW (Cost=14271 Card=48399 Bytes=3242733)   9    8       SORT (UNIQUE) (Cost=14271 Card=48399 Bytes=6098274) 
    10    9      HASH JOIN (Cost=992 Card=187614 Bytes=23639364) 
    11   10      HASH JOIN (Cost=186 Card=7449 Bytes=581022) 
    12   11      TABLE ACCESS (FULL) OF 'MASTER' (Cost=63 Card=10451 Bytes=156765) 
    13   11             HASH JOIN (Cost=105 Card=12489 Bytes=786807) 
    14   13     MERGE JOIN (CARTESIAN) (Cost=40 Card=12489 Bytes=549516) 
    15   14     MERGE JOIN (CARTESIAN) (Cost=6 Card=1 Bytes=13) 
    16   15     TABLE ACCESS (FULL) OF 'SYSTEM' (Cost=3 Card=1 Bytes=3) 
    17   15     BUFFER (SORT) (Cost=3 Card=1 Bytes=10) 
    18   17     TABLE ACCESS (FULL) OF 'SYSTEM' (Cost=3 Card=1 Bytes=10) 
    19   14     BUFFER (SORT) (Cost=37 Card=12489 Bytes=387159) 
    20   19                   TABLE ACCESS (FULL) OF 'ITEM_SUPPLIER_COUNTRY' (Cost=34 Card=12489 Bytes=387159) 
    21   13    TABLE ACCESS (FULL) OF 'SUPPLIER' (Cost=28 Card=24989 Bytes=474791) 
    22   10       VIEW (Cost=536 Card=172449 Bytes=8277552)  23   22             UNION-ALL 
    24   23               INDEX (FAST FULL SCAN) OF 'PK_ITEM_SUPPLIER_COUNTRY' (UNIQUE) (Cost=11 Card=24978 Bytes=324714) 
    25   23               TABLE ACCESS (FULL) OF 'ITEM_SUPPLIER_COUNTRY' (Cost=34 Card=24978 Bytes=399648) 
    26   23               TABLE ACCESS (FULL) OF 'ITEM_SUPPLIER_COUNTRY' (Cost=34 Card=24978 Bytes=374670) 
    27   23               TABLE ACCESS (FULL) OF 'ITEM_SUPPLIER_COUNTRY' (Cost=34 Card=24978 Bytes=499560) 
    28   23               VIEW (Cost=141 Card=24179 Bytes=1039697) 
    29   28                 SORT (UNIQUE) (Cost=141 Card=24179 Bytes=507759) 
    30   29                   INDEX (FAST FULL SCAN) OF 'PK_CASE_UPDATES' (UNIQUE) (Cost=14 Card=24179 Bytes=507759) 
    31   23               VIEW (Cost=141 Card=24179 Bytes=1039697) 
    32   31                 SORT (UNIQUE) (Cost=141 Card=24179 Bytes=507759) 
    33   32                   INDEX (FAST FULL SCAN) OF 'PK_CASE_UPDATES' (UNIQUE) (Cost=14 Card=24179 Bytes=507759) 
    34   23               VIEW (Cost=141 Card=24179 Bytes=1039697) 
    35   34                 SORT (UNIQUE) (Cost=141 Card=24179 Bytes=507759) 
    36   35                   INDEX (FAST FULL SCAN) OF 'PK_CASE_UPDATES' (UNIQUE) (Cost=14 Card=24179 Bytes=507759)
    Thank u


    Message was edited by:
    User71408
  • 57. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    Jonathan,

    I now fully understand your point - there were wait events from multiple queries in the TKPROF output, and I did not recognize that the divider between separate SQL statements was a series of ******

    It has been about two years since I last worked through a TKPROF output, and without seeing the SQL statement, I missed the ****** divider. I either look directly at the 10046 traces, run a DBMS_XPLAN showing actual statistics, or pass the 10046 traces through a trace file parser that I created.

    As a test, I set up a model of views based on views, and passed the 10046 trace through the various analysis methods.

    The SQL statement:
    SELECT
      T1.C1,
      T1.C2,
      T1.C3
    FROM
      T1,
      VIEW_VIEW_T2 T2
    WHERE
      T1.C2 BETWEEN 250000 AND 270000
      AND T1.C1=T2.C1;
    The DBMS_XPLAN:
    -----------------------------------------------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation                       | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem | Used-Tmp|
    -----------------------------------------------------------------------------------------------------------------------------------------------------------------
    |*  1 |  HASH JOIN                      |              |      1 |  30027 |  20001 |00:00:18.75 |   25279 |  27202 |   1992 |  1882K|  1004K| 2590K (0)|         |
    |*  2 |   HASH JOIN                     |              |      1 |  20002 |  20001 |00:00:03.30 |    1986 |   1928 |      0 |  1521K|  1059K| 1542K (0)|         |
    |   3 |    TABLE ACCESS BY INDEX ROWID  | T1           |      1 |  20002 |  20001 |00:00:00.41 |     880 |    835 |      0 |       |       |          |         |
    |*  4 |     INDEX RANGE SCAN            | T1_C2        |      1 |  20002 |  20001 |00:00:00.02 |      45 |      0 |      0 |       |       |          |         |
    |   5 |    INDEX FAST FULL SCAN         | SYS_C0013858 |      1 |    300K|    300K|00:00:01.24 |    1106 |   1093 |      0 |       |       |          |         |
    |   6 |   VIEW                          | VIEW_VIEW_T3 |      1 |    450K|    450K|00:00:13.16 |   23293 |  25274 |   1992 |       |       |          |         |
    |   7 |    SORT UNIQUE                  |              |      1 |    450K|    450K|00:00:11.81 |   23293 |  25274 |   1992 |    16M|  1559K|   11M (0)|   16384 |
    |   8 |     UNION-ALL                   |              |      1 |        |    460K|00:00:09.99 |   23291 |  23282 |      0 |       |       |          |         |
    |   9 |      TABLE ACCESS BY INDEX ROWID| T3           |      1 |  90354 |    100K|00:00:05.13 |    4533 |   4531 |      0 |       |       |          |         |
    |* 10 |       INDEX RANGE SCAN          | SYS_C0013859 |      1 |  90354 |    100K|00:00:00.41 |     366 |    364 |      0 |       |       |          |         |
    |* 11 |      TABLE ACCESS FULL          | T3           |      1 |    360K|    360K|00:00:02.44 |   18755 |  18751 |      0 |       |       |          |         |
    |  12 |      TABLE ACCESS BY INDEX ROWID| T3           |      1 |      1 |      0 |00:00:00.01 |       3 |      0 |      0 |       |       |          |         |
    |* 13 |       INDEX RANGE SCAN          | SYS_C0013859 |      1 |      1 |      0 |00:00:00.01 |       3 |      0 |      0 |       |       |          |         |
    -----------------------------------------------------------------------------------------------------------------------------------------------------------------

    Predicate Information (identified by operation id):
    ---------------------------------------------------
       1 - access("C1"="T3"."C1")
       2 - access("T1"."C1"="C1")
       4 - access("T1"."C2">=250000 AND "T1"."C2"<=270000)
      10 - access("C1">='K 0000000000250000' AND "C1"<='K 0000000000350000')
      11 - filter(("C1">='K 0000000000340000' AND "C1"<='K 0000000000750000'))
      13 - access("C1">='K 0000000000740000' AND "C1"<='K 0000000000850000')
    The TKPROF output:
    ********************************************************************************

    SELECT
      T1.C1,
      T1.C2,
      T1.C3
    FROM
      T1,
      VIEW_VIEW_T2 T2
    WHERE
      T1.C2 BETWEEN 250000 AND 270000
      AND T1.C1=T2.C1

    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.02          0         12          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch      201     11.31      18.79      27202      25277          2       20001
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      203     11.31      18.82      27202      25289          2       20001

    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 63 

    Rows     Row Source Operation
    -------  ---------------------------------------------------
      20001  HASH JOIN  (cr=25277 pr=27202 pw=27202 time=229274 us cost=14550 size=1801620 card=30027)
      20001   HASH JOIN  (cr=1986 pr=1928 pw=1928 time=151417 us cost=1180 size=960096 card=20002)
      20001    TABLE ACCESS BY INDEX ROWID T1 (cr=880 pr=835 pw=835 time=410406 us cost=879 size=580058 card=20002)
      20001     INDEX RANGE SCAN T1_C2 (cr=45 pr=0 pw=0 time=34076 us cost=44 size=0 card=20002)(object id 72115)
    300000    INDEX FAST FULL SCAN SYS_C0013858 (cr=1106 pr=1093 pw=1093 time=1444908 us cost=299 size=5700000 card=300000)(object id 72117)
    450001   VIEW  VIEW_VIEW_T3 (cr=23291 pr=25274 pw=25274 time=2050451 us cost=12795 size=5404284 card=450357)
    450001    SORT UNIQUE (cr=23291 pr=25274 pw=25274 time=808769 us cost=12795 size=13060353 card=450357)
    460002     UNION-ALL  (cr=23291 pr=23282 pw=23282 time=9905378 us)
    100001      TABLE ACCESS BY INDEX ROWID T3 (cr=4533 pr=4531 pw=4531 time=4814582 us cost=4099 size=2620266 card=90354)
    100001       INDEX RANGE SCAN SYS_C0013859 (cr=366 pr=364 pw=364 time=428469 us cost=332 size=0 card=90354)(object id 72119)
    360001      TABLE ACCESS FULL T3 (cr=18755 pr=18751 pw=18751 time=1492456 us cost=5093 size=10440058 card=360002)
          0      TABLE ACCESS BY INDEX ROWID T3 (cr=3 pr=0 pw=0 time=0 us cost=4 size=29 card=1)
          0       INDEX RANGE SCAN SYS_C0013859 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=1)(object id 72119)

    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                     201        0.00          0.00
      db file sequential read                      3700        0.49          3.35
      db file scattered read                        864        0.68          1.61
      db file parallel read                           2        0.04          0.04
      reliable message                                1        0.00          0.00
      enq: KO - fast object checkpoint                1        0.00          0.00
      direct path read                              264        0.08          1.67
      direct path write temp                         47        0.06          0.26
      direct path read temp                          18        0.02          0.08
      SQL*Net message from client                   201        0.13          0.26
    ********************************************************************************
    Partial output from my trace file parser:
    Similar SQL Statements in Group: 1  
      CPU S 90.51%  CLOCK S 68.84%
    First Reference: Cursor 4   Ver 1   Parse at 0.029081
    |PARSEs       1|CPU S    0.000000|CLOCK S    0.029390|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)        12|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
    |EXECs        1|CPU S    0.000000|CLOCK S    0.000090|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
    |FETCHs     201|CPU S   11.310072|CLOCK S   18.796861|ROWs    20001|PHY RD BLKs     27202|CON RD BLKs (Mem)     25277|CUR RD BLKs (Mem)         2|SHARED POOL MISs      0|

    Statement Depth 0 (Application Code)
    SELECT
      T1.C1,
      T1.C2,
      T1.C3
    FROM
      T1,
      VIEW_VIEW_T2 T2
    WHERE
      T1.C2 BETWEEN 250000 AND 270000
      AND T1.C1=T2.C1
    Parse at 0.029076 (Parse to Parse  -0.000005),CPU Time 0.000000,Elapsed Time 0.029390,Rows Affected 0,Blks from Buff 12,Blks from Disk 0,**Shared Pool Misses** 1,Goal=ALL_ROWS
    Execute at 0.029460 (Parse to Exec  0.000379),CPU Time 0.000000,Elapsed Time 0.000090,Rows Affected 0,Blks from Buff 0,Blks from Disk 0
      Fetch at 14.789635 (Parse to Fetch 14.760554),CPU Time 7.285247,Elapsed Time 14.760084,Rows Retrievd 100,Blks from Buff 25277+CU(2),Blks from Disk 25224
      Fetch at 14.817871 (Parse to Fetch 14.788790),CPU Time 0.000000,Elapsed Time 0.001257,Rows Retrievd 100,Blks from Buff 0,Blks from Disk 0
      Fetch at 14.819727 (Parse to Fetch 14.790646),CPU Time 0.000000,Elapsed Time 0.001227,Rows Retrievd 100,Blks from Buff 0,Blks from Disk 0
      Fetch at 14.821564 (Parse to Fetch 14.792483),CPU Time 0.000000,Elapsed Time 0.001226,Rows Retrievd 100,Blks from Buff 0,Blks from Disk 0
      Fetch at 14.823479 (Parse to Fetch 14.794398),CPU Time 0.015600,Elapsed Time 0.001311,Rows Retrievd 100,Blks from Buff 0,Blks from Disk 0
      Fetch at 14.825352 (Parse to Fetch 14.796271),CPU Time 0.000000,Elapsed Time 0.001262,Rows Retrievd 100,Blks from Buff 0,Blks from Disk 0
      Fetch at 14.827191 (Parse to Fetch 14.798110),CPU Time 0.000000,Elapsed Time 0.001218,Rows Retrievd 100,Blks from Buff 0,Blks from Disk 0
    ...
       (Rows 20001)   HASH JOIN  (cr=25277 pr=27202 pw=27202 time=229274 us cost=14550 size=1801620 card=30027)
       (Rows 20001)    HASH JOIN  (cr=1986 pr=1928 pw=1928 time=151417 us cost=1180 size=960096 card=20002)
       (Rows 20001)     TABLE ACCESS BY INDEX ROWID T1 (cr=880 pr=835 pw=835 time=410406 us cost=879 size=580058 card=20002)
       (Rows 20001)      INDEX RANGE SCAN T1_C2 (cr=45 pr=0 pw=0 time=34076 us cost=44 size=0 card=20002)
      (Rows 300000)     INDEX FAST FULL SCAN SYS_C0013858 (cr=1106 pr=1093 pw=1093 time=1444908 us cost=299 size=5700000 card=300000)
      (Rows 450001)    VIEW  VIEW_VIEW_T3 (cr=23291 pr=25274 pw=25274 time=2050451 us cost=12795 size=5404284 card=450357)
      (Rows 450001)     SORT UNIQUE (cr=23291 pr=25274 pw=25274 time=808769 us cost=12795 size=13060353 card=450357)
      (Rows 460002)      UNION-ALL  (cr=23291 pr=23282 pw=23282 time=9905378 us)
      (Rows 100001)       TABLE ACCESS BY INDEX ROWID T3 (cr=4533 pr=4531 pw=4531 time=4814582 us cost=4099 size=2620266 card=90354)
      (Rows 100001)        INDEX RANGE SCAN SYS_C0013859 (cr=366 pr=364 pw=364 time=428469 us cost=332 size=0 card=90354)
      (Rows 360001)       TABLE ACCESS FULL T3 (cr=18755 pr=18751 pw=18751 time=1492456 us cost=5093 size=10440058 card=360002)
           (Rows 0)       TABLE ACCESS BY INDEX ROWID T3 (cr=3 pr=0 pw=0 time=0 us cost=4 size=29 card=1)
           (Rows 0)        INDEX RANGE SCAN SYS_C0013859 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=1)

      0     SQL*Net message to client        On Client/Network
    963.396 SQL*Net message from client      On Client/Network
      3.365 db file sequential read          On DB Server
      1.620 db file scattered read           On DB Server
      0.045 db file parallel read            On DB Server
      0     reliable message                 On DB Server
      0     enq: KO - fast object checkpoint On DB Server
      1.678 direct path read              On DB Server
      0.268 direct path write temp              On DB Server
      0.086 direct path read temp              On DB Server
    Direct from the 10046 trace file:
    =====================
    PARSING IN CURSOR #4 len=128 dep=0 uid=63 oct=3 lid=63 tim=858398105916 hv=3962219977 ad='1ca126a0' sqlid='296c5u3q2pbf9'
    SELECT
      T1.C1,
      T1.C2,
      T1.C3
    FROM
      T1,
      VIEW_VIEW_T2 T2
    WHERE
      T1.C2 BETWEEN 250000 AND 270000
      AND T1.C1=T2.C1
    END OF STMT
    PARSE #4:c=0,e=29390,p=0,cr=12,cu=0,mis=1,r=0,dep=0,og=1,tim=858398105911
    BINDS #4:
    EXEC #4:c=0,e=90,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=858398106295
    WAIT #4: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=858398106340
    WAIT #4: nam='db file sequential read' ela= 8188 file#=1 block#=129193 blocks=1 obj#=72111 tim=858398116477
    WAIT #4: nam='db file sequential read' ela= 204 file#=1 block#=129194 blocks=1 obj#=72111 tim=858398116893
    WAIT #4: nam='db file sequential read' ela= 401 file#=1 block#=129195 blocks=1 obj#=72111 tim=858398118243
    WAIT #4: nam='db file sequential read' ela= 200 file#=1 block#=129196 blocks=1 obj#=72111 tim=858398118815
    WAIT #4: nam='db file sequential read' ela= 198 file#=1 block#=129197 blocks=1 obj#=72111 tim=858398119342
    WAIT #4: nam='db file sequential read' ela= 198 file#=1 block#=129198 blocks=1 obj#=72111 tim=858398119856
    ...
    WAIT #4: nam='direct path read' ela= 46858 file number=1 first dba=199940 block cnt=69 obj#=72118 tim=858412822466
    WAIT #4: nam='direct path write temp' ela= 5633 file number=201 first dba=72393 block cnt=8 obj#=72118 tim=858412844419
    WAIT #4: nam='direct path read temp' ela= 19242 file number=201 first dba=70409 block cnt=7 obj#=72118 tim=858412863979
    FETCH #4:c=7285247,e=14760084,p=25224,cr=25277,cu=2,mis=0,r=100,dep=0,og=1,tim=858412866470
    WAIT #4: nam='SQL*Net message from client' ela= 26788 driver id=1413697536 #bytes=1 p3=0 obj#=72118 tim=858412893368
    WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=72118 tim=858412893476
    FETCH #4:c=0,e=1257,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,tim=858412894706
    ...
    STAT #4 id=1 cnt=20001 pid=0 pos=1 obj=0 op='HASH JOIN  (cr=25277 pr=27202 pw=27202 time=229274 us cost=14550 size=1801620 card=30027)'
    STAT #4 id=2 cnt=20001 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=1986 pr=1928 pw=1928 time=151417 us cost=1180 size=960096 card=20002)'
    STAT #4 id=3 cnt=20001 pid=2 pos=1 obj=72111 op='TABLE ACCESS BY INDEX ROWID T1 (cr=880 pr=835 pw=835 time=410406 us cost=879 size=580058 card=20002)'
    STAT #4 id=4 cnt=20001 pid=3 pos=1 obj=72115 op='INDEX RANGE SCAN T1_C2 (cr=45 pr=0 pw=0 time=34076 us cost=44 size=0 card=20002)'
    STAT #4 id=5 cnt=300000 pid=2 pos=2 obj=72117 op='INDEX FAST FULL SCAN SYS_C0013858 (cr=1106 pr=1093 pw=1093 time=1444908 us cost=299 size=5700000 card=300000)'
    STAT #4 id=6 cnt=450001 pid=1 pos=2 obj=72124 op='VIEW  VIEW_VIEW_T3 (cr=23291 pr=25274 pw=25274 time=2050451 us cost=12795 size=5404284 card=450357)'
    STAT #4 id=7 cnt=450001 pid=6 pos=1 obj=0 op='SORT UNIQUE (cr=23291 pr=25274 pw=25274 time=808769 us cost=12795 size=13060353 card=450357)'
    STAT #4 id=8 cnt=460002 pid=7 pos=1 obj=0 op='UNION-ALL  (cr=23291 pr=23282 pw=23282 time=9905378 us)'
    STAT #4 id=9 cnt=100001 pid=8 pos=1 obj=72118 op='TABLE ACCESS BY INDEX ROWID T3 (cr=4533 pr=4531 pw=4531 time=4814582 us cost=4099 size=2620266 card=90354)'
    STAT #4 id=10 cnt=100001 pid=9 pos=1 obj=72119 op='INDEX RANGE SCAN SYS_C0013859 (cr=366 pr=364 pw=364 time=428469 us cost=332 size=0 card=90354)'
    STAT #4 id=11 cnt=360001 pid=8 pos=2 obj=72118 op='TABLE ACCESS FULL T3 (cr=18755 pr=18751 pw=18751 time=1492456 us cost=5093 size=10440058 card=360002)'
    STAT #4 id=12 cnt=0 pid=8 pos=3 obj=72118 op='TABLE ACCESS BY INDEX ROWID T3 (cr=3 pr=0 pw=0 time=0 us cost=4 size=29 card=1)'
    STAT #4 id=13 cnt=0 pid=12 pos=1 obj=72119 op='INDEX RANGE SCAN SYS_C0013859 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=1)'
    WAIT #4: nam='SQL*Net message from client' ela= 130621 driver id=1413697536 #bytes=1 p3=0 obj#=72118 tim=858417183253
    =====================
    Setup for the test case:
    CREATE TABLE T1 (
      C1 VARCHAR2(20),
      C2 NUMBER(10),
      C3 NUMBER(10),
      C4 VARCHAR2(255),
      PRIMARY KEY(C1));

    INSERT INTO
      T1
    SELECT
      'K'||TO_CHAR(ROWNUM,'0000000000000009'),
      ROWNUM,
      ROWNUM*100,
      DBMS_RANDOM.STRING('A',255)
    FROM
      DUAL
    CONNECT BY
      LEVEL<=1000000;

    ALTER TABLE T1 MODIFY (C2 NOT NULL);

    CREATE UNIQUE INDEX T1_C2 ON T1(C2);

    CREATE TABLE T2 (
      C1 VARCHAR2(20),
      C2 NUMBER(10),
      C3 NUMBER(10),
      C4 VARCHAR2(255),
      PRIMARY KEY(C1));

    INSERT INTO
      T2
    SELECT
      C1,
      C2,
      C3,
      C4
    FROM
      T1
    WHERE
      C2 BETWEEN 1 AND 300000;

    CREATE TABLE T3 (
      C1 VARCHAR2(20),
      C2 NUMBER(10),
      C3 NUMBER(10),
      C4 VARCHAR2(255),
      PRIMARY KEY(C1));

    INSERT INTO
      T3
    SELECT
      C1,
      C2,
      C3,
      C4
    FROM
      T1
    WHERE
      C2 BETWEEN 250000 AND 700000;

    COMMIT;

    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE);
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE);
    EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE);

    CREATE VIEW VIEW_T2 AS
    SELECT
      C1,
      C2,
      C3
    FROM
      T2;

    CREATE VIEW VIEW_VIEW_T2 AS
    SELECT
      T2.C1,
      T2.C2,
      T2.C3
    FROM
      VIEW_T2 T2,
      VIEW_VIEW_T3 T3
    WHERE
      T2.C1=T3.C1;

    CREATE VIEW VIEW_T3_1 AS
    SELECT
      C1,
      C2,
      C3
    FROM
      T3
    WHERE
      C1 BETWEEN 'K 0000000000250000' AND 'K 0000000000350000';

    CREATE VIEW VIEW_T3_2 AS
    SELECT
      C1,
      C2,
      C3
    FROM
      T3
    WHERE
      C1 BETWEEN 'K 0000000000340000' AND 'K 0000000000750000';

    CREATE VIEW VIEW_T3_3 AS
    SELECT
      C1,
      C2,
      C3
    FROM
      T3
    WHERE
      C1 BETWEEN 'K 0000000000740000' AND 'K 0000000000850000';

    CREATE VIEW VIEW_VIEW_T3 AS
    SELECT
      C1,
      C2,
      C3
    FROM
      VIEW_T3_1
    UNION
    SELECT
      C1,
      C2,
      C3
    FROM
      VIEW_T3_2
    UNION
    SELECT
      C1,
      C2,
      C3
    FROM
      VIEW_T3_3;

    SELECT
      T1.C1,
      T1.C2,
      T1.C3
    FROM
      T1,
      VIEW_VIEW_T2 T2
    WHERE
      T1.C2 BETWEEN 250000 AND 270000
      AND T1.C1=T2.C1;
    Too many options for performance tuning some times...

    Thanks again for pointing out the need to double-check the statistics.

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 58. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Charles,
    in TKPROF I found the following.
    error during execute of EXPLAIN PLAN statement
    ORA-01039: insufficient privileges on underlying objects of the view
    parse error offset: 91
    what to do for this. I got Execution Plan and statistics for this previouly. Then why it was failed in the TKprof.

    Thank you.
  • 59. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    The first TKPROF you created used this command:
    tkprof g_ora_14292.trc output.txt explain= /  insert=store.sql sys=no 
    The documentation for TKPROF in 9i:
    http://download.oracle.com/docs/cd/A91202_01/901_doc/server.901/a87503/sqltrace.htm#6467

    The documentation shows a tkprof command that looks like this, and explains the meaning of each part of the TKPROF command:
    TKPROF dlsun12_jane_fg_sqlplus_007.trc OUTPUTA.PRF EXPLAIN=scott/tiger TABLE=scott.temp_plan_table_a INSERT=STOREA.SQL SYS=NO SORT=(EXECPU,FCHCPU)
    Notice what appears after EXPLAIN= in the command from the documentation, it is a user name and password, but there may be another cause for the problem.

    My example TKPROF output was created with the following simple command:
    tkprof g_ora_14292.trc output14292.txt sort=EXEELA
    Try using the simple command, but make certain that your SQL statement is in the file g_ora_14292.trc.

    When you send the output of TKPROF to this website, please include everything between the ***** that appears just before your SQL statement all the way down to the ***** that appears after the "Elapsed times include waiting on following events", just like I did with my example TKPROF that I sent to this website.

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
1 2 3 4 5 6 8 Previous Next