Re: Missing rows under dba_hist_sqlstat

I may have isolated the approximate location of the bug.

The query and its cost go into the structure fot v$sqlarea immediately it starts to run using the pre-adapted plan, but it doesn't go into v$sqlarea_plan_hash at that point - it looks like it is only copied across as the final plan execution completes (or, possibly) returns its first row. As the plan resolves,the plan_hash_value in v$sqlarea changes from the initial plan to the final plan, and the various stats carry on growing.

Regards
Jonathan Lewis

On Wed, 25 Nov 2020 at 12:02, Cherif Ben Henda <cherif.benhenda_at_gmail.com> wrote:

> Please see output of below queries
>
>
> select a.snap_id, min(sample_time) mint, MAX(sample_time) Maxt,
> a.sql_id, a.SQL_ADAPTIVE_PLAN_RESOLVED, a.SQL_FULL_PLAN_HASH_VALUE,
> a.SQL_PLAN_HASH_VALUE
> from dba_hist_active_sess_history a
> where sql_id IN (select a.sql_id FROM v$sql a
> where sql_text like '%optimizer_adaptive_plans_True%'
> and sql_text not like '%sql_text%')
> group by a.SNAP_ID, a.sql_id, a.SQL_ADAPTIVE_PLAN_RESOLVED,
> a.SQL_FULL_PLAN_HASH_VALUE, a.SQL_PLAN_HASH_VALUE Order by 1 ,5 ;
>
>
>
> SNAP_ID | MINT | MAXT SQL_ID
> | SQL_ADAPTIVE_PLAN_RESOLVED |SQL_FULL_PLAN_HASH_VALUE |
> SQL_PLAN_HASH_VALUE
>
> -------------------------------------------------------------------------------|-----------------------------|-------------------------|------------
>
> 53954 | 25-NOV-20 11.44.03.539 AM | 25-NOV-20 11.50.34.130 AM
> 8mngkgqh4c2x6 | 0 | 2910268920 | 0
>
> 53955 | 25-NOV-20 11.50.44.130 AM | 25-NOV-20 11.53.44.196 AM
> 8mngkgqh4c2x6 | 0 | 2910268920 | 0
>
> 53955 | 25-NOV-20 11.53.54.201 AM | 25-NOV-20 12.00.34.310 PM
> 8mngkgqh4c2x6 | 1 | 2910268920 |
> 1821829401
> 53956 | 25-NOV-20 12.00.44.310 PM | 25-NOV-20 12.10.34.423 PM
> 8mngkgqh4c2x6 | 1 | 2910268920 |
> 1821829401
> 53957 | 25-NOV-20 12.10.44.425 PM | 25-NOV-20 12.14.04.489 PM
> 8mngkgqh4c2x6 | 1 | 2910268920 |
> 1821829401
>
> select round(sum(a.ELAPSED_TIME_DELTA/1e6 )) sum_delta,
> round(max(a.ELAPSED_TIME_total/1e6)) tot,
> count(*) count_snaps
> from dba_hist_sqlstat a where sql_id in(
> (select a.sql_id FROM v$sql a where sql_text like
> '%optimizer_adaptive_plans_True%' and sql_text not like '%sql_text%') )
> group by sql_id ;
>
>
> SUM_DELTA TOT COUNT_SNAPS
> 201 1814 1
>
> Le mer. 25 nov. 2020 à 13:00, Cherif Ben Henda <cherif.benhenda_at_gmail.com>
> a écrit :
>
>> They respond .This is not a bug.
>> They did not reproduce this issue.
>> Every time, they send me DOCs, or link to an issue related to
>> DBA_HIST_SQLSTAT.., how to analyze a performance issue... and asked for
>> Disable optimizer_adaptive_plan.
>> Currently is not possible to disable optimizer_adaptive_plan. ( for many
>> raisons ....)
>>
>> I explained to them many times that my request is not to fix the
>> performance issue , I need to see my query on top consuming resources
>> queries in AWR.
>>
>> I have reproduced the issue under 19.6.
>>
>>
>> Thanks,
>> Cherif
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>> Le mer. 25 nov. 2020 à 12:50, Jonathan Lewis <jlewisoracle_at_gmail.com> a
>> écrit :
>>
>>>
>>> I noticed your livesql link the first time around - but I prefer
>>> eliminating the unstated easy options and collecting relevant collateral
>>> information before trying to run up a matching database to do a test, so
>>> I'll repeat the question: what was the justification offered by Oracle
>>> support? We've got your explanation for the anomaly, did they agree with
>>> that then use that to dismiss the anomaly as expected behaviour, or did
>>> they say something else?
>>>
>>>
>>> Regards
>>> Jonathan Lewis
>>>
>>>
>>>
>>> On Wed, 25 Nov 2020 at 11:10, Cherif Ben Henda <
>>> cherif.benhenda_at_gmail.com> wrote:
>>>
>>>> Hello Maris, Jonathan,
>>>> I have worked on many cases where "wall clock time" >> real execution
>>>> time of the query.
>>>> ( file generation taking time par example) .
>>>> In that case , sum(DBA_HIST_SQLSTAT.ELAPSED_TIME_DELTA)
>>>> =MAX(DBA_HIST_SQLSTAT.ELAPSED_TIME_TOTAL)
>>>> and MAX(DBA_HIST_SQLSTAT.ELAPSED_TIME_TOTAL) << "wall clock time"
>>>> I assumed that this query was executed one time.
>>>>
>>>> In my case , the query is executed via PL/SQL function.
>>>>
>>>> Another finding, the insertion into wrh$_sqlstat (DBA_HIST_SQLSTAT) is
>>>> based on V$SQLAREA_PLAN_HASH . When the query is under execution , there is
>>>> no row into V$SQLAREA_PLAN_HASH.
>>>>
>>>> I have shared a simple test case
>>>> https://livesql.oracle.com/apex/livesql/s/kv21hp90yyy8j142r41w00n3s
>>>>
>>>> set optimizer_adaptive_plan = false => I dont have this behavior.
>>>>
>>>> Thanks
>>>> Cherif
>>>>
>>>> Le mer. 25 nov. 2020 à 11:50, Jonathan Lewis <jlewisoracle_at_gmail.com>
>>>> a écrit :
>>>>
>>>>> In the absence of further information I think Maris' observation is
>>>>> the correct one, and you would get a better handle on this by taking a
>>>>> snapshot of the session activity stats and session events for your test
>>>>> case.
>>>>>
>>>>> However, I would be interested in seeing the justification Oracle
>>>>> support gave for their 'not a bug' conclusion.
>>>>>
>>>>> Regards
>>>>> Jonathan Lewis
>>>>>
>>>>>
>>>>> On Wed, 25 Nov 2020 at 10:17, Cherif Ben Henda <
>>>>> cherif.benhenda_at_gmail.com> wrote:
>>>>>
>>>>>> Hi All,
>>>>>> During monitoring of PROD long running reporting...
>>>>>> Oracle version 12.1/ optimizer_adaptive_features =false and optimizer_adaptive_plans
>>>>>> =true, I identified a query taking more than 17 000 sec. The next
>>>>>> day when I generated AWR covering its execution period, I found that this
>>>>>> query had taken 2600 sec. I have checked dba_hist_sqlstat , there is only
>>>>>> one row / one snap. The delta elapsed time was 2600 but the total
>>>>>> elapsed time was exact / AWR report is based on delta columns. Under
>>>>>> dba_hist_active_sess_history , I get the exact number of snap_id, in fact
>>>>>> , there are many missing rows under dba_hist_sqlstat .
>>>>>> I have identified the root cause. During these snapshots , we
>>>>>> don't have a final execution plan ( it was a complex query with more than
>>>>>> 14 tables), it was executed with an adaptive execution plan.
>>>>>> I identified that this behavior happened with dozens of queries.
>>>>>>
>>>>>> I can not share with you the real issue , I succeed in reproducing it.
>>>>>> I need to know if you have encountered a similar issue ? It seems
>>>>>> like a bug
>>>>>> Please find a test case, I have changed AWR snap duration to 5 min.
>>>>>> https://livesql.oracle.com/apex/livesql/s/kv21hp90yyy8j142r41w00n3s
>>>>>>
>>>>>> I have opened an SR but they think it is not a bug ....
>>>>>> --
>>>>>> Cordialement,
>>>>>> Cherif Ben Henda
>>>>>>
>>>>>>
>>>>>>
>>>>
>>>> --
>>>> Cordialement,
>>>> Cherif Ben Henda
>>>>
>>>>
>>>>
>>
>> --
>> Cordialement,
>> Cherif Ben Henda
>>
>>
>>
>
> --
> Cordialement,
> Cherif Ben Henda
>
>
>

--
http://www.freelists.org/webpage/oracle-l