This discussion is archived
1 4 5 6 7 8 Previous Next 117 Replies Latest reply: May 5, 2008 10:19 AM by 181444 Go to original post RSS
  • 75. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    Hi Lewis,
    Sorry for posting wrong output of TKPROF. It's
    previous output.I will post the new o/P.once again
    sorry for this.

    Thank you

    Message was edited by:
    User71408
    You posted the same row source data (same number of rows and time per operation) as on Apr 18, 2008, where the apparent addition of the leading(vcs) hint caused 0 rows to be returned, while the apparent addition of the all_rows hint caused 12+ million rows to be returned. I still have not quite determined how that might happen. I was starting to wonder if your database server does not like hints.

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 76. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Hi Lewis,

    this is "Another point, In addition" for the TKPROF

    Here I am posting the new OUTPUT for TKPROF.Please find the following.
    TKPROF: Release 9.2.0.4.0 - Production on Mon Apr 21 14:04:52 2008
    
    Copyright (c) 1982, 2002, Oracle Corporation.  All rights reserved.
    
    Trace file: adqora3g_ora_230458_SQL_TRACE.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
    ********************************************************************************
    
    The following statements encountered a error during parse:
    
    ALTER SESSION SET EVENTS .10046 TRACE NAME CONTEXT FOREVER, LEVEL 8.
    
    Error encountered: ORA-02246
    --------------------------------------------------------------------------------
    SELECT /*+
         ordered
                    full(iem)
                    full(itl) use_hash(itl)
                    full(s) use_hash(s) swap_join_inputs(s)
                    no_merge(vcs)
                    use_hash(vcs) swap_join_inputs(vcs)
                itl.loc                        store,
                       itl.item                       rms_sku,
                       vcs.case_size                  order_multiple,
                       itl.onsale_date                onsale_date,
                       itl.offsale_date               offsale_date,
                       iem.status                     status
       FROM item_master    iem,
                       item_loc       itl,
                       store          s,
                       v_case_size    vcs
                 WHERE iem.pack_ind                   = 'N'
                   AND iem.item_level                 = iem.tran_level
                   AND iem.status                     = 'A'
    AND iem.forecast_ind               = 'Y'
                   AND iem.item                       = itl.item
                   AND itl.loc_type                   = 'S'
                   AND iem.item                       = vcs.item
                   AND vcs.primary_supp_ind           = 'Y'
                   AND vcs.primary_country_ind        = 'Y'
                   AND itl.loc=s.store 
                   AND NVL(s.STORE_CLOSE_DATE,'04-APR-4444')>=TO_DATE(20080403, 'YYYYMMDD') 
    
    Error encountered: ORA-00936
    --------------------------------------------------------------------------------
     select c.value || .\. || d.instance_name || ._ora_. || a.spid || ..trc. trace_file_is_here
    from v$process a, v$session b, v$parameter c, v$instance d
    
    Error encountered: ORA-00936
    ********************************************************************************
    
    Alter session set SQL_Trace = true
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      2      0.00       0.01          0          0          0           0
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        3      0.00       0.01          0          0          0           0
    
    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: 315
    
    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       14.96         14.96
    ********************************************************************************
    
    ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'
    
    
    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: 0
    Optimizer goal: CHOOSE
    Parsing user id: 315
    
    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
      SQL*Net message from client                     2      274.54        383.25
      SQL*Net break/reset to client                   2        0.00          0.00
    ********************************************************************************
    
    select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1,
      spare2
    from
     obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null
      and linkname is null and subname is null
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        2      0.00       0.00          0          0          0           0
    Execute      9      0.01       0.01          0          0          0           0
    Fetch        9      0.00       0.00          0         19          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       20      0.01       0.01          0         19          0           1
    
    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: SYS   (recursive depth: 1)
    ********************************************************************************
    
    select text
    from
     view$ where rowid=:1
     call     count       cpu    elapsed       disk      query    current        rows
     ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     Parse        8      0.01       0.00          0          0          0           0
     Execute      8      0.00       0.01          0          0          0           0
     Fetch        8      0.00       0.00          0         16          0           8
     ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     total       24      0.01       0.01          0         16          0           8
     
     Misses in library cache during parse: 1
     Optimizer goal: CHOOSE
     Parsing user id: SYS   (recursive depth: 1)
     
     Rows     Row Source Operation
     -------  ---------------------------------------------------
           1  TABLE ACCESS BY USER ROWID VIEW$ (cr=1 r=0 w=0 time=25 us)
     
     ********************************************************************************
     
     select node,owner,name
     from
      syn$ where obj#=:1
     
     
     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        1      0.00       0.00          0          3          0           1
     ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     total        3      0.00       0.00          0          3          0           1
     
     Misses in library cache during parse: 1
     Optimizer goal: CHOOSE
     Parsing user id: SYS   (recursive depth: 1)
     ********************************************************************************
     
     select condition
     from
      cdef$ where rowid=:1
     
     
    call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse      292      0.00       0.00          0          0          0           0
    Execute    292      0.02       0.01          0          0          0           0
    Fetch      292      0.00       0.00          0        585          0         292
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total      876      0.02       0.02          0        585          0         292
    
    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: SYS   (recursive depth: 1)
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
          1  TABLE ACCESS BY USER ROWID CDEF$ (cr=1 r=0 w=0 time=21 us)
    
    ********************************************************************************
    
    SELECT /*+
            ordered
                    full(iem)
                    full(itl) use_hash(itl)
                    full(s) use_hash(s) swap_join_inputs(s)
                    no_merge(vcs)
                    */
     itl.loc                        store,
                       itl.item                       rms_sku,
                       vcs.case_size                  order_multiple,
                       itl.onsale_date                onsale_date,
                       itl.offsale_date               offsale_date,
                       iem.status                     status
    FROM item_master    iem,
                       item_loc       itl,
                       store          s,
                       v_case_size    vcs
                 WHERE iem.pack_ind                   = 'N'
                   AND iem.item_level                 = iem.tran_level
                   AND iem.status                     = 'A'
                   AND iem.forecast_ind               = 'Y'
                   AND iem.item                       = itl.item
                   AND itl.loc_type                   = 'S'
                   AND iem.item                       = vcs.item
                   AND vcs.primary_supp_ind           = 'Y'
                               AND vcs.primary_country_ind        = 'Y'
                               AND itl.loc=s.store 
                               AND NVL(s.STORE_CLOSE_DATE,'04-APR-4444')>=TO_DATE(20080403, 'YYYYMMDD')
                
                
                call     count       cpu    elapsed       disk      query    current        rows
                ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                Parse        1      0.30       0.31          0          3          0           0
                Execute      1      0.00       0.00          0          0          0           0
                Fetch   819704    936.22    2165.47    4806016   34044281          0    12295541
                ------- ------  -------- ---------- ---------- ---------- ----------  ----------
                total   819706    936.52    2165.78    4806016   34044284          0    12295541
                
                Misses in library cache during parse: 1
                Optimizer goal: CHOOSE
                Parsing user id: 315
                
                Rows     Row Source Operation
                -------  ---------------------------------------------------
                12295541  HASH JOIN  (cr=34044281 r=4806016 w=0 time=2139047518 us)
                 212315   VIEW  (cr=7553336 r=10859 w=0 time=85039675 us)
                 212315    VIEW  (cr=7553336 r=10859 w=0 time=84935492 us)
                 212315     SORT UNIQUE (cr=7553336 r=10859 w=0 time=84809086 us)
                 697081      HASH JOIN  (cr=7553336 r=10859 w=0 time=80346870 us)
                 210609       HASH JOIN  (cr=12485 r=9629 w=0 time=4530346 us)
                 210649        TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=500 w=0 time=629484 us)
                 232549        HASH JOIN  (cr=9152 r=9129 w=0 time=2975774 us)
                 210609         MERGE JOIN CARTESIAN (cr=6695 r=6675 w=0 time=1529249 us)
                      1          MERGE JOIN CARTESIAN (cr=30 r=13 w=0 time=121163 us)
                      1           TABLE ACCESS FULL SYSTEM_OPTIONS (cr=15 r=13 w=0 time=120964 us)
                      1           BUFFER SORT (cr=15 r=0 w=0 time=143 us)
                      1            TABLE ACCESS FULL SYSTEM_OPTIONS (cr=15 r=0 w=0 time=72 us)
                 210609          BUFFER SORT (cr=6665 r=6662 w=0 time=1322562 us)
                 210609           TABLE ACCESS FULL ITEM_MASTER (cr=6665 r=6662 w=0 time=1016023 us)
                 232590         TABLE ACCESS FULL ITEM_SUPPLIER (cr=2457 r=2454 w=0 time=557254 us)
                1829931       VIEW  (cr=7540851 r=1230 w=0 time=68727964 us)
                1829931        UNION-ALL  (cr=7540851 r=1230 w=0 time=66794426 us)
                 232590         INDEX FAST FULL SCAN PK_ITEM_SUPP_COUNTRY (cr=1956 r=370 w=0 time=1881373 us)(object id 27601)
                 232590         TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=0 w=0 time=177110 us)
     232590         TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=0 w=0 time=188743 us)
     232590         TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=0 w=0 time=200532 us)
      299857         VIEW  (cr=9082 r=860 w=0 time=5321741 us)
      299857          SORT UNIQUE (cr=9082 r=860 w=0 time=5166268 us)
     1175224           INDEX FAST FULL SCAN PK_CASE_UPDATES (cr=9082 r=860 w=0 time=1598649 us)(object id 64316)
      299857         VIEW  (cr=9082 r=0 w=0 time=4370777 us)
      299857          SORT UNIQUE (cr=9082 r=0 w=0 time=4212861 us)
     1175224           INDEX FAST FULL SCAN PK_CASE_UPDATES (cr=9082 r=0 w=0 time=627394 us)(object id 64316)
      299857         VIEW  (cr=9082 r=0 w=0 time=4406752 us)
      299857          SORT UNIQUE (cr=9082 r=0 w=0 time=4241925 us)
     1175224           INDEX FAST FULL SCAN PK_CASE_UPDATES (cr=9082 r=0 w=0 time=646683 us)(object id 64316)
     11847214   HASH JOIN  (cr=26490945 r=4795157 w=0 time=2033417383 us)
         769    TABLE ACCESS FULL STORE (cr=62 r=60 w=0 time=27019 us)
     13033476    HASH JOIN  (cr=26490883 r=4795097 w=0 time=2013607522 us)
       15406     TABLE ACCESS FULL ITEM_MASTER (cr=6665 r=0 w=0 time=281867 us)
     178209054     PARTITION HASH ALL PARTITION: 1 16 (cr=26484218 r=4795097 w=0 time=29907257715 us)
     178209054      TABLE ACCESS FULL ITEM_LOC PARTITION: 1 16 (cr=26484218 r=4795097 w=0 time=25829497488 us)
     
     
     Elapsed times include waiting on following events:
       Event waited on                             Times   Max. Wait  Total Waited
       ----------------------------------------   Waited  ----------  ------------
       SQL*Net message to client                  819705        0.00          0.40
       db file sequential read                    583673     4063.88      15999.28
       db file scattered read                     138180        4.50        819.63
       latch free                                     17        0.01          0.02
       SQL*Net message from client                819705     4179.10      14707.93
       buffer busy waits                             635        0.00          0.01
       log buffer space                                5        1.00          2.38
       log file switch completion                     10        1.00          1.98
       SQL*Net break/reset to client                   2        0.00          0.00
     ********************************************************************************
     
     select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,
       o.dataobj#,o.flags
     from
      obj$ o where o.obj#=:1
     
     
     call     count       cpu    elapsed       disk      query    current        rows
     ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     Parse        2      0.00       0.00          0          0          0           0
     Execute      3      0.00       0.00          0          0          0           0
     Fetch        3      0.00       0.03          4          9          0           3
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        8      0.00       0.03          4          9          0           3
    
    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: SYS   (recursive depth: 1)
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                         4        0.01          0.03
    ********************************************************************************
    
    select c.value || '\'|| d.instance_name || '_ora_' || a.spid ||'.trc' trace_file_is_here
    from v$process a, v$session b, v$parameter c, v$instance d
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.01       0.01          0         16          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch    11607      1.78       1.76          0          0          0      174087
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total    11609      1.79       1.77          0         16          0      174087
    
    Misses in library cache during parse: 1
    Optimizer goal: CHOOSE
    Parsing user id: 315
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
     174087  NESTED LOOPS  (cr=0 r=0 w=0 time=1207216 us)
       6003   NESTED LOOPS  (cr=0 r=0 w=0 time=68593 us)
        261    MERGE JOIN  (cr=0 r=0 w=0 time=12786 us)
        846     SORT JOIN (cr=0 r=0 w=0 time=3497 us)
        846      NESTED LOOPS  (cr=0 r=0 w=0 time=1564 us)
          1       NESTED LOOPS  (cr=0 r=0 w=0 time=65 us)
          1        NESTED LOOPS  (cr=0 r=0 w=0 time=47 us)
          1         FIXED TABLE FULL X$QUIESCE (cr=0 r=0 w=0 time=7 us)
          1         FIXED TABLE FULL X$KVIT (cr=0 r=0 w=0 time=22 us)
          1        FIXED TABLE FULL X$KSUXSINST (cr=0 r=0 w=0 time=17 us)
        846       FIXED TABLE FULL X$KSPPCV (cr=0 r=0 w=0 time=1163 us)
         261     FILTER  (cr=0 r=0 w=0 time=8058 us)
            846      SORT JOIN (cr=0 r=0 w=0 time=3710 us)
            846       FIXED TABLE FULL X$KSPPI (cr=0 r=0 w=0 time=919 us)
           6003    FIXED TABLE FULL X$KSUSE (cr=0 r=0 w=0 time=51946 us)
         174087   FIXED TABLE FULL X$KSUPR (cr=0 r=0 w=0 time=1046576 us)
        
        
        Elapsed times include waiting on following events:
          Event waited on                             Times   Max. Wait  Total Waited
          ----------------------------------------   Waited  ----------  ------------
          SQL*Net message to client                   11607        0.00          0.00
          SQL*Net message from client                 11607        6.65         14.82
          SQL*Net more data to client                    44        0.00          0.00
        
        
        
        ********************************************************************************
        
        OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
        
        call     count       cpu    elapsed       disk      query    current        rows
        ------- ------  -------- ---------- ---------- ---------- ----------  ----------
        Parse        4      0.31       0.32          0         19          0           0
        Execute      5      0.00       0.01          0          0          0           0
        Fetch   831311    938.00    2167.23    4806016   34044281          0    12469628
        ------- ------  -------- ---------- ---------- ---------- ----------  ----------
        total   831320    938.31    2167.57    4806016   34044300          0    12469628
        
        Misses in library cache during parse: 3
        
        Elapsed times include waiting on following events:
          Event waited on                             Times   Max. Wait  Total Waited
          ----------------------------------------   Waited  ----------  ------------
          SQL*Net message to client                  831315        0.00          0.41
          SQL*Net message from client                831315     4179.10      15120.98
          SQL*Net break/reset to client                   4        0.00          0.00
          db file sequential read                    583673     4063.88      15999.28
          db file scattered read                     138180        4.50        819.63
          latch free                                     17        0.01          0.02
          buffer busy waits                             635        0.00          0.01
          log buffer space                                5        1.00          2.38
          log file switch completion                     10        1.00          1.98
            SQL*Net more data to client                    44        0.00          0.00
          
          
          OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
          
          call     count       cpu    elapsed       disk      query    current        rows
          ------- ------  -------- ---------- ---------- ---------- ----------  ----------
          Parse      305      0.01       0.00          0          0          0           0
          Execute    313      0.03       0.04          0          0          0           0
          Fetch      313      0.00       0.03          4        632          0         305
          ------- ------  -------- ---------- ---------- ---------- ----------  ----------
          total      931      0.04       0.08          4        632          0         305
          
          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                         4        0.01          0.03
          
              4  user  SQL statements in session.
            305  internal SQL statements in session.
            309  SQL statements in session.
          ********************************************************************************
          Trace file: adqora3g_ora_230458_SQL_TRACE.trc
          Trace file compatibility: 9.00.01
          Sort options: default
          
                 0  session in tracefile.
                 4  user  SQL statements in trace file.
               305  internal SQL statements in trace file.
               309  SQL statements in trace file.
                 9  unique SQL statements in trace file.
           3220466  lines in trace file.
    Message was edited by:
    User71408

    Message was edited by:
    User71408

    Message was edited by:
    User71408
  • 77. Re: query tuning
    181444 Expert
    Currently Being Moderated
    hey, it is not always easy to tell who the poster
    intended the comments to. It is a good practice when
    you are commenting to something specific to reference
    the verbage or address the specific user. When just
    posting on the thread topic starting your response with
    something like "Another point, In addition" or some
    other general phrase that helps readers know you are
    just adding to the topic is a good idea.

    -- Mark D Powell --

    Message was edited by: Mark to add returns
    mpowel01
  • 78. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    User71408,

    It appears that Jonathan's hint suggestions significantly reduced the number of rows surviving the first hash join.
    Old:
     11847214   HASH JOIN  (cr=5066660 r=3876780 w=0 time=1400482785 us)
        15406    TABLE ACCESS FULL OBJ#(27569) (cr=6665 r=0 w=0 time=288486 us) (ITEM_MASTER)
    161989081    HASH JOIN  (cr=5059995 r=3876780 w=0 time=5271269810 us)
          769     TABLE ACCESS FULL OBJ#(28943) (cr=62 r=0 w=0 time=1407 us) (STORE)
    178209054     PARTITION HASH ALL PARTITION: 1 16 (cr=5059933 r=3876780 w=0 time=5045798853 us)
    178209054      TABLE ACCESS FULL OBJ#(27216) PARTITION: 1 16 (cr=5059933 r=3876780 w=0 time=4974317964 us) (ITEM_LOC)
    New:
     11847214   HASH JOIN  (cr=26490945 r=4795157 w=0 time=2033417383 us)
          769    TABLE ACCESS FULL STORE (cr=62 r=60 w=0 time=27019 us)
    13033476    HASH JOIN  (cr=26490883 r=4795097 w=0 time=2013607522 us)
        15406     TABLE ACCESS FULL ITEM_MASTER (cr=6665 r=0 w=0 time=281867 us)
    178209054     PARTITION HASH ALL PARTITION: 1 16 (cr=26484218 r=4795097 w=0 time=29907257715 us)
    178209054      TABLE ACCESS FULL ITEM_LOC PARTITION: 1 16 (cr=26484218 r=4795097 w=0 time=25829497488 us)
    But now the number of consistent reads seems to have increased significantly, which might mean that the server's CPU is becoming more of a bottleneck.

    Based on the 12,295,541 rows returned by the SQL statement, and the 819,705 waits on SQL*Net message from client, it appears that you are retrieving roughly 15 rows from the database at a time. If we subtract the max wait SQL*Net message from client time of 4179.10, the client is taking 10,528.83 seconds to perform 819,704 fetches, indicating that it takes the client 0.0128 seconds to retrieve the 15 rows, and request the next 15 rows from the database. This may indicate that there is network contention, but the numbers still do not add up. 10,528 seconds is 175.48 minutes, and you indicated that the query now completes in 42 minutes.

    Please search the trace file for a line that contains the following (there will be letters/numbers before and after this phrase):
    nam='db file sequential read' ela= 40638
    Please copy the 5 lines before the above line in the trace file and the 5 lines after the above line in the trace file and paste them into a response in this message thread.

    Also, search the trace file for a line that contains the following (there will be letters/numbers before and after this phrase):
    nam='SQL*Net message from client' ela= 41791
    Please copy the 5 lines before the above line in the trace file and the 5 lines after the above line in the trace file and paste them into a response in this message thread.

    I am trying to determine the cause of the long 4063.88 second (67.7 minute) wait on the single block read and the 4179.10 second (69.7 minute) wait on the client.

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 79. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Charles ,
    Pls find the following
    WAIT #3: nam='db file sequential read' ela= 211     p1=401 p2=30207 p3=1
    WAIT #3: nam='db file sequential read' ela= 409     p1=401 p2=30206 p3=1
    WAIT #3: nam='db file sequential read' ela= 78559   p1=401 p2=30208 p3=1
    WAIT #3: nam='db file sequential read' ela= 34448   p1=401 p2=30210 p3=1
    WAIT #3: nam='db file sequential read' ela= 40325   p1=401 p2=30209 p3=1
    WAIT #3: nam='db file sequential read' ela= 40638   p1=401 p2=30212 p3=1
    WAIT #3: nam='db file sequential read' ela= 17173   p1=401 p2=30211 p3=1
    WAIT #3: nam='db file sequential read' ela= 105319  p1=401 p2=30214 p3=1
    WAIT #3: nam='db file sequential read' ela= 40270   p1=401 p2=30213 p3=1
    WAIT #3: nam='db file sequential read' ela= 44361   p1=401 p2=30216 p3=1
    WAIT #3: nam='db file sequential read' ela= 358     p1=401 p2=30215 p3=1
    WAIT #3: nam='db file sequential read' ela= 16649   p1=401 p2=30218 p3=1
    WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=131,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875641857
    WAIT #3: nam='SQL*Net message from client' ela= 704 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 1 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=140,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875642773
    WAIT #3: nam='SQL*Net message from client' ela= 668 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 1 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=140,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875643631
    
    WAIT #3: nam='SQL*Net message from client' ela= 4179109066 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0
    FETCH #3:c=10000,e=144,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875643757
    WAIT #3: nam='SQL*Net message from client' ela= 660 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=128,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875644594
  • 80. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Hi Lewis,
    I have posted the TKPROF what I am getting after adding hints which are suggested by u.Please look into this and guide for the next .

    Thank you.
  • 81. Re: query tuning
    26741 Oracle ACE
    Currently Being Moderated
    The wait
    WAIT #3: nam='db file sequential read' ela= 105319  p1=401 p2=30214 p3=1
    is a 105ms wait for a read from disk (or what Oracle thinks is the disk, could be a
    mix of filesystembuffers, IOChannels, SANCache, Disk etc).
    Your read waits seem to be high.

    The wait
    WAIT #3: nam='SQL*Net message from client' ela= 4179109066 p1=1650815232 p2=1 p3=0
    is the 4,179second wait. Was there a long (69minute) wait before the SELECT statement was submitted (sent) to the Database server by the client / appserver ?
    What is Cursor#3 in the trace file at that time ?
  • 82. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    PARSING IN CURSOR #3 len=1360 dep=0 uid=315 oct=0 lid=315 tim=1180444512734348hv=3448745547 ad='e1301938'
    SELECT /*+ordered full(iem) full(itl) use_hash(itl) full(s) use_hash(s) swap_join_inputs(s) no_merge(vcs)*/
         itl.loc store,
         itl.item rms_sku,
         ......
          .....
        ......
    
    
    
    */
    Thank you

    Message was edited by:
    User71408

    Message was edited by:
    User71408
  • 83. Re: query tuning
    26741 Oracle ACE
    Currently Being Moderated
    Well .... there is certainly something wrong with the timing information that we
    see.

    For example, if this line (from the previous tkprof as quoted by Charles)
    178209054      TABLE ACCESS FULL OBJ#(27216) PARTITION: 1 16 (cr=5059933 r=3876780 w=0 time=4974317964 us) (ITEM_LOC)
    and this line from the current tkprof
    178209054      TABLE ACCESS FULL ITEM_LOC PARTITION: 1 16 (cr=26484218 r=4795097 w=0 time=25829497488 us)
    are both correct, the Full Table Scan went from 4,974seconds to 25,829seconds.
    Which is ridiculously high.
  • 84. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Hemanth,
    So what will do for improving performance...
  • 85. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Charles,
    I have posted the O/P what u have asked me..can you please look into this.

    Thank you
  • 86. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    Charles ,
    Pls find the following
    WAIT #3: nam='db file sequential read' ela= 211     p1=401 p2=30207 p3=1
    WAIT #3: nam='db file sequential read' ela= 409     p1=401 p2=30206 p3=1
    WAIT #3: nam='db file sequential read' ela= 78559   p1=401 p2=30208 p3=1
    WAIT #3: nam='db file sequential read' ela= 34448   p1=401 p2=30210 p3=1
    WAIT #3: nam='db file sequential read' ela= 40325   p1=401 p2=30209 p3=1
    WAIT #3: nam='db file sequential read' ela= 40638   p1=401 p2=30212 p3=1
    WAIT #3: nam='db file sequential read' ela= 17173   p1=401 p2=30211 p3=1
    WAIT #3: nam='db file sequential read' ela= 105319  p1=401 p2=30214 p3=1
    WAIT #3: nam='db file sequential read' ela= 40270   p1=401 p2=30213 p3=1
    WAIT #3: nam='db file sequential read' ela= 44361   p1=401 p2=30216 p3=1
    WAIT #3: nam='db file sequential read' ela= 358     p1=401 p2=30215 p3=1
    WAIT #3: nam='db file sequential read' ela= 16649   p1=401 p2=30218 p3=1
    That is good that you found a matching line. There should be another matching line for the 'db file sequential read' that has that number followed by several extra digits (it should be a very big number, like the one that you found for 'SQL*Net message from client'). Please search again for:
    nam='db file sequential read' ela= 40638
    Let's look at what you provided to see what it tells us:
     0.000211 seconds  File=401  Block Start=30207  Num Blocks=1 
    0.000409 seconds  File=401  Block Start=30206  Num Blocks=1
    0.078559 seconds  File=401  Block Start=30208  Num Blocks=1
    0.034448 seconds  File=401  Block Start=30210  Num Blocks=1
    0.040325 seconds  File=401  Block Start=30209  Num Blocks=1
    0.040638 seconds  File=401  Block Start=30212  Num Blocks=1
    0.017173 seconds  File=401  Block Start=30211  Num Blocks=1
    0.105319 seconds  File=401  Block Start=30214  Num Blocks=1
    0.040270 seconds  File=401  Block Start=30213  Num Blocks=1
    0.044361 seconds  File=401  Block Start=30216  Num Blocks=1
    0.000358 seconds  File=401  Block Start=30215  Num Blocks=1
    0.016649 seconds  File=401  Block Start=30218  Num Blocks=1
    Notice that the Block Start numbers are very close together, but in most cases it takes a long time to read the next block, even though the hard drive head(s) should not need to move to a different track. Even if it was necessary to wait for a full rotation of the hard drive platter, it would only take 0.0001 seconds for a full rotation of the hard drive platter with a 10,000 rpm hard drive (or 0.000067 seconds with a 15,000 rpm hard drive). It would seem that something must be instructing the hard drive head to move to a different track between reads. If SCSI hard drives are in use, they should support native command queuing, which should be able to avoid unneccessary head movements from one track to another by sensing that there is another read request in the queue on the same track.

    Please try to find the other 'db file sequential read' line with the very large number.

    >
    WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=131,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875641857
    WAIT #3: nam='SQL*Net message from client' ela= 704 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 1 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=140,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875642773
    WAIT #3: nam='SQL*Net message from client' ela= 668 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 1 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=140,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875643631
    WAIT #3: nam='SQL*Net message from client' ela= 4179109066 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0
    FETCH #3:c=10000,e=144,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875643757
    WAIT #3: nam='SQL*Net message from client' ela= 660 p1=1650815232 p2=1 p3=0
    WAIT #3: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0
    FETCH #3:c=0,e=128,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=4,tim=1180445875644594
    The above is very helpful, it describes what is happening, although there is a bit of a problem with the wait events. Passing what you posted through a program that reads the file and converts it into something a little easier to read (time is in seconds):
    Fetch at 1180445875.641860 (Parse to Fetch 1180445875.641860),CPU Time 0.000000,Elapsed Time 0.000131,Rows Retrievd 15,Blks from Buff 1,Blks from Disk 0
         0.000704   SQL*Net message from client
         0.000001   SQL*Net message to client
    Fetch at 1180445875.642770 (Parse to Fetch 1180445875.642770),CPU Time 0.000000,Elapsed Time 0.000140,Rows Retrievd 15,Blks from Buff 1,Blks from Disk 0
         0.000668   SQL*Net message from client
         0.000001   SQL*Net message to client
    Fetch at 1180445875.643630 (Parse to Fetch 1180445875.643630),CPU Time 0.000000,Elapsed Time 0.000140,Rows Retrievd 15,Blks from Buff 2,Blks from Disk 0
      4179.109066   SQL*Net message from client
         0.000000   SQL*Net message to client
    Fetch at 1180445875.643760 (Parse to Fetch 1180445875.643760),CPU Time 0.010000,Elapsed Time 0.000144,Rows Retrievd 15,Blks from Buff 1,Blks from Disk 0
         0.000660   SQL*Net message from client
         0.000000   SQL*Net message to client
    Fetch at 1180445875.644590 (Parse to Fetch 1180445875.644590),CPU Time 0.000000,Elapsed Time 0.000128,Rows Retrievd 15,Blks from Buff 1,Blks from Disk 0
    The 4179.109 second wait on the client (wait event 'SQL*Net message from client' ) could not have happened if we look at the time stamps on each of the fetches:
    0.641860 seconds
    0.642770 seconds
    0.643630 seconds
    0.643760 seconds
    0.644590 seconds

    If we just compare the time stamps (shown above) with the Elapsed Time for each fetch (and we believe that we can trust the timings):
    0.000131 seconds
    0.000140 seconds
    0.000140 seconds
    0.000144 seconds
    0.000128 seconds

    It appears that either the client is slowing down the rate at which rows are returned (causing a delay between each 15 rows fetched), or the network between the client and server is slowing down the rate at which rows are returned. See if you can find a way to make the client fetch more than 15 rows at a time (this might be a setting in the connection string).

    Charles Hooper
    IT Manager/Oracle DBA
    K&M Machine-Fabricating, Inc.
  • 87. Re: query tuning
    599921 Newbie
    Currently Being Moderated
    Charles ,
    Here am Posting the code for ela=40638...
    WAIT #3: nam='db file sequential read' ela= 260 p1=354 p2=128875 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 180 p1=354 p2=128878 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 179 p1=354 p2=128877 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 178 p1=354 p2=128880 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 192 p1=354 p2=128879 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 197 p1=354 p2=128882 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 192 p1=354 p2=128881 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 4063882583 p1=354 p2=128884 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 194 p1=354 p2=128883 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 180 p1=354 p2=128885 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 192 p1=354 p2=128887 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 176 p1=354 p2=128886 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 179 p1=354 p2=128889 p3=1
    
    WAIT #3: nam='db file sequential read' ela= 186 p1=354 p2=128888 p3=1
  • 88. Re: query tuning
    26741 Oracle ACE
    Currently Being Moderated
    Charles,
    In my opinion it would be futile to compare Oracle Block Numbers and
    'db file sequential read' waits with Disk Mechanics (Drive Heads, Platters, Seek Time)
    to such detail.
    We have no knowledge and cannot assume that Oracle Block ID 30207 and 30206
    are contiguous on the hard disk.
    a) The Oracle Blocks are in db_block_size (presumably 8K ?) while Disk Blocks are
    disk block size (512bytes) ? So a difference of 1 Oracle Blocks is 16 Disk Blocks
    (assuming those sizes).
    b) How Oracle Blocks map to the disk depend on the FileSystem and the Volume
    and the LUN association. If the Volume and/or LUN is striped, you'd get different
    physical mappings depending on the stripe factors.
    c) If the disk holds LUNs for multiple Volumes (FileSystems) then it is servicing
    multiple requests.
    d) If it is inside a SAN (or a NAS) it is very likely serving multiple requests from
    different systems / databases concurrently.
    e) The presence of SAN Cache AND/OR FileSystem Buffer just throws every
    calculation out.

    Then, again look at the one wait
    nam='db file sequential read' ela= 4063882583 p1=354 p2=128884 p3=1
    Totally impossible, unlikely, incomprehensible (4,063seconds ?!)

    There is something wrong with the timing information.
  • 89. Re: query tuning
    CharlesHooper Expert
    Currently Being Moderated
    Charles,
    In my opinion it would be futile to compare Oracle
    Block Numbers and
    'db file sequential read' waits with Disk Mechanics
    (Drive Heads, Platters, Seek Time)
    to such detail.
    We have no knowledge and cannot assume that Oracle
    Block ID 30207 and 30206
    are contiguous on the hard disk.
    a) The Oracle Blocks are in db_block_size
    (presumably 8K ?) while Disk Blocks are
    isk block size (512bytes) ? So a difference of 1
    Oracle Blocks is 16 Disk Blocks
    (assuming those sizes).
    b) How Oracle Blocks map to the disk depend on the
    FileSystem and the Volume
    and the LUN association. If the Volume and/or LUN is
    striped, you'd get different
    physical mappings depending on the stripe factors.
    c) If the disk holds LUNs for multiple Volumes
    (FileSystems) then it is servicing
    multiple requests.
    d) If it is inside a SAN (or a NAS) it is very likely
    serving multiple requests from
    different systems / databases concurrently.
    e) The presence of SAN Cache AND/OR FileSystem Buffer
    just throws every
    calculation out.

    Then, again look at the one wait
    nam='db file sequential read' ela= 4063882583 p1=354
    p2=128884 p3=1
    Totally impossible, unlikely, incomprehensible
    (4,063seconds ?!)

    There is something wrong with the timing information.
    Hemant,

    There are certain things written about Oracle that once read, change the way you look at things. For instance, take a look at some of the details in this document (Optimal Storage Configuration Made Easy):
    http://www.oracle.com/technology/deploy/availability/pdf/oow2000_same.pdf

    We don't know about the OP's file system. Let's assume for a moment that it is a RAID 10 with 64KB stripe width. What does that mean? Eight "sequential" 8KB Oracle blocks will fit into each stripe and be read before the next hard drive in the array needs to be queued for a read. The question then becomes, are these sequentially numbered Oracle blocks?

    What if, as I was attempting to imply in the previous post, that the OP's file system does not even contain SCSI drives, but instead uses drives that do not support native command queuing, as would be the case for most SATA and IDE drives. Worse yet, what if the multiple drives were on the same IDE channel - only one IDE drive on a channel can be active at a time. The point is that we do not know if the OP has 401+ files on a single drive, an IDE master/slave chain of drives, a 20 drive SCSI RAID 10 array, a SAN with 200 drives, or something else. All that we know is that single block reads seem to be taking a long time.

    Moving on, we find a block entry like this one that describes single block read problems with a SAN:
    http://oracledoug.com/serendipity/index.php?/archives/1371-The-Reality-Gap-4-Its-never-the-SAN.html

    It is at this point that I have to wonder, what is causing the single block reads? If we use this as a reference:
    http://jonathanlewis.wordpress.com/2006/12/15/index-operations/
    We find that Index Fast Full Scan "goes to the first block of the segment, and does multi-block reads through the segment, picking up branch and leaf blocks, discarding the branches and using the data in the leaf blocks as if they were skinny tables. Does not return the data in order."

    That seems to indicate that when we see this in the plan: "INDEX FAST FULL SCAN", Oracle should be reading multiple blocks at a time, not one block at a time. It is commonly understood, I believe, that when we see "TABLE ACCESS FULL" in the plan, Oracle should be reading multiple blocks at a time. If we take a look at parts of the plan where it shows an index or table access:
       210649        TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=500 w=0 time=629484 us)
            1           TABLE ACCESS FULL SYSTEM_OPTIONS (cr=15 r=13 w=0 time=120964 us)
            1            TABLE ACCESS FULL SYSTEM_OPTIONS (cr=15 r=0 w=0 time=72 us)
       210609           TABLE ACCESS FULL ITEM_MASTER (cr=6665 r=6662 w=0 time=1016023 us)
       232590         TABLE ACCESS FULL ITEM_SUPPLIER (cr=2457 r=2454 w=0 time=557254 us)
       232590         INDEX FAST FULL SCAN PK_ITEM_SUPP_COUNTRY (cr=1956 r=370 w=0 time=1881373 us)(object id 27601)
       232590         TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=0 w=0 time=177110 us)
       232590         TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=0 w=0 time=188743 us)
       232590         TABLE ACCESS FULL ITEM_SUPP_COUNTRY (cr=3333 r=0 w=0 time=200532 us)
      1175224           INDEX FAST FULL SCAN PK_CASE_UPDATES (cr=9082 r=860 w=0 time=1598649 us)(object id 64316)
      1175224           INDEX FAST FULL SCAN PK_CASE_UPDATES (cr=9082 r=0 w=0 time=627394 us)(object id 64316)
      1175224           INDEX FAST FULL SCAN PK_CASE_UPDATES (cr=9082 r=0 w=0 time=646683 us)(object id 64316)
          769    TABLE ACCESS FULL STORE (cr=62 r=60 w=0 time=27019 us)
        15406     TABLE ACCESS FULL ITEM_MASTER (cr=6665 r=0 w=0 time=281867 us)
    178209054      TABLE ACCESS FULL ITEM_LOC PARTITION: 1 16 (cr=26484218 r=4795097 w=0 time=25829497488 us)
    We only see TABLE ACCESS FULL and INDEX FAST FULL SCAN, and no operations that would seem to trigger a single block read.

    I am not sure yet what is causing the odd timings.

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