Announcement

Collapse

http://progeeking.com

See more
See less

Log file sync when ALTER SYSTEM ARCHIVE LOG CURRENT.

Collapse
X
  • Filter
  • Time
  • Show
Clear All
new posts

  • Log file sync when ALTER SYSTEM ARCHIVE LOG CURRENT.

    Since couple of weeks We were reported for application timeouts.
    Filtering the ASH views by action we detected the wait event as "Log file sync".


    Code:
    select SESSION_ID,SESSION_SERIAL#,SQL_ID,WAIT_TIME,TIME_WAITED/1000000,SESSION_STATE,EVENT,PROGRAM,MODULE,MACHINE,ACTION,TO_CHAR(sample_time,'MM/DD/YY HH24:MI:SS') from DBA_HIST_ACTIVE_SESS_HISTORY
    where sample_time between to_date('06-OCT-2016 11:00:00','DD-MON-YYYY HH24:MI:SS')
    and
    to_date('06-OCT-2016 11:05:00','DD-MON-YYYY HH24:MI:SS')
    and action like '%SUMM%'
    order by sample_time,module,SESSION_ID;
    Result:
    Code:
       
    1250 39991 2xvdc895puz3q 0 0.208247 WAITING db file sequential read JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:01
    1250 39991 2xvdc895puz3q 0 0.158631 WAITING db file sequential read JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:01
    2913 38041 2xvdc895puz3q 0 0.976423 WAITING db file sequential read JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:01
    1250 39991 2xvdc895puz3q 0 0.530788 WAITING gc current block busy JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:01
    2913 38041 2xvdc895puz3q 0 0.17746 WAITING gc current block busy JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:01
    1250 39991 2xvdc895puz3q 0 0.119676 WAITING db file sequential read JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:01
    2913 38041 2xvdc895puz3q 0 0.641426 WAITING gc current block busy JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:02
    1250 39991 2xvdc895puz3q 0 0.366328 WAITING db file sequential read JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:02
    2913 38041 8h5hdrsn5r1sw 0 5.054078 WAITING log file sync JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:02
    1250 39991 1g590nm1jtg1b 0 0.093873 WAITING gc cr multi block request JDBC Thin Client app_interface host_name action(SUMM 10/06/2016 11:02
    So we now know that a delete command is waiting for logfile sync every time when a arch backup is in progress on hourly base.
    In the ASH reports taken the same is clearly represented in the blocking session tab.
    3172, 1( 1) 26.09 log file sync 19.42 SYS oracle@hostname(LGWR) 10/24 [ 42%] 0
    3172, 1( 1) 26.08695652173913043478260869565217391304 gcs log flush sync 3.48 SYS oracle@hostname(LGWR) 10/24 [ 42%] 0
    3172, 1( 1) 26.08695652173913043478260869565217391304 switch logfile command 2.61 SYS oracle@hostname(LGWR) 10/24 [ 42%] 0
    617,58507( 1) 1.45 gc buffer busy acquire 1.45 some_user JDBC Thin Client 8/24 [ 33%] 2

    Checking the archive backup script:

    Code:
    run{
    SQL 'ALTER SYSTEM ARCHIVE LOG CURRENT';
    backup current controlfile;
    SQL 'ALTER SYSTEM ARCHIVE LOG CURRENT';
    backup archivelog all not backed up 1 times;
    DELETE archivelog UNTIL TIME 'SYSDATE-1' BACKED UP 1 TIMES TO DEVICE TYPE DISK;
    }
    Ops. this script is actually doing 3x archive log current commands initiating checkpoints on both RAC nodes. This process is locking the redo until it is completed .
    Our application functionality has huge user commit operations as per the AWR report so this will be for sure impacted by the redo lock.

    In addition to the above in 11g Oracle is automatically executing the "archive log current" when initiating "backup archivelog all" command.


    We just edited the backup script to limit the redo locks.

    Code:
    run{
    backup archivelog all not backed up 1 times;
    DELETE archivelog UNTIL TIME 'SYSDATE-1' BACKED UP 1 TIMES TO DEVICE TYPE DISK;
    backup current controlfile;
    }
    Voala.. No commit operations blocked for 5+ seconds with log file sync event.

    Good point to start this investigation can be found in
Working...
X