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 secThe 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.3ft%-40s %20s %-60st%6s %sn",$1*1e3,$4*1e3,l,q,qb[q],ofe,NR
if ( q != "") versions[l" "q]=versions[l" "q] ofe"="($1*1e3)"msn"
}
/Query Block Registry/,/^:/{
if ( $0 ~/Query Block Registry/ ) { ; print "" ; print " cpu(ms) ela(ms) "$0 ; print "" }
else { printf "%10.3f %10.3ft%sn",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$10Here 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 &tracefileAnd find which transformation is responsible for most of the parse time.
![Thumbnail [60x60]](https://www.dbi-services.com/blog/wp-content/uploads/2022/12/oracle-square.png)
![Thumbnail [90x90]](https://www.dbi-services.com/blog/wp-content/uploads/2022/08/DWE_web-min-scaled.jpg)