Oracle Scratchpad

November 17, 2019

Parse Time

Filed under: Oracle,Troubleshooting — Jonathan Lewis @ 7:37 pm GMT Nov 17,2019

This is a note I started drafting In October 2012. It’s a case study from an optimizer (10053) trace file someone emailed to me, and it describes some of the high-level steps I went through to see if I could pinpoint what the optimizer was doing that fooled it into spending a huge amount of time optimising a statement that ultimately executed very quickly.

Unfortunately I never finished my notes and I can no longer find the trace file that the article was based on, so I don’t really know what I was planning to say to complete the last observation I had recorded.

I was prompted a  couple of days ago to publish the notes so far because I was reminded in a conversation with members of the Oak Table Network about an article that Franck Pachot wrote a couple of years ago. In 12c Oracle Corp. introduced a time-reporting mechanism for the optimizer trace. If some optimisation step takes “too long” (1 second, by default) then the optimizer will write a “TIMER:” line into the trace file telling you what the operation was and how long it took to complete and how much CPU time it used.  The default for “too long” can be adjusted by setting a “fix control”.  This makes it a lot easier (see below) to find out where the time went if you see a very long parse time.

But let’s get back to the original trace file and blog note draft. It started with a question on OTN and an extract from a tkprof output to back up a nasty  performance issue.



What do you do about a parse time of 46 seconds ? That was the question that came up on OTN a few days ago – and here’s the tkprof output to demonstrate it.

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)
       ... and lots more lines of plan

According to tkprof, it takes 46 seconds – virtually all CPU time – to optimise this statement, then 0.63 seconds to run it. You might spot that this is 11gR2 (in fact it’s from the fact that the second line of the “Row Source Operation” includes a report of the estimated cost (and size/bytes and card/rows) of the query, which is only 1,331.

Things were actually worse than they seem at first sight; when we saw more of tkprof output the following also showed up:

  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') 
  NO_PARALLEL_INDEX("VAL_000002") */ :"SYS_B_02" AS C1, 
  SAMPLE BLOCK (:"SYS_B_21" , :"SYS_B_22") SEED (:"SYS_B_23") "VAL_000002" 
  WHERE ... 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch        5     21.41      24.14      11108      37331          0           5
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       15     21.41      24.15      11108      37331          0           5
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 144     (recursive depth: 1)
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=7466 pr=3703 pw=0 time=5230126 us)
   3137126    3137126    3137126   PARTITION HASH ALL PARTITION: 1 128 (cr=7466 pr=3703 pw=0 time=2547843 us cost=18758 size=131597088 card=3133264)
   3137126    3137126    3137126    TABLE ACCESS SAMPLE RECORDTEXTVALUE PARTITION: 1 128 (cr=7466 pr=3703 pw=0 time=2372509 us cost=18758 size=131597088 card=3133264)

This piece of SQL executed five times as the query was optimised, adding a further 24 seconds elapsed time and 21 CPU seconds which, surprisingly, weren’t included in the headline 46 seconds. The total time spent in optimising the statement was around 70 seconds, of which about 68 seconds were spent on (or waiting for) the CPU.

This is unusual – I don’t often see SQL statements taking more than a few seconds to parse – not since 8i, and not without complex partition views – and I certainly don’t expect to see a low cost query in taking anything like 70 (or even 46) seconds to optimise.

The OP had enabled the 10046 and the 10053 traces at the same time – and since the parse time was sufficiently unusual I asked him to email me the raw trace file – all 200MB of it.

Since it’s not easy to process 200MB of trace file the first thing to do is extract a few headline details, and I thought you might be interested to hear about some of the methods I use on the rare occasions when I decide to look at a 10053.

My aim is to investigate a very long parse time and the tkprof output had already shown me that there were a lot of tables in the query, so I had the feeling that the problem would relate to the amount of work done testing possible join orders; I’ve also noticed that the dynamic sampling code ran five times – so I’m expecting to see some critical stage of the optimisation run 5 times (although I don’t know why it should).

