Hello,
Thanks for your time and help.
While investigating a query in 12c (version 12.1.0.2, OS: RHEL 6.4) Pre production testing, I have generated AWR in a 2 hour sample , I was surprised to see lot of parse calls from a recursive SQL and top wait being Latch Free accounting for 60% of DB time. I couldn't find any Application Queries consuming significant DB Time, only one recursive SQL has consumed 13% of DB time .
Need help in understanding below questions
1) I couldn't find which SQL contributed to DB time of 449 mins, considering the top sql (which seems to be related to snapshot) contributed to 13% and rest < 1%.
2) From Time Model statistics , I could see Hard Parse time being 95% of DB time, but I am assuming this parse time should be shown in SQL elapsed time of queries.
3) What might have caused SQLID 4b4wp0a8dvkf0 to execute 172016 times.
I have gone through Frank's below post, I couldn't verify if to be a bug ( bug 20907061) as I do not have trace output. I will check if the issue can be reproduced.
http://blog.dbi-services.com/sql-plan-directives-strike-again/
I have copied the AWR relevant details to whatever I described above.
| Snap Id | Snap Time | Sessions | Cursors/Session | CDB |
|---|
| Begin Snap: | 2316 | 19-Jul-16 18:00:28 | 95 | 2.3 | YES |
| End Snap: | 2318 | 19-Jul-16 20:00:55 | 90 | 2.5 | YES |
| Elapsed: | | 120.46 (mins) | | | |
| DB Time: | | 449.96 (mins) | | | |
Top 10 Foreground Events by Total Wait Time
| Event | Waits | Total Wait Time (sec) | Wait Avg(ms) | % DB time | Wait Class |
|---|
| latch free | 543,901 | 16.4K | 30.14 | 60.7 | Other |
| DB CPU | | 10.1K | | 37.5 | |
Time Model Statistics
| Statistic Name | Time (s) | % of DB Time | % of Total CPU Time |
|---|
| parse time elapsed | 25,854.53 | 95.77 | |
| hard parse elapsed time | 25,792.75 | 95.54 | |
| sql execute elapsed time | 23,411.16 | 86.72 | |
SQL ordered by Elapsed Time
| Elapsed Time (s) | Executions | Elapsed Time per Exec (s) | %Total | %CPU | %IO | SQL Id | SQL Module | PDB Name | SQL Text |
|---|
| 3,691.00 | 172,016 | 0.02 | 13.67 | 25.04 | 0.00 | 4b4wp0a8dvkf0 | | | SELECT executions, end_of_fetc... |
| 97.83 | 10,010 | 0.01 | 0.36 | 99.62 | 0.00 | 7y6sm34vu7g0d | | | SELECT /* OPT_DYN_SAMP */ /*+ ... |
| 69.81 | 2,630,472 | 0.00 | 0.26 | 84.83 | 0.00 | 47r1y8yn34jmj | | | select default$ from col$ wher... |
SQLID: 4b4wp0a8dvkf0
SELECT executions, end_of_fetch_count, elapsed_time/px_servers elapsed_time, cpu_time/px_servers cpu_time, buffer_gets/executions buffer_gets FROM (SELECT sum(executions_delta) as EXECUTIONS, sum(case when px_servers_execs_delta > 0 then px_servers_execs_delta else executions_delta end) as px_servers, sum(end_of_fetch_count_delta) as end_of_fetch_count, sum(elapsed_time_delta) as ELAPSED_TIME, sum(cpu_time_delta) as CPU_TIME, sum(buffer_gets_delta) as BUFFER_GETS FROM DBA_HIST_SQLSTAT s, V$DATABASE d, DBA_HIST_SNAPSHOT sn WHERE s.dbid = d.dbid AND bitand(nvl(s.flag, 0), 1) = 0 AND sn.end_interval_time > (select systimestamp at TIME ZONE dbtimezone from dual) - 7 AND s.sql_id = :1 AND s.snap_id = sn.snap_id AND s.instance_number = sn.instance_number AND s.dbid = sn.dbid AND parsing_schema_name = :2)
SQlID:
select default$ from col$ where rowid=:1
SQL ordered by Parse Calls
| Parse Calls | Executions | % Total Parses | SQL Id | SQL Module | PDB Name | SQL Text |
|---|
| 2,627,699 | 2,630,472 | 49.54 | 47r1y8yn34jmj | | | select default$ from col$ wher... |
select default$ from col$ where rowid=:1
| Latch Name | Get Requests | Pct Get Miss | Avg Slps /Miss | Wait Time (s) | NoWait Requests | Pct NoWait Miss |
|---|
| Result Cache: RC Latch | 3,550,181 | 16.14 | 1.03 | 16394 | 0 | |
| | | | | | |