1 2 3 Previous Next 40 Replies Latest reply: Apr 4, 2014 12:05 AM by Franck Pachot RSS

    tkprof shows disk Fetch 251154528

    Dan Paul

      Database Gurus,

       

      We have GL_JE_LINES table which has few million rows. The query takes awful long time - several hours. We traced the program and then sorted by top SQL and here is what was found.

       

      SELECT GCC.CODE_COMBINATION_ID, GCC.SEGMENT8, GJL.JE_HEADER_ID,

        GJL.JE_LINE_NUM, GJL.ATTRIBUTE20, GJL.ACCOUNTED_DR, GJL.ACCOUNTED_CR

      FROM

      GL_CODE_COMBINATIONS GCC, GL_JE_HEADERS GJH, GL_JE_LINES GJL, GL_JE_SOURCES

        GJS WHERE GCC.CODE_COMBINATION_ID = GJL.CODE_COMBINATION_ID AND

        GJH.JE_HEADER_ID = GJL.JE_HEADER_ID AND GJL.ATTRIBUTE20 IS NULL AND

        GCC.TEMPLATE_ID IS NULL AND GJH.STATUS = 'P' AND GJH.JE_SOURCE =

        GJS.JE_SOURCE_NAME AND GJS.USER_JE_SOURCE_NAME NOT IN ('CAS M161 RECON',

        'CAS M161 CONV') AND GJH.ACTUAL_FLAG = :B14 AND :B13 =

        SUBSTR(GJL.ATTRIBUTE3,1,7) AND :B12 = GCC.SEGMENT1 AND :B11 = GCC.SEGMENT2

        AND :B10 = GCC.SEGMENT3 AND :B9 = GCC.SEGMENT4 AND :B8 = GCC.SEGMENT5 AND

        :B7 = GCC.SEGMENT6 AND :B6 = GCC.SEGMENT7 AND :B5 = GCC.SEGMENT9 AND :B4 =

        GCC.SEGMENT10 AND :B3 = GCC.SEGMENT11 AND :B2 = GCC.SEGMENT12 AND :B1 =

        GCC.SEGMENT13

       

       

      call     count       cpu    elapsed       disk      query    current        rows

      ------- ------  -------- ---------- ---------- ---------- ----------  ----------

      Parse        1      0.00       0.00          0          0          0           0

      Execute   4699     14.92      14.42          0          0          2           0

      Fetch     4747  33325.07   70062.51  251154528  334260271          0       42965

      ------- ------  -------- ---------- ---------- ---------- ----------  ----------

      total     9447  33339.99   70076.94  251154528  334260271          2       42965

       

      Misses in library cache during parse: 1

      Misses in library cache during execute: 9

      Optimizer mode: ALL_ROWS

      Parsing user id: 173  (APPS)   (recursive depth: 1)

       

      Rows     Row Source Operation

      -------  ---------------------------------------------------

           10  NESTED LOOPS  (cr=88 pr=26 pw=0 time=738 us)

           10   NESTED LOOPS  (cr=78 pr=26 pw=0 time=675 us cost=44 size=148 card=1)

           10    NESTED LOOPS  (cr=74 pr=25 pw=0 time=567 us cost=43 size=120 card=1)

           20     NESTED LOOPS  (cr=23 pr=16 pw=0 time=437 us cost=41 size=107 card=1)

            2      TABLE ACCESS BY INDEX ROWID GL_CODE_COMBINATIONS (cr=5 pr=5 pw=0 time=17184 us cost=4 size=71 card=1)

            2       INDEX RANGE SCAN GL_CODE_COMBINATIONS_CAT (cr=3 pr=3 pw=0 time=6 us cost=3 size=0 card=1)(object id 32601067)

           20      TABLE ACCESS BY INDEX ROWID GL_JE_LINES (cr=18 pr=11 pw=0 time=378 us cost=37 size=36 card=1)

           28       INDEX RANGE SCAN GL_JE_LINES_N1 (cr=8 pr=5 pw=0 time=143 us cost=3 size=0 card=162)(object id 34055)

           10     TABLE ACCESS BY INDEX ROWID GL_JE_HEADERS (cr=51 pr=9 pw=0 time=0 us cost=2 size=13 card=1)

           20      INDEX UNIQUE SCAN GL_JE_HEADERS_U1 (cr=31 pr=5 pw=0 time=0 us cost=1 size=0 card=1)(object id 34017)

           10    INDEX UNIQUE SCAN GL_JE_SOURCES_TL_U1 (cr=4 pr=1 pw=0 time=0 us cost=0 size=0 card=1)(object id 74988)

           10   TABLE ACCESS BY INDEX ROWID GL_JE_SOURCES_TL (cr=10 pr=0 pw=0 time=0 us cost=1 size=28 card=1)

       

       

      Rows     Execution Plan

      -------  ---------------------------------------------------

            0  SELECT STATEMENT   MODE: ALL_ROWS

           10   NESTED LOOPS

           10    NESTED LOOPS

           10     NESTED LOOPS

           20      NESTED LOOPS

            2       TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF

                        'GL_CODE_COMBINATIONS' (TABLE)

            2        INDEX   MODE: ANALYZED (RANGE SCAN) OF

                         'GL_CODE_COMBINATIONS_CAT' (INDEX)

           20       TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF

                        'GL_JE_LINES' (TABLE)

           28        INDEX   MODE: ANALYZED (RANGE SCAN) OF

                         'GL_JE_LINES_N1' (INDEX)

           10      TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF

                       'GL_JE_HEADERS' (TABLE)

           20       INDEX   MODE: ANALYZED (UNIQUE SCAN) OF

                        'GL_JE_HEADERS_U1' (INDEX (UNIQUE))

           10     INDEX   MODE: ANALYZED (UNIQUE SCAN) OF

                      'GL_JE_SOURCES_TL_U1' (INDEX (UNIQUE))

           10    TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF

                     'GL_JE_SOURCES_TL' (TABLE)

       

       

      Elapsed times include waiting on following events:

        Event waited on                             Times   Max. Wait  Total Waited

        ----------------------------------------   Waited  ----------  ------------

        Disk file operations I/O                        8        0.00          0.00

        db file sequential read                   251165467       16.68      44044.34

        latch free                                      7        0.00          0.00

        latch: object queue header operation            2        0.00          0.00

        latch: cache buffers chains                    10        0.00          0.00

        read by other session                           2        0.15          0.18

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

       

      The trace file has mostly waits

      .......

      WAIT #6: nam='db file sequential read' ela= 27 file#=10 block#=250526 blocks=1 obj#=34028 tim=24617642669841

      WAIT #6: nam='db file sequential read' ela= 28 file#=10 block#=250527 blocks=1 obj#=34028 tim=24617642669982

      WAIT #6: nam='db file sequential read' ela= 29 file#=10 block#=250560 blocks=1 obj#=34028 tim=24617642670113

      WAIT #6: nam='db file sequential read' ela= 25 file#=10 block#=250561 blocks=1 obj#=34028 tim=24617642670208

      WAIT #6: nam='db file sequential read' ela= 23 file#=359 block#=242454 blocks=1 obj#=34055 tim=24617642670338

      WAIT #6: nam='db file sequential read' ela= 26 file#=10 block#=250562 blocks=1 obj#=34028 tim=24617642670433

      ...

       

      Appreciate any help in providing any insights

       

      Thanks

      Dan Paul

        • 1. Re: tkprof shows disk Fetch 251154528
          Srini Chavali-Oracle

          Is this custom code or seeded code ? Are statistics current ? If this is seeded code, how is this code invoked (form, report etc), and has an SR been opened ?

           

          Srini

          • 2. Re: tkprof shows disk Fetch 251154528
            Dan Paul

            It is custom code and called from concurrent request.

             

            Yes, Stats are run every night and are current.

             

            No SR opened as Oracle would not entertain it being custom code.

             

            Dan

            • 3. Re: tkprof shows disk Fetch 251154528
              Dan Paul

              Here is the actual query simplified

              SELECT gcc.code_combination_id, gcc.segment8,

                               gjl.je_header_id, gjl.JE_LINE_NUM, gjl.attribute20,

                               gjl.accounted_dr, gjl.accounted_cr

                      FROM gl_code_combinations gcc, gl_je_headers gjh, gl_je_lines gjl,

                              gl_je_sources gjs

                      WHERE  gcc.code_combination_id = gjl.code_combination_id

                        AND gjh.je_header_id = gjl.je_header_id

                        AND gcc.template_id IS NULL

                        AND gjh.status = 'P'

                        AND gjh.je_source = gjs.je_source_name

                       AND gjh.actual_flag IN ('A','E')

              • 4. Re: tkprof shows disk Fetch 251154528
                sb92075

                My observation is that the posted SQL runs in just under 15 seconds.

                The total elapsed time exceeds 70,000 seconds because the SQL is executed almost 5000 TIMES.

                One way  to reduce the total elapsed time is to avoid executing the SQL so many times.

                Do you really get different result set each time?

                • 5. Re: tkprof shows disk Fetch 251154528
                  Franck Pachot

                  Hi,

                  The last execution did 26 physical reads. But on average the 4747 executions did 53000 physical reads per execution. So there are probably a set of parameters for which that plan is not good at all.

                  If you are tracing with dbms_session.session_trace_enable in 11g then you can use plan_stat => 'all_executions' to see which Row Source Operation is responsible for all those disk reads.

                  You can also get bind values and check the raw trace to see which one is responsible for high reads.

                  Regards,

                  Franck.

                  • 6. Re: tkprof shows disk Fetch 251154528
                    Dan Paul

                    The trace is still running and I ran the TKPROF midway. What bothers me is that tail of trace file (running since yesterday and size currently as 40434664880 bytes ) shows only WAIT

                     

                    WAIT #7: nam='db file sequential read' ela= 29 file#=363 block#=160820 blocks=1 obj#=34028 tim=24628676005072

                    WAIT #7: nam='db file sequential read' ela= 28 file#=363 block#=160821 blocks=1 obj#=34028 tim=24628676005210

                    WAIT #7: nam='db file sequential read' ela= 42 file#=359 block#=169710 blocks=1 obj#=34055 tim=24628676005348

                    WAIT #7: nam='db file sequential read' ela= 20630 file#=363 block#=160822 blocks=1 obj#=34028 tim=24628676026064

                    WAIT #7: nam='db file sequential read' ela= 544 file#=363 block#=160823 blocks=1 obj#=34028 tim=24628676026745

                    WAIT #7: nam='db file sequential read' ela= 22389 file#=363 block#=160824 blocks=1 obj#=34028 tim=24628676049258

                    WAIT #7: nam='db file sequential read' ela= 28093 file#=363 block#=160825 blocks=1 obj#=34028 tim=24628676077476

                    WAIT #7: nam='db file sequential read' ela= 3428 file#=363 block#=160826 blocks=1 obj#=34028 tim=24628676081057

                    WAIT #7: nam='db file sequential read' ela= 20412 file#=359 block#=169746 blocks=1 obj#=34055 tim=24628676101584

                     

                    The file is too large for vi. Once it finishes, I will compress it and move to desktop for review.

                    • 7. Re: tkprof shows disk Fetch 251154528
                      Srini Chavali-Oracle

                      Is this the only code that runs slow ? Or is all of EBS slow in general ? If the latter, I suspect your IO/storage subsystem. Pl also review these two threads on how to post a tuning request -

                       

                      When your query takes too long ...

                       

                      HOW TO: Post a SQL statement tuning request - template posting

                      • 8. Re: tkprof shows disk Fetch 251154528
                        Dan Paul

                        This query was slow to begin with and then we upgraded to 11G and many of the queries took longer than usual.

                         

                        Tracing few long running requests showed time spent on FND queries and I do have a SR open with Oracle. Following changes Analyst were implemented in TEST and that is where the query is running since yesterday.

                         

                        compatible version is 10.2 but your database is 11.2

                        _index_join_enabled FALSE Y

                        _sqlexec_progression_cost 0 Y

                        db_file_multiblock_read_count 64 Y

                        query_rewrite_enabled true Y

                         

                        QUERY

                        select upper(nvl(syn.table_owner,usr.oracle_username)) into :b0

                        from

                        fnd_responsibility resp ,fnd_data_group_units dg ,fnd_oracle_userid usr ,

                        all_tables tab ,all_synonyms syn where ((((((((resp.application_id=:b1 and

                        resp.responsibility_id=:b2) and dg.application_id=

                        resp.data_group_application_id) and dg.data_group_id=resp.data_group_id)

                        and usr.oracle_id=dg.oracle_id) and syn.synonym_name(+)=upper(:b3)) and

                        syn.owner(+)=usr.oracle_username) and tab.table_name=upper(:b3)) and

                        tab.owner=nvl(syn.table_owner,usr.oracle_username))

                         

                         

                        call count cpu elapsed disk query current rows

                        ------- ------ -------- ---------- ---------- ---------- ---------- ----------

                        Parse 1 0.04 0.03 0 0 0 0

                        Execute 8494 11.29 11.22 0 0 0 0

                        Fetch 8494 16913.01 17024.08 650438 1927018444 18 2120

                        ------- ------ -------- ---------- ---------- ---------- ---------- ----------

                        total 16989 16924.34 17035.34 650438 1927018444 18 2120

                         

                         


                        • 9. Re: tkprof shows disk Fetch 251154528
                          Srini Chavali-Oracle

                          If you have upgraded your database (pl post exact version to 4 digits), your compatible should be set to 11.2. Assuming EBS version 12.1.x, I suggest you review MOS Doc 396009.1. Also run the script in MOS Doc 174605.1 and review the output. For EBS, the 4 init.ora parameters you listed should not be set for 11gR2 - looks like whomever did the upgrade did not perform a thorough job.

                          • 10. Re: tkprof shows disk Fetch 251154528
                            Dan Paul

                            Looking at the proc, this SQL is in a cursor and called multiple times to get an unique row which then is updated.

                             

                            So the calls (4747 or more) is how the PROC is designed.

                            • 11. Re: tkprof shows disk Fetch 251154528
                              Dan Paul

                              The above query is an cursor loop. So executed as many times as number of rows returned by external cursor.

                              • 12. Re: tkprof shows disk Fetch 251154528
                                Dan Paul

                                >>Do you really get different result set each time?

                                Yes, each execution of the SQL returns a unique value from gl_je_lines table which is then updated. This query worked good when the table was small but with around 22 million rows, it is taking its toll

                                • 13. Re: tkprof shows disk Fetch 251154528
                                  Dan Paul

                                  Srini,

                                   

                                  Database version is "Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production"

                                  No, we are on 11i. Upgrade to R12 is in testing phase. Output of bde_chk_cbo.sql will be uploaded now

                                  • 14. Re: tkprof shows disk Fetch 251154528
                                    Srini Chavali-Oracle

                                    11.2.0.1 is pretty buggy - the target version should have been at least 11.2.0.3 - https://blogs.oracle.com/stevenChan/entry/11gr2_11_2_0_3 - if not 11.2.0.4 - https://blogs.oracle.com/stevenChan/entry/11_2_0_4_database

                                     

                                    For 11i, pl see MOS Doc 216205.1 for initialization parameter settings.

                                     

                                    As part of the upgrade, were system stats gathered ? See MOS Doc 368252.1

                                    1 2 3 Previous Next