Re: Missing rows under dba_hist_sqlstat

I've run the test on 12.2.0.1 and 19.3.0.0. There's definitely something odd happening. Taking awr snapshots every couple of minutes after the plan is resolved and the query has been executing for several minutes, the awr doesn't capture the query.

After the query completes what's captured looks as if it has remembered what would have been in the previous snapshot for SOME of the sqlstat figures if it had been captured.

PDB capture and CDB capture may behave slightly differently - I did manage to get a row for a zero plan hash value AND a non-zero in the same snapshot in one test on 12.2

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