Re: session time model issue

From: Cary Millsap <cary.millsap_at_method-r.com>
Date: Mon, 28 Jan 2013 09:37:06 -0600
Message-ID: <CAJOkrQbuT7t17HsjfjXKpQZ1g6sG=U9ahZEm1WX--3QFXT5aMg_at_mail.gmail.com>

Taking the simple case of a recursive parse call as an example, it's executed as if the unrolled code path looks like this: parse(...) {

    c0 = getrusage(); /* dramatic oversimplification */     code path to do parsing needs, itself, to make a parse call;     parse(...) {

        c0 = getrusage();
        code path to do parsing;
        c1 = getrusage();
        c = c1 - c0;  /* this is the c statistic that's emitted to the

trace for the PARSE...dep=1 call */

    }
    finish up the outer parse call;
    c1 = getrusage();
    c = c1 - c0; /* this is the c statistic that's emitted to the trace for the PARSE...dep=0 call */
}

...So you'll see in the trace file something like:

PARSE #42 c=8,...,dep=1,...
PARSE #12 c,...,dep=0,...

In this example, the PARSE #12 *contains* the PARSE #42, or equivalently you could say that the PARSE #42 executed within the context of the PARSE #12. The outer call lasted for the elapsed duration that a user would have experienced, 10us. The inner PARSE call, consuming 8us, contributed to the 10us. You could say roughly that, had the inner PARSE #42 not taken place, the outer PARSE #12 would have consumed only c=2us.

Understanding this, which is not to difficult to comprehend when you see the trace data, makes it easier to understand what conspires to make the aggregated information in the fixed views look the sometimes peculiar way it does.

Cary Millsap
Method R Corporation
http://method-r.com
software, courses, consulting

On Sat, Jan 12, 2013 at 1:57 PM, Tanel Poder <tanel_at_tanelpoder.com> wrote:

> Just treat them as they are - if 1000ms out of a second is seemingly spent
> on execution and "additional" 900ms out of the same second were spent on
> hard parsing, then they both happened, but just at a different level or
> recursive depth.
> I'm not saying that these operations were executing at the same time, but
> rather the parsing operation took a dive into (recursive) execution level
> and while recursive execution for the parsing operation was running, the
> time still was accounted for both (again it's just based on taking deltas
> between begin & end operation snapshots and recursive operations apparently
> break the logic somewhat).
>
> I prefer this behavior to artificially hiding or subtracting time from raw
> measurements. Should it show 100% execution and 0% parsing - or only 10% on
> execution and 90% parsing in this case ... maybe a new time model metric
> "recursive execution time" could help ...
>
> --
> *Tanel Poder*
> Online Training! - http://blog.tanelpoder.com/seminar
> The Voicee App - http://voic.ee
>
>
> On Thu, Jan 10, 2013 at 12:54 PM, Remigiusz Sokolowski <
> remigiusz.sokolowski_at_nordea.com> wrote:
>
> > Point taken - almost whole parse time elapsed is counted as hard parse
> > and in trace file there is a lot of recursive queries as this is quite a
> > complex query.
> >
> > So an additional question - how to treat these stats - because recursive
> > sql is done on behalf of parsing actually?
> >
> > On 09.01.2013 17:51, Tanel Poder wrote:
> > > Hi Remigiusz,
> > >
> > > This seems to happen (at least in some versions) when a (hard) parse
> > > causes recursive SQL execution (for data dictionary access, FGAC
> > > predicate generation etc) ...
> > >
> > > --
> > > Tanel Poder
> > > New Online Training! - http://blog.tanelpoder.com/seminar
> > > The Voicee App - http://voic.ee
> > >
> > >
> > > On Wed, Jan 9, 2013 at 3:09 PM, Remigiusz Sokolowski
> > > <remigiusz.sokolowski_at_nordea.com
> > > <mailto:remigiusz.sokolowski_at_nordea.com>> wrote:
> > >
> > > On 09.01.2013 04:48, Jeremy Schneider wrote:
> > > > On Tue, 8 Jan 2013 12:49:44 +0100
> > > > Remigiusz Sokolowski <remigiusz.sokolowski_at_nordea.com
> > > <mailto:remigiusz.sokolowski_at_nordea.com>> wrote:
> > > >
> > > >> I have just reviewed the session time model gathered for a
> single
> > > >> query. My concern is that parse time elapsed is nearly 97% (and
> > > >> actually the whole amount is attributed to hard parse) of the DB
> > time
> > > >> and sql execute elapsed time is 99% of the DB time.
> > > >>
> > > >> As this is for one session I assume there is no possibility the
> > > sum of
> > > >> ingredients is more than DB time (of course by much), so it
> seems
> > > >> reasonable to assume sql execute elapsed time is execute, fetch
> > and
> > > >> parse, which is against the docs.
> > >
> >
> >
> > --
> > Pole na kazi
> >
> > ----------------------------------------------------------------------
> > Remigiusz Sokolowski <remigiusz.sokolowski_at_nordea.com>
> > pos : Senior DBA at DIiUSI
> > addr : Nordea Bank Polska SA, Luzycka 6A st, 81-537 Gdynia, Poland
> > phone : +48 58 667 17 43
> > mobile: +48 602 42 42 77
> > Nordea Bank Polska S.A. z siedziba w Gdyni, ul. Kielecka 2, 81-303
> Gdynia,
> > wpisana do Rejestru Przedsiebiorców Krajowego Rejestru Sadowego pod
> > numerem: 0000021828,
> > dla której dokumentacje przechowuje Sad Rejonowy Gdansk - Pólnoc w
> Gdansku,
> > VIII Wydzial Gospodarczy Krajowego Rejestru Sadowego,
> > o kapitale zakladowym i wplaconym w wysokosci: 277.493.500,00 zlotych,
> > NIP: 586-000-78-20, REGON: 190024711
> >
>
> --
> http://www.freelists.org/webpage/oracle-l
>
>
>

--
http://www.freelists.org/webpage/oracle-l

Received on Mon Jan 28 2013 - 16:37:06 CET