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

        The actual amount of time spent executing the operation (HH:MM:SS.FF).

Especially in your case, you retrieved 9999 rows. If you run an SQL- Trace, you will see a lot of SQL*Net message to client, which is not accounted in A-Time.
Tanel has some infos why this is not about TCP/IP roundtrip [2], but that's not your question here.

[1] Troubleshooting Oracle Performance - p210 - http://antognini.ch/top/ [2] http://blog.tanelpoder.com/2008/02/07/sqlnet-message-to-client-wait-gotcha/

hth,
  Martin

> 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




application/pkcs7-signature attachment: smime.p7s