Step 1: Use grep (or find if you’re on Windows) to do a quick check for the number of join orders considered. I’m just searching for the text “Join order[“ appearing at the start of line and then counting how many times I find it:

[jonathan@linux01 big_trace]$ grep "^Join order\[" orcl_ora_25306.trc  | wc -l

That’s 6,266 join orders considered – let’s take a slightly closer look:

[jonathan@linux01 big_trace]$ grep -n "^Join order\[" orcl_ora_25306.trc >temp.txt
[jonathan@linux01 big_trace]$ tail -2 temp.txt
4458394:Join order[581]:  RECORDTYPEMEMBER[RTM]#9  RECORD_[VAL_000049]#13  ...... from$_subquery$_008[TBL_000020]#2
4458825:Join order[1]:  VM_NWVW_1[VM_NWVW_1]#0

The line of dots represents another 11 tables (or similar objects) in the join order. But there are only 581 join orders (apparently) before the last one in the file (which is a single view transformation). I’ve used the “-n” option with grep, so if I wanted to look at the right bit of the file I could tail the last few thousand lines, but my machine is happy to use vi on a 200MB file, and a quick search (backwards) through the file finds the number 581 in the following summary text (which does not appear in all versions of the trace file):

Number of join permutations tried: 581

So a quick grep for “join permutations” might be a good idea. (In the absence of this line I’d have got to the same result by directing the earlier grep for “^Join order\[“ to a file and playing around with the contents of the file.

[jonathan@linux01 big_trace]$ grep -n "join permutations" orcl_ora_25306.trc
11495:Number of join permutations tried: 2
11849:Number of join permutations tried: 1
12439:Number of join permutations tried: 2
13826:Number of join permutations tried: 2
14180:Number of join permutations tried: 1
14552:Number of join permutations tried: 2
15938:Number of join permutations tried: 2
16292:Number of join permutations tried: 1
16665:Number of join permutations tried: 2
18141:Number of join permutations tried: 2
18550:Number of join permutations tried: 2
18959:Number of join permutations tried: 2
622799:Number of join permutations tried: 374
624183:Number of join permutations tried: 2
624592:Number of join permutations tried: 2
624919:Number of join permutations tried: 1
625211:Number of join permutations tried: 2
1759817:Number of join permutations tried: 673
1760302:Number of join permutations tried: 1
1760593:Number of join permutations tried: 2
1760910:Number of join permutations tried: 1
1761202:Number of join permutations tried: 2
2750475:Number of join permutations tried: 674
2751325:Number of join permutations tried: 2
2751642:Number of join permutations tried: 1
2751933:Number of join permutations tried: 2
2752250:Number of join permutations tried: 1
2752542:Number of join permutations tried: 2
3586276:Number of join permutations tried: 571
3587133:Number of join permutations tried: 2
3587461:Number of join permutations tried: 1
3587755:Number of join permutations tried: 2
3588079:Number of join permutations tried: 1
3588374:Number of join permutations tried: 2
4458608:Number of join permutations tried: 581
4458832:Number of join permutations tried: 1

The key thing we see here is that there are five sections of long searches, and a few very small searches. Examination of the small search lists shows that they relate to some inline views which simply join a couple of tables. For each of the long searches we can see that the first join order in each set is for 14 “tables”. This is where the work is going. But if you add up the number of permutations in the long searches you get a total of 2,873, which is a long way off the 6,266 that we found with our grep for “^Join order[“ – so where do the extra join orders come from ? Let’s take a closer look at the file where we dumped all the Join order lines – the last 10 lines look like this:

4452004:Join order[577]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4452086:Join order[577]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4453254:Join order[578]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4453382:Join order[578]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4454573:Join order[579]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4454655:Join order[579]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4455823:Join order[580]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4455905:Join order[580]:  RECORD_[VAL_000033]#10  from$_subquery$_017[TBL_000029]#1 ...
4457051:Join order[581]:  RECORDTYPEMEMBER[RTM]#9  RECORD_[VAL_000049]#13  ...
4458394:Join order[581]:  RECORDTYPEMEMBER[RTM]#9  RECORD_[VAL_000049]#13  ...
4458825:Join order[1]:  VM_NWVW_1[VM_NWVW_1]#0

Every single join order seems to have appeared twice, and doubling the counts we got for the sum of the permutations gets us close to the total we got for the join order search. We can zoom in a little closer, does the text near the start of the two occurrences of join order 581 give us any clues ? We see the following just before the second one:

****** Recost for ORDER BY (using join row order) *******

The optimizer has tried to find a way of eliminating some of the cost by letting the table join order affect the order of the final output. Let’s do another grep to see how many join orders have been recosted:

[jonathan@linux01 big_trace]$ grep "Recost for ORDER BY" orcl_ora_25306.trc | sort | uniq -c
    452 ****** Recost for ORDER BY (using index) ************
   2896 ****** Recost for ORDER BY (using join row order) *******

So we’ve done a huge amount recosting. Let’s check arithmetic: 452 + 2,896 + 2,873 = 6,221, which is remarkably close to the 6,266 we needed (and that’s ignoring a few dozen join orders that were needed for the inline views, and the final error is too small for me to worry about).

We can conclude, therefore, that we did a huge amount of work costing a 14 table join a little over 6,000 times. It’s possible, of course, that we discarded lots of join orders very early on in the cost stage, so we could count the number of times we see a “Now joining” message – to complete a single pass on a 14 table join the optimizer will have to report “Now joining” 13 times.

[jonathan@linux01 big_trace]$ grep -n "Now joining" orcl_ora_25306.trc | wc -l

Since the message appeared 44,000 times from 6,200 join orders we have an average of 7 steps evaluated per join order. Because of the way that the optimizer takes short-cuts I think this is a fairly strong clue that most of the join order calculations actually completed, or got very close to completing, over the whole 14 tables. (The optimizer remembers “partial results” from previous join order calculations, so doesn’t have to do 13 “Now joining” steps on every single join order.)

We still need to know why the optimizer tried so hard before supplying a plan – so let’s look for the “Best so far” lines, which the trace file reports each time the optimizer finds a better plan than the previous best. Here’s an example of what we’re looking for:

       Cost: 206984.61  Degree: 1  Resp: 206984.61  Card: 0.00 Bytes: 632
Best so far:  Table#: 0  cost: 56.9744  card: 1.0000  bytes: 30
              Table#: 3  cost: 59.9853  card: 0.0000  bytes: 83
              Table#: 6  cost: 60.9869  card: 0.0000  bytes: 151
              Table#:10  cost: 61.9909  card: 0.0000  bytes: 185
              Table#: 5  cost: 62.9928  card: 0.0000  bytes: 253
              Table#: 2  cost: 65.0004  card: 0.0000  bytes: 306
              Table#: 1  cost: 122.4741  card: 0.0000  bytes: 336
              Table#: 8  cost: 123.4760  card: 0.0000  bytes: 387
              Table#: 4  cost: 125.4836  card: 0.0000  bytes: 440
              Table#: 7  cost: 343.2625  card: 0.0000  bytes: 470
              Table#: 9  cost: 345.2659  card: 0.0000  bytes: 530
              Table#:11  cost: 206981.5979  card: 0.0000  bytes: 564
              Table#:12  cost: 206982.6017  card: 0.0000  bytes: 598
              Table#:13  cost: 206984.6055  card: 0.0000  bytes: 632

As you can see, we get a list of the tables (identified by their position in the first join order examined) with details of accumulated cost. But just above this tabular display there’s a repeat of the cost that we end up with. So let’s write, and apply, a little awk script to find all the “Best so far” lines and then print the line two above. Here’s a suitable script, followed by a call to use it:

        if (index($0,"Best so far") != 0) {print NR m2}
        m2 = m1; m1 = $0;

awk -f cost.awk orcl_ora_25306.trc >temp.txt

An alternative to writing a little awk script would have been to use grep with the “lines before” option:

grep -n -B+2  "Best so far" | grep Cost

There was a bit of a mess in the output – there are a couple of special cases (relating, in our trace file, to the inline views and the appearance of a “group by placement”) that cause irregular patterns to appear, but the script was effective for the critical 14 table join. And looking through the list of costs for the various permutations we find that almost all the options show a cost of about 206,000 – except for the last few in two of the five “permutation sets” that suddenly drop to costs of around 1,500 and 1,300. The very high starting cost explains why the optimizer was prepared to spend so much time trying to find a good path and why it kept working so hard until the cost dropped very sharply.

Side bar: I have an old note from OCIS (“Oracle Customer Information System” – the precursor of the precursor of the precursor of MOS) that the optimizer will stop searching when (number of join orders tested) * (number of “non-single-row” tables (according to the single table access path) * 0.3) is greater than (best cost so far). I even have a test script (run against, dated September 2002) that seems to demonstrate the correctness of the formula. 

The formula may be terribly out of date by now and the rules of exactly how and when it applies may have changed – the model didn’t seem to work when I ran it against 19.3 – but the general principle may still holds true.

At this point we might decide that we ought to look at the initial join order and at the join order where the cost dropped dramatically, and try to work out why Oracle picked such a bad starting join order, and what it was about the better join order that the optimizer had missed. This might allow us to recognise some error in the statistics for either the “bad” starting order or the “good” starting order and allow us to solve the problem by (e.g.) creating a column group or gathering some specific statistics. We might simply decide that we’ll take a good join order and pass it to the optimizer through a /*+ leading() */ hint, or simply take the entire outline and attach it to the query through a faked SQL Profile or SQL Plan Baseline (or embedded set of hints) [ed: or SQL Patch, as the more desirable option, in the later versions of Oracle].

However, for the purposes of this exercise (and because sometimes you have to find a strategic solution rather than a “single statement” solution) I’m going to carry on working through mechanisms for dissecting the trace file without looking too closely at any of the fine detail.

The final “high-level” target I picked was to pin down why there were 5 sets of join orders. I had noticed something particular about the execution plan supplied – it showed several occurrences of the operation “VIEW PUSHED PREDICATE” so I wondered if this might be relevant. So I did a quick check near the start of the main body of the trace file for anything that might be a clue and found the following just after the “QUERY BLOCK SIGNATURE”.

  signature(): NULL
Cost-Based Join Predicate Push-down
JPPD: Checking validity of push-down in query block SEL$6E5D879B (#4)
JPPD:   Checking validity of push-down from query block SEL$6E5D879B (#4) to query block SEL$C20BB4FE (#6)
Check Basic Validity for Non-Union View for query block SEL$C20BB4FE (#6)
JPPD:     JPPD bypassed: View has non-standard group by.
JPPD:   No valid views found to push predicate into.
JPPD: Checking validity of push-down in query block SEL$799AD133 (#3)
JPPD:   Checking validity of push-down from query block SEL$799AD133 (#3) to query block SEL$EFE55ECA (#7)
Check Basic Validity for Non-Union View for query block SEL$EFE55ECA (#7)
JPPD:     JPPD bypassed: View has non-standard group by.
JPPD:   No valid views found to push predicate into.
JPPD: Checking validity of push-down in query block SEL$C2AA4F6A (#2)
JPPD:   Checking validity of push-down from query block SEL$C2AA4F6A (#2) to query block SEL$799AD133 (#3)
Check Basic Validity for Non-Union View for query block SEL$799AD133 (#3)
JPPD:     Passed validity checks
JPPD:   Checking validity of push-down from query block SEL$C2AA4F6A (#2) to query block SEL$6E5D879B (#4)
Check Basic Validity for Non-Union View for query block SEL$6E5D879B (#4)
JPPD:     Passed validity checks
JPPD:   Checking validity of push-down from query block SEL$C2AA4F6A (#2) to query block SEL$FC56C448 (#5)
Check Basic Validity for Non-Union View for query block SEL$FC56C448 (#5)
JPPD:     Passed validity checks
JPPD: JPPD:   Pushdown from query block SEL$C2AA4F6A (#2) passed validity checks.
Join-Predicate push-down on query block SEL$C2AA4F6A (#2)
JPPD: Using search type: linear
JPPD: Considering join predicate push-down
JPPD: Starting iteration 1, state space = (3,4,5) : (0,0,0)

As you can see we are doing cost-based join-predicate pushdown, and there are three targets which are valid for the operation. Notice the line that says “Using search type: linear”, and the highly suggestive “Starting iteration 1” – let’s look for more lines with “Starting iteration”

[jonathan@linux01 big_trace]$ grep -n "Starting iteration" orcl_ora_25306.trc
9934:GBP: Starting iteration 1, state space = (20,21) : (0,0)
11529:GBP: Starting iteration 2, state space = (20,21) : (0,C)
11562:GBP: Starting iteration 3, state space = (20,21) : (F,0)
12479:GBP: Starting iteration 4, state space = (20,21) : (F,C)
12517:GBP: Starting iteration 1, state space = (18,19) : (0,0)
13860:GBP: Starting iteration 2, state space = (18,19) : (0,C)
13893:GBP: Starting iteration 3, state space = (18,19) : (F,0)
14587:GBP: Starting iteration 4, state space = (18,19) : (F,C)
14628:GBP: Starting iteration 1, state space = (16,17) : (0,0)
15972:GBP: Starting iteration 2, state space = (16,17) : (0,C)
16005:GBP: Starting iteration 3, state space = (16,17) : (F,0)
16700:GBP: Starting iteration 4, state space = (16,17) : (F,C)
16877:JPPD: Starting iteration 1, state space = (3,4,5) : (0,0,0)
622904:JPPD: Starting iteration 2, state space = (3,4,5) : (1,0,0)
1759914:JPPD: Starting iteration 3, state space = (3,4,5) : (1,1,0)
2750592:JPPD: Starting iteration 4, state space = (3,4,5) : (1,1,1)

In passing we’ve picked up some analysis for “group by placement”, but there are four iterations for the JPPD state space (3,4,5) – and look at the huge gaps between their “Starting iteration” lines. In fact, let’s go a little closer and combine their starting lines with the lines above where I searched for “Number of join permutations tried:” (using egrep to search for multiple items in the same pass)

16877:JPPD: Starting iteration 1, state space = (3,4,5) : (0,0,0)
622799:Number of join permutations tried: 374

622904:JPPD: Starting iteration 2, state space = (3,4,5) : (1,0,0)
1759817:Number of join permutations tried: 673

1759914:JPPD: Starting iteration 3, state space = (3,4,5) : (1,1,0)
2750475:Number of join permutations tried: 674

2750592:JPPD: Starting iteration 4, state space = (3,4,5) : (1,1,1)
3586276:Number of join permutations tried: 571

4458608:Number of join permutations tried: 581

At this point my notes end and I don’t know where I was going with the investigation. I know that I suggested to the OP that the cost-based join predicate pushdown was having a huge impact on the optimization time and suggested he experiment with disabling the feature. (Parse time dropped dramatically, but query run-time went through the roof – so that proved a point, but wasn’t a useful strategy).

I don’t know, however, what the fifth long series of permutations was for, so if I could find the trace file one of the things I’d do next would be to look at the detail a few lines before line 4,458,608 to see what triggered that part of the re-optimization. I’d also want to know whether the final execution plan came from the fifth series and could be reached without involving all the join predicate pushdown work, or whether it was a plan that was only going to appear after the optimizer had worked through all 4 iterations.

The final plan did involve all 3 pushed predicates (which looksl like it might have been from iteration 4), so it might have been possible to find a generic strategy for forcing unconditional predicate pushing without doing all the expensive intermediate work.

The only other note that I’ve got about this case comes from the original forum thread where I’ve highlighted the fact that thetrace file showed that the MBRC (system statistics multiblock read count) was set to 1. The effect of this would be to give tablescans an abnormally high cost, and that might be enough to drive the optimizer into pick a very  bad first join order that allowed it spend a long time optimising, and also made it hard to find a lower cost join order.


Version 12c and beyond

That was then, and this is now. And something completely different might have appeared in 12c (or 19c) – but the one thing that is particularly helpful is that you can bet that every iteration of the JPPD state spaces would have produced a “TIMER:” line in the trace file, making it very easy to run grep -n “TIMER:” (or -nT to improve the layout slightly as I recently discovered) against the trace file to pinpoint the issue very quickly.

Here’s an example from my killer_parse.sql query after setting _fix_control=’16923858:4′ (1e4 microseconds = 1/100th second) in an instance of 19c:

$ grep -nT TIMER or19_ora_21051.trc

16426  :TIMER:      bitmap access paths cpu: 0.104006 sec elapsed: 0.105076 sec
252758 :TIMER:     costing general plans cpu: 0.040666 sec elapsed: 0.040471 sec
309460 :TIMER:      bitmap access paths cpu: 0.079509 sec elapsed: 0.079074 sec
312584 :TIMER: CBQT OR expansion SEL$765CDFAA cpu: 10.474142 sec elapsed: 10.508788 sec
313974 :TIMER: Complex View Merging SEL$765CDFAA cpu: 1.475173 sec elapsed: 1.475418 sec
315716 :TIMER: Table Expansion SEL$765CDFAA cpu: 0.046262 sec elapsed: 0.046647 sec
316036 :TIMER: Star Transformation SEL$765CDFAA cpu: 0.029077 sec elapsed: 0.026912 sec
318207 :TIMER: Type Checking after CBQT SEL$765CDFAA cpu: 0.220506 sec elapsed: 0.219273 sec
318208 :TIMER: Cost-Based Transformations (Overall) SEL$765CDFAA cpu: 13.632516 sec elapsed: 13.666360 sec
328948 :TIMER:      bitmap access paths cpu: 0.093973 sec elapsed: 0.095008 sec
632935 :TIMER: Access Path Analysis (Final) SEL$765CDFAA cpu: 7.703016 sec elapsed: 7.755957 sec
633092 :TIMER: SQL Optimization (Overall) SEL$765CDFAA cpu: 21.539010 sec elapsed: 21.632012 sec

The closing 21.63 seconds (line 633092) is largely:

  • 7.7559 seconds (line 632,935) Access Path Analysis (Final) plus
  • 13.666 seconds (line 318208) Cost-Based Transformation

and that 13.666 seconds is mostly

    • 1.475 seconds (line 313,974) Complex View Merging plus
    • 10.508 seconds (line 312,584) CBQT OR expansion

so let’s try disabling OR expansion (alter session set “_no_or_expansion”=true;) and try again:

$ grep -nT TIMER or19_ora_22205.trc
14884  :TIMER:      bitmap access paths cpu: 0.062453 sec elapsed: 0.064501 sec
15228  :TIMER: Access Path Analysis (Final) SEL$1 cpu: 0.256751 sec elapsed: 0.262467 sec
15234  :TIMER: SQL Optimization (Overall) SEL$1 cpu: 0.264099 sec elapsed: 0.268183 sec

Not only was optimisation faster, the runtime was quicker too.

Warning – it’s not always that easy.


For another example where the Timer lines of the 10053 trace proved very helpful (and also pointed to the new Cost Based Or Expansion) here’s a link to a note on the Pythian blog.



  1. Thanks for this nice and detailed article. A couple of months ago I have been confronted to several parsing issue in PeopleSoft in a 12cR1 with queries using complex views.

    The quick fix I have found is to use /*+ no_query_transformation*/ which indeed did the job.

    I’ve 10053 traced one of the above queries and have found such a kind of trace file

    xxxx# grep TIMER yyyy_ora_212312_MHOParsingIssue.trc
    TIMER:     costing general plans cpu: 3.202 sec elapsed: 3.612 sec
    TIMER:     costing general plans cpu: 2.623 sec elapsed: 2.808 sec
    TIMER:  SU: costing SEL$191DE02A cpu: 62.336 sec elapsed: 73.491 sec
    TIMER:     costing additional plans cpu: 4.841 sec elapsed: 5.223 sec
    TIMER:  SU: costing Interleaved CVM SEL$E4D08F70 cpu: 119.721 sec elapsed: 147.164 sec
    TIMER:  i JPPD: iteration (#2) SEL$191DE02A cpu: 65.091 sec elapsed: 75.275 sec
    TIMER:  SU: Interleaved JPPD SEL$191DE02A cpu: 127.483 sec elapsed: 154.004 sec
    TIMER:  SU: iteration (#1) SEL$191DE02A cpu: 309.553 sec elapsed: 374.850 sec
    TIMER: CBQT SU and CVM SEL$1 cpu: 363.743 sec elapsed: 442.333 sec
    TIMER: Cost-Based Transformations (Overall) SEL$8F76A17B cpu: 364.535 sec elapsed: 443.767 sec

    This is very strange to find such a long parsing time nowadays.

    By the way I have also tried this: alter session set “_sql_diag_repo_retain” = true; trying to find the number of transformations checked

    Best regards
    Mohamed Houri

    Comment by hourim — November 18, 2019 @ 12:32 pm GMT Nov 18,2019 | Reply

  2. Coincidentally this year @POUG I did a demo with long parsing. It took about 3 minutes in my case, and sometimes hours in a client’s environment. Also due to OR expansion. I find it easier to get a few process stack traces with oradebug short_stack, and then paste it into the nicely done to get an idea what is going on. In this case, it was 4 levels of OR expansion, and when it’s turned off the parsing takes a few seconds, and run time is under a second.

    Comment by Timur Akhmadeev — November 25, 2019 @ 9:23 am GMT Nov 25,2019 | Reply

  3. Excellent article Jonathan. Thank you very much.

    I have a 10053 trace showing the parse time at almost 8 minutes. It is mainly due to OR-Expansion. I hinted to turn that off and the time is down to 90sec. Still not great but better than 8min.
    However in looking at the timing I am noticing the CPU time is only ~50-60% of the elapsed time for nearly all the timings. This seems to indicate the process also cannot get on the CPU.
    Does that sound like a correct assessment?
    This is a customer AIX system. I suspect the timing issue between Oracle and AIX Power8 processor might be having an effect here but not sure.

    31309673:TIMER:     costing additional plans cpu: 0.618 sec elapsed: 1.525 sec
    31313681:TIMER: Access Path Analysis (Final) SEL$5C987028 cpu: 40.287 sec elapsed: 72.257 sec
    31313992:TIMER: SQL Optimization (Overall) SEL$5C987028 cpu: 273.974 sec elapsed: 475.533 sec


    Comment by Andrew Markiewicz — January 3, 2020 @ 3:50 pm GMT Jan 3,2020 | Reply

    • Andrew,

      Contention for CPU is certainly possible. Optimisation is CPU intensive and hugely focused on local memory, so you could simply be seeing your session being pre-empted by the O/S is there’s a lot going on. Other factors, though, might be I/O time to read the data dictionary or to sample some stats, or sleeps on latches while trying to acquire space in the shared pool, or O/S effects as your PGA tries to allocate large amounts of memory.

      If you can repeat the tests and check the contents of v$active_session_history for the session (if you’re suitably licensed) you might get a better idea of whether it’s an accounting error or real wait time due to other effects. If the “in parse / in hard parse” columns are Y for the whole time period and every sample is “ON CPU” then it’s probably some form of CPU accounting or pre-empting problem.

      Comment by Jonathan Lewis — January 3, 2020 @ 9:18 pm GMT Jan 3,2020 | Reply

  4. Hello,

    After upgrading databases from to Oracle 19.8, i have a lot of performance issues.

    Parsing times goes up to 50 seconds …!

    All of them are parsing issues due to subquery’s/views.

    Some of them can be resolved by “_optimizer_squ_bottomup”=false ; but most of them can only made faster with hint NO_QUERY_TRANSFORMATION.

    It concerns a lot of query’s … so not a fast job to resolve the problem, and my opinion not the right way to take … as this is a optimizer bug ?

    What’s going wrong in Oracle 19.8 ? Logged also a SR at Oracle’s support …..

    Anyone a better idea to solve the problem (fix_control,hidden param, …. )?

    Kind reagards

    Comment by Erik — October 18, 2020 @ 12:25 pm BST Oct 18,2020 | Reply

  5. Erik,

    Thanks for the comment. It can be very helpful for other users to see warnings about upgrades – especially if the subsequent comments lead to some resolution.

    It’s a little surprising that setting “_optimizer_squ_bottomup” to false help since its value would have been true in your previous version anyway.

    Two things that are always worth a try:

    a) Do the queries that only get faster with “/*+ no_query_transformation */ also get faster if you set optimizer_features_enable back to If so then you may be able to pin a specific parameter that was relevant to all the examples. (It looks like you may have tried this approach already, given your discovery of the _optimizer_squ_bottomup fix).

    b) Have you run a 10053 trace against one of the queries that doesn’t respond to the parameter change and then extracted the TIMER lines from it. That might give you a clue about what mechanism the optimizer was working that used so much time – which might then be a good pointer to what feature to disable.

    A final thought about parse times – if 19.8 decides to do a lot of dynamic sampling for some reason then the parse time might be spent on sampling queries of the database; have you checked for SQL being executed in mid-parse? (A basic SQL_trace highlight this).

    Jonathan Lewis

    Comment by Jonathan Lewis — October 19, 2020 @ 10:45 am BST Oct 19,2020 | Reply

  6. Jonathan,

    So, after doing more tests:

    setting for /*+ no_query_transformation */ gives an better parse time, but in 90% of the cases a very worse execution time/plan (much slower than without the hint).
    setting /*+ OPT_PARAM(”optimizer_features_enable” ””) */ gives the best overall performance, but that’s not really the best choice.

    From 10053 level 1 trace:
    :TIMER: Cost-Based Join Predicate Push-Down SEL$1359959D cpu: 44.963 sec elapsed: 44.962 sec
    :TIMER: Cost-Based Transformations (Overall) SEL$1359959D cpu: 218.433 sec elapsed: 218.437 sec
    :TIMER: Access Path Analysis (Final) SEL$1359959D cpu: 1.659 sec elapsed: 1.657 sec
    :TIMER: SQL Optimization (Overall) SEL$1359959D cpu: 220.622 sec elapsed: 220.631 sec

    grep “^Join order\[” a.trc | wc -l

    Logged also an SR ………

    Kind regards

    Comment by Erik — October 19, 2020 @ 7:47 pm BST Oct 19,2020 | Reply

  7. Excellent one Jonathan, Thank you very much.
    with the hint /*+ no_query_transformation*/ it has reduced parse time a half, but sometimes there are more no of parses and reason is not recorded in the v$sql_shared_cursor, and in te TKPROF also its not showing the reason for hard parse. is there any trace that can be enabled to know the reason for each hard parse of a particular SQLID? thanks in advance.

    Comment by Mohan — January 13, 2022 @ 3:36 am GMT Jan 13,2022 | Reply

    • Mohan,

      Thank you for the question.

      If the reason doesn’t show up in v$sql_shared_cursor then I doubt if the information can be found anywhere else. I have noticed documents on MOS occasionally which explain version-specific cases of multple child cursors appearing with no explanation flagged in v$sql_shared_cursor, but the number of columns in that view keeps increasing to cater for the cases which had previously been missed. If you’re using a very recent version of Oracle it’s possible that it’s something to do with a new code path that hasn’t yet been fixed to include a relevant flag/bit.

      Jonathan Lewis

      Comment by Jonathan Lewis — January 13, 2022 @ 11:18 am GMT Jan 13,2022 | Reply

RSS feed for comments on this post. TrackBack URI

Comments and related questions are welcome.

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

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

Website Powered by

%d bloggers like this: