Home > Oracle > Timing: query execution statistics (rowsource statistics). Part 1: How it works

Timing: query execution statistics (rowsource statistics). Part 1: How it works

December 24, 2012 Leave a comment Go to comments

This is the first (but not last) blogpost of my explanation of timing. This stuff is about timing in query execution statistics which also called rowsource statistics.

Here I am explaining

    • why reported actual time (“A-Time” or “time=” in sql trace) can be inconsistent,
    • why execution time with statistics_level=all can be longer,
    • and how exactly it works.

This stuff covers versions 10g and later if another is not mentioned.

Merry Christmas and Happy New Year 2013! ;-)

Introduction

The rowsource statistics are figures as time spent during execution of rowsource (a step of execution plan), number of returned rows, number of buffer gets and physical reads and writes and some statistics of usage of workareas. These statistics are populated in V$SQL_PLAN_STATISTICS and V$SQL_PLAN_STATISTICS_ALL (based on X$QESRSTAT and X$QESRSTATALL) when statistics gathering is enabled. Also if sql_trace (10046 event) is enabled then these statistics are printed in raw trace file as details inside rows “STAT #” and can be seen in tkprof report as execution plan.

The statistics gathering is enabled for a query only if it is turned on before a query execution and can be seen only when the query is finished (event with error) or canceled.

Rowsource statistics were introduced in Oracle 9i, but there was no useful interface to see they in convenient form. In 10g very important tool has been introduced – the function DBMS_XPLAN.DISPLAY_CURSOR having many useful options. The tool has become an indispensable tool for SQL tuning.

How to use

 Gathering of rowsource statistics can be enabled by one of following options:

1. set parameter statistics_level to all (at session or system level)
2. run a query with hint gather_plan_statistics
3. enable sql trace

  • these methods explained more detailed below in the section “Timing sampling frequency” (part 2).

Gathered statistics populate V$SQL_PLAN_STATISTICS and V$SQL_PLAN_STATISTICS_ALL and can bee seen either
– by very useful form using function DBMS_XPLAN.DISPLAY_CURSOR (preferable).
– directly query V$SQL_PLAN_STATISTICS_ALL
– in trace file as STAT# rows or in tkprof report as figures inside brackets in execution plan, if a query was traced by sql trace

Using DBMS_XPLAN.DISPLAY_CURSOR with SQL trace
It is helpful to emphasize that even you used sql trace in order to investigate what is going on with a query, it is possible to use dbms_xplan.display_cursor to see rowsource statistics.
Pros are obvious:
It is easier, because it does not require access to the trace file on the host.
Rowsource statistics printed in tracefile contain only minimum of figures: cr (consistent reads), pr (physical reads), pw (physical writes), time. At the same time complete rowsource statistics collected in v$sql_plan_statistics[_all] and printed by dbms_xplan.display_cursor() contain more useful information then in trace, in particular
– starts (number of times a rowsource has been executed),
– current gets. Trace shows cu= only for sql call level (parse, exec, fetch) as “cu=” stat, but not for rowsource level. In the same time DISPLAY_CURSOR() shows “buffer gets” that is sum of cr and cu, but it is possible to query v$sql_plan_statistics[_all] to see cr and cu as separated values;
– workareas and tempspace usage
So, rowsource statistics printed in tracefile is only restricted subset of gathered statistics.
Also display_cursor() is able to provide much helpful information related with execution plan as predicates, column projection, notes, etc.

Cons:
V$SQL_PLAN_STATISTICS[_ALL] contains two sets of figures: one is cumulated values for ALL executions of a cursor and one for LAST execution of the cursor. It means that if a query should be executed many times and only one of execution in the middle is object of interest, then V$SQL_PLAN_STATISTICS[_ALL] and DISPLAY_CURSOR() can be useless, SQL trace is more appropriate.

The gathering of the rowsource statistics by sql trace also means that if you need to get rowsource statistics and session settings cannot be changed (so, parameter statistics_level cannot be used), the query cannot be changed (so, hint gather_plan_statistics cannot be used), then it is possible to just enable sql trace in the session, or enable sql trace for exact query using 11g synthax:

SQL> alter system set events 'sql_trace[sql:gpdmdntvzjgcr]';

where “gpdmdntvzjgcr” is sql_id which we are going to trace

  • upd: There is also an option create SQL profile with hint gather_plan_statistics inside, can be useful especially in cases when sql_id is unknown for example when sql text is always changed/unique due to used literals, details in comments below the page

Rowsources and rowsource statistics architecture

Let’s look how rowsource statistics work. Let’s prepare data, this is a table with 50 rows and an index

SQL> create table tbl(id not null, pad) as
  2      select rownum as id, rpad('X',100,'X') as pad
  4        from all_objects
  5       where rownum <= 50;
Table created

SQL> create index idx on tbl(id);

Index created

SQL> exec dbms_stats.gather_table_stats(user, 'TBL', estimate_percent => 100, cascade => true);

PL/SQL procedure successfully completed

execute the Digger

digger.sh -p PID -FSmdeoz -f opifch* -t *,libc.so.1:gethrtime > output.trc

It means:
-f - opifch* - tracing is enabled inside function which name is beginning from opifch
-t - *,libc.so.1:gethrtime - to trace all calls of Oracle and calls gethrtime from library libc
-F - to print flow indents
-S - trace all syscalls
-m - print module
-d - print relative timestamps
-z - print user stack before enter into qergsFetch

and execute a query

select --+ index(tbl)
       count(pad)
  from tbl;

-----------------------------------------------------
| Id  | Operation                    | Name | Rows  |
-----------------------------------------------------
|   0 | SELECT STATEMENT             |      |     1 |
|   1 |  SORT AGGREGATE              |      |     1 |
|   2 |   TABLE ACCESS BY INDEX ROWID| TBL  |    50 |
|   3 |    INDEX FULL SCAN           | IDX  |    50 |
-----------------------------------------------------

twice – once without rowsource statistics: stats_disabled_full.txt
and once with them: freq1_full.txt

  • The files stats_disabled_full.txt and freq1_full.txt mentioned above contain complete output of function calls. Instead of show complete tree of calls I will use the output of only qer* and qesa* functions and gethrtime() library call, just for better readability.
    In order to do get this output I execute Digger as above, but with parameters
    -f qerstFetch
    -t qer*,qesa*,libc.so.1:gethrtime
    digger.sh -p PID -FSmdeoz -f qerstFetch -t qer*,qesa*,libc.so.1:gethrtime > output.trc
    

    what means to trace only qer* and qesa* function calls and function gethrtime from library libc inside function qerstFetch. So, the output below is from files containing these calls.
    Why qer* and qesa* ? Functions qer* are Query Execution Rowsource layer and qesa* is just to have function qesaFastAggNonDistSS in the output, I will explain about it in the section Rowsource Arcitechture

We can see that with enabled rowsource statistics every call of rowsource function is wrapped in qerst* correlated functions.

The output without rowsource statistics: stats_disabled.txt

module call(args)             = return
------ ---------------------------------
oracle -> qergsFetch(0xC1A2D828, 0xFFFFFD7FFDC353E8, 0x4B6D830)
oracle   -> qertbFetchByRowID(0xC1A2D9F8, 0xFFFFFD7FFDC350C0, 0x39983B8)
oracle     -> qerixtFetch(0xC1A2DC80, 0xFFFFFD7FFDC349B8, 0x0)
oracle     <- qerixtFetch = 0x0
oracle     -> qertbGetPartitionNumber(0xFFFFFD7FFFDFB264, 0xC1A2DB08, 0xFFFFFD7FFDC35188)
oracle     <- qertbGetPartitionNumber = 0x1
oracle     -> qerixtFetch(0xC1A2DC80, 0xFFFFFD7FFDC349B8, 0x0)
oracle     <- qerixtFetch = 0x0

The output with rowsource statistics: freq1.txt

   module call(args)             = return
--------- ---------------------------------
   oracle -> qerstFetch(0xC19A32B8, 0xFFFFFD7FFDC349B8, 0x4B6D830)
libc.so.1   -> gethrtime(0xFFFFFD7FFFDFB510, 0x0, 0x43)
libc.so.1   <- gethrtime = 0xB3789663
   oracle   -> qergsFetch(0xC19A3428, 0xFFFFFD7FFDC346D8, 0x3570158)
   oracle     -> qerstFetch(0xC19A3520, 0xFFFFFD7FFDC34438, 0x39983B8)
libc.so.1       -> gethrtime(0xFFFFFD7FFFDFB290, 0x0, 0x14)
libc.so.1       <- gethrtime = 0xB37B2B9C
   oracle       -> qertbFetchByRowID(0xC19A3688, 0xFFFFFD7FFDC34120, 0x3570158)
   oracle         -> qerstFetch(0xC19A3810, 0xFFFFFD7FFDC34088, 0x0)
