RE: Long Parse Time
- From: "Tanel Poder" <tanel@xxxxxxxxxx>
- To: <oracle-l@xxxxxxxxxxxxx>
- Date: Thu, 7 May 2009 14:09:23 +0300
Again, if parsing takes minutes or tens of seconds of CPU time then you're
hitting a bug or someone has fiddled with undocumented parameters! Parsing
should not take that long!
Yes one way is to try to disable "this and that" in hope that the problem
goes away, but the SYSTEMATIC approach would be seeing WHERE the parsing
TIME is spent!
1) If we have a regular performance problem, we aren't going to drop or
create random indexes, we PROFILE the operation and SEE where the response
time was spent and act accordingly.
2) If we have a PARSING performance problem, we shouldn't start randomly
flipping switches either, we should also PROFILE that operation and SEE
where the time was spent and act accordingly.
In 1st case we'd use sql_trace + a profiler (like tkprof or method-r
profiler)
In 2nd case we can use process stack sampling and some profiler to aggregate
these stacks (pick your favorite, I've written dstackprof and ostackprof
for example)
Reading a oracle process stack profile is harder due function names being
less documented - but wait, there IS the public metalink note 175982.1 which
documents a lot of function name prefixes (modules) in Oracle kernel.
I have used this systematic approach for troubleshooting just a problem like
this. Process stack profiling showed me functions starting with "kkz" as
prevalent and the explanation in that note was: "support for snapshots or
Materialized View validation and operation".
Then I knew to set query_rewrite_enabled = false for quick workaround and I
was better equipped for a metalink search returned me the bug.
The point I'm making here - systematic troubleshooting does NOT end where
Oracle's built-in instrumentation ends. When having performance problems,
crashes or hangs, we always should start from well-known Oracle's built in
instrumentation (like wait interface, sess_time_model, sql_trace) and if
that doesn't help then either look into process stack or 10053 trace in this
case.
You can perform some sort of profiling on 10053 trace as well if its too
large for manual reading.
Lets check how many join orders were evaluated in total:
$ grep -c "Join order\[" lin10g_ora_15175.trc
320
In my case there's no problem with the number of of join orders tried as the
query (select count(*) from dba_segments) joins quite a few tables.
Lets see the breakdown, if some join orders were re-evaluated a huge number
of times (due a bug perhaps):
$ grep "Join order\[" lin10g_ora_15175.trc | cut -d: -f2 | sort | uniq -c |
sort -n | tail -10
4 SYS_OBJECTS[SO]#3 SEG$[S]#4 OBJ$[O]#5 TS$[TS]#1 USER$[U]#2
FILE$[F]#0
4 SYS_OBJECTS[SO]#3 SEG$[S]#4 OBJ$[O]#5 USER$[U]#2 FILE$[F]#0
TS$[TS]#1
4 SYS_OBJECTS[SO]#3 SEG$[S]#4 OBJ$[O]#5 USER$[U]#2 TS$[TS]#1
FILE$[F]#0
4 SYS_OBJECTS[SO]#3 SEG$[S]#4 TS$[TS]#1 FILE$[F]#0 OBJ$[O]#5
USER$[U]#2
4 SYS_OBJECTS[SO]#3 SEG$[S]#4 TS$[TS]#1 OBJ$[O]#5 FILE$[F]#0
USER$[U]#2
4 SYS_OBJECTS[SO]#3 SEG$[S]#4 TS$[TS]#1 OBJ$[O]#5 USER$[U]#2
FILE$[F]#0
4 TS$[TS]#1 SEG$[S]#4 FILE$[F]#0 SYS_OBJECTS[SO]#3 OBJ$[O]#5
USER$[U]#2
4 TS$[TS]#1 SEG$[S]#4 SYS_OBJECTS[SO]#3 FILE$[F]#0 OBJ$[O]#5
USER$[U]#2
4 TS$[TS]#1 SEG$[S]#4 SYS_OBJECTS[SO]#3 OBJ$[O]#5 FILE$[F]#0
USER$[U]#2
4 TS$[TS]#1 SEG$[S]#4 SYS_OBJECTS[SO]#3 OBJ$[O]#5 USER$[U]#2
FILE$[F]#0
In my case the max number of re-evaluations per join order was only 4 (due
costed query transformations probably) so I see no problem here. In your
case with 300MB tracefile you may see some larger numbers if you're hitting
a bug like that. Again, this is not the only way of "profiling" CBO trace
file..
--
Tanel Poder
http://blog.tanelpoder.com
> -----Original Message-----
> From: oracle-l-bounce@xxxxxxxxxxxxx
> [mailto:oracle-l-bounce@xxxxxxxxxxxxx] On Behalf Of Randolf Geist
> Sent: 07 May 2009 10:49
> To: oracle-l@xxxxxxxxxxxxx
> Subject: RE: Long Parse Time
>
> Ric,
>
> I've recently had an issue with a query that took up to 20
> mins (!) to parse, containing simple equality joins to
> multiple table, inline views and uncorrelated subqueries.
>
> In addition to the suggestions that you've already got two
> things that might help to reduce the parse time significantly:
>
> 1. Use subquery factoring: It's not well known but at least
> up to 11.1.0.6 (I haven't tested it in 11.1.0.7 yet) there is
> a significant difference between using (inline) views (or no
> view at all) and doing the same with subquery factoring.
> Using subquery factoring disables certain optimizer paths, in
> particular some part of the Cost Based Query
> Transformation/Complex view merging, see e.g. here:
>
> http://oracle-randolf.blogspot.com/2008/01/subquery-factoring-
> and-cost-based-query.html
>
> In your case this might help to reduce the parse time since
> the CBQT feedback loop might take a significant amount of parse time.
>
> 2. Combine above with "NO_MERGE" hints: Using the simple
> NO_MERGE hint in the factored out subquery reduces the number
> of options to evaluate even further
>
> Using this approach I was able to cut down the parse time to
> 5-7 seconds and the execution time to 1 second, which was
> acceptable in this case given the initial parse time of
> several minutes.
>
> Using the undocumented parameters mentioned by Tanel you
> should be able to quickly find out if above mentioned
> features are causing the issues (Cost Based Query
> Transformation, Complex View Merging, etc.) and if yes, the
> outlined rewrites might help in this matter without the need
> to fiddle with the undocumented parameters.
>
> Regards,
> Randolf
>
> Oracle related stuff blog:
> http://oracle-randolf.blogspot.com/
>
> SQLTools++ for Oracle (Open source Oracle GUI for Windows):
> http://www.sqltools-plusplus.org:7676/
> http://sourceforge.net/projects/sqlt-pp/
--
//www.freelists.org/webpage/oracle-l
Other related posts:
