Re: Question about the 'A-Time' in dbms_xplan.display_cursor's output
- From: gengmao <gengmao@xxxxxxxxx>
- To: Tanel Poder <tanel@xxxxxxxxxx>
- Date: Wed, 25 Feb 2009 15:36:47 +0800
Poder,
Very glad getting your reply. Your clarification is very clear.
Thanks,
Eric Geng
On Wed, Feb 25, 2009 at 2:21 PM, Tanel Poder <tanel@xxxxxxxxxx> wrote:
> 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
>
> ------------------------------
> *From:* oracle-l-bounce@xxxxxxxxxxxxx [mailto:
> oracle-l-bounce@xxxxxxxxxxxxx] *On Behalf Of *gengmao
> *Sent:* 25 February 2009 07:08
> *To:* Martin Berger
> *Cc:* ORACLE-L@xxxxxxxxxxxxx
> *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@xxxxxxxxx>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
>>
>>
>>
>
Other related posts:
