RE: Long Parse Time

From: Tanel Poder <tanel_at_poderc.com>
Date: Thu, 7 May 2009 14:09:23 +0300
Message-ID: <BB28F745E4DF4ACAA8FC40E965DA4B4C_at_porgand>



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_at_freelists.org
> [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Randolf Geist
> Sent: 07 May 2009 10:49
> To: oracle-l_at_freelists.org
> 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/
-- http://www.freelists.org/webpage/oracle-l
Received on Thu May 07 2009 - 06:09:23 CDT

Original text of this message