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@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@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@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@xxxxxxxxx>
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@xxxxxxxxx> 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@xxxxxxxxx> 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
