Re: what data do I trust?
Date: Fri, 2 Oct 2020 11:51:40 -0400
Message-ID: <CAK5zhLKZTdzOP8NrWWPRJuSM1MPDVs3z1BybOmdutjyTV-Yitw_at_mail.gmail.com>
Sayan,
I missed something I thought I already looked for. The previous snap_id had overhead, but no completed execution:
1 select snap_id, plan_hash_value, executions_total, executions_delta,
elapsed_time_total, elapsed_time_delta, version_count
2 from dba_hist_sqlstat
3 where sql_id='xxxxxxxx' and snap_id between 35477 and 35478
4* order by 1
primary:sys_at_CDB$ROOT> /
SNAP_ID PLAN_HASH_VALUE EXECUTIONS_TOTAL EXECUTIONS_DELTA ELAPSED_TIME_TOTAL ELAPSED_TIME_DELTA VERSION_COUNT
---------- --------------- ---------------- ----------------
------------------ ------------------ -------------
35477 327755044 2 0
1,301,726,321 0 16
409869216 4 0
2,670,095,806 0 16
4055578955 3 0
1,429,409,399 0 16
3663452314 2 0
1,107,109,286 0 16
3077835551 2 0
1,160,012,926 0 16
2653522984 1 0
653,922,053 0 16
878986732 0 0
2,647,242,771 2,647,242,771 16
515147057 2 0
1,250,162,134 0 16
35478 327755044 2 0
1,301,726,321 0 16
3663452314 2 0
1,107,109,286 0 16
3077835551 2 0
1,160,012,926 0 16
2653522984 1 0
653,922,053 0 16
878986732 1 1
5,388,766,867 2,741,524,096 16
515147057 2 0
1,250,162,134 0 16
409869216 4 0
2,670,095,806 0 16
4055578955 3 0
1,429,409,399 0 16
16 rows selected.
I assume the entries with zero delta are child cursors still in v$sql which weren't chosen by the optimizer.
However, the total and delta entries look a bit funny to me for other snap_id's and cursors. See, for example p_h_v of 327755044
primary:sys_at_CDB$ROOT> l
1 select snap_id, plan_hash_value, executions_total, executions_delta,
elapsed_time_total, elapsed_time_delta, version_count
2 from dba_hist_sqlstat
3 where sql_id='xxxxxxxxx' and snap_id between 35417 and 35441
4* order by 1
primary:sys_at_CDB$ROOT > /
SNAP_ID PLAN_HASH_VALUE EXECUTIONS_TOTAL EXECUTIONS_DELTA ELAPSED_TIME_TOTAL ELAPSED_TIME_DELTA VERSION_COUNT
---------- --------------- ---------------- ----------------
------------------ ------------------ -------------
35417 2653522984 1 0
653,922,053 0 16
3077835551 1 0
532,858,604 0 16
3663452314 2 0
1,107,109,286 0 16
4055578955 3 0
1,429,409,399 0 16
41677380 1 0
1,069,981,031 0 16
515147057 3 1
1,684,206,754 631,459,536 16
409869216 5 0
3,090,020,369 0 16
*327755044 2 0
1,204,156,441 0 16*
1217463290 1 0
520,204,117 0 16
35429 2653522984 1 0
653,922,053 0 16
3077835551 1 0
532,858,604 0 16
3663452314 2 0
1,107,109,286 0 16
4055578955 3 0
1,429,409,399 0 16
1217463290 1 0
520,204,117 0 16
41677380 1 0
1,069,981,031 0 16
*327755044 2 1
1,332,854,019 701,125,070 16*
409869216 4 0
2,703,344,869 0 16
515147057 2 0
1,250,162,134 0 16
35441 4055578955 3 0
1,429,409,399 0 16
3663452314 2 0
1,107,109,286 0 16
3077835551 1 0
532,858,604 0 16
2653522984 1 0
653,922,053 0 16
41677380 1 0
1,069,981,031 0 16
409869216 4 0
2,703,344,869 0 16
515147057 2 0
1,250,162,134 0 16
1217463290 1 0
520,204,117 0 16
*327755044 2 1
1,301,726,321 669,997,372 16*
27 rows selected.
Does this just mean that the child cursor was aged out of v$sql, and when it was first loaded (executions_total goes from 0 to 1) it was too lightweight to be captured in dba_hist_sqlstat?
After going through this, guess I'll have to rewrite some scripts.
Thanks again.
Henry
On Fri, Oct 2, 2020 at 10:15 AM Sayan Malakshinov <xt.and.r_at_gmail.com> wrote:
> Hi Henry,
>
> Have you checked executions_total and elapsed_time_total? Looks like it
> accounted 2742 sec in current snapshot and 5389-2742 sec (2647) in previous
> snapshot
>
> On Fri, Oct 2, 2020 at 5:12 PM <niall.litchfield_at_gmail.com> wrote:
>
>> I don't know this, but feel I once did, does a rolled back execution not
>> count to the dba_hist cpu and elapsed totals.? Should be possible to test
>> this.
>>
>> On Fri, Oct 2, 2020 at 3:06 PM Henry Poras <henry.poras_at_gmail.com> wrote:
>>
>>> I'm seeing a discrepancy between some data in an AWR report and
>>> dba_hist_sqlstat (v 12.1). Hoping someone can help (I hate it when I don't
>>> know what data to believe). It looks like the AWR is roughly doubling a
>>> bunch of the values. AWR show 1 execution, elapsed time (and elapsed time
>>> per sec) = 5389 sec, cpu time = 62, while
>>> dba_hist_sqlstat.executions_delta=1, elapsed_time_delta=> 2742 sec,
>>> cpu_time_delta=>30 sec. There is no entry for this sql_id in the previous
>>> or following snap_id. Any ideas???
>>>
>>> Thanks.
>>>
>>> Henry
>>>
>>>
>>>
>>>
>>
>> --
>> Niall Litchfield
>> Oracle DBA
>> http://www.orawin.info
>>
>
>
> --
> Best regards,
> Sayan Malakshinov
> Oracle performance tuning engineer
> Oracle ACE Associate
> http://orasql.org
>
-- http://www.freelists.org/webpage/oracle-lReceived on Fri Oct 02 2020 - 17:51:40 CEST