Re: Missing rows under dba_hist_sqlstat

Another oddity is that Oracle is using v$sqlarea_plan_hash rather than v$sqlstats_plan_hash which does get updated in a more timely manner.

Regards
Jonathan Lewis

On Wed, 25 Nov 2020 at 17:25, Jonathan Lewis <jlewisoracle_at_gmail.com> wrote:

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