This discussion is archived
1 2 3 Previous Next 41 Replies Latest reply: Oct 18, 2012 1:39 PM by 439902 RSS

Hard Parse Time - too long...

439902 Newbie
Currently Being Moderated
We have a DSS type database (11G R2), which has all kinds of queries run against it. There is not one typical query that is generated by the app, and so, while we use bind variables (good practice), no two requests are alike.

Some of the queries may end up joining 10-20 tables (the same table actually gets used multiple times). While these are not difficult to generate, they do take time to parse. On a few queries I noticed that query itself might execute in 3-4 seconds, but because DB needs to do a hard parse, total time will be close to a minute.

Doing a query against V$SESS_TIME_MODEL shows "hard parse elapsed time" = 45,709,571.

Is there any way to help speed up the process? Our tables/indexes are mostly cached due to system using the same set over and over again, so it seems impractical that DB would spend so much time parsing...

Any help/suggestions would be much appreciated.

Thank you in advance.

--Alex                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           
  • 1. Re: Hard Parse Time - too long...
    rp0428 Guru
    Currently Being Moderated
    >
    Doing a query against V$SESS_TIME_MODEL shows "hard parse elapsed time" = 45,709,571.

    Is there any way to help speed up the process? Our tables/indexes are mostly cached due to system using the same set over and over again, so it seems impractical that DB would spend so much time parsing...
    >
    Is that 46 second time for one query? To get anything close to accurate you need to check the time in a new session that has only run the one query.

    See the two threads referenced here for how to post a tuning request and the information needed.
    SQL and PL/SQL FAQ

    Post the execution plan or trace, the query and the DDL for the tables and indexes involved, the table row counts and information about the filter predicate selectivity.

    Are statistics up to date for all of the tables and indexes involved? Post the commands you are using to collect the statistics.
  • 2. Re: Hard Parse Time - too long...
    439902 Newbie
    Currently Being Moderated
    Yes, this is for one query. On a flushed DB (buffer pool/shared pool), a single query was executed in a SQLPlus window. Keeping the window open (to be able to track its SID), SYSTEM account was used to execute:
    select * from V$SESS_TIME_MODEL where SID=NN;
    Among other values, here are the ones reported:
    STAT_NAME     VALUE
    DB time     48533918
    DB CPU     42158590
    parse time elapsed     45739291
    hard parse elapsed time     45734101
    PL/SQL execution elapsed time     247
    inbound PL/SQL rpc elapsed time     0
    PL/SQL compilation elapsed time     7151
    Java execution elapsed time     0
    repeated bind elapsed time     1500
    RMAN cpu time (backup/restore)     0


    Statistics are up to date (100% sampling).


    Query is long:
    SELECT
        COUNT (DISTINCT ent_000000.pk)
    FROM entity ent_000000 
        INNER JOIN recordtextvalue val_000002
            ON val_000002.sourceentityfk = ent_000000.pk
            AND val_000002.fieldfk = HEXTORAW ('80B58FEACC79E011AD2400155D018001')
            AND (   LOWER (val_000002.VALUE) LIKE LOWER ('%1%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%2%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%3%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%4%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%5%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%6%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%7%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%8%') ESCAPE '~'
                 )
        INNER JOIN recordsinglechoicevalue val_000012
            ON val_000012.sourceentityfk = ent_000000.pk
            AND val_000012.fieldfk = HEXTORAW ('8DB58FEACC79E011AD2400155D018001')
        INNER JOIN record_ rec_000014
            ON rec_000014.pk = val_000012.recordfk
            AND rec_000014.entityfk = val_000012.sourceentityfk
            AND rec_000014.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
        INNER JOIN
           (SELECT  
                MAX (rec_000016.TIMESTAMP) AS TIMESTAMP, 
                rec_000016.entityfk AS groupkey
            FROM record_ rec_000016 
                INNER JOIN recordsinglechoicevalue val_000018
                    ON val_000018.recordfk = rec_000016.pk
                    AND val_000018.sourceentityfk = rec_000016.entityfk
                    AND val_000018.fieldfk = HEXTORAW ('8DB58FEACC79E011AD2400155D018001')
            WHERE 1 = 1 
                AND rec_000016.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
            GROUP BY rec_000016.entityfk
            ) tbl_000020
            ON tbl_000020.TIMESTAMP = rec_000014.TIMESTAMP 
            AND tbl_000020.groupkey = rec_000014.entityfk
        INNER JOIN recordsinglechoicevalue val_000021
            ON val_000021.sourceentityfk = ent_000000.pk
            AND val_000021.fieldfk = HEXTORAW ('AF5F45338C58DE4CB3833AD9D54351A7')
        INNER JOIN record_ rec_000023
            ON rec_000023.pk = val_000021.recordfk
            AND rec_000023.entityfk = val_000021.sourceentityfk
            AND rec_000023.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
        JOIN
           (SELECT   MIN (rec_000025.TIMESTAMP) AS TIMESTAMP, rec_000025.entityfk AS groupkey
                FROM record_ rec_000025 INNER JOIN recordsinglechoicevalue val_000027
                     ON val_000027.recordfk = rec_000025.pk
                   AND val_000027.sourceentityfk = rec_000025.entityfk
                   AND val_000027.fieldfk = HEXTORAW ('AF5F45338C58DE4CB3833AD9D54351A7')
               WHERE 1 = 1 AND rec_000025.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
            GROUP BY rec_000025.entityfk) tbl_000029
            ON tbl_000029.TIMESTAMP = rec_000023.TIMESTAMP
            AND tbl_000029.groupkey = rec_000023.entityfk
            AND val_000021.choicefk IN
                (HEXTORAW ('A038588B67E6C6418360E92AB231EA30'),
                 HEXTORAW ('DA6E7059FB243F40B97CF91BA75EE532'),
                 HEXTORAW ('DA6BE7C37D157A4BBD34032F76983916')
                )
        INNER JOIN record_ val_000033
            ON val_000033.pk = rec_000023.pk
            AND val_000033.entityfk = rec_000023.entityfk
            AND val_000033.TIMESTAMP IS NOT NULL
            AND val_000033.recordtypefk IN (SELECT rt.pk
                                           FROM recordtype rt JOIN recordtypemember rtm ON rtm.recordtypefk = rt.pk
                                          WHERE rtm.fieldfk = HEXTORAW ('83B58FEACC79E011AD2400155D018001'))
            AND val_000033.TIMESTAMP >= TO_DATE ('1/1/1925 12:00:00 AM', 'MM/DD/YYYY HH:MI:SS AM')
        INNER JOIN recordsinglechoicevalue val_000036
            ON val_000036.sourceentityfk = ent_000000.pk
            AND val_000036.fieldfk = HEXTORAW ('125A01C9DAF726448D8DB1F7B27091DE')
        INNER JOIN record_ rec_000038
            ON rec_000038.pk = val_000036.recordfk
            AND rec_000038.entityfk = val_000036.sourceentityfk
            AND rec_000038.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
        JOIN
            (SELECT   MIN (rec_000040.TIMESTAMP) AS TIMESTAMP, rec_000040.entityfk AS groupkey
                FROM record_ rec_000040 INNER JOIN recordsinglechoicevalue val_000042
                     ON val_000042.recordfk = rec_000040.pk
                   AND val_000042.sourceentityfk = rec_000040.entityfk
                   AND val_000042.fieldfk = HEXTORAW ('125A01C9DAF726448D8DB1F7B27091DE')
               WHERE 1 = 1 AND rec_000040.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
            GROUP BY rec_000040.entityfk) tbl_000044
            ON tbl_000044.TIMESTAMP = rec_000038.TIMESTAMP
            AND tbl_000044.groupkey = rec_000038.entityfk
            AND val_000036.choicefk IN
                (HEXTORAW ('9DDEB479A5F44C4AB9C03B0FBE2CCD89'),
                 HEXTORAW ('723CBD322AB52B439E9160F29BB27E17'),
                 HEXTORAW ('492F484AD5FED04893F82F4824F1B5E2'),
                 HEXTORAW ('C3F9C1F514AFB146A0F4BABAA2577B84')
                )
        INNER JOIN record_ val_000049
            ON val_000049.entityfk = ent_000000.pk
            AND 'Diagnosis' IS NOT NULL
            AND val_000049.recordtypefk IN (SELECT rt.pk
                                           FROM recordtype rt JOIN recordtypemember rtm ON rtm.recordtypefk = rt.pk
                                          WHERE rtm.fieldfk = HEXTORAW ('F85D675BF5D04448A608F9479A653BD3')) 
     WHERE 1 = 1 
     AND ent_000000.entitytypefk = HEXTORAW ('66B9B948F000DB1192370014A5726350')
    ;
    ... and here is the explain plan for it:
    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 1632407278
    
    -----------------------------------------------------------------------------------------------------------------------------------------------
    | Id  | Operation                                     | Name                          | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
    -----------------------------------------------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT                              |                               |     1 |    10 |  1331   (6)| 00:00:01 |       |       |
    |   1 |  SORT AGGREGATE                               |                               |     1 |    10 |            |          |       |       |
    |   2 |   VIEW                                        | VM_NWVW_1                     |     1 |    10 |  1331   (6)| 00:00:01 |       |       |
    |   3 |    HASH GROUP BY                              |                               |     1 |   581 |  1331   (6)| 00:00:01 |       |       |
    |   4 |     NESTED LOOPS                              |                               |     1 |   581 |  1330   (6)| 00:00:01 |       |       |
    |   5 |      NESTED LOOPS                             |                               |     1 |   568 |  1326   (6)| 00:00:01 |       |       |
    |   6 |       NESTED LOOPS                            |                               |     1 |   515 |  1324   (6)| 00:00:01 |       |       |
    |   7 |        NESTED LOOPS                           |                               |     1 |   502 |  1319   (6)| 00:00:01 |       |       |
    |   8 |         NESTED LOOPS SEMI                     |                               |     1 |   449 |  1317   (6)| 00:00:01 |       |       |
    |   9 |          NESTED LOOPS                         |                               |     1 |   415 |  1316   (6)| 00:00:01 |       |       |
    |  10 |           NESTED LOOPS                        |                               |     1 |   402 |  1311   (6)| 00:00:01 |       |       |
    |  11 |            NESTED LOOPS                       |                               |     4 |  1396 |  1303   (6)| 00:00:01 |       |       |
    |  12 |             NESTED LOOPS                      |                               |     4 |  1156 |  1295   (6)| 00:00:01 |       |       |
    |* 13 |              HASH JOIN                        |                               |     4 |   952 |  1291   (6)| 00:00:01 |       |       |
    |* 14 |               HASH JOIN                       |                               |    21 |  3570 |  1284   (6)| 00:00:01 |       |       |
    |  15 |                PARTITION HASH SINGLE          |                               |   293 | 19924 |     4   (0)| 00:00:01 |    98 |    98 |
    |  16 |                 INLIST ITERATOR               |                               |       |       |            |          |       |       |
    |* 17 |                  INDEX RANGE SCAN             | RDSINGLECHOICEVALUE_CFER_IDX  |   293 | 19924 |     4   (0)| 00:00:01 |    98 |    98 |
    |* 18 |                HASH JOIN                      |                               |  1186 |   118K|  1280   (6)| 00:00:01 |       |       |
    |* 19 |                 INDEX RANGE SCAN              | ENTITY_TYPE_PK_IDX            | 16538 |   549K|    19   (6)| 00:00:01 |       |       |
    |  20 |                 NESTED LOOPS                  |                               |   146K|  9749K|  1257   (6)| 00:00:01 |       |       |
    |  21 |                  SORT UNIQUE                  |                               |     1 |    34 |     2   (0)| 00:00:01 |       |       |
    |* 22 |                   INDEX RANGE SCAN            | RDTYPEMEMBER_FIELD_RDTYPE_IDX |     1 |    34 |     2   (0)| 00:00:01 |       |       |
    |* 23 |                  INDEX RANGE SCAN             | RECORD_TYPE_ENTITY_PK_IDX     |   141K|  4693K|  1254   (6)| 00:00:01 |       |       |
    |  24 |               PARTITION HASH SINGLE           |                               |  3300 |   219K|     6   (0)| 00:00:01 |    30 |    30 |
    |  25 |                INLIST ITERATOR                |                               |       |       |            |          |       |       |
    |* 26 |                 INDEX RANGE SCAN              | RDSINGLECHOICEVALUE_CFER_IDX  |  3300 |   219K|     6   (0)| 00:00:01 |    30 |    30 |
    |  27 |              PARTITION HASH SINGLE            |                               |     1 |    51 |     1   (0)| 00:00:01 |     9 |     9 |
    |* 28 |               INDEX RANGE SCAN                | RDSINGLECHOICEVALUE_EFR_IDX   |     1 |    51 |     1   (0)| 00:00:01 |     9 |     9 |
    |  29 |             PARTITION HASH SINGLE             |                               |     1 |    60 |     2   (0)| 00:00:01 |     5 |     5 |
    |* 30 |              TABLE ACCESS BY LOCAL INDEX ROWID| RECORDTEXTVALUE               |     1 |    60 |     2   (0)| 00:00:01 |     5 |     5 |
    |* 31 |               INDEX RANGE SCAN                | RDTEXTVALUE_EFR_IDX           |     1 |       |     1   (0)| 00:00:01 |     5 |     5 |
    |* 32 |            TABLE ACCESS BY INDEX ROWID        | RECORD_                       |     1 |    53 |     2   (0)| 00:00:01 |       |       |
    |* 33 |             INDEX UNIQUE SCAN                 | RECORD_TYPE_ENTITY_PK_IDX     |     1 |       |     1   (0)| 00:00:01 |       |       |
    |* 34 |           VIEW PUSHED PREDICATE               |                               |     1 |    13 |     5  (20)| 00:00:01 |       |       |
    |* 35 |            FILTER                             |                               |       |       |            |          |       |       |
    |  36 |             SORT AGGREGATE                    |                               |     1 |    73 |            |          |       |       |
    |  37 |              NESTED LOOPS                     |                               |       |       |            |          |       |       |
    |  38 |               NESTED LOOPS                    |                               |     1 |    73 |     5  (20)| 00:00:01 |       |       |
    |  39 |                VIEW                           | VW_GBF_11                     |     1 |    20 |     3  (34)| 00:00:01 |       |       |
    |  40 |                 SORT GROUP BY                 |                               |     1 |    51 |     3  (34)| 00:00:01 |       |       |
    |  41 |                  PARTITION HASH SINGLE        |                               |     1 |    51 |     2   (0)| 00:00:01 |    98 |    98 |
    |* 42 |                   INDEX RANGE SCAN            | RDSINGLECHOICEVALUE_EFR_IDX   |     1 |    51 |     2   (0)| 00:00:01 |    98 |    98 |
    |* 43 |                INDEX UNIQUE SCAN              | RECORD_TYPE_ENTITY_PK_IDX     |     1 |       |     1   (0)| 00:00:01 |       |       |
    |  44 |               TABLE ACCESS BY INDEX ROWID     | RECORD_                       |     1 |    53 |     2   (0)| 00:00:01 |       |       |
    |* 45 |          INDEX RANGE SCAN                     | RDTYPEMEMBER_FIELD_RDTYPE_IDX |     1 |    34 |     1   (0)| 00:00:01 |       |       |
    |* 46 |         TABLE ACCESS BY INDEX ROWID           | RECORD_                       |     1 |    53 |     2   (0)| 00:00:01 |       |       |
    |* 47 |          INDEX UNIQUE SCAN                    | RECORD_TYPE_ENTITY_PK_IDX     |     1 |       |     1   (0)| 00:00:01 |       |       |
    |* 48 |        VIEW PUSHED PREDICATE                  |                               |     1 |    13 |     5  (20)| 00:00:01 |       |       |
    |* 49 |         FILTER                                |                               |       |       |            |          |       |       |
    |  50 |          SORT AGGREGATE                       |                               |     1 |    73 |            |          |       |       |
    |  51 |           NESTED LOOPS                        |                               |       |       |            |          |       |       |
    |  52 |            NESTED LOOPS                       |                               |     1 |    73 |     5  (20)| 00:00:01 |       |       |
    |  53 |             VIEW                              | VW_GBF_17                     |     1 |    20 |     3  (34)| 00:00:01 |       |       |
    |  54 |              SORT GROUP BY                    |                               |     1 |    51 |     3  (34)| 00:00:01 |       |       |
    |  55 |               PARTITION HASH SINGLE           |                               |     1 |    51 |     2   (0)| 00:00:01 |    30 |    30 |
    |* 56 |                INDEX RANGE SCAN               | RDSINGLECHOICEVALUE_EFR_IDX   |     1 |    51 |     2   (0)| 00:00:01 |    30 |    30 |
    |* 57 |             INDEX UNIQUE SCAN                 | RECORD_TYPE_ENTITY_PK_IDX     |     1 |       |     1   (0)| 00:00:01 |       |       |
    |  58 |            TABLE ACCESS BY INDEX ROWID        | RECORD_                       |     1 |    53 |     2   (0)| 00:00:01 |       |       |
    |* 59 |       TABLE ACCESS BY INDEX ROWID             | RECORD_                       |     1 |    53 |     2   (0)| 00:00:01 |       |       |
    |* 60 |        INDEX UNIQUE SCAN                      | RECORD_TYPE_ENTITY_PK_IDX     |     1 |       |     1   (0)| 00:00:01 |       |       |
    |* 61 |      VIEW PUSHED PREDICATE                    |                               |     1 |    13 |     4   (0)| 00:00:01 |       |       |
    |* 62 |       FILTER                                  |                               |       |       |            |          |       |       |
    |  63 |        SORT AGGREGATE                         |                               |     1 |   104 |            |          |       |       |
    |  64 |         NESTED LOOPS                          |                               |       |       |            |          |       |       |
    |  65 |          NESTED LOOPS                         |                               |     1 |   104 |     4   (0)| 00:00:01 |       |       |
    |  66 |           PARTITION HASH SINGLE               |                               |     1 |    51 |     2   (0)| 00:00:01 |     9 |     9 |
    |* 67 |            INDEX RANGE SCAN                   | RDSINGLECHOICEVALUE_EFR_IDX   |     1 |    51 |     2   (0)| 00:00:01 |     9 |     9 |
    |* 68 |           INDEX UNIQUE SCAN                   | RECORD_TYPE_ENTITY_PK_IDX     |     1 |       |     1   (0)| 00:00:01 |       |       |
    |  69 |          TABLE ACCESS BY INDEX ROWID          | RECORD_                       |     1 |    53 |     2   (0)| 00:00:01 |       |       |
    -----------------------------------------------------------------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
      13 - access("VAL_000036"."SOURCEENTITYFK"="ENT_000000"."PK")
      14 - access("VAL_000021"."SOURCEENTITYFK"="ENT_000000"."PK")
      17 - access(("VAL_000021"."CHOICEFK"=HEXTORAW('A038588B67E6C6418360E92AB231EA30')  OR
                  "VAL_000021"."CHOICEFK"=HEXTORAW('DA6BE7C37D157A4BBD34032F76983916')  OR
                  "VAL_000021"."CHOICEFK"=HEXTORAW('DA6E7059FB243F40B97CF91BA75EE532') ) AND
                  "VAL_000021"."FIELDFK"=HEXTORAW('AF5F45338C58DE4CB3833AD9D54351A7') )
      18 - access("VAL_000049"."ENTITYFK"="ENT_000000"."PK")
      19 - access("ENT_000000"."ENTITYTYPEFK"=HEXTORAW('66B9B948F000DB1192370014A5726350') )
      22 - access("RTM"."FIELDFK"=HEXTORAW('F85D675BF5D04448A608F9479A653BD3') )
      23 - access("VAL_000049"."RECORDTYPEFK"="RTM"."RECORDTYPEFK")
      26 - access(("VAL_000036"."CHOICEFK"=HEXTORAW('492F484AD5FED04893F82F4824F1B5E2')  OR
                  "VAL_000036"."CHOICEFK"=HEXTORAW('723CBD322AB52B439E9160F29BB27E17')  OR
                  "VAL_000036"."CHOICEFK"=HEXTORAW('9DDEB479A5F44C4AB9C03B0FBE2CCD89')  OR
                  "VAL_000036"."CHOICEFK"=HEXTORAW('C3F9C1F514AFB146A0F4BABAA2577B84') ) AND
                  "VAL_000036"."FIELDFK"=HEXTORAW('125A01C9DAF726448D8DB1F7B27091DE') )
      28 - access("VAL_000012"."SOURCEENTITYFK"="ENT_000000"."PK" AND "VAL_000012"."FIELDFK"=HEXTORAW('8DB58FEACC79E011AD2400155D018001') )
      30 - filter(LOWER("VAL_000002"."VALUE") LIKE U'%1%' ESCAPE U'~' OR LOWER("VAL_000002"."VALUE") LIKE U'%2%' ESCAPE U'~' OR
                  LOWER("VAL_000002"."VALUE") LIKE U'%3%' ESCAPE U'~' OR LOWER("VAL_000002"."VALUE") LIKE U'%4%' ESCAPE U'~' OR
                  LOWER("VAL_000002"."VALUE") LIKE U'%5%' ESCAPE U'~' OR LOWER("VAL_000002"."VALUE") LIKE U'%6%' ESCAPE U'~' OR
                  LOWER("VAL_000002"."VALUE") LIKE U'%7%' ESCAPE U'~' OR LOWER("VAL_000002"."VALUE") LIKE U'%8%' ESCAPE U'~')
      31 - access("VAL_000002"."SOURCEENTITYFK"="ENT_000000"."PK" AND "VAL_000002"."FIELDFK"=HEXTORAW('80B58FEACC79E011AD2400155D018001') )
      32 - filter("VAL_000033"."TIMESTAMP">=TIMESTAMP' 1925-01-01 00:00:00')
      33 - access("RECORDTYPEFK"=HEXTORAW('7EB58FEACC79E011AD2400155D018001')  AND "ENTITYFK"="VAL_000021"."SOURCEENTITYFK" AND
                  "VAL_000021"."RECORDFK"="VAL_000033"."PK")
      34 - filter("TBL_000029"."TIMESTAMP"="TIMESTAMP")
      35 - filter(COUNT(*)>0 AND MIN("REC_000025"."TIMESTAMP")>=TIMESTAMP' 1925-01-01 00:00:00')
      42 - access("VAL_000027"."SOURCEENTITYFK"="ENTITYFK" AND "VAL_000027"."FIELDFK"=HEXTORAW('AF5F45338C58DE4CB3833AD9D54351A7') )
      43 - access("REC_000025"."RECORDTYPEFK"=HEXTORAW('7EB58FEACC79E011AD2400155D018001')  AND "REC_000025"."ENTITYFK"="ENTITYFK" AND
                  "ITEM_2"="REC_000025"."PK")
           filter("ITEM_1"="REC_000025"."ENTITYFK")
      45 - access("RTM"."FIELDFK"=HEXTORAW('83B58FEACC79E011AD2400155D018001')  AND
                  "RTM"."RECORDTYPEFK"=HEXTORAW('7EB58FEACC79E011AD2400155D018001') )
           filter("VAL_000033"."RECORDTYPEFK"="RTM"."RECORDTYPEFK")
      46 - filter("REC_000038"."TIMESTAMP" IS NOT NULL)
      47 - access("REC_000038"."RECORDTYPEFK"=HEXTORAW('7EB58FEACC79E011AD2400155D018001')  AND
                  "REC_000038"."ENTITYFK"="VAL_000036"."SOURCEENTITYFK" AND "REC_000038"."PK"="VAL_000036"."RECORDFK")
      48 - filter("TBL_000044"."TIMESTAMP"="REC_000038"."TIMESTAMP")
      49 - filter(COUNT(*)>0)
      56 - access("VAL_000042"."SOURCEENTITYFK"="REC_000038"."ENTITYFK" AND
                  "VAL_000042"."FIELDFK"=HEXTORAW('125A01C9DAF726448D8DB1F7B27091DE') )
      57 - access("REC_000040"."RECORDTYPEFK"=HEXTORAW('7EB58FEACC79E011AD2400155D018001')  AND
                  "REC_000040"."ENTITYFK"="REC_000038"."ENTITYFK" AND "ITEM_2"="REC_000040"."PK")
           filter("ITEM_1"="REC_000040"."ENTITYFK")
      59 - filter("REC_000014"."TIMESTAMP" IS NOT NULL)
      60 - access("REC_000014"."RECORDTYPEFK"=HEXTORAW('7EB58FEACC79E011AD2400155D018001')  AND
                  "REC_000014"."ENTITYFK"="VAL_000012"."SOURCEENTITYFK" AND "REC_000014"."PK"="VAL_000012"."RECORDFK")
      61 - filter("TBL_000020"."TIMESTAMP"="REC_000014"."TIMESTAMP")
      62 - filter(COUNT(*)>0)
      67 - access("VAL_000018"."SOURCEENTITYFK"="REC_000014"."ENTITYFK" AND
                  "VAL_000018"."FIELDFK"=HEXTORAW('8DB58FEACC79E011AD2400155D018001') )
      68 - access("REC_000016"."RECORDTYPEFK"=HEXTORAW('7EB58FEACC79E011AD2400155D018001')  AND
                  "REC_000016"."ENTITYFK"="REC_000014"."ENTITYFK" AND "VAL_000018"."RECORDFK"="REC_000016"."PK")
           filter("VAL_000018"."SOURCEENTITYFK"="REC_000016"."ENTITYFK")
    
    Note
    -----
       - dynamic sampling used for this statement (level=4)
       - automatic DOP: Computed Degree of Parallelism is 1 because of parallel threshold
    
    
    Statistics
    ----------------------------------------------------------
              0  recursive calls
              0  db block gets
          30331  consistent gets
              0  physical reads
              0  redo size
            367  bytes sent via SQL*Net to client
            364  bytes received via SQL*Net from client
              2  SQL*Net roundtrips to/from client
           5179  sorts (memory)
              0  sorts (disk)
              1  rows processed
    
    SQL>
    Record***Value tables are all partitioned by FieldFk (64 partitions by hash).


    Thank you!

    --Alex

    Edited by: al**** on Oct 12, 2012 6:15 PM

    Edited by: al**** on Oct 12, 2012 6:16 PM

    Edited by: al**** on Oct 12, 2012 6:17 PM

    Edited by: al**** on Oct 12, 2012 6:17 PM
  • 3. Re: Hard Parse Time - too long...
    rp0428 Guru
    Currently Being Moderated
    Thanks for the information but please edit that last reply and put \
     tags on the line before and the line after the code to preserve formatting. See the FAQ for other formatting options. Most volunteers won't even bother looking at unformatted code content; it's to hard to follow.
    
    One thing I noticed is that although you said
    {quote}
    Statistics are up to date (100% sampling).
    {quote}
    The query is using dynamic sampling. With that many tables that could account for a significant fraction of the parse time.
    {quote}
    - dynamic sampling used for this statement (level=4)
    {quote}
    That typically means that Oracle will sample 64 blocks from each sampled table.
    
    See Maria Colgan's article about 'Dynamic sampling and its impact on the Optimizer '.
    https://blogs.oracle.com/optimizer/entry/dynamic_sampling_and_its_impact_on_the_optimizer
    
    Ms. Colgan is a member of the Oracle Optimizer development team and has many other good articles on her site.
    
    See also chap 13 Managing Optimizer Statistics in the Performance Tuning Guide
    http://docs.oracle.com/cd/E25178_01/server.1111/e16638/stats.htm                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                            
  • 4. Re: Hard Parse Time - too long...
    439902 Newbie
    Currently Being Moderated
    Thank you for the pointers on formatting and such...

    I have experimented with various degrees of Dynamic Sampling, all to no avail...
    From 0 all the way up to 7. There is no difference in the parse/execute times - for this particular query.

    We leave it at 4, only to satisfy the queries that are not potentially covered by indexes (in the odd chance that our DSS needs to support something that is not a "typical kind" of request).

    I know there are a lot of tables at stake for the optimizer to mull through.
    Our app is "database agnostic", supporting SQL Server as well. And there the query executes in 3-4 seconds. Pretty much the same amount of time it takes in Oracle, once the parsing is completed...

    Is there any way to try and reduce the parse time?

    Thank you in advance.

    --Alex                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           
  • 5. Re: Hard Parse Time - too long...
    sb92075 Guru
    Currently Being Moderated
    al**** wrote:
    Thank you for the pointers on formatting and such...

    I have experimented with various degrees of Dynamic Sampling, all to no avail...
    From 0 all the way up to 7. There is no difference in the parse/execute times - for this particular query.

    We leave it at 4, only to satisfy the queries that are not potentially covered by indexes (in the odd chance that our DSS needs to support something that is not a "typical kind" of request).

    I know there are a lot of tables at stake for the optimizer to mull through.
    Our app is "database agnostic", supporting SQL Server as well. And there the query executes in 3-4 seconds. Pretty much the same amount of time it takes in Oracle, once the parsing is completed...

    Is there any way to try and reduce the parse time?

    Thank you in advance.

    --Alex
    post SQL & results that show how you obtain the parse time values.
  • 6. Re: Hard Parse Time - too long...
    Iordan Iotzov Expert
    Currently Being Moderated
    In 11gR2, Oracle takes the liberty to increase the dynamic sampling level for certain statements that involve large tables – Metalink Note
    Different Level for Dynamic Sampling used than the Specified Level [ID 1102413.1]     

    You can also take a look at this great blog post - http://coskan.wordpress.com/2012/05/31/plan-stability-through-upgrade-to-11g-why-is-my-plan-changed-auto-adjusted-dynamic-sampling/

    Iordan Iotzov
    http://iiotzov.wordpress.com/
  • 7. Re: Hard Parse Time - too long...
    P F Explorer
    Currently Being Moderated
    Try taking a 10046 and 10053 trace of the query for an explain plan for and check specifically where the time is spent.
    It may also pay to generate frequent short stacks while parsing as well. Repeating stacks may be a good indicator of the area the extra time is spents and you may be able to use this to search if there are any matching arsing bugs.
    On the other hand, it may just be that the query needs to take a long time to parse and there is nothing you can do if the sql is dynamic.
  • 8. Re: Hard Parse Time - too long...
    JohnWatson Guru
    Currently Being Moderated
    Hello. No-one has said this, so I will: no query has ever taken 45 seconds to parse. Your figures from v$sess_time_model are cumulative for the session, flushing the caches will have no effect. Trace the session, use tkprof, and perhaps you'll see where the time is spent.
  • 9. Re: Hard Parse Time - too long...
    439902 Newbie
    Currently Being Moderated
    Here is the output - from the trace (level 8)
    SELECT
        COUNT (DISTINCT ent_000000.pk)
    FROM entity ent_000000
        INNER JOIN recordtextvalue val_000002
            ON val_000002.sourceentityfk = ent_000000.pk
            AND val_000002.fieldfk = HEXTORAW ('80B58FEACC79E011AD2400155D018001')
            AND (   LOWER (val_000002.VALUE) LIKE LOWER ('%1%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%2%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%3%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%4%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%5%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%6%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%7%') ESCAPE '~'
                  OR LOWER (val_000002.VALUE) LIKE LOWER ('%8%') ESCAPE '~'
                 )
        INNER JOIN recordsinglechoicevalue val_000012
            ON val_000012.sourceentityfk = ent_000000.pk
            AND val_000012.fieldfk = HEXTORAW ('8DB58FEACC79E011AD2400155D018001')
        INNER JOIN record_ rec_000014
            ON rec_000014.pk = val_000012.recordfk
            AND rec_000014.entityfk = val_000012.sourceentityfk
            AND rec_000014.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
        INNER JOIN
           (SELECT
                MAX (rec_000016.TIMESTAMP) AS TIMESTAMP,
                rec_000016.entityfk AS groupkey
            FROM record_ rec_000016
                INNER JOIN recordsinglechoicevalue val_000018
                    ON val_000018.recordfk = rec_000016.pk
                    AND val_000018.sourceentityfk = rec_000016.entityfk
                    AND val_000018.fieldfk = HEXTORAW ('8DB58FEACC79E011AD2400155D018001')
            WHERE 1 = 1
                AND rec_000016.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
            GROUP BY rec_000016.entityfk
            ) tbl_000020
            ON tbl_000020.TIMESTAMP = rec_000014.TIMESTAMP
            AND tbl_000020.groupkey = rec_000014.entityfk
        INNER JOIN recordsinglechoicevalue val_000021
            ON val_000021.sourceentityfk = ent_000000.pk
            AND val_000021.fieldfk = HEXTORAW ('AF5F45338C58DE4CB3833AD9D54351A7')
        INNER JOIN record_ rec_000023
            ON rec_000023.pk = val_000021.recordfk
            AND rec_000023.entityfk = val_000021.sourceentityfk
            AND rec_000023.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
        JOIN
           (SELECT   MIN (rec_000025.TIMESTAMP) AS TIMESTAMP, rec_000025.entityfk AS groupkey
                FROM record_ rec_000025 INNER JOIN recordsinglechoicevalue val_000027
                     ON val_000027.recordfk = rec_000025.pk
                   AND val_000027.sourceentityfk = rec_000025.entityfk
                   AND val_000027.fieldfk = HEXTORAW ('AF5F45338C58DE4CB3833AD9D54351A7')
               WHERE 1 = 1 AND rec_000025.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
            GROUP BY rec_000025.entityfk) tbl_000029
            ON tbl_000029.TIMESTAMP = rec_000023.TIMESTAMP
            AND tbl_000029.groupkey = rec_000023.entityfk
            AND val_000021.choicefk IN
                (HEXTORAW ('A038588B67E6C6418360E92AB231EA30'),
                 HEXTORAW ('DA6E7059FB243F40B97CF91BA75EE532'),
                 HEXTORAW ('DA6BE7C37D157A4BBD34032F76983916')
                )
        INNER JOIN record_ val_000033
            ON val_000033.pk = rec_000023.pk
            AND val_000033.entityfk = rec_000023.entityfk
            AND val_000033.TIMESTAMP IS NOT NULL
            AND val_000033.recordtypefk IN (SELECT rt.pk
                                           FROM recordtype rt JOIN recordtypemember rtm ON rtm.recordtypefk = rt.pk
                                          WHERE rtm.fieldfk = HEXTORAW ('83B58FEACC79E011AD2400155D018001'))
            AND val_000033.TIMESTAMP >= TO_DATE ('1/1/1925 12:00:00 AM', 'MM/DD/YYYY HH:MI:SS AM')
        INNER JOIN recordsinglechoicevalue val_000036
            ON val_000036.sourceentityfk = ent_000000.pk
            AND val_000036.fieldfk = HEXTORAW ('125A01C9DAF726448D8DB1F7B27091DE')
        INNER JOIN record_ rec_000038
            ON rec_000038.pk = val_000036.recordfk
            AND rec_000038.entityfk = val_000036.sourceentityfk
            AND rec_000038.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
        JOIN
            (SELECT   MIN (rec_000040.TIMESTAMP) AS TIMESTAMP, rec_000040.entityfk AS groupkey
                FROM record_ rec_000040 INNER JOIN recordsinglechoicevalue val_000042
                     ON val_000042.recordfk = rec_000040.pk
                   AND val_000042.sourceentityfk = rec_000040.entityfk
                   AND val_000042.fieldfk = HEXTORAW ('125A01C9DAF726448D8DB1F7B27091DE')
               WHERE 1 = 1 AND rec_000040.recordtypefk = HEXTORAW ('7EB58FEACC79E011AD2400155D018001')
            GROUP BY rec_000040.entityfk) tbl_000044
            ON tbl_000044.TIMESTAMP = rec_000038.TIMESTAMP
            AND tbl_000044.groupkey = rec_000038.entityfk
            AND val_000036.choicefk IN
                (HEXTORAW ('9DDEB479A5F44C4AB9C03B0FBE2CCD89'),
                 HEXTORAW ('723CBD322AB52B439E9160F29BB27E17'),
                 HEXTORAW ('492F484AD5FED04893F82F4824F1B5E2'),
                 HEXTORAW ('C3F9C1F514AFB146A0F4BABAA2577B84')
                )
        INNER JOIN record_ val_000049
            ON val_000049.entityfk = ent_000000.pk
            AND 'Diagnosis' IS NOT NULL
            AND val_000049.recordtypefk IN (SELECT rt.pk
                                           FROM recordtype rt JOIN recordtypemember rtm ON rtm.recordtypefk = rt.pk
                                          WHERE rtm.fieldfk = HEXTORAW ('F85D675BF5D04448A608F9479A653BD3'))
     WHERE 1 = 1
     AND ent_000000.entitytypefk = HEXTORAW ('66B9B948F000DB1192370014A5726350')
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1     46.27      46.53          0          5          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        2      0.33       0.63        129      30331          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4     46.60      47.17        129      30336          0           1
    
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 144  
    Number of plan statistics captured: 1
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=30331 pr=129 pw=0 time=637272 us)
           863        863        863   VIEW  VM_NWVW_1 (cr=30331 pr=129 pw=0 time=637378 us cost=1331 size=10 card=1)
           863        863        863    HASH GROUP BY (cr=30331 pr=129 pw=0 time=637131 us cost=1331 size=581 card=1)
          2589       2589       2589     NESTED LOOPS  (cr=30331 pr=129 pw=0 time=924500 us cost=1330 size=581 card=1)
          2589       2589       2589      NESTED LOOPS  (cr=24991 pr=129 pw=0 time=878990 us cost=1326 size=568 card=1)
          2589       2589       2589       NESTED LOOPS  (cr=20546 pr=129 pw=0 time=865301 us cost=1324 size=515 card=1)
          2589       2589       2589        NESTED LOOPS  (cr=15830 pr=116 pw=0 time=795057 us cost=1319 size=502 card=1)
          2589       2589       2589         NESTED LOOPS SEMI (cr=11381 pr=116 pw=0 time=781860 us cost=1317 size=449 card=1)
          2589       2589       2589          NESTED LOOPS  (cr=11379 pr=116 pw=0 time=779589 us cost=1316 size=415 card=1)
          2589       2589       2589           NESTED LOOPS  (cr=5714 pr=61 pw=0 time=663093 us cost=1311 size=402 card=1)
          3009       3009       3009            NESTED LOOPS  (cr=2860 pr=61 pw=0 time=141601 us cost=1303 size=1396 card=4)
          3018       3018       3018             NESTED LOOPS  (cr=1023 pr=58 pw=0 time=97732 us cost=1295 size=1156 card=4)
          3333       3333       3333              HASH JOIN  (cr=80 pr=18 pw=0 time=674194 us cost=1291 size=952 card=4)
          4626       4626       4626               HASH JOIN  (cr=65 pr=7 pw=0 time=48999 us cost=1284 size=3570 card=21)
          1542       1542       1542                PARTITION HASH SINGLE PARTITION: 98 98 (cr=9 pr=7 pw=0 time=10814 us cost=4 size=19924 card=293)
          1542       1542       1542                 INLIST ITERATOR  (cr=9 pr=7 pw=0 time=10452 us)
          1542       1542       1542                  INDEX RANGE SCAN RDSINGLECHOICEVALUE_CFER_IDX PARTITION: 98 98 (cr=9 pr=7 pw=0 time=13573 us cost=4 size=19924 card=293)(object id 1274261)
         20507      20507      20507                HASH JOIN  (cr=56 pr=0 pw=0 time=23990 us cost=1280 size=120972 card=1186)
         16538      16538      16538                 INDEX RANGE SCAN ENTITY_TYPE_PK_IDX (cr=18 pr=0 pw=0 time=3212 us cost=19 size=562292 card=16538)(object id 1263004)
         20507      20507      20507                 NESTED LOOPS  (cr=38 pr=0 pw=0 time=7705 us cost=1257 size=9983624 card=146818)
             1          1          1                  SORT UNIQUE (cr=2 pr=0 pw=0 time=52 us cost=2 size=34 card=1)
             1          1          1                   INDEX RANGE SCAN RDTYPEMEMBER_FIELD_RDTYPE_IDX (cr=2 pr=0 pw=0 time=15 us cost=2 size=34 card=1)(object id 1263046)
         20507      20507      20507                  INDEX RANGE SCAN RECORD_TYPE_ENTITY_PK_IDX (cr=36 pr=0 pw=0 time=3840 us cost=1254 size=4805764 card=141346)(object id 1263050)
          3631       3631       3631               PARTITION HASH SINGLE PARTITION: 30 30 (cr=15 pr=11 pw=0 time=13613 us cost=6 size=224400 card=3300)
          3631       3631       3631                INLIST ITERATOR  (cr=15 pr=11 pw=0 time=13103 us)
          3631       3631       3631                 INDEX RANGE SCAN RDSINGLECHOICEVALUE_CFER_IDX PARTITION: 30 30 (cr=15 pr=11 pw=0 time=12585 us cost=6 size=224400 card=3300)(object id 1274261)
          3018       3018       3018              PARTITION HASH SINGLE PARTITION: 9 9 (cr=943 pr=40 pw=0 time=134515 us cost=1 size=51 card=1)
          3018       3018       3018               INDEX RANGE SCAN RDSINGLECHOICEVALUE_EFR_IDX PARTITION: 9 9 (cr=943 pr=40 pw=0 time=130343 us cost=1 size=51 card=1)(object id 1274390)
          3009       3009       3009             PARTITION HASH SINGLE PARTITION: 5 5 (cr=1837 pr=3 pw=0 time=57872 us cost=2 size=60 card=1)
          3009       3009       3009              TABLE ACCESS BY LOCAL INDEX ROWID RECORDTEXTVALUE PARTITION: 5 5 (cr=1837 pr=3 pw=0 time=54431 us cost=2 size=60 card=1)
          3018       3018       3018               INDEX RANGE SCAN RDTEXTVALUE_EFR_IDX PARTITION: 5 5 (cr=929 pr=0 pw=0 time=10595 us cost=1 size=0 card=1)(object id 1271843)
          2589       2589       2589            TABLE ACCESS BY INDEX ROWID RECORD_ (cr=2854 pr=0 pw=0 time=19202 us cost=2 size=53 card=1)
          3009       3009       3009             INDEX UNIQUE SCAN RECORD_TYPE_ENTITY_PK_IDX (cr=1850 pr=0 pw=0 time=9289 us cost=1 size=0 card=1)(object id 1263050)
          2589       2589       2589           VIEW PUSHED PREDICATE  (cr=5665 pr=55 pw=0 time=167586 us cost=5 size=13 card=1)
          2589       2589       2589            FILTER  (cr=5665 pr=55 pw=0 time=163887 us)
          2589       2589       2589             SORT AGGREGATE (cr=5665 pr=55 pw=0 time=160864 us)
          2589       2589       2589              NESTED LOOPS  (cr=5665 pr=55 pw=0 time=155067 us)
          2589       2589       2589               NESTED LOOPS  (cr=3076 pr=55 pw=0 time=144927 us cost=5 size=73 card=1)
          2589       2589       2589                VIEW  VW_GBF_11 (cr=1244 pr=55 pw=0 time=133117 us cost=3 size=20 card=1)
          2589       2589       2589                 SORT GROUP BY (cr=1244 pr=55 pw=0 time=131015 us cost=3 size=51 card=1)
          2589       2589       2589                  PARTITION HASH SINGLE PARTITION: 98 98 (cr=1244 pr=55 pw=0 time=112928 us cost=2 size=51 card=1)
          2589       2589       2589                   INDEX RANGE SCAN RDSINGLECHOICEVALUE_EFR_IDX PARTITION: 98 98 (cr=1244 pr=55 pw=0 time=108482 us cost=2 size=51 card=1)(object id 1274390)
          2589       2589       2589                INDEX UNIQUE SCAN RECORD_TYPE_ENTITY_PK_IDX (cr=1832 pr=0 pw=0 time=8237 us cost=1 size=0 card=1)(object id 1263050)
          2589       2589       2589               TABLE ACCESS BY INDEX ROWID RECORD_ (cr=2589 pr=0 pw=0 time=7048 us cost=2 size=53 card=1)
             1          1          1          INDEX RANGE SCAN RDTYPEMEMBER_FIELD_RDTYPE_IDX (cr=2 pr=0 pw=0 time=18 us cost=1 size=34 card=1)(object id 1263046)
          2589       2589       2589         TABLE ACCESS BY INDEX ROWID RECORD_ (cr=4449 pr=0 pw=0 time=11631 us cost=2 size=53 card=1)
          2589       2589       2589          INDEX UNIQUE SCAN RECORD_TYPE_ENTITY_PK_IDX (cr=1860 pr=0 pw=0 time=6655 us cost=1 size=0 card=1)(object id 1263050)
          2589       2589       2589        VIEW PUSHED PREDICATE  (cr=4716 pr=13 pw=0 time=84995 us cost=5 size=13 card=1)
          2589       2589       2589         FILTER  (cr=4716 pr=13 pw=0 time=82614 us)
          2589       2589       2589          SORT AGGREGATE (cr=4716 pr=13 pw=0 time=80278 us)
          2589       2589       2589           NESTED LOOPS  (cr=4716 pr=13 pw=0 time=75445 us)
          2589       2589       2589            NESTED LOOPS  (cr=2127 pr=13 pw=0 time=66822 us cost=5 size=73 card=1)
          2589       2589       2589             VIEW  VW_GBF_17 (cr=293 pr=13 pw=0 time=56306 us cost=3 size=20 card=1)
          2589       2589       2589              SORT GROUP BY (cr=293 pr=13 pw=0 time=54302 us cost=3 size=51 card=1)
          2589       2589       2589               PARTITION HASH SINGLE PARTITION: 30 30 (cr=293 pr=13 pw=0 time=40170 us cost=2 size=51 card=1)
          2589       2589       2589                INDEX RANGE SCAN RDSINGLECHOICEVALUE_EFR_IDX PARTITION: 30 30 (cr=293 pr=13 pw=0 time=35998 us cost=2 size=51 card=1)(object id 1274390)
          2589       2589       2589             INDEX UNIQUE SCAN RECORD_TYPE_ENTITY_PK_IDX (cr=1834 pr=0 pw=0 time=7440 us cost=1 size=0 card=1)(object id 1263050)
          2589       2589       2589            TABLE ACCESS BY INDEX ROWID RECORD_ (cr=2589 pr=0 pw=0 time=5633 us cost=2 size=53 card=1)
          2589       2589       2589       TABLE ACCESS BY INDEX ROWID RECORD_ (cr=4445 pr=0 pw=0 time=10931 us cost=2 size=53 card=1)
          2589       2589       2589        INDEX UNIQUE SCAN RECORD_TYPE_ENTITY_PK_IDX (cr=1856 pr=0 pw=0 time=6412 us cost=1 size=0 card=1)(object id 1263050)
          2589       2589       2589      VIEW PUSHED PREDICATE  (cr=5340 pr=0 pw=0 time=40596 us cost=4 size=13 card=1)
          2589       2589       2589       FILTER  (cr=5340 pr=0 pw=0 time=38309 us)
          2589       2589       2589        SORT AGGREGATE (cr=5340 pr=0 pw=0 time=36174 us)
          2589       2589       2589         NESTED LOOPS  (cr=5340 pr=0 pw=0 time=31550 us)
          2589       2589       2589          NESTED LOOPS  (cr=2751 pr=0 pw=0 time=24490 us cost=4 size=104 card=1)
          2589       2589       2589           PARTITION HASH SINGLE PARTITION: 9 9 (cr=923 pr=0 pw=0 time=15670 us cost=2 size=51 card=1)
          2589       2589       2589            INDEX RANGE SCAN RDSINGLECHOICEVALUE_EFR_IDX PARTITION: 9 9 (cr=923 pr=0 pw=0 time=11842 us cost=2 size=51 card=1)(object id 1274390)
          2589       2589       2589           INDEX UNIQUE SCAN RECORD_TYPE_ENTITY_PK_IDX (cr=1828 pr=0 pw=0 time=5954 us cost=1 size=0 card=1)(object id 1263050)
          2589       2589       2589          TABLE ACCESS BY INDEX ROWID RECORD_ (cr=2589 pr=0 pw=0 time=4318 us cost=2 size=53 card=1)
    
    
    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
      db file sequential read                       129        0.00          0.30
      asynch descriptor resize                        2        0.00          0.00
      SQL*Net message from client                     2       19.58         19.58
    ********************************************************************************
    
    SQL ID: bh7jda5rbamvk Plan Hash: 0
    
    ALTER SESSION SET sql_trace=FALSE
    It clearly shows parsing as the time spent...
  • 10. Re: Hard Parse Time - too long...
    JohnWatson Guru
    Currently Being Moderated
    Well, I was wrong: it really does seem to be taking that long to parse.
    I guess that means there is no point in trying to tune the SQL!
    All I can suggest is to analyze the data dictionary, and (since you say you have good stats) set dynamic sampling to zero.

    If you re-run the statement, does it re-use the cursor and give a sub-second response?
    There are zillions of _parameters one can set to control (for example) how many plans the optimizer considers. Could someone have been trying to be clever with them?                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               
  • 11. Re: Hard Parse Time - too long...
    439902 Newbie
    Currently Being Moderated
    If the statement is re-run, it comes back instantaneously. So, to your point, the plan is cached by then, and is re-used.
    But since no two queries are alike in our app, that does not help us much :)

    I did gather_system_stats, gather_dictionary_stats, gather_fixed_objects_stats - you name it! All with 100 percent for estimates (where applicable). So it is not that...

    We have not messed up with the _parameters (perhaps, we should? ;))...

    I tried running with dynamic sampling=0, and the results are (as expected) the same. It is parsing, and not peaking that takes time.
    Our queries pull info from up to about 20 tables (more than 20 is less frequent). The typical range is 5-10. That definitely exceeds the default threshold for the search limit and the max permutations. Lowering it even more (if only theoretically) will probably have adverse effect on the overall system performance.

    Other ideas?

    Thank you!
  • 12. Re: Hard Parse Time - too long...
    JohnWatson Guru
    Currently Being Moderated
    What happens if you set optimizer_mode=rule ? I don't mean what happens to the SQL plan and execution, what happens to the parse? The rule based optimizer is often a lot faster.
  • 13. Re: Hard Parse Time - too long...
    Jonathan Lewis Oracle ACE Director
    Currently Being Moderated
    Are the various queries similar in shape ? It's possible that we can control the amount of parsing that the optimizer does by injecting some hints to bypass certain search paths. It's messy, in general, trying to hint ANSI SQL in Oracle, and perhaps you're not allowed to do it at all if you also expect to run on SQL Server.

    Notice the three plan lines that have (View pushed predicate) - Oracle will have taken some time to work out lots of plans where it didn't push predicates, or even unnested or merge. You might get some benefit if you put in some hints that insist that Oracle does what it has done (if this example is a generic shape for your queries).

    For the IN (select min/max()...) put in /*+ no_unnest push_pred */ after the select.
    For the Join to (select max() ...) try putting in /*+ no_merge push_pred */

    I believe the plan won't change, but the parse time should drop - but, given that it's ANSI - this may not work the way I hope.

    One other thing - when you call dbms_xplan, include the 'OUTLINE' format command. This will show us the hints that Oracle would use to regenerate the plan from an OUTLINE (or SQL Baseline in 11g). This may give us a few more clues about how it add a few more query block hints that have a generic effect on your key queries.

    Regards
    Jonathan Lewis
  • 14. Re: Hard Parse Time - too long...
    439902 Newbie
    Currently Being Moderated
    Rule does not seem to make a dent:
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1     47.98      48.21          0          5          0           0
    Execute      1      0.00       0.00          0          0          0           0
    Fetch        2      0.32       0.54        117      30321          0           1
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        4     48.30      48.76        117      30326          0           1
    
    Misses in library cache during parse: 1
    Optimizer mode: RULE
    Parsing user id: 144
    Number of plan statistics captured: 1
1 2 3 Previous Next

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points