getting back to the original question, An AWR does not provide the information as to which specific SQL's cause which event. However ASH does

Hi Connor,

Thanks for the reply.

I was looking for the statement because I would know what schema executes that statement since I am familiar with the application SQL. Based on your query on performance views, I gather that I may not be able to figure out what SQL listed in the AWR report caused all of the log file syncs, right? I am looking at an AWR report from last week so querying performance views won't help identify the cause from last week.

Our box is not CPU bound.

I did find an extremely large amount of "user commits" in the AWR report.

user commits 29,737

Is there anyway that I can find out from this old AWR report, what process executed all of these "user commits"? When a background process commits, does it also increment "user commits"? It is very odd


BTW: I do know that the ASH report would tell me what user & SQL was the cause of the 'log file sync' in the "Top SQL with Top Events" section. Unfortunately, the details in there are dropped off if we gather the report too late. My assumption is that the details are only available for an hour after they are written to the dynamic performance view (V$ views). Once they are transferred to the static data dictionary (DBA_*), a lot of the details are truncated.

Thanks for your help.

John

select * from dba_hist_active_sess_history where event='log file sync'

Hi Connor,

DBA_HIST_ACTIVE_SESS_HISTORY did allow me to figure out what sessions were waiting on "log file sync", but unfortunately it didn't include the SQL_ID.

BTW: These "DBA_HIST_*_HISTORY" views are great. I wish that someone would provide a book that would help us extract information. About 15 years ago I owned a book that showed us how to extract our own data from the statspack tables. Do you know of any?

Finally, I figured out what confused me when I looked at the AWR report. In the AWR report I saw:

Tota Wait % DB
Event Waits Time Avg(ms) time Wait Class
------------------------------ ------------ ---- ------- ------ ----------
log file sync 30,256 3801 126 98.3 Commit

3800 seconds spent on "log file sync". Then, I went to "SQL ordered by Elapsed Time" to make a connection with the log file sync wait time. However, in there I saw that the most costly SQL statement only took 8 seconds! that is what had me confused since "log file sync" took over 3800sec.

Next, I looked at "SQL ordered by Gets" section. Here I find all of the Insert and delete statements that must execute a "commit" after each insert and delete.

Buffer Gets Elapsed
Gets Executions per Exec %Total Time (s)
----------- ----------- ------------ ------ ----------
48,132 5,768 8.3 5.2 0.8
INSERT INTO "........."

42,118 5,767 7.3 4.6 0.8
DELETE FROM "........"
etc.


3800 seconds were spent on "log file sync" yet, if add up all of the SQL executed against the database, it doesn't equal more than 500 seconds. What is going on here? 3800 seconds were spent on "log file sync". I would expect insert & delete statements to be > 3800 since I am sure that they were slowed down by "log file sync" time, right?

Thanks

Hi Connor,

I think I understand. So Oracle will add the wait times like 'db file sequential' and 'buffer busy waits', but it will not add wait events like 'log file sync'. I then have to think about whether the wait events happen outside of the SQL call or within the SQL call so that I can get an idea of the clock time. It would be good if Oracle categorized the wait events as wait events that happen within SQL and outside of SQL.

It wouldn't the INSERT / UPDATE / DELETE statement that is waiting on the 'log file sync' event. It would be the subsequent COMMIT.

Can you catch it ?

See http://blog.orapub.com/20150608/What-does-a-blank-empty-or-null-sql_id-mean.html
and http://blog.orapub.com/20150630/Does-an-Oracle-commit-always-have-a-blank-empty-or-null-sql_id.html


Hemant