libc.so.1           -> gethrtime(0xFFFFFD7FFFDFAF90, 0x0, 0x51)
libc.so.1           <- gethrtime = 0xB37D610A
   oracle           -> qerixtFetch(0xC19A39A0, 0xFFFFFD7FFDC33980, 0x0)
   oracle           <- qerixtFetch = 0x0
   oracle           -> qerstUpdateStats(0xFFFFFD7FFDC34088, 0xFFFFFD7FFFDFAF90, 0x1)
libc.so.1             -> gethrtime(0x59, 0xCA6C3AE0, 0x5A)
libc.so.1             <- gethrtime = 0xB3812DCB
   oracle           <- qerstUpdateStats = 0xE9E8513F
   oracle         <- qerstFetch = 0x0
   oracle         -> qertbGetPartitionNumber(0xFFFFFD7FFFDFB084, 0xC19A3798, 0xFFFFFD7FFDC341E8)
   oracle         <- qertbGetPartitionNumber = 0x1
   oracle         -> qerstRowP(0xFFFFFD7FFFDFB250, 0x7FFF, 0x3570158)
   oracle           -> qerstUpdateStats(0xFFFFFD7FFDC34438, 0xFFFFFD7FFFDFB290, 0x1)
libc.so.1             -> gethrtime(0x59, 0xCA6C3AE0, 0x5A)
libc.so.1             <- gethrtime = 0xB38957DB
   oracle           <- qerstUpdateStats = 0xE9E850AF
libc.so.1           -> gethrtime(0xFFFFFD7FFFDFB450, 0x7FFF, 0xFFFFFD7FFDC4BBC8)
libc.so.1           <- gethrtime = 0xB38B4E8F
   oracle         <- qerstRowP = 0x7FFF
  • Pay attention that parameter -S has been used in Digger, it means to trace syscalls, but we do not see such syscalls as gethrtime(), only library calls. It is because gethrtime() is implemented as special type of system call – fast trap syscall. On Linux Oracle calls gettimeofday(), which implemented as vsyscall/VDSO, it is also special type of syscall, which allows application in user space to perform some kernel actions without as much overhead as a system call.

Each real rowsource function as qergsFetch, qerixtFetch, qertbFetchByRowID now is wrapped by qerstFetch function with calling of qerstSnapStats() before real rowsource function and qerstUpdateStats() after it. Inside functions qerstSnapStats() and qerstUpdateStats() Oracle calls getting timestamp in order to calculate time.

a construction

-> qersomeFetch()
<- qersomeFetch()

becames

-> qerstFetch()
  -> qerstSnapStats()
    -> gethrtime()
    <- gethrtime
  <- qerstSnapStats
  -> qersomeFetch()
  <- qersomeFetch
  -> qerstUpdateStats()
    -> gethrtime()
    <- gethrtime
  <- qerstUpdateStats
<- qerstFetch

Inside this qerst* function before and after rowsource function call there are calls of a functions qerstSnapStats()/qerstUpdateStats() getting timestamp, gethrtime() in this case (Solaris). In Linux Oracle calls gettimeofday().

  • Notice that I said qerstSnapStats(), but there is no function qerstSnapStats() in the output above. I suggest that it is because compilator inline optimizations. In the same case in 10g we can see that qerst* functions do not call gethrtime() directly.
    An excerpt from 10.2.0.5:

    -> qergsFetch(0x389777988, 0x332EF70, 0xFFFFFD7FFFDFC4B0)
      -> qerstFetch(0x389777A68, 0x1C84DE0, 0x389777988)
        -> qerstSnapStats(0xFFFFFD7FFDB77520, 0xFFFFFD7FFFDFC2C8, 0x389777988)
          -> gethrtime(0xFFFFFD7FFDB77520, 0xFFFFFD7FFFDFC2C8, 0x389777988)
          <- gethrtime = 0x55E25FEA
        <- qerstSnapStats = 0x3CD57897
        -> qertbFetchByRowID(0x389777BD0, 0x332EF70, 0xFFFFFD7FFFDFC320)
          -> qerstFetch(0x389777D48, 0x0, 0xFFFFFD7FFFDFC218)
            -> qerstSnapStats(0xFFFFFD7FFDB772C8, 0xFFFFFD7FFFDFBEC8, 0xFFFFFD7FFFDFC218)
              -> gethrtime(0xFFFFFD7FFDB772C8, 0xFFFFFD7FFFDFBEC8, 0xFFFFFD7FFFDFC218)
              <- gethrtime = 0x55E65426
            <- qerstSnapStats = 0x3CD57995
            -> qerixtFetch(0x389777ED8, 0x0, 0xFFFFFD7FFFDFC218)
            <- qerixtFetch = 0x0
            -> qerstUpdateStats(0xFFFFFD7FFDB772C8, 0xFFFFFD7FFFDFBEC8, 0x1)
              -> gethrtime(0xFFFFFD7FFDB772C8, 0xFFFFFD7FFFDFBEC8, 0x1)
              <- gethrtime = 0x55EAB35F
              -> gethrtime(0xFFFFFD7FFDB772C8, 0xFFFFFD7FFFDFBEC8, 0xF3)
              <- gethrtime = 0x55EBAAB1
            <- qerstUpdateStats = 0x3CD57AEA
          <- qerstFetch = 0x0
    

    But here in 10g we can see another problem – qerstUpdateStats calls gethrtime() twice! We will see effects below.
    Just keep this in mind, when see the output from 11.2 above, that in cases which looks like qerstFetch() or qerstRowP calls gethrtime() directly, in fact between them there is qerstSnapStats()

Keep in mind that an execution plan is a virtual flow of execution.
Example, let’s look at our execution plan:

-----------------------------------------------------
| Id  | Operation                    | Name | Rows  |
-----------------------------------------------------
|   0 | SELECT STATEMENT             |      |     1 |
|   1 |  SORT AGGREGATE              |      |     1 |
|   2 |   TABLE ACCESS BY INDEX ROWID| TBL  |    20 |
|   3 |    INDEX FULL SCAN           | IDX  |    20 |
-----------------------------------------------------

Virtual flow is:
SELECT STATEMENT (fetch) calls SORT AGGREGATE
SORT AGGREGATE calls TABLE ACCESS BY INDEX ROWID
TABLE ACCESS BY INDEX ROWID calls INDEX FULL SCAN

It almost matches with real flow, but not completely. In reality some actions related with rowsource SORT AGGREGATE are executed inside TABLE ACCESS BY INDEX ROWID.
stats_disabled.txt:

 -> qergsFetch(0xC12FEB20, 0xFFFFFD7FFDC3B490, 0x4B6D830)
   -> qertbFetchByRowID(0xC12FECF0, 0xFFFFFD7FFDC3B168, 0x39983B8)
     -> qerixtFetch(0xC12FEF50, 0xFFFFFD7FFDC3AA60, 0x0)
     <- qerixtFetch = 0x0
     -> qertbGetPartitionNumber(0xFFFFFD7FFFDFB264, 0xC12FEE00, 0xFFFFFD7FFDC3B230)
     <- qertbGetPartitionNumber = 0x1
     -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0x39983B8)
     <- qesaFastAggNonDistSS = 0x7FFF
     -> qerixtFetch(0xC12FEF50, 0xFFFFFD7FFDC3AA60, 0x0)
     <- qerixtFetch = 0x0
     -> qertbGetPartitionNumber(0xFFFFFD7FFFDFB264, 0xC12FEE00, 0xFFFFFD7FFDC3B230)
     <- qertbGetPartitionNumber = 0x1
     -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0x39983B8)
     <- qesaFastAggNonDistSS = 0x7FFF

Pay attention that the function qesaFastAggNonDistSS from SORT AGGREGATE rowsource is called inside qertbFetchByRowID.

Or another example: let’s take a slightly changed query with Hash Join:

select --+ index(t) leading(t t2) use_hash(t)
       count(pad)
  from tbl t, dual t2
 where substr(t.pad, 1, 1) = t2.dummy;

----------------------------------------------
| Id  | Operation                     | Name |
----------------------------------------------
|   0 | SELECT STATEMENT              |      |
|   1 |  SORT AGGREGATE               |      |
|*  2 |   HASH JOIN                   |      |
|   3 |    TABLE ACCESS BY INDEX ROWID| TBL  |
|   4 |     INDEX FULL SCAN           | IDX  |
|   5 |    TABLE ACCESS FULL          | DUAL |
----------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("T2"."DUMMY"=SUBSTR("T"."PAD",1,1))

Run the Digger:

digger.sh -p PID -FSmdeoz -f qergsFetch -t qer*,qesa* > hj_stats_dis_qer_qesa.txt

