1 2 Previous Next 22 Replies Latest reply: Jun 17, 2014 3:28 AM by Ramin Hashimzadeh RSS

    Reg: finding the root cause step-by-step...

    ranit B

      Hi Experts,

       

      I am facing a performance hit on a query and trying to debug it.

      Seems like the stats are up-to-date but still not sure on the exact cause.

       

      My query:

      SELECT /*+ GATHER_PLAN_STATISTICS */

          STH.PR_AMOUNT,

          STH.LN_NUMBER,

          'RBX2' NAMED

      FROM

          STH,

          GPTS

      WHERE

          GPTS.OCC_LNO = STH.LN_NUMBER

          AND STH.DEAL_TYPE NOT LIKE 'PY%'

          AND STH.WHITE_OFF = '0'

          AND STH.NXT_SEQUENCE = 0

          AND STH.INC_FLAG = 'Y'

          AND STH.NEXTDUEDT > LAST_DAY(ADD_MONTHS(GPTS.END_DATE, 1))

          AND  STH.DEAL_TYPE NOT IN ('PRP','PRA','IVT', 'NLD' )

          AND

          EXISTS(

               SELECT 1 FROM STM

               WHERE 

                     GPTS.OCC_LNO = STM.LN_NUMBER 

                     AND NOT(STH.DEAL_TYPE = 'SPR' AND STM.INT_TYPE <> 5)

          )

      ;

      Execution plan:

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

      | Id  | Operation                      | Name               | Rows  | Bytes | Cost (%CPU)| Time     |     

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

      |   0 | SELECT STATEMENT               |                    |       |       |  6046K(100)|          |     

      |   1 |  NESTED LOOPS                  |                    |       |       |            |          |     

      |   2 |   NESTED LOOPS                 |                    | 45728 |  2322K|  2407K  (1)| 08:01:36 |     

      |   3 |    TABLE ACCESS FULL           | gpts               |   400K|  7437K|  1097   (1)| 00:00:14 |     

      |*  4 |    INDEX RANGE SCAN            | sth_IDX5           |     3 |       |     3   (0)| 00:00:01 |     

      |*  5 |     TABLE ACCESS BY INDEX ROWID| stm                |     1 |    13 |     4   (0)| 00:00:01 |     

      |*  6 |      INDEX RANGE SCAN          | stm_IDX2           |     1 |       |     3   (0)| 00:00:01 |     

      |*  7 |   TABLE ACCESS BY INDEX ROWID  | sth                |     1 |    33 |     6   (0)| 00:00:01 |     

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

                                                                                                               

      Query Block Name / Object Alias (identified by operation id):                                             

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

                                                                                                               

         1 - SEL$1                                                                                              

         3 - SEL$1 / gpts@SEL$1                                                                   

         4 - SEL$1 / sth@SEL$1                                                                          

         5 - SEL$2 / stm@SEL$2                                                                          

         6 - SEL$2 / stm@SEL$2                                                                          

         7 - SEL$1 / sth@SEL$1                                                                          

                                                                                                               

      Outline Data                                                                                              

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

                                                                                                               

        /*+                                                                                                     

            BEGIN_OUTLINE_DATA                                                                                  

            IGNORE_OPTIM_EMBEDDED_HINTS                                                                         

            OPTIMIZER_FEATURES_ENABLE('11.2.0.3')                                                               

            DB_VERSION('11.2.0.3')                                                                              

            ALL_ROWS                                                                                            

            OUTLINE_LEAF(@"SEL$2")                                                                              

            OUTLINE_LEAF(@"SEL$1")                                                                              

            FULL(@"SEL$1" "gpts"@"SEL$1")                                                         

            INDEX(@"SEL$1" "sth"@"SEL$1" ("sth"."ln_number" "sth"."deal_type"            

                    "sth"."rep_period" "sth"."nxt_sequence"))                             

            LEADING(@"SEL$1" "gpts"@"SEL$1" "sth"@"SEL$1")                                

            USE_NL(@"SEL$1" "sth"@"SEL$1")                                                              

            NLJ_BATCHING(@"SEL$1" "sth"@"SEL$1")                                                        

            PUSH_SUBQ(@"SEL$2")                                                                                 

            INDEX_RS_ASC(@"SEL$2" "stm"@"SEL$2" ("stm"."ln_number"))                           

            END_OUTLINE_DATA                                                                                    

        */                                                                                                      

                                                                                                               

      Predicate Information (identified by operation id):                                                       

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

                                                                                                               

         4 - access("gpts"."occ_lno"="sth"."ln_number" AND                          

                    "sth"."nxt_sequence"=0)                                                             

             filter(("sth"."nxt_sequence"=0 AND "sth"."deal_type"<>'PRP' AND                      

                    "sth"."deal_type"<>'NLD' AND "sth"."deal_type"<>'IVT' AND                       

                    "sth"."deal_type"<>'PRA' AND "sth"."deal_type" NOT LIKE 'PY%' AND  IS NOT NULL))

         5 - filter((:B1<>'SPR' OR TO_NUMBER("stm"."INT_TYPE")=5))                                       

         6 - access("stm"."ln_number"=:B1)                                                             

         7 - filter(("sth"."white_off"='0' AND "sth"."inc_flag"='Y' AND "sth"."NEXTDUEDT">LAST_DAY(ADD_MONTHS(INTERNAL_FUNCTION("gpts"."end_date"),1))))                                                                        

                                                                                                               

      Column Projection Information (identified by operation id):                                               

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

                                                                                                               

         1 - "sth"."ln_number"[VARCHAR2,20], "sth"."PR_AMOUNT"[NUMBER,22]                        

         2 - "gpts"."end_date"[DATE,7], "sth".ROWID[ROWID,10],                 

             "sth"."ln_number"[VARCHAR2,20]                                                            

         3 - "gpts"."end_date"[DATE,7],                                                

             "gpts"."occ_lno"[VARCHAR2,20]                                                   

         4 - "sth".ROWID[ROWID,10], "sth"."ln_number"[VARCHAR2,20]                             

         6 - "stm".ROWID[ROWID,10]                                                                      

         7 - "sth"."PR_AMOUNT"[NUMBER,22] 

       

      If I see the query plan it is doing a NL join and that is where the cost is growing. I tried rewriting the query but no good.

      The stats are updated today itself.

       

      I want to understand and find the right way to do the root cause analysis. What is the correct approach? Please advise.

       

      Usually, I start with rewriting the query in different ways and check plan if there is any better. I also check if the stats are up-to-date (don't know about the HIstogram-thing).

       

      Please let me know if you need some ASH-related inputs or any other information.

       

       

      Thanks and Regards,

      -- Ranit

      ( on Oracle 11.2.0.3.0 - Exadata )

        • 1. Re: Reg: finding the root cause step-by-step...
          Ramin Hashimzadeh

          Have you got index on GPTS.OCC_LNO ???

          After execution /*+ GATHER_PLAN_STATISTICS */ show execution plan


           

          select * from table (dbms_xplan.display_cursor (format=>'ALLSTATS LAST'));

           


          ----

          Ramin Hashimzade

          • 2. Re: Reg: finding the root cause step-by-step...
            ranit B

            HI Ramin,

             

            What i posted is from:

            select * from table (dbms_xplan.display_cursor (format=>'ADVANCED'));

             

            Here is the execution plan you asked for:

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

            | Id  | Operation                      | Name               | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |    

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

            |   0 | SELECT STATEMENT               |                    |      1 |        |    191 |00:00:00.05 |   16259 |     37 |    

            |   1 |  NESTED LOOPS                  |                    |      1 |        |    191 |00:00:00.05 |   16259 |     37 |    

            |   2 |   NESTED LOOPS                 |                    |      1 |  45728 |   3742 |00:00:00.05 |   12614 |     37 |    

            |   3 |    TABLE ACCESS FULL           | gpts               |      1 |    400K|    934 |00:00:00.01 |     101 |     20 |    

            |*  4 |    INDEX RANGE SCAN            | sth_IDX5           |    934 |      3 |   3742 |00:00:00.05 |   12513 |     17 |    

            |*  5 |     TABLE ACCESS BY INDEX ROWID| stm                |   2468 |      1 |   2461 |00:00:00.02 |    9506 |     17 |    

            |*  6 |      INDEX RANGE SCAN          | stm_IDX2           |   2468 |      1 |   2468 |00:00:00.01 |    7038 |      0 |    

            |*  7 |   TABLE ACCESS BY INDEX ROWID  | sth                |   3742 |      1 |    191 |00:00:00.02 |    3645 |      0 |    

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

                                                                                                                                       

            Predicate Information (identified by operation id):                                                                         

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

                     

               4 - access("gpts"."occ_lno"="sth"."ln_number" AND                         

                          "sth"."nxt_sequence"=0)                                                            

                   filter(("sth"."nxt_sequence"=0 AND "sth"."deal_type"<>'PRP' AND                     

                          "sth"."deal_type"<>'NLD' AND "sth"."deal_type"<>'IVT' AND                      

                          "sth"."deal_type"<>'PRA' AND "sth"."deal_type" NOT LIKE 'PY%' AND  IS NOT NULL))

               5 - filter((:B1<>'SPR' OR TO_NUMBER("stm"."INT_TYPE")=5))                                      

               6 - access("stm"."ln_number"=:B1)                                                            

               7 - filter(("sth"."white_off"='0' AND "sth"."inc_flag"='Y' AND                     

                          "sth"."NEXTDUEDT">LAST_DAY(ADD_MONTHS(INTERNAL_FUNCTION("gpts"."end_date"),1))))

             

            Regarding indexes:

            No, I don't have index on GPTS table column.

             

            Record count:

            STH - 186,885,633

            GPTS - 400,860

            STM - 3,186,973

             

            Actual output row count of the query should be - 113,782

             

            Please advise.

            • 3. Re: Reg: finding the root cause step-by-step...
              Ramin Hashimzadeh

              ok

              please gather stats for table GPTS as

              begin

                DBMS_STATS.gather_table_stats(ownname           => '<owner>',

                                              tabname           => 'GPTS',

                                               cascade          => true); 

              end;

              then give execution plan again

              select * from table (dbms_xplan.display_cursor (format=>'ALLSTATS LAST'));

               

              also please give sql result for

              select t.index_name,

                       t.index_type,

                       c.COLUMN_NAME             

              from user_indexes t

              join user_ind_columns c

              on c.INDEX_NAME = t.index_name

              where t.table_name = 'GPTS'

               

              P.S i Think creating index on table GPTS for column OCC_LNO will increase your performance .


              ----

              Ramin Hashimzade

              • 4. Re: Reg: finding the root cause step-by-step...
                Hemant K Chitale

                What is the "performance hit" ?

                 

                This shows that the execution time is less than a second

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

                | Id  | Operation                      | Name               | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |    

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

                |   0 | SELECT STATEMENT               |                    |      1 |        |    191 |00:00:00.05 |   16259 |     37 |    

                 

                 

                 

                Hemant K Chitale

                • 5. Re: Reg: finding the root cause step-by-step...
                  ranit B

                  Hi Hemant,

                   

                  That could be because my client IDE has prefetch of 100 rows.

                  I even doubt if this execution plan is proper because in steps - 4,5,6,7 - cardinality is 1 and 3, which looks very unusual. My table and index has huge no of records.

                   

                  Please advise.

                  • 6. Re: Reg: finding the root cause step-by-step...
                    Dom Brooks

                    > I even doubt if this execution plan is proper because in steps - 4,5,6,7 - cardinality is 1 and 3, which looks very unusual. My table and index has huge no of records

                    Lines 4-7 refer to the inner rowsources of a nested loop.

                    Therefore the estimate refers to the number of rows per start.

                    • 7. Re: Reg: finding the root cause step-by-step...
                      ranit B

                      Hello Dom,

                      Thanks for your response, but I still didn't get your point "number of rows per start"

                       

                      |*  4 |    INDEX RANGE SCAN            | sth_IDX5           |     3 |       |     3   (0)| 00:00:01 |     

                      |*  5 |     TABLE ACCESS BY INDEX ROWID| stm                |     1 |    13 |     4   (0)| 00:00:01 |     

                      |*  6 |      INDEX RANGE SCAN          | stm_IDX2           |     1 |       |     3   (0)| 00:00:01 |     

                      |*  7 |   TABLE ACCESS BY INDEX ROWID  | sth                |     1 |    33 |     6   (0)| 00:00:01 |     

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

                        

                      Here I am checking the 1st execution plan of my post, taken by setting format => 'ALL'

                      • 8. Re: Reg: finding the root cause step-by-step...
                        Mohamed Houri

                        Ranit


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

                        | Id  | Operation                      | Name               | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |   

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

                        |   0 | SELECT STATEMENT               |                    |      1 |        |    191 |00:00:00.05 |   16259 |     37 |   

                        |   1 |  NESTED LOOPS                  |                    |      1 |        |    191 |00:00:00.05 |   16259 |     37 |   

                        |   2 |   NESTED LOOPS                 |                    |      1 |  45728 |   3742 |00:00:00.05 |   12614 |     37 |   

                        |   3 |    TABLE ACCESS FULL           | gpts               |      1 |    400K|    934 |00:00:00.01 |     101 |     20 |   

                        |*  4 |    INDEX RANGE SCAN            | sth_IDX5           |    934 |      3 |   3742 |00:00:00.05 |   12513 |     17 |   

                        |*  5 |     TABLE ACCESS BY INDEX ROWID| stm                |   2468 |      1 |   2461 |00:00:00.02 |    9506 |     17 |   

                        |*  6 |      INDEX RANGE SCAN          | stm_IDX2           |   2468 |      1 |   2468 |00:00:00.01 |    7038 |      0 |   

                        |*  7 |   TABLE ACCESS BY INDEX ROWID  | sth                |   3742 |      1 |    191 |00:00:00.02 |    3645 |      0 |   

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


                        When you consider the Estimated Rows of operations 5,6 and 7 (for example) you should compare Starts*E-Rows  to the Actual Rows (A-Rows).

                         

                         

                         

                        For example the number of rows that Oracle Estimated for operation 5 is Starts(2468) * E-Rows (1) = 2468 which is close to the Actual Rows(2461) produced by this operation

                         

                         

                         

                        Best regards

                        Mohamed Houri

                        • 9. Re: Reg: finding the root cause step-by-step...
                          ranit B

                          When you consider the Estimated Rows of operations 5,6 and 7 (for example) you should compare Starts*E-Rows  to the Actual Rows (A-Rows).

                           

                          For example the number of rows that Oracle Estimated for operation 5 is Starts(2468) * E-Rows (1) = 2468 which is close to the Actual Rows(2461) produced by this operation

                          Then why not for step-4 ?

                          934*3 = 2802 smaller than A-rows = 3742.

                           

                          And, what if i consider my execution plan 1 :

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

                          | Id  | Operation                      | Name               | Rows  | Bytes | Cost (%CPU)| Time     |     

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

                          |   0 | SELECT STATEMENT               |                    |       |       |  6046K(100)|          |     

                          |   1 |  NESTED LOOPS                  |                    |       |       |            |          |     

                          |   2 |   NESTED LOOPS                 |                    | 45728 |  2322K|  2407K  (1)| 08:01:36 |     

                          |   3 |    TABLE ACCESS FULL           | gpts               |   400K|  7437K|  1097   (1)| 00:00:14 |     

                          |*  4 |    INDEX RANGE SCAN            | sth_IDX5           |     3 |       |     3   (0)| 00:00:01 |     

                          |*  5 |     TABLE ACCESS BY INDEX ROWID| stm                |     1 |    13 |     4   (0)| 00:00:01 |     

                          |*  6 |      INDEX RANGE SCAN          | stm_IDX2           |     1 |       |     3   (0)| 00:00:01 |     

                          |*  7 |   TABLE ACCESS BY INDEX ROWID  | sth                |     1 |    33 |     6   (0)| 00:00:01 |     

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

                           

                          The statistics are up to date, but still seems optimizer is not making proper cardinality estimates ("rows" column)

                          Please advise.

                          • 10. Re: Reg: finding the root cause step-by-step...
                            Dom Brooks

                            > Then why not for step-4 ?

                            > 934*3 = 2802 smaller than A-rows = 3742.

                            Same for step 4.

                            It's an estimate.

                            The optimizer is estimating join cardinalities based on the column statistics of the respective tables.

                            And I consider that estimate to be in the right ballpark.

                             

                            > And, what if i consider my execution plan 1

                            1. The estimated "starts" is just the number of rows driving the nested loop, i.e. 400K

                            2. Your table statistics are wrong. Your unfiltered full table scan of gpts is expected to return 400K and it only returns 932 rows.

                            • 11. Re: Reg: finding the root cause step-by-step...
                              Mohamed Houri

                              Could you try to instruct the CBO so that it will not unnest the subquery.

                               

                              Something like this

                               

                              SELECT /*+ GATHER_PLAN_STATISTICS */

                              STAGE5_GSE_QA.STH.PR_AMOUNT,

                              STAGE5_GSE_QA.STH.LN_NUMBER,

                                  'RBX2' NAMED

                              FROM

                                  STH,

                                  GPTS

                              WHERE

                                  GPTS.OCC_LNO = STH.LN_NUMBER

                                  AND STH.DEAL_TYPE NOT LIKE 'PY%'

                                  AND STH.WHITE_OFF = '0'

                                  AND STH.NXT_SEQUENCE = 0

                                  AND STH.INC_FLAG = 'Y'

                                  AND STH.NEXTDUEDT > LAST_DAY(ADD_MONTHS(GPTS.END_DATE, 1))

                                  AND  STH.DEAL_TYPE NOT IN ('PRP','PRA','IVT', 'NLD' )

                                  AND

                                  EXISTS(

                                       SELECT /*+ no_unnest */ 1 FROM STM

                                       WHERE

                              GPTS.OCC_LNO = STM.LN_NUMBER

                                             AND NOT(STH.DEAL_TYPE = 'SPR' AND STM.INT_TYPE <> 5)

                                  )

                              ;                                               

                               

                              There are 191 rows to be generated while the first part of the NESTED LOOP handles 3742 records (coming from index operation number 4) and which drives again operation n°7. May be with the

                              subquery not unnested the CBO will comes up with a plan that will eliminate records much earlier.

                               

                              And as Dom Brooks has already pointed it out, the CBO is not correctly estimating operation 3  (TABLE ACCESS FULL   | gpts) as far as it is predicting 400K while this operation produced only 934 rows.

                               

                              Are you selecting from GPTS table?

                               

                              I mean in the following select from what tables the column PR_AMOUNT, LN_NUMBER and NAMED are coming?

                               

                              SELECT /*+ GATHER_PLAN_STATISTICS */

                                  STAGE5_GSE_QA.STH.PR_AMOUNT,

                              STAGE5_GSE_QA.STH.LN_NUMBER,

                                  'RBX2' NAMED

                              FROM

                                  STH,

                                  GPTS

                               

                              If you are not selecting from GPTS then you could re-write your query to include GPTS table into the exist subquery

                               

                              Best regards

                              Mohamed Houri

                              • 12. Re: Reg: finding the root cause step-by-step...
                                Hemant K Chitale

                                >That could be because my client IDE has prefetch of 100 rows.

                                Meaning ?

                                Did you run the query to retrieve all the rows or stop at only 191 rows ?

                                 

                                 

                                Hemant K Chitale


                                • 13. Re: Reg: finding the root cause step-by-step...
                                  Ramin Hashimzadeh

                                  Hi Ranit

                                  Did you check what i was wrote in my prev post?

                                   

                                  ----

                                  Ramin Hashimzade

                                  • 14. Re: Reg: finding the root cause step-by-step...
                                    ranit B

                                    Hemant,

                                     

                                    I didn't fetch all the rows. I stopped at 191 rows.

                                     

                                    What is the correct method to measure the time taken to retrieve complete rows?

                                     

                                    1) Shall i go to IDE's output grid and do Ctrl+End which will take me to the last record,

                                    or

                                    2) Can I use SQL*Plus with SET TIMING ON and output off option (i.e. using SET AUTOTRACE . . .)

                                     

                                    Please advise.

                                    1 2 Previous Next