日志文件相关等待

日志文件相关等待:
redo对于数据库来说非常重要,有一系统等待事件和日志相关,通过v$event_name视图可以找到这些等待事件:

sys@CCDB> select name from v$event_name where name like '%log%';
NAME
--------------------------------------------------
logout restrictor
LNS ASYNC archive log
LNS ASYNC end of log
log file sequential read
log file single write
log file parallel write
log buffer space
log file switch (checkpoint incomplete)
log file switch (private strand flush incomplete)
log file switch (archiving needed)
switch logfile command
log file switch completion
log file sync
simulated log write delay
Streams capture: waiting for archive log
ges RMS0 retry add redo log
gcs log flush sync
log switch/archive
ARCH wait for archivelog lock
MRP wait on archivelog delay
MRP wait on archivelog arrival
MRP wait on archivelog archival
log file switch (clearing log file)
enq: XR - database force logging
recovery area: computing applied logs
enq: FL - Flashback database log
flashback free VI log
flashback log switch
log write(odd)
log write(even)
30 rows selected.

下面摘录几个重要事件进行详细介绍。

1. log file switch(日志文件切换):
log file switch当日志文件发生切换时出现,在数据库进行日志切换后,后台进程LGWR需要关闭当前日志组,切换并打开下一个日志组,在这个切换过程中,数据库的所有DML操作都处于停顿状态,直至这个切换完成。

log file switch主要包含两个事件,log file switch (checkpoint incomplete)和log file switch (archiving needed)。
⑴ log file switch (archiving needed),即日志切换(需要归档),这个等待事件出现时通常是因为日志组循环写满以后,在需要覆盖先前日志时,发现日志归档尚未完成,出现该等待。由于redo能不写出,该等待出现时,数据库将陷于停顿状态。

出现该等待,可能表示I/O存在问题、归档进程写出缓慢,也有可能是日志组设置不合理等原因导致。针对不同原因,可以考虑采用解决办法有:
·可以考虑增大日志文件和增加日志组;
·移动归档文件到快速磁盘;
·调整log_archive_max_processes参数等。

⑵ log file switch (checkpoint incomplete),即日志切换(检查点未完成)。当所有的日志组都写满之后,LGWR试图覆盖某个日志文件,如果这时数据库没有完成写出由这个日志文件所保护的脏数据时(检查点未完成),该等待事件出现。该等待出现时,数据库同样将陷于停顿状态。

同时警告日志文件中会记录如下信息:

Sat Feb 13 06:10:52 2010
Thread 1 advanced to log sequence 5115
  Current log# 3 seq# 5115 mem# 0: /home/oracle/app/oracle/oradata/ccdb/redo03.log
Thread 1 cannot allocate new log, sequence 5116
Checkpoint not complete
  Current log# 3 seq# 5115 mem# 0: /home/oracle/app/oracle/oradata/ccdb/redo03.log
Thread 1 advanced to log sequence 5116
  Current log# 1 seq# 5116 mem# 0: /home/oracle/app/oracle/oradata/ccdb/redo01.log

该等待事件通常表示DBWR写出速度太慢或者I/O存在问题。为解决该问题,用户可能需要考虑增加额外的DBWR或者增加日志组或日志文件大小。log file switch引起的等待都是非常重要的,如果出现就应该引起重视,并由DBA介入进行及时处理。

2. log file sync(日志文件同步):
当一个用户提交或回滚数据时,LGWR将会话期的重做由日志缓冲器写入到重做日志中,LGWR完成任务以后会通知用户进程。日志文件同步过程(Log File Sync)必须等待这一过程成功完成。对于回滚操作,该事件记录从用户发出rollback命令到回滚完成的时间。

如果该等待过多,可能说明LGWR的写出效率低下,或者系统提交过于频繁。针对该问题,可以关注log file parallel write等待事件,或者通过user commits、user rollback等统计信息观察提交或回滚次数。

可能的解决方案主要有:
·提高LGWR性能,尽量使用快速磁盘,不要把redo log file存放在RAID5的磁盘上;
·使用批量提交;
·适当使用NOLOGGING/UNRECOVERABLE等选项。

可以通过如下公式计算平均redo写大小:

avg.redo writ size = (redo block written/redo writes)*512 bytes

如果系统产生redo很多,而每次写的较少,一般说明LGWR被过于频繁地激活了。可能导致过多的redo相关latch的竞争,而且Oracle可能无法有效地使用piggyback的功能。

从一个Statspack报告中提取一些数据来研究一下这个问题。
Report概要信息如下:

STATSPACK report for

Database    DB Id    Instance     Inst Num  Startup Time   Release     RAC
~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
          3317656585 ccdb                1 03-Feb-10 22:20 11.1.0.6.0  NO

Host Name             Platform                CPUs Cores Sockets   Memory (G)
~~~~ ---------------- ---------------------- ----- ----- ------- ------------
     MWSG1            Linux 64-bit for AMD       4     4       4          5.5

Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:         22 14-Apr-10 10:00:04      155       2.0
  End Snap:         23 14-Apr-10 11:00:05      233       2.1
   Elapsed:          60.02 (mins)
   DB time:         244.73 (mins)     DB CPU:        9.92 (mins)

Cache Sizes            Begin        End
~~~~~~~~~~~       ---------- ----------
    Buffer Cache:       912M              Std Block Size:         8K
     Shared Pool:       576M                  Log Buffer:     6,939K

Load Profile              Per Second    Per Transaction    Per Exec    Per Call
~~~~~~~~~~~~      ------------------  ----------------- ----------- -----------
      DB time(s):                4.1                8.0        0.01        0.00
       DB CPU(s):                0.2                0.3        0.00        0.00
       Redo size:            5,148.5           10,147.7

等待事件如下:

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
db file sequential read                        249,549      12,994     52   81.7
log file sync                                    9,125       1,092    120    6.9
log file parallel write                          8,932         864     97    5.4
control file parallel write                      1,189         425    357    2.7
CPU time                                                       324           2.0
          -------------------------------------------------------------
                                                             Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
db file sequential read           249,549    0     12,994     52    136.6   81.7
log file sync                       9,125    6      1,092    120      5.0    6.9
log file parallel write             8,932    0        864     97      4.9    5.4
control file parallel write         1,189    0        425    357      0.7    2.7

注意以上的输出信息,这里log file sync和log file parallel write还有control file parallel write等待事件同时出现,那么可能的一个原因是I/O竞争导致了性能问题,实际用户环境正是日志文件和数据文件和控制文件等同时存放在RAID5的磁盘上,存在性能问题需要调整。

统计信息如下:

Statistic                                      Total     per Second    per Trans
--------------------------------- ------------------ -------------- ------------
......
redo blocks checksummed by FG (ex             12,546            3.5          6.9
redo blocks written                           42,942           11.9         23.5
redo blocks written for direct wr             65,824           18.3         36.0
redo buffer allocation retries                     3            0.0          0.0
redo entries                                  43,842           12.2         24.0
redo log space requests                            3            0.0          0.0
redo log space wait time                          29            0.0          0.0
redo ordering marks                              788            0.2          0.4
redo size                                 18,539,824        5,148.5     10,147.7
redo subscn max counts                         1,830            0.5          1.0
redo synch time                              109,173           30.3         59.8
redo synch writes                              8,489            2.4          4.7
redo wastage                               2,431,180          675.1      1,330.7
redo write time                               86,227           24.0         47.2
redo writer latching time                          0            0.0          0.0
redo writes                                    8,936            2.5          4.9
......
sorts (disk)                                       0            0.0          0.0
sorts (memory)                               558,140          155.0        305.5
sorts (rows)                              18,638,004        5,175.8     10,201.4
......
transaction rollbacks                              1            0.0          0.0
transaction tables consistent rea                  0            0.0          0.0
transaction tables consistent rea                  0            0.0          0.0
undo change vector size                    6,314,760        1,753.6      3,456.4
user I/O wait time                         1,308,751          363.4        716.3
user calls                                 5,128,699        1,424.2      2,807.2
user commits                                   1,816            0.5          1.0
user rollbacks                                    11            0.0          0.0
workarea executions - onepass                      0            0.0          0.0
workarea executions - optimal                538,179          149.5        294.6
write clones created in backgroun                  0            0.0          0.0
write clones created in foregroun                 14            0.0          0.0
          -------------------------------------------------------------

根据统计信息可以计算平均日志写大小:

avg.redo write size = ( Redo block written/redo writes )*512 bytes
                    = ( 42,942/8,936 )*512
                    = 2.4KB
这个平均值过小了,说明系统提交过于频繁。

等待事件柱状图如下:

Wait Event Histogram  DB/Inst: CCDB/ccdb  Snaps: 22-23
-> Total Waits - units: K is 1000, M is 1000000, G is 1000000000
-> % of Waits - column heading: <=1s is truly <1024ms, >1s is truly >=1024ms
-> % of Waits - value: .0 indicates value was <.05%, null is truly 0
-> Ordered by Event (idle events last)

                           Total ----------------- % of Waits ------------------
Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
......
control file parallel writ 1189                            2.0  53.1  37.0   7.9
control file sequential re 5059   99.8          .0    .1    .0    .1          .0
cursor: mutex X             292   96.6    .7    .3          .7    .3   1.4
cursor: pin S               476   70.2   2.9   7.4   7.6   5.7   5.5    .8
cursor: pin S wait on X      23    4.3               4.3  82.6   8.7
db file parallel read         2                           50.0        50.0
db file scattered read      116   18.1   7.8  15.5  32.8  14.7   9.5   1.7
db file sequential read     249K  23.0   3.1  11.4  28.1  15.3   7.6  10.9    .7
......
log file parallel write    8935           .1   2.7  14.6  26.9  20.7  33.3   1.6
log file sequential read     49   16.3              63.3   6.1  10.2   4.1
log file single write         2                     50.0  50.0
log file switch completion    2                                      100.0
log file sync              9128    1.9    .4   7.2   9.3  23.6  17.1  40.5

从等待事件柱状图,也可以明显地看到I/O竞争导致了性能问题。

 

3. log file single write
该事件仅与写日志文件头块相关,通常发生在增加新的组成员和增进序列号(log switch)时。头块写单个进行,因为头块的部分信息是文件号,每个文件不同。

更新日志文件头这个操作在后台完成,一般很少出现等待,无需太多关注。在log switch的过程中,LGWR需要改写日志文件头,有时可以观察到该等待事件的增加:

sys@CCDB> select event,time_waited from v$system_event where event = 'log file single write';
EVENT                                    TIME_WAITED
---------------------------------------- -----------
log file single write                           5541

sys@CCDB> alter system switch logfile;
System altered.

sys@CCDB> alter system switch logfile;
System altered.

sys@CCDB> select event,time_waited from v$system_event where event = 'log file single write';
EVENT                                    TIME_WAITED
---------------------------------------- -----------
log file single write                           5546

 

4. log file parallel write
从log buffer写redo记录到日志文件,主要指常规写操作(相对于log file sync)。
如果每个日志组存在多个组成员,当flush log buffer时,写操作是并行的,这时此等待事件可能出现。

尽管这个写操作并行处理,直到所有I/O操作完成该写操作才会完成(如果磁盘支持异步IO或者使用IO SLAVE,那么即使只有一个redo log file member,也有可能出现此等待)。这个参数和log file sync时间相比较可以用来衡量log file的写入成本,通常称为同步成本率。

 

5. log Buffer Space - 日志缓冲空间
当数据库产生日志的速度比LGWR的写出速度快,或者是当日志切换(log switch)太慢时,就会发生这种等待。
这个等待出现时,通常表明redo log buffer过小,为解决这个问题,可以考虑增大日志文件的大小,或者增加日志缓冲区的大小。

另外一个可能的原因是磁盘I/O存在瓶颈,可以考虑使用写入速度更快的磁盘。在允许的条件下,可以考虑使用裸设备来存放日志文件,提高写入效率。在一般的系统中,最低的标准是,不要把日志文件和数据文件存放在一起,因为通常日志文件只写不读,分离存放可以获得性能提升,尽量使用RAID10而不是RAID5磁盘来存储日志文件。

Log Buffer Space等待事件出现时,数据库将陷入停顿状态,所有和日志生成相关的操作全部不能进行,所以这个等待事件应该引起充分的重视。

- The End -