run the query, the output: hj_stats_dis_qer_qesa.txt

We can see here that “build input” is building inside qertbFetchByRowID (the table TBL), and walking through “probe input” inside qertbFetch (the table DUAL).

-> qergsFetch(0xBF321E00, 0xFFFFFD7FFDC3B230, 0x4B6D830)
  -> qerhjFetch(0xBF321FA0, 0xFFFFFD7FFDC3AFD8, 0x39983B8)
    ....
    -> qertbFetchByRowID(0xBF3266D0, 0xFFFFFD7FFDC37258, 0x6C7FED0)
      -> qerixtFetch(0xBF326958, 0xFFFFFD7FFDC36B50, 0x0)
      <- qerixtFetch = 0x0
      -> qertbGetPartitionNumber(0xFFFFFD7FFFDFB0B4, 0xBF3267E0, 0xFFFFFD7FFDC37320)
      <- qertbGetPartitionNumber = 0x1
      -> qerhjSplitBuild(0xFFFFFD7FFFDFB2E0, 0x7FFF, 0x6C7FED0)
      <- qerhjSplitBuild = 0x7FFE
      -> qerixtFetch(0xBF326958, 0xFFFFFD7FFDC36B50, 0x0)
      <- qerixtFetch = 0x0
      -> qertbGetPartitionNumber(0xFFFFFD7FFFDFB0B4, 0xBF3267E0, 0xFFFFFD7FFDC37320)
      <- qertbGetPartitionNumber = 0x1
      -> qerhjSplitBuild(0xFFFFFD7FFFDFB2E0, 0x7FFE, 0x6C7FED0)
      <- qerhjSplitBuild = 0x7FFE
      ...
    <- qertbFetchByRowID = 0x7FFE
     ...
    -> qertbFetch(0xBF322208, 0xFFFFFD7FFDC375D0, 0x6C85860)
      -> qerhjInnerProbeHashTable(0xFFFFFD7FFFDFB2E0, 0x7FFF, 0x0)
        -> qerhjBuildHashTable(0xBF321FA0, 0xFFFFFD7FFDC3AFD8, 0xFFFFFD7FFFDFB2E0
          -> qerhjAllocHashTable(0xBF321FA0, 0xFFFFFD7FFDC3AFD8, 0x32)
          <- qerhjAllocHashTable = 0x80
        <- qerhjBuildHashTable = 0x51
        -> qerhjSplitProbe(0xFFFFFD7FFFDFB2E0, 0xFFFFFD7FFDC3AFD8, 0x0)
        <- qerhjSplitProbe = 0x0
        -> qerhjWalkHashBucket(0xFFFFFD7FFFDFB2E0, 0xFFFFFD7FFDC3AFD8, 0x7FFF)
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F366)
          <- qesaFastAggNonDistSS = 0x7FFF
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F2F7)
          <- qesaFastAggNonDistSS = 0x7FFF
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F288)
          <- qesaFastAggNonDistSS = 0x7FFF
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F219)
          <- qesaFastAggNonDistSS = 0x7FFF
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F1AA)
          <- qesaFastAggNonDistSS = 0x7FFF
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F13B)
          <- qesaFastAggNonDistSS = 0x7FFF
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F0CC)
          <- qesaFastAggNonDistSS = 0x7FFF
          -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB540, 0x7FFF, 0xFFFFFD7FFDA7F05D)
          <- qesaFastAggNonDistSS = 0x7FFF
          ...
        <- qerhjWalkHashBucket = 0x7FFF
      <- qerhjInnerProbeHashTable = 0x7FFF
    <- qertbFetch = 0x7FFF
    ...
  <- qerhjFetch = 0x7FFF
<- qergsFetch = 0x0

Why it is important in context of our topic – because it means that Oracle cannot measure time just before enter in rowsource and after exit, something like this:

-> qerstSnapStats() -- get time here
  -> qerhjFetch()
    -> qerstSnapStats() -- get time here
      -> qertbFetchByRowID()
      <- qertbFetchByRowID
    <- qerstUpdateStats -- get time here, calculate time spent in qertbFetchByRowID
  <- qerhjFetch
<- qerstUpdateStats -- get time here, calculate time spent in qerhjFetch

In order to to separate time spent in one rowsource from another, in mentioned cases Oracle has to call qerstSnapStats/qerstUpdateStats for every row using function qerstRowP:
(the output for the latest query and the same with enabled rowsource statistics: hj_freq1.txt)

