1 4 5 6 7 8 Previous Next 117 Replies Latest reply: May 5, 2008 12:19 PM by 181444 Go to original post RSS
      • 75. Re: query tuning
        Charles Hooper
        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
          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
            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
              Charles Hooper
              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
                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
                  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
                    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
                      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
                        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
                          Hemanth,
                          So what will do for improving performance...
                          • 85. Re: query tuning
                            599921
                            Charles,
                            I have posted the O/P what u have asked me..can you please look into this.

                            Thank you
                            • 86. Re: query tuning
                              Charles Hooper
                              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
                                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
                                  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
                                    Charles Hooper
                                    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