Oracle log file sync waits info script ...
oracle log file sync waits Script to Collect Log File Sync Diagnostic Information (lfsdiag.sql) (Doc ID 1064487.1) his script is intended to provide a user friendly guide to troubleshoot log file sync waits. The script will look at important parameters involved in log file sync waits, log file sync wait histogram data, and the script will look at some of the worst average log file sync times in the active session history data and AWR data and dump information to help determine why those times were the highest. The script will create a file called lfsdiag_<timestamp>.out in your local directory. -- NAME: LFSDIAG.SQL -- ------------------------------------------------------------------------ -- AUTHOR: Michael Polaski - Oracle Support Services -- ------------------------------------------------------------------------ -- PURPOSE: -- This script is intended to provide a user friendly guide to troubleshoot -- log file sync waits. The script will look at important parameters involved -- in log file sync waits, log file sync wait histogram data, and the script -- will look at the worst average log file sync times in the active session -- history data and AWR data and dump information to help determine why those -- times were the highest. The script will create a file called -- lfsdiag_<timestamp>.out in your local directory. set echo off set feedback off column timecol new_value timestamp column spool_extension new_value suffix select to_char(sysdate,'Mondd_hh24mi') timecol,'.out' spool_extension from sys.dual; column output new_value dbname select value || '_' output from v$parameter where name = 'db_name'; spool lfsdiag_&&dbname&×tamp&&suffix set trim on trims on lines 200 pages 400 verify off alter session set optimizer_features_enable = '10.2.0.4'; PROMPT LFSDIAG DATA FOR &&dbname&×tamp PROMPT Note: All timings are in milliseconds (1000 milliseconds = 1 second) set linesize 300 pagesize 300 PROMPT PROMPT IMPORTANT PARAMETERS RELATING TO LOG FILE SYNC WAITS: column name format a40 wra column value format a40 wra select inst_id, name, value from gv$parameter where ((value is not null and name like '%log_archive%') or name like '%commit%' or name like '%event=%' or name like '%lgwr%') and name not in (select name from gv$parameter where (name like '%log_archive_dest_state%' and value = 'enable') or name = 'log_archive_format') order by 1,2,3; set linesize 300 column REDOLOG_FILE_NAME format a50 SELECT a.GROUP#, a.THREAD#, a.SEQUENCE#, a.ARCHIVED, a.STATUS, b.MEMBER AS REDOLOG_FILE_NAME, (a.BYTES/1024/1024) AS SIZE_MB FROM v$log a JOIN v$logfile b ON a.Group#=b.Group# ORDER BY a.GROUP# ASC; prompt redo Recommended Size SELECT (SELECT ROUND(AVG(BYTES) / 1024 / 1024, 2) FROM V$LOG) AS "Redo size (MB)",ROUND((20 / AVERAGE_PERIOD) * (SELECT AVG(BYTES) FROM V$LOG) / 1024 / 1024, 2) AS "Recommended Size (MB)" FROM (SELECT AVG((NEXT_TIME - FIRST_TIME) * 24 * 60) AS AVERAGE_PERIOD FROM V$ARCHIVED_LOG WHERE FIRST_TIME > SYSDATE - 7 ) SELECT (SELECT ROUND(AVG(BYTES) / 1024 / 1024, 2) FROM V$LOG) AS "Redo size (MB)",ROUND((20 / AVERAGE_PERIOD) * (SELECT AVG(BYTES) FROM V$LOG) / 1024 / 1024, 2) AS "Recommended Size (MB)" FROM (SELECT AVG((NEXT_TIME - FIRST_TIME) * 24 * 60) AS AVERAGE_PERIOD FROM V$ARCHIVED_LOG WHERE FIRST_TIME > SYSDATE - 3 ) PROMPT PROMPT ASH THRESHOLD... PROMPT PROMPT This will be the threshold in milliseconds for average log file sync PROMPT times. This will be used for the next queries to look for the worst PROMPT 'log file sync' minutes. Any minutes that have an average log file PROMPT sync time greater than the threshold will be analyzed further. column threshold_in_ms new_value threshold format 999999999.999 select min(threshold_in_ms) threshold_in_ms from (select inst_id, to_char(sample_time,'Mondd_hh24mi') minute,avg(time_waited)/1000 threshold_in_ms from gv$active_session_history where event = 'log file sync' group by inst_id,to_char(sample_time,'Mondd_hh24mi') order by 3 desc) where rownum <= 10; PROMPT PROMPT ASH WORST MINUTES FOR LOG FILE SYNC WAITS: PROMPT PROMPT APPROACH: These are the minutes where the avg log file sync time PROMPT was the highest (in milliseconds). column minute format a12 tru column event format a30 tru column program format a40 tru column total_wait_time format 999999999999.999 column avg_time_waited format 999999999999.999 select to_char(sample_time,'Mondd_hh24mi') minute, inst_id, event,sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS,avg(time_waited)/1000 AVG_TIME_WAITED from gv$active_session_history where event = 'log file sync' group by to_char(sample_time,'Mondd_hh24mi'), inst_id, event having avg(time_waited)/1000 > &&threshold order by 1,2; PROMPT PROMPT ASH LFS BACKGROUND PROCESS WAITS DURING WORST MINUTES: PROMPT PROMPT APPROACH: What is LGWR doing when 'log file sync' waits PROMPT are happening? LMS info may be relevent for broadcast PROMPT on commit and LNS data may be relevant for dataguard. PROMPT If more details are needed see the ASH DETAILS FOR WORST PROMPT MINUTES section at the bottom of the report. column inst format 999 column minute format a12 tru column event format a30 tru column program format a50 wra select to_char(sample_time,'Mondd_hh24mi') minute, inst_id inst, program, event,sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS,avg(time_waited)/1000 AVG_TIME_WAITED from gv$active_session_history where to_char(sample_time,'Mondd_hh24mi') in (select to_char(sample_time,'Mondd_hh24mi') from gv$active_session_history where event = 'log file sync' group by to_char(sample_time,'Mondd_hh24mi'), inst_id having avg(time_waited)/1000 > &&threshold and sum(time_waited)/1000 > 1) and (program like '%LGWR%' or program like '%LMS%' or program like '%LNS%' or event = 'log file sync') group by to_char(sample_time,'Mondd_hh24mi'), inst_id, program, event order by 1,2,3,5 desc, 4; PROMPT PROMPT HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS: PROMPT PROMPT APPROACH: Look at the wait distribution for log file sync waits PROMPT by looking at "wait_time_milli". Look at the high wait times then PROMPT see if you can correlate those with other related wait events. column event format a40 wra select inst_id, event, wait_time_milli, wait_count from gv$event_histogram where event in ('log file sync','gcs log flush sync','log file parallel write','wait for scn ack','log file switch completion','gc cr grant 2-way','gc buffer busy','gc current block 2-way') or event like '%LGWR%' or event like '%LNS%' order by 2 desc,1,3; PROMPT PROMPT ORDERED BY WAIT_TIME_MILLI select inst_id, event, wait_time_milli, wait_count from gv$event_histogram where event in ('log file sync','gcs log flush sync','log file parallel write','wait for scn ack','log file switch completion','gc cr grant 2-way','gc buffer busy','gc current block 2-way') or event like '%LGWR%' or event like '%LNS%' order by 3,1,2 desc; PROMPT PROMPT REDO WRITE STATS PROMPT PROMPT "redo write time" in centiseconds (100 per second) PROMPT 11.1: "redo write broadcast ack time" in centiseconds (100 per second) PROMPT 11.2: "redo write broadcast ack time" in microseconds (1000 per millisecond) column value format 99999999999999999999 column milliseconds format 99999999999999.999 select v.version, ss.inst_id, ss.name, ss.value,decode(substr(version,1,4),'11.1',decode (name,'redo write time',value*10,'redo write broadcast ack time',value*10),'11.2', decode (name,'redo write time',value*10,'redo write broadcast ack time',value/1000),decode (name,'redo write time',value*10)) milliseconds from gv$sysstat ss, v$instance v where name like 'redo write%' and value > 0 order by 1,2,3; PROMPT PROMPT AWR WORST AVG LOG FILE SYNC SNAPS: PROMPT PROMPT APPROACH: These are the AWR snaps where the average 'log file sync' PROMPT times were the highest. column begin format a12 tru column end format a12 tru column name format a13 tru select dhs.snap_id, dhs.instance_number inst, to_char(dhs.begin_interval_time,'Mondd_hh24mi') BEGIN, to_char(dhs.end_interval_time,'Mondd_hh24mi') END, en.name, se.time_waited_micro/1000 total_wait_time, se.total_waits,se.time_waited_micro/1000 / se.total_waits avg_time_waited from dba_hist_snapshot dhs, wrh$_system_event se, v$event_name en where (dhs.snap_id = se.snap_id and dhs.instance_number = se.instance_number) and se.event_id = en.event_id and en.name = 'log file sync' and dhs.snap_id in (select snap_id from (select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited from wrh$_system_event se, v$event_name en where se.event_id = en.event_id and en.name = 'log file sync' order by avg_time_waited desc) where rownum < 4) order by 1,2; PROMPT PROMPT AWR REDO WRITE STATS PROMPT PROMPT "redo write time" in centiseconds (100 per second) PROMPT 11.1: "redo write broadcast ack time" in centiseconds (100 per second) PROMPT 11.2: "redo write broadcast ack time" in microseconds (1000 per millisecond) column stat_name format a30 tru select v.version, ss.snap_id, ss.instance_number inst, sn.stat_name, ss.value,decode(substr(version,1,4), '11.1',decode (stat_name,'redo write time',value*10,'redo write broadcast ack time',value*10),'11.2',decode (stat_name,'redo write time',value*10,'redo write broadcast ack time',value/1000), decode (stat_name,'redo write time',value*10)) milliseconds from wrh$_sysstat ss, wrh$_stat_name sn, v$instance v where ss.stat_id = sn.stat_id and sn.stat_name like 'redo write%' and ss.value > 0 and ss.snap_id in (select snap_id from ( select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited from wrh$_system_event se, v$event_name en where se.event_id = en.event_id and en.name = 'log file sync' order by avg_time_waited desc) where rownum < 4) order by 1,2,3; PROMPT PROMPT AWR LFS AND OTHER RELATED WAITS FOR WORST LFS AWRs: PROMPT PROMPT APPROACH: These are the AWR snaps where the average 'log file sync' PROMPT times were the highest. Look at related waits at those times. column name format a40 tru select se.snap_id, se.instance_number inst, en.name,se.total_waits, se.time_waited_micro/1000 total_wait_time,se.time_waited_micro/1000 / se.total_waits avg_time_waited from wrh$_system_event se, v$event_name en where se.event_id = en.event_id and (en.name in ('log file sync','gcs log flush sync','log file parallel write','wait for scn ack','log file switch completion','gc cr grant 2-way','gc buffer busy','gc current block 2-way') or en.name like '%LGWR%' or en.name like '%LNS%') and se.snap_id in (select snap_id from (select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited from wrh$_system_event se, v$event_name en where se.event_id = en.event_id and en.name = 'log file sync' order by avg_time_waited desc) where rownum < 4) order by 1, 6 desc; PROMPT PROMPT AWR HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS FOR WORST LFS AWRs: PROMPT Note: This query won't work on 10.2 - ORA-942 PROMPT PROMPT APPROACH: Look at the wait distribution for log file sync waits PROMPT by looking at "wait_time_milli". Look at the high wait times then PROMPT see if you can correlate those with other related wait events. select eh.snap_id, eh.instance_number inst, en.name, eh.wait_time_milli, eh.wait_count from wrh$_event_histogram eh, v$event_name en where eh.event_id = en.event_id and (en.name in ('log file sync','gcs log flush sync','log file parallel write','wait for scn ack','log file switch completion','gc cr grant 2-way','gc buffer busy','gc current block 2-way') or en.name like '%LGWR%' or en.name like '%LNS%') and snap_id in (select snap_id from (select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited from wrh$_system_event se, v$event_name en where se.event_id = en.event_id and en.name = 'log file sync' order by avg_time_waited desc) where rownum < 4) order by 1,3 desc,2,4; PROMPT PROMPT ORDERED BY WAIT_TIME_MILLI PROMPT Note: This query won't work on 10.2 - ORA-942 select eh.snap_id, eh.instance_number inst, en.name, eh.wait_time_milli, eh.wait_count from wrh$_event_histogram eh, v$event_name en where eh.event_id = en.event_id and (en.name in ('log file sync','gcs log flush sync','log file parallel write','wait for scn ack','log file switch completion','gc cr grant 2-way','gc buffer busy','gc current block 2-way') or en.name like '%LGWR%' or en.name like '%LNS%') and snap_id in (select snap_id from ( select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited from wrh$_system_event se, v$event_name en where se.event_id = en.event_id and en.name = 'log file sync' order by avg_time_waited desc) where rownum < 4) order by 1,4,2,3 desc; PROMPT PROMPT ASH DETAILS FOR WORST MINUTES: PROMPT PROMPT APPROACH: If you cannot determine the problem from the data PROMPT above, you may need to look at the details of what each session PROMPT is doing during each 'bad' snap. Most likely you will want to PROMPT note the times of the high log file sync waits, look at what PROMPT LGWR is doing at those times, and go from there... set linesize 300 pagesize 200 column program format a45 wra column sample_time format a25 tru column event format a30 tru column time_waited format 999999.999 column p1 format a40 tru column p2 format a40 tru column p3 format a40 tru select sample_time, inst_id inst, session_id, program, event, time_waited/1000 TIME_WAITED,p1text||': '||p1 p1,p2text||': '||p2 p2,p3text||': '||p3 p3 from gv$active_session_history where to_char(sample_time,'Mondd_hh24mi') in (select to_char(sample_time,'Mondd_hh24mi') from gv$active_session_history where event = 'log file sync' group by to_char(sample_time,'Mondd_hh24mi'), inst_id having avg(time_waited)/1000 > &&threshold) and time_waited > 0.5 order by 1,2,3,4,5; select to_char(sysdate,'Mondd hh24:mi:ss') TIME from dual; spool off PROMPT PROMPT OUTPUT FILE IS: lfsdiag_&&dbname&×tamp&&suffix PROMPT
Search This Blog
Total Pageviews
Monday, 17 July 2017
Oracle log file sync waits ...
Subscribe to:
Post Comments (Atom)
Oracle DBA
anuj blog Archive
- ► 2011 (362)
No comments:
Post a Comment