Re: Question about the 'A-Time' in dbms_xplan.display_cursor's output

From: (wrong string) 조동욱 <ukja.dion_at_gmail.com>
Date: Mon, 23 Feb 2009 11:31:44 +0900
Message-ID: <43c2e3d60902221831md8c5986i7d545cf1fcab914b_at_mail.gmail.com>



My thought:

Time in sql*plus = client-tier time which includes network delay time + database time
Time in plan statistics = database-tier time

One way to verify it is to compare the plan statistics and sql trace.



Dion Cho - Oracle Performance Storyteller

http://dioncho.wordpress.com (english)
http://ukja.tistory.com (korean)


On Mon, Feb 23, 2009 at 11:01 AM, gengmao <gengmao_at_gmail.com> wrote:

> Hi,
> I use /*+ gather_plan_statistics */ and dbms_xplan.display_cursor(null,
> null, 'ALLSTATS LAST')) to show a query's plan statistics.
>
> There's a A-Time column in the output. Is it the actual time taken in an
> operation? Does it equal to last_elapsed_time column in
> v$sql_plan_statistics?
>
> I believe so, but I observed that for some long queries, A-Times are
> little. It doesn't match the real wall clock time. For example,
>
> SQL> set timing on
>
> SQL> select /*+ gather_plan_statistics */ * from large_table where rownum <
> 10000;
> ....
>
> 9999 rows selected.
>
> Elapsed: *00:01:11.59*
>
> SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS
> LAST'));
>
> PLAN_TABLE_OUTPUT
>
> --------------------------------------------------------------------------------
>
> SQL_ID 5gpp067wgrtsp, child number 0
> -------------------------------------
> select /*+ gather_statistics */ * from large_table where rownum <
> :"SYS_B_0"
>
> Plan hash value: 9990311
>
> -----------------------------------------------------------------------------------------------------
>
> | Id | Operation | Name | Starts |
> E-Rows | A-Rows | A-Time | Buffers | Reads |
>
> PLAN_TABLE_OUTPUT
>
> -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> |* 1 | COUNT STOPKEY | | 1 |
> | 9999 |*00:00:00.21* | 791 | 127 |
>
> | 2 | TABLE ACCESS FULL| LARGE_TABLE | 1 | 11170 | 9999 |
> *00:00:00.19* | 791 | 127 |
>
>
> Predicate Information (identified by operation id):
> ---------------------------------------------------
>
> 1 - filter(ROWNUM<:SYS_B_0)
>
> Note
> -----
> - dynamic sampling used for this statement
>
>
> 22 rows selected.
>
> Elapsed: 00:00:00.46
>
>
> I am wondering why the A-Time does not match the wall clock time? Is there
> any way to get the actual time taken in each step of an execution plan?
>
>
> The database is 10.2.0.4.
>
> Thanks,
> Eric Geng
>
>

--
http://www.freelists.org/webpage/oracle-l
Received on Sun Feb 22 2009 - 20:31:44 CST

Original text of this message