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

  • From: Martin Berger <martin.a.berger@xxxxxxxxx>
  • To: gengmao@xxxxxxxxx
  • Date: Tue, 24 Feb 2009 20:53:57 +0100

according to chris Antogninis TOP [1] it's
        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

Other related posts:

  1. Home
  2. oracle-l
  3. Archive
  4. 02-2009