log file sync waits / slow response time at log switches

From: Gerald Cunningham <gcunningham_at_proteus-technologies.com>
Date: Thu, 14 Feb 2008 14:21:45 -0500
Message-ID: <F1886AFB628EA94098943970F1563B89F5542D@LINUS.proteus-technologies.com>

Hi all,  

My 10046 tracing is showing a lot of "log file sync" waits. Also, users log files (processes are doing DML) are showing spikes in response time that match the times of the log switches.  

This is a physical Data Guard implementation with 1 primary / 1 standby. Oracle 9.2.0.8 64-bit on Solaris.  

From the alert log, it appears that Oracle is waiting until the redo information has been written to the standby site before it switches the primary's redo logs.  

log_archive_dest_3 was set to mandatory, so I tried setting it to optional (see line "c" below). This didn't appear to have any effect. Here is an excerpt of my primary alert log:  

===
(a) Thu Feb 14 17:39:23 2008

    LGWR: Completed archiving log 2 thread 1 sequence 155723     Creating archive destination LOG_ARCHIVE_DEST_3: 'STDBY_DG'     LNS0 started with pid=249, OS id=9556
(b) Thu Feb 14 17:39:32 2008

    LGWR: Beginning to archive log 3 thread 1 sequence 155724     Thread 1 advanced to log sequence 155274

      Current log# 3 seq# 155724 mem# 0: /dbdata_11/oradata/prod/redo03_1.log
      Current log# 3 seq# 155724 mem# 1: /dbdata_12/oradata/prod/redo03_2.log

    Thu Feb 14 17:39:32 2008

    ARC1: Evaluating archive   log 2 thread 1 sequence 155723
    ARC1: Archive destination LOG_ARCHIVE_DEST_3: Previously completed
    ARC1: Beginning to archive log 2 thread 1 sequence 155723

    Creating archive destination LOG_ARCHIVE_DEST_2: '/dbdata_15/oradata/prod/ARCHIVE/arch_1_155723.arc'     Creating archive destination LOG_ARCHIVE_DEST_1: '/dbdata_10/oradata/prod/ARCHIVE/arch_1_155723.arc'     Thu Feb 14 17:39:45 2008
    ARC1: Completed archiving log 2 thread 1 sequence 155723     Thu Feb 14 17:41:45 2008
(c) ALTER SYSTEM SET log_archive_dest_3='service=STDBY_DG LGWR ASYNC=20480 AFFIRM OPTIONAL REOPEN=30' SCOPE=MEMORY;
(d) Thu Feb 14 17:43:17 2008

    LGWR: Completed archiving log 3 thread 1 sequence 155724     Creating archive destination LOG_ARCHIVE_DEST_3: 'STDBY_DG'     LNS0 started with pid=221, OS id=12045
(e) Thu Feb 14 17:43:35 2008

    LGWR: Beginning to archive log 1 thread 1 sequence 155725     Thread 1 advanced to log sequence 155275

      Current log# 1 seq# 155725 mem# 0: /dbdata_16/oradata/prod/redo01_1.log
      Current log# 1 seq# 155725 mem# 1: /dbdata_17/oradata/prod/redo01_2.log

===
Questions:  

• I believe the time from a-to-b and d-to-e is where my users are waiting, because Oracle hasn't switched the redo log yet. Is this true? These 2 waits are 9 seconds and 18 seconds! Sometimes they are longer, or shorter, but this is typical.
• I thought when I changed dest_3 to optional, Oracle would switch the local/primary first, then do the "standby stuff". Why isn't it?
• Is the time from a-to-b and c-to-d for creating the new LNS0 process? If so, is there any way to have a persistent LNS0 process?
• Is there any way to force the local/primary redo to switch *before* doing any standby work?

Thanks very much for any help!  

Jerry

--
http://www.freelists.org/webpage/oracle-l

Received on Thu Feb 14 2008 - 13:21:45 CST