This was first published on https://blog.dbi-services.com/cbo-parse-time-match-time-with-transformation (2017-02-04)
Republishing here for new followers. The content is related to the the versions available at the publication date
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 / TABLE_WITH_DATES@SEL$10 66 - SEL$10 / TABLE_WITH_DATES@SEL$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.
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:
Hi Mikhail, This is strange. I dont expect the need for ora_debug_table without other trace settings. Thanks to have shared that in case someone encounters the same, Franck.