Log file sync from neither I/O nor CPU

Two most popular causes for log file sync waits are redo filesystem I/O and CPU (or CPU scheduling). I’d like to share an example of a third scenario.

A few days ago, I noticed a weird spike in log file sync average duration on a production 11.2 database:

select time,
       snap_id,
       round(time_delta/1e3/nullif(waits_delta,0), 1) avg_wait_ms,
       waits_delta num_of_waits,
       round(time_delta/1e6) total_seconds
from
(       
  select sn.snap_id,
         sn.begin_interval_time time,
         e.total_waits - lag(e.total_waits) over (partition by e.event_name order by e.snap_id) waits_delta,
         e.time_waited_micro - lag(e.time_waited_micro) OVER (PARTITION BY e.event_name ORDER BY e.snap_id) time_delta
  from dba_hist_system_event e,
       dba_hist_snapshot sn
  where e.snap_id = sn.snap_id
  AND e.event_name = 'log file sync'
) ev
WHERE ev.time_delta > 0 
order by time desc

========================================================================
begin_interval_time     snap_id avg_wait_ms num_of_waits   total_seconds
========================================================================
05-OCT-14 11.30.14  AM	52454   1170.2	     14113	       16515
05-OCT-14 11.14.04  AM	52454   10.6	     8463	       89
05-OCT-14 08.00.03  AM	52454   19.8	     339975	       6715
05-OCT-14 07.30.02  AM	52454   8.6	         15728	       135
05-OCT-14 07.00.00  AM	52454   18	         15678	       282
05-OCT-14 06.30.58  AM	52454   12.2	     15696	       192
05-OCT-14 06.00.57  AM	52454   73	         18480	       1349
05-OCT-14 05.30.55  AM	52454   12.9	     18385	       237
05-OCT-14 05.00.51  AM	52454   17.5	     17033	       299

Wait event histogram showed that the average was distorted by a few super-long waits:

select wait_time_milli, wait_count
from dba_hist_event_histogram h,      
     dba_hist_snapshot sn
where h.snap_id = sn.snap_id
and event_name = 'log file sync'
and sn.snap_id = 52454
order by wait_time_milli;

=========================
wait_time_milli wait_count
==========================
1	            247
2	            8466
4	            364854
8	            214135
16	            183034
32	            91450
64	            23878
128	            7027
256	            9411
512	            3118
1024	        777
2048	        6
4096	        19
8192	        15
16384	        24
32768	        1
65536	        10
131072	        51
262144	        65

I checked the log writer activity in ASH and found that it was stuck on “enq: CF – contention” wait for a few straight minutes. “CF” means “control file”, i.e. the log writer needed to write to the control file (probably because it was about to switch log files which requires an update to the control files) but couldn’t do it because something else was writing to it. It was straightforward to find that it was RMAN: ASH gave me blocking session id and serial number (blocking_session, blocking_session_serial#):

select distinct blocking_session, blocking_session_serial#
from dba_hist_active_sess_history ash
where program like '%LGWR%'
and event = 'enq: CF - contention'
and sample_time between to_date('11:00 05-Oct-2014', 'hh24:mi dd-mon-yyyy') 
                and to_date('12:00 05-Oct-2014', 'hh24:mi dd-mon-yyyy');

and module/program columns told me that session belonged to RMAN:

select distinct module, program, action
from dba_hist_active_sess_history
where session_id = 7395 
and session_serial# = 2807

rman@gmfxdbp1 (TNS V1-V3)	rman@gmfxdbp1 (TNS V1-V3)	0003613 STARTED53
rman@gmfxdbp1 (TNS V1-V3)	rman@gmfxdbp1 (TNS V1-V3)	0007777 STARTED53
rman@gmfxdbp1 (TNS V1-V3)	rman@gmfxdbp1 (TNS V1-V3)	0012913 STARTED53
rman@gmfxdbp1 (TNS V1-V3)	rman@gmfxdbp1 (TNS V1-V3)	0014887 STARTED53
rman@gmfxdbp1 (TNS V1-V3)	rman@gmfxdbp1 (TNS V1-V3)	0025379 STARTED53
rman@gmfxdbp1 (TNS V1-V3)	rman@gmfxdbp1 (TNS V1-V3)	0027865 STARTED53
....

During that period, that RMAN session was busy on “control file paralle write”:

select to_char(sample_time, 'dd-mon-yy hh24:mi:ss') sample_time, event, round(delta_write_io_bytes/1024/1024/10) megabytes_per_sec
from dba_hist_active_sess_history
where session_id = 7395 
and session_serial# = 2807
and sample_time between to_date('11:00 05-Oct-2014', 'hh24:mi dd-mon-yyyy') 
                and to_date('12:00 05-Oct-2014', 'hh24:mi dd-mon-yyyy')
order by sample_time desc

================================================================
sample_time          event                     megabytes_per_sec
================================================================
05-oct-14 11:57:03	control file parallel write	      10
05-oct-14 11:56:53	control file parallel write	      10
05-oct-14 11:56:42	control file parallel write	      9
...
05-oct-14 11:46:54	control file parallel write	      9

So for 10 minutes, rman was writing at 9-10 MB/s, i.e. the total amount of information written within that time frame was over 5 GB, i.e. several times the size of the control files. I’m not really sure what all this information was about. Since there was a lot of non-standard one-off activity in the database at the moment (and it was clearly not a good idea not to disable the backup before starting it), and since the incident wasn’t impactful enough to warrant further investigation so I just left it at that. I did discuss this with the production DBA though, and he suggested that one of the reasons that explained high write activity was high value of _control_file_record_keep_time parameter (set to 95 days).

This short example illustrates following points:
– there are other scenarios for log file sync than slow I/O or CPU/scheduling issues
– the most direct way to investigate the origin of log file sync waits is by looking at LGWR session (using trace if possible, or ASH or real-time monitoring tools otherwise) rather than at global statistics
– high backup activity can have nasty performance side effects, especially when it overlaps with other activities, and when control_file_record_keep_time is high.