什么是log buffer space？
该等待事件问进程等待log buffer空间，因为此时写入log buffer的redo entry速度要高于lgwr 将redo entry写入online redolog的速度，导致log buffer塞满进而产生log buffer space等待事件。深入一点解释就是在往log buffer写入redo entry时候要先获取redo allocation latch，在获取该latch后开始寻获log buffer中剩余的空闲区域写入数据，如果此时没有剩余空间给与写入redo entry则发生log buffer space等待事件，此时可能也会等待log file switch completion事件，因为如果此时遭遇redo online log写满的情况则会发生log switch的情况，在切换过程 logbuffer瞬间写满日志，lgwr进程等待切换结束则出现switch相关等待事件，同时在切换完成后由于大量进程瞬间往log buffer space写入redo entry导致buffer塞满则此时等待log buffer space事件。
应该搜集那些信息来分析’log buffer space’等待事件？
1.发生此事件时候的日志切换频率
2.实例的内存设置以及AWR或者statspack报告
3.发生此事件时候实例的日志切换频率
4.发生此事件时候系统的整体IO负载
5.如果为Dataguard环境，检查DG的模式以及日志传输的延时情况
触发’log buffer space’等待事件的原因？
1.系统IO能力不足
2.日志切换过于频繁
3.过小的log buffer
4.Dataguard在最大可用模式以上保护级别的络传输效率低下
如何处理log buffer space等待事件？
导致log buffer space的原因前面分析过了，针对前面的情况大致的列出一些处理思路。
1.系统IO能力不足这个在log file sync的讨论中介绍过了该如何处理，尽量提升io能力，将redo log放在io能力高的存储上
2.日志切换过于频繁这个时候一般都会导致log buffer space和log file switch completion的等待，如果日志小了，频繁的切换会导致此2个事件的产生，所以一般建议将redo设置大一些，并放在io能力高的文件系统
3.过小的log buffer，这个情况和2有相似点，可能同时存在redo logfile size过小，log bufer过小的情况，再此时如果把log buffer设置大点log file sync等待就可能增加，所以针对不同的log buffer大小对log buffer space事件的影响做个测试验证下。
测试：
1.构建T1表10w条记录
2.在log buffer 256k时候update t1表
3.在log buffer 10m时候update t1表
然后分别确认2和3的log buffer space等待情况
1.构建T1表
SQL> select count(*) from t1;
COUNT(*)
----------
150068
SQL> insert into t1 select * from t1;
150068 rows created.
SQL> commit;
Commit complete.
SQL> select count(*) from t1;
COUNT(*)
----------
300136
SQL> alter table t1 add num number;
Table altered.
SQL> alter table t1 modify num varchar2(200);
Table altered.
SQL> select num from t1 where rownum < 2;
NUM
--------------------------------------------------------------------------------
AAAMr8AAEAAAAA8AAA
2.在log buffer 2M时候update t1表
在表t1中更新30w条数据，同时观察等待
SQL> show sga
Total System Global Area 318767104 bytes
Fixed Size 1267260 bytes
Variable Size 100665796 bytes
Database Buffers 213909504 bytes
Redo Buffers 2924544 bytes
SQL> conn luda/luda
Connected.
SQL> @sess_stat
SP2-0158: unknown SET option "header"
EVENT TOTAL_WAITS TIME_WAITED
---------------------------------------------------------------- ----------- -----------
SQL*Net message from client 11 4439
db file sequential read 55 0
SQL*Net message to client 12 0
SQL> update t1 set object_name='LUDATOU',num=rowid;
300408 rows updated.
SQL> @sess_stat
SP2-0158: unknown SET option "header"
EVENT TOTAL_WAITS TIME_WAITED
---------------------------------------------------------------- ----------- -----------
SQL*Net message from client 14 8837
log buffer space 11 37
log file switch completion 8 7
db file scattered read 544 6
events in waitclass Other 31 1
SQL*Net message to client 15 0
db file sequential read 70 0
观察整体的等待
SQL> @snaper all,out 5 3 214
-- Session Snapper v2.02 by Tanel Poder ( http://www.tanelpoder.com )
----------------------------------------------------------------------------------------------------------------------
SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
214, LUDA , STAT, opened cursors cumulative , 198, 39.6,
214, LUDA , STAT, user calls , 2, .4,
214, LUDA , STAT, recursive calls , 2007, 401.4,
214, LUDA , STAT, recursive cpu usage , 12, 2.4,
214, LUDA , STAT, session logical reads , 390254, 78.05k,
214, LUDA , STAT, CPU used by this session , 198, 39.6,
214, LUDA , STAT, DB time , 261, 52.2,
214, LUDA , STAT, user I/O wait time , 6, 1.2,
214, LUDA , STAT, session uga memory , 65464, 13.09k,
214, LUDA , STAT, session uga memory max , 65464, 13.09k,
214, LUDA , STAT, messages sent , 365, 73,
214, LUDA , STAT, session pga memory , 65536, 13.11k,
214, LUDA , STAT, session pga memory max , 65536, 13.11k,
214, LUDA , STAT, enqueue requests , 836, 167.2,
214, LUDA , STAT, enqueue conversions , 113, 22.6,
214, LUDA , STAT, enqueue releases , 834, 166.8,
214, LUDA , STAT, physical read total IO requests , 559, 111.8,
214, LUDA , STAT, physical read total multi block requests, 544, 108.8,
214, LUDA , STAT, physical read total bytes , 35151872, 7.03M,
214, LUDA , STAT, db block gets , 383374, 76.67k,
214, LUDA , STAT, db block gets from cache , 383374, 76.67k,
214, LUDA , STAT, consistent gets , 6880, 1.38k,
214, LUDA , STAT, consistent gets from cache , 6880, 1.38k,
214, LUDA , STAT, consistent gets - examination , 1695, 339,
214, LUDA , STAT, physical reads , 4291, 858.2,
214, LUDA , STAT, physical reads cache , 4291, 858.2,
214, LUDA , STAT, physical read IO requests , 559, 111.8,
214, LUDA , STAT, physical read bytes , 35151872, 7.03M,
214, LUDA , STAT, db block changes , 655501, 131.1k,
214, LUDA , STAT, change write time , 105, 21,
214, LUDA , STAT, redo synch writes , 1, .2,
214, LUDA , STAT, free buffer requested , 13313, 2.66k,
214, LUDA , STAT, switch current to new buffer , 4241, 848.2,
214, LUDA , STAT, write clones created in foreground , 3, .6,
214, LUDA , STAT, physical reads cache prefetch , 3732, 746.4,
214, LUDA , STAT, shared hash latch upgrades - no wait , 5, 1,
214, LUDA , STAT, calls to kcmgcs , 132, 26.4,
214, LUDA , STAT, calls to kcmgas , 9027, 1.81k,
214, LUDA , STAT, calls to get snapshot scn: kcmgss , 786, 157.2,
214, LUDA , STAT, redo entries , 326611, 65.32k,
214, LUDA , STAT, redo size , 96942748, 19.39M,
214, LUDA , STAT, redo buffer allocation retries , 15, 3,
214, LUDA , STAT, redo log space requests , 8, 1.6,
214, LUDA , STAT, redo log space wait time , 7, 1.4,
214, LUDA , STAT, redo ordering marks , 4744, 948.8,
214, LUDA , STAT, redo subscn max counts , 6443, 1.29k,
214, LUDA , STAT, undo change vector size , 37734184, 7.55M,
214, LUDA , STAT, no work - consistent read gets , 2974, 594.8,
214, LUDA , STAT, cleanouts only - consistent read gets , 1661, 332.2,
214, LUDA , STAT, immediate (CR) block cleanout applicatio, 1661, 332.2,
214, LUDA , STAT, deferred (CURRENT) block cleanout applic, 2582, 516.4,
214, LUDA , STAT, commit txn count during cleanout , 1661, 332.2,
214, LUDA , STAT, cleanout - number of ktugct calls , 1661, 332.2,
214, LUDA , STAT, IMU Flushes , 1, .2,
214, LUDA , STAT, table scans (short tables) , 173, 34.6,
214, LUDA , STAT, table scans (long tables) , 1, .2,
214, LUDA , STAT, table scan rows gotten , 325791, 65.16k,
214, LUDA , STAT, table scan blocks gotten , 4607, 921.4,
214, LUDA , STAT, table fetch by rowid , 9, 1.8,
214, LUDA , STAT, cluster key scans , 8, 1.6,
214, LUDA , STAT, cluster key scan block gets , 8, 1.6,
214, LUDA , STAT, rows fetched via callback , 1, .2,
214, LUDA , STAT, index crx upgrade (positioned) , 2, .4,
214, LUDA , STAT, index fetch by key , 11, 2.2,
214, LUDA , STAT, index scans kdiixs1 , 14, 2.8,
214, LUDA , STAT, session cursor cache hits , 177, 35.4,
214, LUDA , STAT, session cursor cache count , 1, .2,
214, LUDA , STAT, cursor authentications , 2, .4,
214, LUDA , STAT, buffer is pinned count , 296391, 59.28k,
214, LUDA , STAT, buffer is not pinned count , 26, 5.2,
214, LUDA , STAT, workarea executions - optimal , 5, 1,
214, LUDA , STAT, parse time cpu , 1, .2,
214, LUDA , STAT, parse time elapsed , 1, .2,
214, LUDA , STAT, parse count (total) , 188, 37.6,
214, LUDA , STAT, parse count (hard) , 6, 1.2,
214, LUDA , STAT, execute count , 198, 39.6,
214, LUDA , STAT, bytes sent via SQL*Net to client , 147, 29.4,
214, LUDA , STAT, bytes received via SQL*Net from client , 208, 41.6,
214, LUDA , STAT, SQL*Net roundtrips to/from client , 1, .2,
214, LUDA , STAT, sorts (memory) , 9, 1.8,
214, LUDA , STAT, sorts (rows) , 33, 6.6,
214, LUDA , TIME, hard parse elapsed time , 7721, 1.54ms, .2%, | |
214, LUDA , TIME, repeated bind elapsed time , 23, 4.6us, .0%, | |
214, LUDA , TIME, parse time elapsed , 17186, 3.44ms, .3%, | |
214, LUDA , TIME, DB CPU , 1980114, 396.02ms, 39.6%, |@@@@ |
214, LUDA , TIME, sql execute elapsed time , 2544856, 508.97ms, 50.9%, |@@@@@@ |
214, LUDA , TIME, DB time , 2547798, 509.56ms, 51.0%, |@@@@@@ |
214, LUDA , WAIT, log buffer space , 373101, 74.62ms, 7.5%, |@ |
214, LUDA , WAIT, log file switch completion , 73175, 14.64ms, 1.5%, |@ |
214, LUDA , WAIT, db file sequential read , 1750, 350us, .0%, | |
214, LUDA , WAIT, db file scattered read , 59996, 12ms, 1.2%, |@ |
214, LUDA , WAIT, SQL*Net message to client , 4, .8us, .0%, | |
214, LUDA , WAIT, SQL*Net message from client , 1448235, 289.65ms, 29.0%, |@@@ |
-- End of snap 1, end=2014-07-16 16:34:54, seconds=5
通过以上测试我们可以发现，在2M左右大小的log buffer中，更新表t1过程总体产生的log buffer space等待为74.62ms，log buffer space等待触发次数11次.
继续第二步测试。
3.在log buffer 10M时候update t1表
SQL> conn luda/luda
Connected.
SQL> update t1 set object_name='LUDATOU',num=rowid;
300408 rows updated.
SQL> @sess_stat
SP2-0158: unknown SET option "header"
EVENT TOTAL_WAITS TIME_WAITED
---------------------------------------------------------------- ----------- -----------
SQL*Net message from client 12 2951
log file switch (checkpoint incomplete) 4 112
log file switch completion 5 45
events in waitclass Other 4 11
db file scattered read 544 5
Data file init write 21 4
log buffer space 2 2
control file parallel write 9 1
SQL*Net message to client 13 0
db file parallel read 1 0
db file single write 3 0
control file sequential read 60 0
db file sequential read 71 0
13 rows selected.
同时观测总体等待
SQL> @snaper all,out 5 3 214
-- Session Snapper v2.02 by Tanel Poder ( http://www.tanelpoder.com )
----------------------------------------------------------------------------------------------------------------------
SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
214, LUDA , STAT, opened cursors cumulative , 80, 16,
214, LUDA , STAT, opened cursors current , 1, .2,
214, LUDA , STAT, user calls , 1, .2,
214, LUDA , STAT, recursive calls , 955, 191,
214, LUDA , STAT, recursive cpu usage , 9, 1.8,
214, LUDA , STAT, session logical reads , 344227, 68.85k,
214, LUDA , STAT, CPU used by this session , 196, 39.2,
214, LUDA , STAT, user I/O wait time , 7, 1.4,
214, LUDA , STAT, messages sent , 107, 21.4,
214, LUDA , STAT, session pga memory , 4587520, 917.5k,
214, LUDA , STAT, session pga memory max , 4587520, 917.5k,
214, LUDA , STAT, enqueue waits , 1, .2,
214, LUDA , STAT, enqueue requests , 220, 44,
214, LUDA , STAT, enqueue conversions , 26, 5.2,
214, LUDA , STAT, enqueue releases , 218, 43.6,
214, LUDA , STAT, physical read total IO requests , 575, 115,
214, LUDA , STAT, physical read total multi block requests, 513, 102.6,
214, LUDA , STAT, physical read total bytes , 33865728, 6.77M,
214, LUDA , STAT, physical write total IO requests , 32, 6.4,
214, LUDA , STAT, physical write total multi block request, 10, 2,
214, LUDA , STAT, physical write total bytes , 10797056, 2.16M,
214, LUDA , STAT, db block gets , 335817, 67.16k,
214, LUDA , STAT, db block gets from cache , 335817, 67.16k,
214, LUDA , STAT, consistent gets , 8410, 1.68k,
214, LUDA , STAT, consistent gets from cache , 8410, 1.68k,
214, LUDA , STAT, consistent gets - examination , 4064, 812.8,
214, LUDA , STAT, physical reads , 4050, 810,
214, LUDA , STAT, physical reads cache , 4050, 810,
214, LUDA , STAT, physical read IO requests , 531, 106.2,
214, LUDA , STAT, physical read bytes , 33177600, 6.64M,
214, LUDA , STAT, db block changes , 611828, 122.37k,
214, LUDA , STAT, prefetch clients - default , 1, .2,
214, LUDA , STAT, change write time , 49, 9.8,
214, LUDA , STAT, free buffer requested , 12576, 2.52k,
214, LUDA , STAT, switch current to new buffer , 4030, 806,
214, LUDA , STAT, physical reads cache prefetch , 3522, 704.4,
214, LUDA , STAT, shared hash latch upgrades - no wait , 3, .6,
214, LUDA , STAT, calls to kcmgcs , 5, 1,
214, LUDA , STAT, calls to kcmgas , 8532, 1.71k,
214, LUDA , STAT, calls to get snapshot scn: kcmgss , 273, 54.6,
214, LUDA , STAT, redo entries , 305759, 61.15k,
214, LUDA , STAT, redo size , 91112824, 18.22M,
214, LUDA , STAT, redo buffer allocation retries , 7, 1.4,
214, LUDA , STAT, redo log space requests , 6, 1.2,
214, LUDA , STAT, redo log space wait time , 59, 11.8,
214, LUDA , STAT, redo ordering marks , 4489, 897.8,
214, LUDA , STAT, redo subscn max counts , 8528, 1.71k,
214, LUDA , STAT, undo change vector size , 35556100, 7.11M,
214, LUDA , STAT, no work - consistent read gets , 133, 26.6,
214, LUDA , STAT, cleanouts only - consistent read gets , 4030, 806,
214, LUDA , STAT, immediate (CR) block cleanout applicatio, 4030, 806,
214, LUDA , STAT, commit txn count during cleanout , 4030, 806,
214, LUDA , STAT, cleanout - number of ktugct calls , 4030, 806,
214, LUDA , STAT, auto extends on undo tablespace , 2, .4,
214, LUDA , STAT, IMU pool not allocated , 1, .2,
214, LUDA , STAT, IMU- failed to get a private strand , 1, .2,
214, LUDA , STAT, table scans (short tables) , 55, 11,
214, LUDA , STAT, table scans (long tables) , 1, .2,
214, LUDA , STAT, table scan rows gotten , 313370, 62.67k,
214, LUDA , STAT, table scan blocks gotten , 4135, 827,
214, LUDA , STAT, table fetch by rowid , 9, 1.8,
214, LUDA , STAT, cluster key scans , 8, 1.6,
214, LUDA , STAT, cluster key scan block gets , 8, 1.6,
214, LUDA , STAT, rows fetched via callback , 1, .2,
214, LUDA , STAT, index crx upgrade (positioned) , 2, .4,
214, LUDA , STAT, index fetch by key , 11, 2.2,
214, LUDA , STAT, index scans kdiixs1 , 14, 2.8,
214, LUDA , STAT, session cursor cache hits , 59, 11.8,
214, LUDA , STAT, cursor authentications , 2, .4,
214, LUDA , STAT, buffer is pinned count , 285420, 57.08k,
214, LUDA , STAT, buffer is not pinned count , 26, 5.2,
214, LUDA , STAT, workarea executions - optimal , 5, 1,
214, LUDA , STAT, parse time cpu , 1, .2,
214, LUDA , STAT, parse count (total) , 70, 14,
214, LUDA , STAT, parse count (hard) , 6, 1.2,
214, LUDA , STAT, execute count , 80, 16,
214, LUDA , STAT, bytes received via SQL*Net from client , 194, 38.8,
214, LUDA , STAT, sorts (memory) , 9, 1.8,
214, LUDA , STAT, sorts (rows) , 33, 6.6,
214, LUDA , TIME, hard parse elapsed time , 7737, 1.55ms, .2%, | |
214, LUDA , TIME, repeated bind elapsed time , 46, 9.2us, .0%, | |
214, LUDA , TIME, parse time elapsed , 11032, 2.21ms, .2%, | |
214, LUDA , TIME, DB CPU , 1620000, 324ms, 32.4%, |@@@@ |
214, LUDA , TIME, sql execute elapsed time , 2440182, 488.04ms, 48.8%, |@@@@@ |
214, LUDA , TIME, DB time , 2442540, 488.51ms, 48.9%, |@@@@@ |
214, LUDA , WAIT, Data file init write , 25778, 5.16ms, .5%, |@ |
214, LUDA , WAIT, control file sequential read , 447, 89.4us, .0%, | |
214, LUDA , WAIT, control file parallel write , 6142, 1.23ms, .1%, | |
214, LUDA , WAIT, log buffer space , 19503, 3.9ms, .4%, | |
214, LUDA , WAIT, log file switch (checkpoint incomplete) , 127979, 25.6ms, 2.6%, |@ |
214, LUDA , WAIT, log file switch completion , 446061, 89.21ms, 8.9%, |@ |
214, LUDA , WAIT, db file sequential read , 419, 83.8us, .0%, | |
214, LUDA , WAIT, db file scattered read , 49967, 9.99ms, 1.0%, |@ |
214, LUDA , WAIT, db file single write , 998, 199.6us, .0%, | |
214, LUDA , WAIT, SQL*Net message from client , 2462840, 492.57ms, 49.3%, |@@@@@ |
通过测试3可以发现在10m左右的log buffer 中log buffer space总的等待时间为3.9ms，总体等待次数2次。
测试3和测试2说明了在log buffer加大的情况下，log buffer space等待次数降低，但是log file switch completion等待也随着增加，所以调整log buffer space从整体的等待来看加大log buffer并不是绝对的。
另一种方法来降低log buffer space的办法就是减少redo的产生量，比如nologging或者直接路径写。
4.DG中的日志传输延时影响
在这种情况中可以参考前面的gc block lost中网络的调整，保证日志的传输效率。
还有一种就是压缩日志大小。
