精华 log buffer及日志管理深入分析及性能调整（四）

3.2 log buffer的等待事件
3.2.1 log file sync等待事件
当用户发出提交或回滚语句时会触发LGWR将重做记录写入联机日志文件，这种触发LGWR的方式叫做同步写（sync writes）触发，而其他剩下的触发LGWR的方式叫做后台写（background writes）。log file sync等待事件只与sync writes有关，而log file parallel write等待事件只与background writes有关。

    举例来说，一个用户进程可能进行一个非常大的事务，该事务会产生非常多的重做记录，从而引起很多的background writes。不过，用户session所运行的事务永远不会等待这些background writes完成以后才继续进行。一旦用户进程提交或回滚了事务，那么用户进程将触发LGWR，并且等待log file sync等待事件，一直等到LGWR将当前的重做记录，包括提交或回滚标记全都写入联机日志文件里为止。在这个日志同步（log synchronization）的过程中（将日志缓冲区中的重做记录写入联机日志文件的过程通常也叫做日志同步过程），LGWR进程等待sync write结束，这时它的等待事件为：log file parallel write，而用户session也在等待sync write结束，而这时它等待的等待事件为：log file sync事件。

一旦进程开始等待log file sync事件，用两种方式退出该等待：
1) 当日志缓冲区里的重做记录都写入联机日志文件以后，由LGWR触发，告诉前台进程。

2) 当等待事件超时(通常是1秒)时，前台进程检查当前的log SCN，来判断当前进程的提交是否已经将重做记录写到了联机日志文件里了。如果已经写好了，前台进程继续进行，否则前台进程继续等待log file sync事件。

通常，log file sync等待事件是可以不用过多考虑的。但是如果很多session都在等待该事件的话，就会影响系统的整体响应时间了。我们来模拟一下这两个等待事件。

SQL> create table t1(id number,name varchar2(20))
as select rownum as rid,'abcdef'
2 from dba_objects where rownum<=40000;
SQL> connect / as sysdba
Connected.
SQL> startup force

在运行测试脚本前，先看看统计信息和等待事件各是什么。

SQL> select name,value from v$sysstat where name in('redo entries','redo size',
2 'redo synch writes','redo wastage','redo write time','redo writes') order by name;
NAME VALUE
---------------------------------------------------------------- ---------
redo entries 375
redo wastage 9552
redo write time 131
redo writes 41
 SQL> select SID,EVENT,TOTAL_WAITS WAIT_CLASS from v$session_event
2 where sid in(159,166) and event in ('log file sync','log file parallel write');
no rows selected
SQL> begin
2 for x in(select rowid rid,t1.* from t1)
3 loop
4 update t1 set name=lower(name) where rowid=x.rid;
5 commit;
6 end loop;
7 end;
8 / 在运行测试脚本以后，再来看看统计信息和等待事件发生了哪些变化。
SQL> select name,value from v$sysstat where name in('redo entries','redo size',
2 'redo synch writes','redo wastage','redo write time','redo writes') order by name;
NAME VALUE
---------------------------------------------------------------- ----------
redo entries 49586
 redo size 20031044
redo synch writes 18
 redo wastage 2382452
 redo write time 996
 redo writes 5986
 SQL> select distinct sid from v$mystat;
SID
----------
159
 SQL> select c.sid,a.name from v$bgprocess a ,v$process b , v$session c
2 where a.paddr=b.addr and b.addr = c.paddr and a.name='LGWR';
SID NAME
---------- -----
166 LGWR
SQL> select SID,EVENT,TOTAL_WAITS WAIT_CLASS from v$session_event
2 where sid in(159,166) and event in ('log file sync','log file parallel write');
SID EVENT TOTAL_WAITS WAIT_CLASS
------ --------------------- ----------- ----------
159 log file sync 3 Commit
 166 log file parallel write 6007 System I/O

    从上面的测试，我们可以明显看到，通过在循环中不断进行提交，出现了3次log file sync等待事件。而实际上，过于频繁的提交也正是log file sync等待事件出现的主要原因。而log file parallel write等待事件则总是会出现的，只要LGWR开始刷新日志缓冲区，该进程就会等待log file parallel write等待事件，是不可避免的，不用过多关注该等待事件。同时，我们可以看到，由于过多的提交，导致生成的重做记录的数量非常巨大，redo size为19845884（20031044-185160）字节，也就相当于将近19M。
注 意：10g以后在v$system_event和v$session_event中会由字段wait_class显示等待事件所属的类别。也就是该等待事 件是由于什么原因引起的。上面我们可以看到log file sync是由于提交引起的，log file parallel write是由于进行物理I/O引起的。

    我们来修改一下上面的脚本，将commit移出循环以后，再按照上面的测试步骤执行一遍。可以发现log file sync等待事件只会出现1次，也就是说减小了一半的log file sync的等待。同时，通过将commit移出循环，所产生的重做记录的数量也下降到大约10M，也就是说减少了将近一半的日志量。

    由此，我们也就可以知道，要减小log file sync的主要方法就是减少提交或回滚的次数。同时，过于频繁的提交不光会引起log file sync等待事件，而且很有可能引起ora-01555：snapshot too old错误。我们可以使用下面的SQL语句来查找log file sync等待所占的总共等待时间的百分比，以及每个session平均每个小时提交多少次，进而可以找到该session执行了哪些SQL语句引起了过于 频繁的提交。

select a.sid,
a.event,
a.time_waited,
a.time_waited / c.sum_time_waited * 100 pct_wait_time,
d.value user_commits,
round((sysdate - b.logon_time) * 24) hours_connected
from v$session_event a, v$session b, v$sesstat d,
(select sid, sum(time_waited) sum_time_waited
from v$session_event
where event not in ('Null event',
'client message',
'KXFX: Execution Message Dequeue - Slave',
'PX Deq: Execution Msg',
'KXFQ: kxfqdeq - normal deqeue',
'PX Deq: Table Q Normal',
'Wait for credit - send blocked',
'PX Deq Credit: send blkd',
'Wait for credit - need buffer to send',
'PX Deq Credit: need buffer',
'Wait for credit - free buffer',
'PX Deq Credit: free buffer',
'parallel query dequeue wait',
'PX Deque wait',
'Parallel Query Idle Wait - Slaves',
'PX Idle Wait',
'slave wait',
'dispatcher timer',
'virtual circuit status',
'pipe get',
'rdbms ipc message',
'rdbms ipc reply',
'pmon timer',
'smon timer',
'PL/SQL lock timer',
'SQL*Net message from client',
'WMON goes to sleep')
having sum(time_waited) > 0 group by sid) c
where a.sid = b.sid
and a.sid = c.sid
and a.sid = d.sid
and d.statistic# = (select statistic#
from v$statname
where name = 'user commits')
and a.time_waited > 10000
and a.event = 'log file sync'
order by pct_wait_time, hours_connected;

    如果应用程序已经确保了使用正确的频率进行提交，则还是发现很严重的log file sync等待事件，则比较常见的原因主要包括：
1) 联机日志文件放在一个很慢的磁盘上。可以用前面我们提到的log file parallel write的平均等待时间应该小于等于10个毫秒来判断，磁盘速度是否过慢。

2) 联机日志文件与其他随机写入的文件放在了同一个磁盘上。从前面已经知道，联机日志文件都是顺序写入的。不能够将其与其他随机写入的文件放在一起，需要存放在单个的磁盘上。

3) 联机日志文件放在了RAID 5的磁盘组里。RAID 5适合频繁的读取，比如数据仓库类的应用等，但不适合频繁写入。

    最好能够将每个联机日志文件都放在单独的小的、转速快的磁盘上，与数据文件所在的磁盘阵列分开。
如果可以的话，最好不要使用文件系统来管理磁盘，直接使用RAW设备，直接交给oracle来管理磁盘。而且，oracle中最适合放在RAW设备上的文件就是联机日志文件。
3.2.2 其他相关的等待事件
当进程需要向日志缓冲区里拷贝重做记录时，发现没有足够的可用空间时，则必须等待log buffer space事件。如果一个进程花费了太多的时间在log buffer space等待事件上，这通常是由于下面两个原因：
1) 日志缓冲区尺寸太小。对于一个繁忙的批处理数据库系统里，一个太小的日志缓冲区（小于512K）会导致进程等待log buffer space。

2) LGWR进程太慢了，这也就是物理I/O速度过慢。可以通过检查log file parallel write等待事件的平均等待时间来判断，如果大于10毫秒，则说明LGWR过慢。
可以通过增加日志缓冲区的尺寸或加快LGWR的进程来减少log buffer space等待事件。

而较小尺寸的联机日志文件会引起log file switch completion和log file switch (checkpoint incomplete)
这 两个等待事件。log file switch completion表示进程正在等待日志切换完成。而当应用程序产生很多重做，然后由LGWR进程非常快得写日志文件并进行日志切换时，这时DBWR进 程还没有把脏数据块写入磁盘以通知checkpoint结束时，这个时候产生log file switch (checkpoint incomplete)等待事件。可以通过增加联机日志文件的尺寸来减少log file switch completion和log file switch (checkpoint incomplete)。

使用如下SQL来显示有关日志缓冲区的latch free的misrate是否很大。
select name,gets,misses,to_char((misses/(gets+misses)) * 100,'990.99') misrate
from v$latch where name in ( 'redo allocation' , 'redo copy', 'redo writing')