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

From: Tanel Poder <tanel_at_poderc.com>
Date: Wed, 25 Feb 2009 08:21:42 +0200
Message-ID: <5BF6A083534145E79C7EFE7FA62EB021_at_porgand>

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:  

http://blog.tanelpoder.com/2008/06/15/advanced-oracle-troubleshooting-guide- part-6-understanding-oracle-execution-plans-with-os_explain/  

--

Regards,
Tanel Poder
http://blog.tanelpoder.com <http://blog.tanelpoder.com/>

---

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
Cc: ORACLE-L_at_freelists.org
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.

1. plan statistics PLAN_TABLE_OUTPUT

   ---

   ---

   | 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 |
2. 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)'
3. tkprof 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.

-Eric

On Wed, Feb 25, 2009 at 3:53 AM, Martin Berger <martin.a.berger_at_gmail.com> wrote:

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

--

http://www.freelists.org/webpage/oracle-l Received on Wed Feb 25 2009 - 00:21:42 CST