-> qerstRowP(0xFFFFFD7FFFDFAEC0, 0x7FFE, 0x3570158)
  -> qerstUpdateStats(0xFFFFFD7FFDC37608, 0xFFFFFD7FFFDFAF00, 0x1)
    -> gethrtime(0x59, 0xCA6EA940, 0x5A)
    <- gethrtime = 0x68E025
  <- qerstUpdateStats = 0x236
  -> qerstRowP(0xFFFFFD7FFFDFAFE0, 0x7FFE, 0x368F5DD68)
    -> qerstUpdateStats(0xFFFFFD7FFDC3A780, 0xFFFFFD7FFFDFB020, 0x1)
      -> gethrtime(0x59, 0xCA6EA940, 0x5A)
      <- gethrtime = 0x6B3FC8
    <- qerstUpdateStats = 0x339
    -> qerhjSplitBuild(0xFFFFFD7FFFDFB100, 0x7FFE, 0x368F5DE04)
    <- qerhjSplitBuild = 0x7FFE
    -> gethrtime(0xA545FF26, 0xFFFFFD7FFDB80FD0, 0x1)
    <- gethrtime = 0x6EDEB8
  <- qerstRowP = 0x7FFE
  -> gethrtime(0xA545FF26, 0x4E, 0x59)
  <- gethrtime = 0x706660
<- qerstRowP = 0x7FFE

or

-> qerstRowP(0xFFFFFD7FFFDFB250, 0x7FFF, 0xFFFFFD7FFDA7DFE3)
  -> qerstUpdateStats(0xFFFFFD7FFDC3B520, 0xFFFFFD7FFFDFB290, 0x1)
    -> gethrtime(0x59, 0xCA6EA940, 0x5A)
    <- gethrtime = 0x323F47B
  <- qerstUpdateStats = 0x27
  -> qesaFastAggNonDistSS(0xFFFFFD7FFFDFB450, 0x7FFF, 0xFFFFFD7FFDC16CD0)
  <- qesaFastAggNonDistSS = 0x7FFF
  -> gethrtime(0xFFFFFD7FFFDFB450, 0x7FFF, 0xFFFFFD7FFDC32938)
  <- gethrtime = 0x324AA83
<- qerstRowP = 0x7FFF

qerstUpdateStats() here updates statistics for qertbFetchByRowID, it allows the time spent in hash join or “sort aggregate” be not included in TABLE ACCESS BY INDEX ROWID despite the fact that physically hashing and counting happens inside TABLE ACCESS BY INDEX ROWID.

The result of this flow: these rowsources calculate time for every processed row. Thus, number of timer calls is approximately equal number of processed rows in every rowsource (except top) multiplied by two (two timestamps on row – SnapStats/UpdateStats), instead of just number of rowsources.

Now is the time to look in more detail at timing: Part 2: Overhead and inconsistent time

About these ads
  1. December 25, 2012 at 8:42 am

    Good stuff Alexander ! one remark : In case you can not change the query to add the hint gather_plan_statistics then you can use sql profile to add the hint see http://kerryosborne.oracle-guy.com/scripts/create_1_hint_sql_profile.sql from http://kerryosborne.oracle-guy.com/2010/02/gather_plan_statistics/

    • December 27, 2012 at 9:04 pm

      Hi Bertrand,

      Thanks for pointed this out.

      In cases when we cannot “alter” the session and change the query in which we are interested, SQL trace looks like more easier and flexible – it is possible to restrict area of tracing by particular session or a process, to get a tracefile if rowsource statistics is not enough, etc.

      SQL profiles with hint gather_plan_statistics have advantages in following cases:
      – it works on 10g
      – it is permanent object, so it lives through reboots (in fact tracing by client_id/module/action also lives through reboots)
      – it can be especially very useful when we are interested in some exact query where SQL ID is unknown, and especially when even exact SQL text is unknown due to used and changing literals (and we don’t know where [session / process] it will be run). In such cases a SQL profile with the option force_match = TRUE (normalizing literals to binds) is irreplaceable.

  1. May 22, 2013 at 12:40 pm
  2. June 4, 2013 at 8:55 pm
  3. March 18, 2014 at 9:39 am

Leave a Reply

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

WordPress.com Logo

You are commenting using your WordPress.com 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 )

Google+ photo

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

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 82 other followers

%d bloggers like this: