RE: Question about the 'A-Time' in dbms_xplan.display_cursor's output
Date: Wed, 25 Feb 2009 08:21:42 +0200
A-Time is the actual time spent inside a rowsource function of an execution plan tree. This does not include time spent returning results back to client (nor waiting for next command from client) as during that Oracle is not executing parts of execution plan.
If rowsource level execution statistics gathering is enabled, then each rowsource (line) in execution plan is wrapped inside a statistics collection rowsource (qerst* functions) which does the measurements. Both sql_trace and dbms_xplan (which uses v$sql_plan_statistics) do get their numbers from these stats collection functions.
I've explained it in the end of this post:
From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org]
On Behalf Of gengmao
Sent: 25 February 2009 07:08
To: Martin Berger
Subject: Re: Question about the 'A-Time' in dbms_xplan.display_cursor's output
Thanks for your suggestion.
Looking at the SQL trace, I am sure that the A-Time in plan statistics comes from the STAT in sql trace, the time in trkprof also comes from it.
- plan statistics
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers |
|* 1 | COUNT STOPKEY | | 1 | | 9999 |00:00:00.07 | 791 | | 2 | TABLE ACCESS FULL| LARGE_TABLE | 1 | 9999 | 9999 |00:00:00.05 | 791 |
- sql trace STAT #1 id=1 cnt=9999 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=791 pr=0 pw=0 time =72666 us)' STAT #1 id=2 cnt=9999 pid=1 pos=1 obj=96186 op='TABLE ACCESS FULL LARGE_TABLE (c r=791 pr=0 pw=0 time=51280 us)'
Rows Row Source Operation
9999 COUNT STOPKEY (cr=791 pr=0 pw=0 time=72666 us) 9999 TABLE ACCESS FULL LARGE_TABLE (cr=791 pr=0 pw=0 time=51280 us)
I could not find out direct connections between execute time, fetch time, elapsed time and A-Time. While,I believe the A-Time does not include any client wait time. There are many sql*net wait events in sql trace. They are obviously longer than A-Time.
On Wed, Feb 25, 2009 at 3:53 AM, Martin Berger <martin.a.berger_at_gmail.com> wrote:
according to chris Antogninis TOP  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
Tanel has some infos why this is not about TCP/IP roundtrip [2 ], but that's not your question here.
 Troubleshooting Oracle Performance - p210 - http://antognini.ch/top/
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 <
9999 rows selected.
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 |
|* 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)
- dynamic sampling used for this statement
22 rows selected.
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.
http://www.freelists.org/webpage/oracle-l Received on Wed Feb 25 2009 - 00:21:42 CST