Infrastructure at your Service

Franck Pachot

CBO parse time – matching time with transformation

By Franck Pachot

.
By a strange coincidence, I’ve encountered several cases of long parse time recently. That was the occasion to give a closer look at a CBO trace enhancement that came with April 2016 PSU: Bug 16923858 Diagnostic enhancement to annotate 10053 trace with accumulated parse time

I have a query that takes several seconds to parse and here is the new parse time information when you trace SQL_Compiler (the 10053 trace):

$ grep TIMER db003_ora_22231_orig.trc
TIMER:     costing additional plans cpu: 1.807 sec elapsed: 2.019 sec
TIMER:     costing general plans cpu: 26.131 sec elapsed: 27.747 sec
TIMER:     costing additional plans cpu: 8.995 sec elapsed: 9.329 sec
TIMER:  SU: costing SEL$A2089C65 cpu: 38.313 sec elapsed: 40.506 sec
TIMER:     costing additional plans cpu: 1.523 sec elapsed: 1.850 sec
TIMER:   SU: costing Interleaved CVM SEL$488B5694 cpu: 4.255 sec elapsed: 4.807 sec
TIMER:  SU: Interleaved CVM SEL$A2089C65 cpu: 4.293 sec elapsed: 4.846 sec
TIMER:  i     costing additional plans cpu: 1.742 sec elapsed: 1.884 sec
TIMER:  i     costing general plans cpu: 21.343 sec elapsed: 21.843 sec
TIMER:  i     costing additional plans cpu: 8.072 sec elapsed: 8.375 sec
TIMER:  i  JPPD: costing SEL$A2089C65 cpu: 32.798 sec elapsed: 33.838 sec
TIMER:  i JPPD: iteration (#1) SEL$A2089C65 cpu: 32.822 sec elapsed: 33.863 sec
TIMER:  i     costing general plans cpu: 22.088 sec elapsed: 22.751 sec
TIMER:  i     costing additional plans cpu: 5.484 sec elapsed: 5.745 sec
TIMER:  i  JPPD: costing SEL$A2089C65 cpu: 30.181 sec elapsed: 31.113 sec
TIMER:  i JPPD: iteration (#2) SEL$A2089C65 cpu: 30.197 sec elapsed: 31.129 sec
TIMER:  SU: Interleaved JPPD SEL$A2089C65 cpu: 63.026 sec elapsed: 64.999 sec
TIMER: SU: iteration (#1) SEL$A2089C65 cpu: 105.656 sec elapsed: 110.375 sec
TIMER:  SU: costing SEL$EB7B6E47 cpu: 3.749 sec elapsed: 4.025 sec
TIMER: SU: iteration (#2) SEL$EB7B6E47 cpu: 3.762 sec elapsed: 4.038 sec
TIMER: CBQT SU and CVM SEL$1 cpu: 109.512 sec elapsed: 114.507 sec
TIMER: Cost-Based Transformations (Overall) SEL$62E0E936 cpu: 110.118 sec elapsed: 115.112 sec
TIMER:     costing additional plans cpu: 1.247 sec elapsed: 1.485 sec
TIMER: Access Path Analysis (Final) SEL$62E0E936 cpu: 2.227 sec elapsed: 2.227 sec
TIMER: SQL Optimization (Overall) SEL$62E0E936 cpu: 114.674 sec elapsed: 119.906 sec

The default is to have a line when an operation takes more than 1 second. You can change that with the fix control:

This will trace all times > 10 microseconds:

alter session set "_fix_control"='16923858:1';

This will trace all times > 10 seconds:

alter session set "_fix_control"='16923858:7';

You get it: each level increases the threshold to the next order of magnitude, the default is 6 (1 second)

I’ve a small awk script to display the time in a better format:


   cpu(ms)    ela(ms)
 42138.000  42159.000       costing general plans                                                                                                       12.1.0.2 640468
  6416.000   6418.000       costing additional plans                                                                                                    12.1.0.2 719893
  1509.000   1509.000       costing general plans                                                                                                       12.1.0.2 753749
  2377.000   2377.000      or expansion check                                                                                                           12.1.0.2 763107
 52698.000  52721.000    SU: costing                                     SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)                            12.1.0.2 763120
  2035.000   2035.000       costing general plans                                                                                                       12.1.0.2 842348
  2642.000   2642.000      or expansion check                                                                                                           12.1.0.2 849927
  4920.000   4921.000     SU: costing Interleaved CVM                    SEL$959A6A10 (VIEW MERGE SEL$5061678E; SEL$CAA3F13B)                           12.1.0.2 849940
  4941.000   4942.000    SU: Interleaved CVM                             SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)                            12.1.0.2 849942
 42556.000  42568.000    i     costing general plans                                                                                                    12.1.0.2 1482291
  6348.000   6348.000    i     costing additional plans                                                                                                 12.1.0.2 1561716
  1653.000   1653.000    i     costing general plans                                                                                                    12.1.0.2 1595574
  2487.000   2488.000    i    or expansion check                                                                                                        12.1.0.2 1604932
 52924.000  52938.000    i  JPPD: costing                                SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)(COPY SEL$5061678E)         12.1.0.2 1604945
 52933.000  52947.000    i JPPD: iteration (#1)                          SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)(COPY SEL$5061678E)         12.1.0.2 1604956
  1116.000   1116.000    i     costing additional plans                                                                                                 12.1.0.2 1630694
 33570.000  33576.000    i     costing general plans                                                                                                    12.1.0.2 2098660
 10614.000  10622.000    i     costing additional plans                                                                                                 12.1.0.2 2211397
  2092.000   2093.000    i     costing general plans                                                                                                    12.1.0.2 2246743
  1396.000   1397.000    i     costing additional plans                                                                                                 12.1.0.2 2264252
  3778.000   3780.000    i    or expansion check                                                                                                        12.1.0.2 2265816
 50741.000  50759.000    i  JPPD: costing                                SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)(COPY SEL$5061678E)         12.1.0.2 2265829
 50752.000  50769.000    i JPPD: iteration (#2)                          SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)(COPY SEL$5061678E)         12.1.0.2 2265839
103688.000 103719.000    SU: Interleaved JPPD                            SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)(COPY SEL$5061678E)         12.1.0.2 2265844
161339.000 161394.000   SU: iteration (#1)                               SEL$5061678E (SUBQUERY UNNEST SEL$93416A64; SEL$10)(COPY SEL$5061678E)         12.1.0.2 2265846
  3250.000   3252.000    SU: costing                                            SEL$1 (PARSER)(COPY SEL$1)                                              12.1.0.2 2307338
  3262.000   3264.000   SU: iteration (#2)                                      SEL$1 (PARSER)(COPY SEL$1)                                              12.1.0.2 2307349
164632.000 164689.000   CBQT SU and CVM                                         SEL$1 (PARSER)(COPY SEL$1)                                              12.1.0.2 2307498
164827.000 164884.000   Cost-Based Transformations (Overall)                    SEL$1 (PARSER)(COPY SEL$1)                                              12.1.0.2 2307946
  2577.000   2578.000       costing general plans                                                                                                       12.1.0.2 2387060
  3204.000   3204.000      or expansion check                                                                                                           12.1.0.2 2393273
  4597.000   4598.000   Access Path Analysis (Final)                            SEL$1 (PARSER)(COPY SEL$1)                                              12.1.0.2 2393703
170872.000 170931.000   SQL Optimization (Overall)                              SEL$1 (PARSER)(COPY SEL$1)                                              12.1.0.2 2393730

Note that I’m more interested by the CPU time because the elapsed time includes the time to write to the trace.
I’m reading a 2 million line 10053 trace file here. The CBO takes time but is doing lot of work here.

My awk script also records the maximum time spend on each query block and then displays the ‘Query Block Registry’ with those times. This is a good way to understand which CBO transformation is responsible for most of the parse time:


   cpu(ms)    ela(ms)   Query Block Registry:
     0.000      0.000   SEL$10 0x897e9b8 (PARSER) [FINAL]
161339.000 161394.000     SEL$5061678E 0x0 (SUBQUERY UNNEST SEL$93416A64; SEL$10)
     0.000      0.000       SEL$6F0423A9 0x0 (PUSHED PREDICATE SEL$CAA3F13B; SEL$5061678E; "VW_SQ_3"@"SEL$93416A64" 28)
     0.000      0.000       SEL$959A6A10 0x0 (VIEW MERGE SEL$5061678E; SEL$CAA3F13B)
     0.000      0.000     SEL$1DF60DFD 0x0 (QUERY BLOCK TABLES CHANGED SEL$10)
     0.000      0.000       SEL$CAA3F13B 0x0 (SUBQ INTO VIEW FOR COMPLEX UNNEST SEL$1DF60DFD)
     0.000      0.000         SEL$6F0423A9 0x0 (PUSHED PREDICATE SEL$CAA3F13B; SEL$5061678E; "VW_SQ_3"@"SEL$93416A64" 28)
     0.000      0.000         SEL$959A6A10 0x0 (VIEW MERGE SEL$5061678E; SEL$CAA3F13B)
     0.000      0.000   SEL$9 0x8987df0 (PARSER) [FINAL]
     0.000      0.000   SEL$8 0x8988ee8 (PARSER) [FINAL]
     0.000      0.000   SEL$7 0x898a4f8 (PARSER) [FINAL]
     0.000      0.000   SEL$6 0x898c028 (PARSER) [FINAL]
     0.000      0.000   SEL$5 0x898d268 (PARSER) [FINAL]
     0.000      0.000   SEL$4 0x898eaf8 (PARSER) [FINAL]
     0.000      0.000   SEL$3 0x89912b8 (PARSER) [FINAL]
     0.000      0.000   SEL$2 0x89923c0 (PARSER) [FINAL]
170872.000 170931.000   SEL$1 0x89a3ef0 (PARSER) [FINAL]
     0.000      0.000     SEL$93416A64 0x0 (VIEW ADDED SEL$1)
161339.000 161394.000       SEL$5061678E 0x0 (SUBQUERY UNNEST SEL$93416A64; SEL$10)
     0.000      0.000         ...

The interesting point here is that the [FINAL] is the transformation that is chosen by the optimizer, so we know that we have spent time on a query block that has been finally chosen for the best plan.

Before going further, here is my ugly awk script that gives the above output from a 10053 trace file:


BEGIN{
        print ; print "   cpu(ms)    ela(ms)"
}
/^ *optimizer_features_enable += +/{
        ofe=$3 ; sub(/^[8-9][.]/,"0&",ofe)
        delete qb
}
/TIMER/{
        l=$0 ; sub(/ cpu: .*$/,"",l) ; sub(/TIMER: /,"",l)
        sub(/^.* cpu: /,"") # --> $1 is cpu $4 is ela
        q=gensub(/^.* /,"","g",l);
        if ( qb[q] == "" ) { q="" } else { sub(/ [^ ]*$/,"",l) }
        if ( q!="" && $1*1e3 > cpu[q] ) cpu[q]=$1*1e3
        if ( q!="" && $4*1e3 > ela[q] ) ela[q]=$4*1e3
        printf "%10.3f %10.3f\t%-40s %20s %-60s\t%6s %s\n",$1*1e3,$4*1e3,l,q,qb[q],ofe,NR
        if ( q != "") versions[l" "q]=versions[l" "q] ofe"="($1*1e3)"ms\n"
}
/Query Block Registry/,/^:/{
        if ( $0 ~/Query Block Registry/ ) { ; print "" ; print "   cpu(ms)    ela(ms)   "$0 ; print "" }
        else { printf "%10.3f %10.3f\t%s\n",cpu[$1],ela[$1],$0 }
}

So, I know that the unnesting of subquery SEL$10 is responsible for my long parse time. The ‘+alias’ format of the explain plan is an easy way to find which subquery it is comes from, :

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
 
  64 - SEL$10
  65 - SEL$10 / [email protected]$10
  66 - SEL$10 / [email protected]$10

Here is the subselect (I redacted the table names).

AND begin_date =
  (SELECT MAX (begin_date)
  FROM table_with_dates
  WHERE some_id = some_id
  AND begin_date <= ...
  )

So what can I do from now? I can avoid the subquery unnesting by adding the NO_UNNEST hin in the subquery, or add it to the main query as /*+ NO_UNNEST( @SEL$10) */

This really reduces the parse time, but I have to check that the plan is still acceptable. Actually we cannot blame the CBO for the time it takes here, because the goal of subquery unnesting (SU) is exactly that: open the way to lot of new access path, that can be cost based and may give a better execution plan. And an application should not parse too often, so spending a few seconds in parsing is not bad if it helps to execute the query quickly all over the day.

So don’t forget to have the latest PSU and trace with:

alter session set events 'trace [SQL_Compiler.*]';
explain plan for ...
alter session set events 'trace [SQL_Compiler.*] off';

get timer information with:

column value new_value tracefile
select value from v$diag_info where name='Default Trace File';
column value new_value clear
host grep TIMER &tracefile

And find which transformation is responsible for most of the parse time.

2 Comments

  • Mikhail Velikikh says:

    Hi Franck,

    Thank you for sharing this information.
    When I tried to trace some of my queries, I got an ORA-942 error due to missing ora_debug_table.
    Here is what I did:

    SQL> alter session set events 'trace[sql_compiler.*]';
     
    Session altered.
     
    SQL> explain plan for
    2 SELECT
    3 OWNER
    4 ,CONSTRAINT_NAME
    5 ,CONSTRAINT_TYPE
    6 FROM
    7 (
    8 SELECT
    9 1 OBY
    10 ,OWNER
    11 ,CONSTRAINT_NAME
    12 ,CONSTRAINT_TYPE
    13 FROM
    14 DBA_CONSTRAINTS CON
    15 WHERE
    16 (
    17 CON.OWNER = : B2
    18 AND CON.TABLE_NAME = : B1
    19 )
    20 AND CON.CONSTRAINT_NAME NOT IN (
    21 SELECT
    22 LOG_GROUP_NAME
    23 FROM
    24 DBA_LOG_GROUPS LOG
    25 WHERE
    26 LOG.OWNER = : B2
    27 AND LOG.TABLE_NAME = : B1
    28 )
    29 ) C_ALL
    30 ORDER BY
    31 OBY
    32 ,CONSTRAINT_TYPE
    33 /
    OBY
    *
    ERROR at line 31:
    ORA-00604: error occurred at recursive SQL level 1
    ORA-00942: table or view does not exist
     
    I narrowed down the issue using:
    SQL> alter session set events '942 trace name errorstack level 3';
     
    Session altered.
     
    ----- Current SQL Statement for this session (sql_id=fj197u8g1z63s) -----
    insert into ora_debug_table (time, txt0, txt1, txt2, txt3, txt4, num0, num1, num2, num3, num4, num5, num6, num7, num8, num9) values(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16)
     
     
    Then I created this ora_debug_table table and things went fine after that:
     
    SQL> CREATE TABLE ora_debug_table (
    2 time DATE,
    3 txt0 VARCHAR2(4000), txt1 VARCHAR2(4000),
    4 txt2 VARCHAR2(4000), txt3 VARCHAR2(4000),
    5 txt4 VARCHAR2(4000),
    6 num0 NUMBER, num1 NUMBER, num2 NUMBER,
    7 num3 NUMBER, num4 NUMBER, num5 NUMBER,
    8 num6 NUMBER, num7 NUMBER, num8 NUMBER,
    9 num9 NUMBER
    10 );
     
    Table created.
     
    SQL>
    SQL> explain plan for
    2 SELECT
    3 OWNER
    4 ,CONSTRAINT_NAME
    5 ,CONSTRAINT_TYPE
    6 FROM
    7 (
    8 SELECT
    9 1 OBY
    10 ,OWNER
    11 ,CONSTRAINT_NAME
    12 ,CONSTRAINT_TYPE
    13 FROM
    14 DBA_CONSTRAINTS CON
    15 WHERE
    16 (
    17 CON.OWNER = : B2
    18 AND CON.TABLE_NAME = : B1
    19 )
    20 AND CON.CONSTRAINT_NAME NOT IN (
    21 SELECT
    22 LOG_GROUP_NAME
    23 FROM
    24 DBA_LOG_GROUPS LOG
    25 WHERE
    26 LOG.OWNER = : B2
    27 AND LOG.TABLE_NAME = : B1
    28 )
    29 ) C_ALL
    30 ORDER BY
    31 OBY
    32 ,CONSTRAINT_TYPE
    33 /
     
    Explained.

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Franck Pachot
Franck Pachot

Principal Consultant / Database Evangelist