Skip to content

浅谈oracle技术系列 - 2. page

Oracle10g版本后enq: TX – allocate ITL entry等待事件的根源以及解决思路

客户昨日一套核心系统有进程挂住，top等待事件为enq: TX – allocate ITL entry，判断为itl争用的原因，这方面以前做了不少测试并没有整理，这里顺便做个整理作为诊断手段用。该内容主要分为主要的三个部分：

一.itl的解释以及原理
二.数据块上的initrans不能扩展分配slot导致的itl争用测试
三.索引块上递归事务专用的itl slot争用的识别判断

 

一.ITL原理解释

ITL(Interested Transaction List)是Oracle数据块内部的一个组成部分，用来记录该块所有发生的事务，一个itl可以看作是一个记录，在一个时间，可以记录一个事务（包括提交或者未提交事务）。当然，如果这个事务已经提交，那么这个itl的位置就可以被反复使用了，因为itl类似记录，所以，有的时候也叫itl槽位。Oracle的每个数据块中都有一个或者多个事务槽，每一个对数据块的并发访问事务都会占用一个事务槽。 表和索引的事务槽ini_trans是1、max_trans是255，在oracle10g中，不能修改max_trans这个参数，因为oracle10g忽略了这个参数。如果一个事务一直没有提交，那么，这个事务将一直占用一个itl槽位，itl里面记录了事务信息，回滚段的嵌入口，事务类型等等。如果这个事务已经提交，那么，itl槽位中还保存的有这个事务提交时候的SCN号。如dump一个块，就可以看到itl信息：

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0006.002.0000158e  0x0080104d.00a1.6e  --U-  734  fsc 0x0000.6c9deff0
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000

如果在并发量特别大的系统中，最好分配足够的itl个数（10g之前的版本），其实它并浪费不了太多的空间，或者，设置足够的pctfree，保证itl能扩展，但是pctfree有可能是被行数据给消耗掉的，如update可能一下占满块空间，所以，也有可能导致块内部的空间不够而导致itl等待，所以在通常情况下，10g版本后引起itl等待的原因往往是因为块的空间不足导致，并不是tran事务槽数量不足，在正常情况下2k的数据块最多可以拥有41个itl，4k数据块最多拥有83，8k最多用友169个itl（以itl 24byte为单位）。INITRANS不足的问题不会出现在索引数据块上，当发现没有足够空间分配ITL slot时，无论是枝点块还是叶子块，数据块会发生分裂(Index Block Split)。

有一种特殊情况也会引起ITL的等待，就是在索引上的递归事务itl争用，这种情况比较特殊。在索引的枝节点上，有且只有一个ITL slot，它是用于当发生节点分裂的递归事务(Recursive Transaction)。在叶子节点上，第一条ITL Slot也是用于分裂的递归事务的。在一个用户事务中，如果发生多次分裂，每一次分裂都是由一个单独的递归事务控制的，如果下层节点分裂导致其父节点分裂，它们的分裂则由同一个递归事务控制。当2个事务同时需要分裂一个枝节点或者叶子节点时，或者枝节点下的2个子节点分别被2个事务分裂，就会造成这种ITL等待。

 

2.数据块上的initrans不能扩展分配slot导致的itl争用测试

我们做个测试关于如果数据块没有空间留给itl slot扩展时候的测试，创建表luda，指定pctfree为0，同时指定initrans为1然后填满相关数据块，再对块满的数据进行更新模拟出itl的等待。
创建表luda，并指定pctfree为0，initrans为1

SQL> create table luda(a int) pctfree 0 initrans 1;

Table created.

 

插入大量数据

SQL> begin
2 for i in 1..20000 loop
3 insert into luda values(i);
4 end loop;
5 end;
6 /

PL/SQL procedure successfully completed.

SQL> commit ;

Commit complete.

 

SQL> select f,b,count(*) from (select dbms_rowid.rowid_relative_fno(rowid) f,dbms_rowid.rowid_block_number(rowid) b
2 from luda) group by f,b order by 3;

F B COUNT(*)
---------- ---------- ----------
1 61101 200
1 61093 734
1 61089 734
1 61095 734
1 61085 734
1 61099 734
1 61074 734
1 61077 734
1 61080 734
1 61092 734
1 61100 734
1 61083 734
1 61091 734
1 61097 734
1 61098 734
1 61075 734
1 61076 734
1 61078 734
1 61081 734
1 61084 734
1 61087 734
1 61096 734
1 61079 734
1 61094 734
1 61088 734
1 61090 734
1 61082 734
1 61086 734

 

插入20018条数据后可以发现该表有26个数据块，填满了除了61101块意外的其他数据块。
接着导出已经填满的数据块61074.

SQL> alter system dump datafile 1 block 61074;

System altered.

 

Block header dump: 0x0040ee92
Object id on Block? Y
seg/obj: 0xcb0a csc: 0x00.bb6a1 itc: 2 flg: - typ: 1 - DATA
fsl: 0 fnx: 0x0 ver: 0x01

Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0005.020.0000013b 0x0080078c.013c.3a --U- 734 fsc 0x0000.000bb765
0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000
--可以发现initrans为1的情况下默认是有2个事务槽，itc=2
data_block_dump,data header at 0xd7fe45c
===============
tsiz: 0x1fa0
hsiz: 0x5ce
pbl: 0x0d7fe45c
bdba: 0x0040ee92
76543210
flag=--------
ntab=1
nrow=734
frre=-1
fsbo=0x5ce
fseo=0xbf8

avsp=0x4
tosp=0x4
0xe:pti[0] nrow=734 offs=0

 

块满的情况测试slot的分配，根据前面的查询结果我们知道单个块的存储行数为734行，也可以通过dump中的nrow=734得知，所以我们在这部测试中依次更新第100，200，300行的数据。

session 1 更新第100行的数据：

SQL> update luda set a=a
2 where dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=61074
3 and dbms_rowid.ROWID_ROW_NUMBER(rowid)=100;

1 row updated.

 

session 2更新第200行的数据：

SQL> update luda set a=a
2 where dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=61074
3 and dbms_rowid.ROWID_ROW_NUMBER(rowid)=200;

1 row updated.

 

session 3更新第300行的数据，session3的sid为158，并且在执行过程中session 3 hang住：

SQL> select sid from v$mystat where rownum=1;

SID
----------
158

SQL> update luda set a=a
2 where dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=61074
3 and dbms_rowid.ROWID_ROW_NUMBER(rowid)=300;
--此时进程hang住
 

alter system dump datafile 1 block 61074；

 

Block header dump: 0x0040ee92
Object id on Block? Y
seg/obj: 0xcb0a csc: 0x00.bb97e itc: 2 flg: - typ: 1 - DATA
fsl: 0 fnx: 0x0 ver: 0x01

Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0003.014.00000159 0x008006bb.01f1.12 ---- 1 fsc 0x0000.00000000
0x02 0x0005.00e.0000013c 0x0080083c.014b.20 ---- 1 fsc 0x0000.00000000
--通过此时的dump我们也可以发现原先为被占用的2个事务槽已经被占用而且事务未提交。
data_block_dump,data header at 0xd77645c
===============
tsiz: 0x1fa0
hsiz: 0x5ce
pbl: 0x0d77645c
bdba: 0x0040ee92
76543210
flag=--------
ntab=1
nrow=734
frre=-1
fsbo=0x5ce
fseo=0xbf8
avsp=0x4
tosp=0x4
0xe:pti[0] nrow=734 offs=0

 

 
--查询158进程的等待事件为itl的相关等待事件enq: TX - allocate ITL entry
SQL> select sid,event from v$session where sid=158;

SID EVENT
---------- ----------------------------------------------------------------
158 enq: TX - allocate ITL entry

从以上验证了空间不足的情况下会导致itl无法分配引起enq: TX – allocate ITL entry等待事件的产生。

接下来测试块不满的情况，在表luda中目前有数据的块为26个，其中块号为61101的块只有200条数据，只占用该块30%的空间，为了测试需要对61101号块采用4个session分别对第10，20，30，40行进行更新：

session 1：

 

SQL> update luda set a=a
2 where dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=61101
3 and dbms_rowid.ROWID_ROW_NUMBER(rowid)=10;

1 row updated.

 

 

session2：

 

SQL> update luda set a=a
2 where dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=61101
3 and dbms_rowid.ROWID_ROW_NUMBER(rowid)=20;

1 row updated.

 

session3：

 

SQL> update luda set a=a
2 where dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=61101
3 and dbms_rowid.ROWID_ROW_NUMBER(rowid)=30;

1 row updated.

 

session4：

SQL> update luda set a=a
2 where dbms_rowid.ROWID_BLOCK_NUMBER(rowid)=61101
3 and dbms_rowid.ROWID_ROW_NUMBER(rowid)=40;

1 row updated.

 

以上4个session都没有遇到阻塞，导出61101号块可以发现该块有4个itl slot，自动扩展了2个slot，验证了在空间足够的情况下itl slot会自动扩展。

SQL> alter system dump datafile 1 block 61101;

System altered.

 

--

Block header dump: 0x0040eead
Object id on Block? Y
seg/obj: 0xcb0a csc: 0x00.bc003 itc: 4 flg: O typ: 1 - DATA
fsl: 0 fnx: 0x0 ver: 0x01

Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x0003.014.00000159 0x008006bb.01f1.13 ---- 1 fsc 0x0000.00000000
0x02 0x0009.016.0000013b 0x0080075c.0143.37 ---- 1 fsc 0x0000.00000000
0x03 0x0005.00e.0000013c 0x0080083c.014b.21 ---- 1 fsc 0x0000.00000000
0x04 0x0002.026.00000139 0x00800130.00fc.09 ---- 1 fsc 0x0000.00000000
--itc=4，在61101块上存在4条未提交的事务，分别是我们刚才执行的sesson1-4.

data_block_dump,data header at 0xe17048c
===============
tsiz: 0x1f70
hsiz: 0x1a2
pbl: 0x0e17048c
bdba: 0x0040eead
76543210
flag=--------
ntab=1
nrow=200
frre=-1
fsbo=0x1a2
fseo=0x1957
avsp=0x16c6
tosp=0x16c6
0xe:pti[0] nrow=200 offs=0

 

以上测试说明了在Oracle10g以来，itl的争用事件产生在数据块上主要是受块空间的影响，如果大量事务在相关block上执行操作但是当块无法满足分配事务槽，则会产生itl相关争用。
下一节主要是区分是索引块还是表数据块的争用. http://www.ludatou.com/?p=1920

Buffer cache Data access tuning Database Instance tuning Oracle Oracle 排障配置与调整 performance tuning 浅谈oracle技术系列 等待事件 | Guang Cai Li |

浅谈如何计算oracle文件的偏移量

##############################
www.ludatou.com 大头
转载请指明处，否则追究法律责任
##############################

了解oracle的偏移量可以帮助在一些特殊恢复场景时候急救需求用到。
关于oracle 偏移量在10g之前一直是DBA需要惦记的事情，曾经有一个在AIX平台存在的经典bug2620053就是因为关于在裸设备上偏移量的问题，在那个时代DBA在aix系统普遍使用裸设备，每次加数据文件总是要考虑到offset的问题。

在众多平台中，目前只有在AIX平台上在为Oracle使用裸设备时候，会预留出4k的空间保留裸设备元数据，俗称磁盘头（lv header）。而在以前HP TRU64也存在一样的情况，只是目前TRU 64已经不受Oracle支持了。
在每一个oracle文件都存在一个系统文件头（block 0），它们由oracle维护，数据文件上的BLOCK 0的大小等于该数据文件的block_size，而重做日志文件上的BLOCK 0除了hp平台为1M外其他都为512bytes（具体可以通过dump logfile，通过tracefile的block_size查出）。BLOCK 0之后的BLOCK 1就是Oracle header block。这里的BLOCK 1的offset就等于v$datafile中的block1_offset。

在正常情况下，不算上AIX,HP tru64的平台中使用裸设备的话，实际的oracle数据的byte offset通用计算方法如下：

byte offset=oracle_block_number * oracle_block_size （对应文件上的block number）
另外一种算法是
byte offset=block1_offset + 1 + ((oracle_block_number - 1) * oracle_block_size)
因为严格意义上讲，block1_offset并不是oracle真实数据的起始块，这两种结果都一样，只是从意义上区分开来了。

在AIX，HP tru64系统上使用裸设备的情况下，byte offset计算方法如下：

offset = raw_device_block0_offset + 1 + (oracle_block_number * oracle_block_size)

其实到这里就可以看出来了，在AIX平台上，当使用裸设备时候（这里的裸设备不是使用-T -O的big vg或者scan vg划分出来的lv），脱离了文件系统管理，file_syatem_block0_offset为0。只有在使用文件系统存放oracle文件的时才存在file_syatem_block0_offset为对应的blocksize或者redoblocksize。

AIX平台裸设备offset：

raw_device_block0_offset = 4096
file_system_block0_offset = 0

HP tru64平台裸设备offset：

raw_device_block0_offset = 65536
file_system_block0_offset = 0

从oracle 9203开始，Oracle就建议使用rlv这种不带raw_device_block0_offset的类型裸设备（lv），具体信息参考
《关于aix上的逻辑卷偏移量》

相比较而言，

Oracle Oracle恢复 数据技术 浅谈oracle技术系列 | Guang Cai Li | |   file offset

浅谈log buffer space等待事件

什么是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中网络的调整，保证日志的传输效率。
还有一种就是压缩日志大小。

Oracle 数据技术 浅谈oracle技术系列 等待事件 | Guang Cai Li | |   log buffer space

浅谈log file sync等待事件诊断（三）

提供一个辅助诊断log file sync的脚本，该脚本有助于诊断log file sync时候锁需要的数据库相关信息的获取，具体如下：

-- NAME: LFSDIAG.SQL
-- ------------------------------------------------------------------------
-- AUTHOR: Michael Polaski - Oracle Support Services
-- ------------------------------------------------------------------------
-- PURPOSE:
-- This script is intended to provide a user friendly guide to troubleshoot
-- log file sync waits. The script will look at important parameters involved
-- in log file sync waits, log file sync wait histogram data, and the script
-- will look at the worst average log file sync times in the active session
-- history data and AWR data and dump information to help determine why those
-- times were the highest. The script will create a file called
-- lfsdiag_<timestamp>.out in your local directory.

set echo off
set feedback off
column timecol new_value timestamp
column spool_extension new_value suffix
select to_char(sysdate,'Mondd_hh24mi') timecol,
'.out' spool_extension from sys.dual;
column output new_value dbname
select value || '_' output
from v$parameter where name = 'db_name';
spool lfsdiag_&&dbname&&timestamp&&suffix
set trim on
set trims on
set lines 140
set pages 100
set verify off
alter session set optimizer_features_enable = '10.2.0.4';

PROMPT LFSDIAG DATA FOR &&dbname&&timestamp
PROMPT Note: All timings are in milliseconds (1000 milliseconds = 1 second)

PROMPT
PROMPT IMPORTANT PARAMETERS RELATING TO LOG FILE SYNC WAITS:
column name format a40 wra
column value format a40 wra
select inst_id, name, value from gv$parameter
where ((value is not null and name like '%log_archive%') or
name like '%commit%' or name like '%event=%' or name like '%lgwr%')
and name not in (select name from gv$parameter where (name like '%log_archive_dest_state%'
and value = 'enable') or name = 'log_archive_format')
order by 1,2,3;

PROMPT
PROMPT ASH THRESHOLD...
PROMPT
PROMPT This will be the threshold in milliseconds for average log file sync
PROMPT times. This will be used for the next queries to look for the worst
PROMPT 'log file sync' minutes. Any minutes that have an average log file
PROMPT sync time greater than the threshold will be analyzed further.
column threshold_in_ms new_value threshold format 999999999.999
select min(threshold_in_ms) threshold_in_ms
from (select inst_id, to_char(sample_time,'Mondd_hh24mi') minute,
avg(time_waited)/1000 threshold_in_ms
from gv$active_session_history
where event = 'log file sync'
group by inst_id,to_char(sample_time,'Mondd_hh24mi')
order by 3 desc)
where rownum <= 10;

PROMPT
PROMPT ASH WORST MINUTES FOR LOG FILE SYNC WAITS:
PROMPT
PROMPT APPROACH: These are the minutes where the avg log file sync time
PROMPT was the highest (in milliseconds).
column minute format a12 tru
column event format a30 tru
column program format a40 tru
column total_wait_time format 999999999999.999
column avg_time_waited format 999999999999.999
select to_char(sample_time,'Mondd_hh24mi') minute, inst_id, event,
sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS,
avg(time_waited)/1000 AVG_TIME_WAITED
from gv$active_session_history
where event = 'log file sync'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id, event
having avg(time_waited)/1000 > &&threshold
order by 1,2;

PROMPT
PROMPT ASH LFS BACKGROUND PROCESS WAITS DURING WORST MINUTES:
PROMPT
PROMPT APPROACH: What is LGWR doing when 'log file sync' waits
PROMPT are happening? LMS info may be relevent for broadcast
PROMPT on commit and LNS data may be relevant for dataguard.
PROMPT If more details are needed see the ASH DETAILS FOR WORST
PROMPT MINUTES section at the bottom of the report.
column inst format 999
column minute format a12 tru
column event format a30 tru
column program format a40 wra
select to_char(sample_time,'Mondd_hh24mi') minute, inst_id inst, program, event,
sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS,
avg(time_waited)/1000 AVG_TIME_WAITED
from gv$active_session_history
where to_char(sample_time,'Mondd_hh24mi') in (select to_char(sample_time,'Mondd_hh24mi')
from gv$active_session_history
where event = 'log file sync'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id
having avg(time_waited)/1000 > &&threshold and sum(time_waited)/1000 > 1)
and (program like '%LGWR%' or program like '%LMS%' or
program like '%LNS%' or event = 'log file sync')
group by to_char(sample_time,'Mondd_hh24mi'), inst_id, program, event
order by 1,2,3,5 desc, 4;

PROMPT
PROMPT HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS:
PROMPT
PROMPT APPROACH: Look at the wait distribution for log file sync waits
PROMPT by looking at "wait_time_milli". Look at the high wait times then
PROMPT see if you can correlate those with other related wait events.
column event format a40 wra
select inst_id, event, wait_time_milli, wait_count
from gv$event_histogram
where event in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way') or
event like '%LGWR%' or event like '%LNS%'
order by 2 desc,1,3;

PROMPT
PROMPT ORDERED BY WAIT_TIME_MILLI
select inst_id, event, wait_time_milli, wait_count
from gv$event_histogram
where event in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or event like '%LGWR%' or event like '%LNS%'
order by 3,1,2 desc;

PROMPT
PROMPT REDO WRITE STATS
PROMPT
PROMPT "redo write time" in centiseconds (100 per second)
PROMPT 11.1: "redo write broadcast ack time" in centiseconds (100 per second)
PROMPT 11.2: "redo write broadcast ack time" in microseconds (1000 per millisecond)
column value format 99999999999999999999
column milliseconds format 99999999999999.999
select v.version, ss.inst_id, ss.name, ss.value,
decode(substr(version,1,4),
'11.1',decode (name,'redo write time',value*10,
'redo write broadcast ack time',value*10),
'11.2',decode (name,'redo write time',value*10,
'redo write broadcast ack time',value/1000),
decode (name,'redo write time',value*10)) milliseconds
from gv$sysstat ss, v$instance v
where name like 'redo write%' and value > 0
order by 1,2,3;

PROMPT
PROMPT AWR WORST AVG LOG FILE SYNC SNAPS:
PROMPT
PROMPT APPROACH: These are the AWR snaps where the average 'log file sync'
PROMPT times were the highest.
column begin format a12 tru
column end format a12 tru
column name format a13 tru
select dhs.snap_id, dhs.instance_number inst, to_char(dhs.begin_interval_time,'Mondd_hh24mi') BEGIN,
to_char(dhs.end_interval_time,'Mondd_hh24mi') END,
en.name, se.time_waited_micro/1000 total_wait_time, se.total_waits,
se.time_waited_micro/1000 / se.total_waits avg_time_waited
from dba_hist_snapshot dhs, wrh$_system_event se, v$event_name en
where (dhs.snap_id = se.snap_id and dhs.instance_number = se.instance_number)
and se.event_id = en.event_id and en.name = 'log file sync' and
dhs.snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,2;

PROMPT
PROMPT AWR REDO WRITE STATS
PROMPT
PROMPT "redo write time" in centiseconds (100 per second)
PROMPT 11.1: "redo write broadcast ack time" in centiseconds (100 per second)
PROMPT 11.2: "redo write broadcast ack time" in microseconds (1000 per millisecond)
column stat_name format a30 tru
select v.version, ss.snap_id, ss.instance_number inst, sn.stat_name, ss.value,
decode(substr(version,1,4),
'11.1',decode (stat_name,'redo write time',value*10,
'redo write broadcast ack time',value*10),
'11.2',decode (stat_name,'redo write time',value*10,
'redo write broadcast ack time',value/1000),
decode (stat_name,'redo write time',value*10)) milliseconds
from wrh$_sysstat ss, wrh$_stat_name sn, v$instance v
where ss.stat_id = sn.stat_id
and sn.stat_name like 'redo write%' and ss.value > 0
and ss.snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,2,3;

PROMPT
PROMPT AWR LFS AND OTHER RELATED WAITS FOR WORST LFS AWRs:
PROMPT
PROMPT APPROACH: These are the AWR snaps where the average 'log file sync'
PROMPT times were the highest. Look at related waits at those times.
column name format a40 tru
select se.snap_id, se.instance_number inst, en.name,
se.total_waits, se.time_waited_micro/1000 total_wait_time,
se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and (en.name in
('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or en.name like '%LGWR%' or en.name like '%LNS%')
and se.snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1, 6 desc;

PROMPT
PROMPT AWR HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS FOR WORST LFS AWRs:
PROMPT Note: This query won't work on 10.2 - ORA-942
PROMPT
PROMPT APPROACH: Look at the wait distribution for log file sync waits
PROMPT by looking at "wait_time_milli". Look at the high wait times then
PROMPT see if you can correlate those with other related wait events.
select eh.snap_id, eh.instance_number inst, en.name, eh.wait_time_milli, eh.wait_count
from wrh$_event_histogram eh, v$event_name en
where eh.event_id = en.event_id and
(en.name in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or en.name like '%LGWR%' or en.name like '%LNS%')
and snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,3 desc,2,4;

PROMPT
PROMPT ORDERED BY WAIT_TIME_MILLI
PROMPT Note: This query won't work on 10.2 - ORA-942
select eh.snap_id, eh.instance_number inst, en.name, eh.wait_time_milli, eh.wait_count
from wrh$_event_histogram eh, v$event_name en
where eh.event_id = en.event_id and
(en.name in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or en.name like '%LGWR%' or en.name like '%LNS%')
and snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,4,2,3 desc;

PROMPT
PROMPT ASH DETAILS FOR WORST MINUTES:
PROMPT
PROMPT APPROACH: If you cannot determine the problem from the data
PROMPT above, you may need to look at the details of what each session
PROMPT is doing during each 'bad' snap. Most likely you will want to
PROMPT note the times of the high log file sync waits, look at what
PROMPT LGWR is doing at those times, and go from there...
column program format a45 wra
column sample_time format a25 tru
column event format a30 tru
column time_waited format 999999.999
column p1 format a40 tru
column p2 format a40 tru
column p3 format a40 tru
select sample_time, inst_id inst, session_id, program, event, time_waited/1000 TIME_WAITED,
p1text||': '||p1 p1,p2text||': '||p2 p2,p3text||': '||p3 p3
from gv$active_session_history
where to_char(sample_time,'Mondd_hh24mi') in (select
to_char(sample_time,'Mondd_hh24mi')
from gv$active_session_history
where event = 'log file sync'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id
having avg(time_waited)/1000 > &&threshold)
and time_waited > 0.5
order by 1,2,3,4,5;

select to_char(sysdate,'Mondd hh24:mi:ss') TIME from dual;

spool off

PROMPT
PROMPT OUTPUT FILE IS: lfsdiag_&&dbname&&timestamp&&suffix
PROMPT

该脚本输出结果大致如下：

LFSDIAG DATA FOR DBM_Oct10_1307
Note: All timings are in milliseconds (1000 milliseconds = 1 second)

IMPORTANT PARAMETERS RELATING TO LOG FILE SYNC WAITS:

   INST_ID NAME                                     VALUE
---------- ---------------------------------------- ----------------------------------------
         1 commit_logging
         1 commit_point_strength                    1
         1 commit_wait
         1 commit_write
         1 log_archive_local_first                  TRUE
         1 log_archive_max_processes                4
         1 log_archive_min_succeed_dest             1
         1 log_archive_start                        FALSE
         1 log_archive_trace                        0
         2 commit_logging
         2 commit_point_strength                    1
         2 commit_wait
         2 commit_write
         2 log_archive_local_first                  TRUE
         2 log_archive_max_processes                4
         2 log_archive_min_succeed_dest             1
         2 log_archive_start                        FALSE
         2 log_archive_trace                        0

ASH THRESHOLD...

This will be the threshold in milliseconds for average log file sync
times. This will be used for the next queries to look for the worst
'log file sync' minutes. Any minutes that have an average log file
sync time greater than the threshold will be analyzed further.

THRESHOLD_IN_MS
---------------
           .000

ASH WORST MINUTES FOR LOG FILE SYNC WAITS:

APPROACH: These are the minutes where the avg log file sync time
was the highest (in milliseconds).

MINUTE          INST_ID EVENT                            TOTAL_WAIT_TIME      WAITS   AVG_TIME_WAITED
------------ ---------- ------------------------------ ----------------- ---------- -----------------
Oct01_0111            2 log file sync                               .807          1              .807
Oct02_0600            2 log file sync                              4.308          1             4.308
Oct09_0043            2 log file sync                            999.805          1           999.805

ASH LFS BACKGROUND PROCESS WAITS DURING WORST MINUTES:

APPROACH: What is LGWR doing when 'log file sync' waits
are happening? LMS info may be relevent for broadcast
on commit and LNS data may be relevant for dataguard.
If more details are needed see the ASH DETAILS FOR WORST
MINUTES section at the bottom of the report.

MINUTE       INST PROGRAM                                  EVENT                            TOTAL_WAIT_TIME      WAITS   AVG_TIME_WAITED
------------ ---- ---------------------------------------- ------------------------------ ----------------- ---------- -----------------
Oct02_0600      2 oracle@racnode1.us.oracle.com (LGWR)    log file parallel write                    4.088          1             4.088
Oct02_0600      2 oracle@racnode1.us.oracle.com (M000)    log file sync                              4.308          1             4.308
Oct09_0043      2 oracle@racnode1.us.oracle.com (LGWR)    log file parallel write                 1000.738          1          1000.738
Oct09_0043      2 sqlplus@racnode1.us.oracle.com (TNS V1- log file sync                            999.805          1           999.805
                  V3)


HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS:

APPROACH: Look at the wait distribution for log file sync waits
by looking at "wait_time_milli". Look at the high wait times then
see if you can correlate those with other related wait events.

   INST_ID EVENT                                    WAIT_TIME_MILLI WAIT_COUNT
---------- ---------------------------------------- --------------- ----------
         2 wait for scn ack                                       1          0
         2 wait for scn ack                                       2          0
         2 wait for scn ack                                       4          0
         2 wait for scn ack                                       8          1
         1 log file sync                                          1      10247
         1 log file sync                                          2        435
         1 log file sync                                          4        122
         1 log file sync                                          8         33
         1 log file sync                                         16          4
         1 log file sync                                         32          2
         1 log file sync                                         64          2
         1 log file sync                                        128          1
         1 log file sync                                        256          1
         1 log file sync                                        512          0
....................................
Oracle 数据技术 浅谈oracle技术系列 等待事件 | Guang Cai Li |

浅谈log file sync等待事件诊断（二）

原因3：用户提交过于频繁导致log file sync

在这种情况下，过多的 commit 活动可能会导致性能问题，因为把 redo 从日志缓冲区刷新到重做日志可能会导致等待’log file sync’。
如果’log file sync’的平均等待时间比’log file parallel write’高很多，这意味着大部分时间等待不是由于等待 redo 的写入，因而问题的原因不是 IO 慢导致。，其他时间可能是 CPU 活动竞争，而且是过多的 commit 导致的最常见的竞争。此外，如果’log file sync’的平均等待时间低，但等待次数高，那么应用程序可能 commit 过于频繁。

在 AWR 或 Statspack 报告中，如果每次 commit/rollback 的平均 user calls（”user calls/(user commits+user rollbacks)”） 小于 30， 表明 commit 过于频繁。
建议

  • 如果有很多短事务，看是否可能把这些事务组合在一起，从而减少 commit 操作。 因为每一个 commit 都必须收到相关 REDO 已写到磁盘上的确认，额外的 commit 会显著的增加开销。虽然 Oracle 可以将某些 commit 组合在一起，通过事务的批处理来减少commit的总体数量还是可以带来非常有益的效果。
  • 看看是否有操作可以使用 COMMIT NOWAIT 选项 （使用前应明白该选项会带来的后果）。
  • 看看是否有操作可以使用 NOLOGGING/ UNRECOVERABLE 选项完成（在不追求可恢复的情况下）。

 

经过已经分析，大概可以得出一个思路，尽量结合与lgwr有关的等待事件一起结合起来定位问题，此时应该检查awr或者statspack的等待事件。

11g新特性：
在oracle 11.2版本中引入了 Adaptive Log File sync，由参数_use_adaptive_log_file_sync控制，该参数在11.2.0.1和11.2.0.2默认设置为 false。
从 11.2.0.3 开始默认是 true。 当启用时，Oracle 可以在两种方法之间切换：

Post/wait，传统发布写重做日志完成的方法
Polling，一种新的方法，其中前台进程会检查 LGWR 是否已写完成。

该特性在一定情况下也会造成log file sync等待大量增加。

当log file sync等待事件是由于RAC节点之间SCN同步引起的，其解决方法如下：
1、检查LMS进程数量是否足够。
2、检查系统CPU资源是否足够。
3、检查RAC节点之间的私有通信是否正常。
4、设置隐含参数_immediate_commit_propagation为false，禁用immediate commit propagation特性。
RAC节点之间CR块传递
Oracle为了保证Instance Recovery实例恢复机制，而要求每一个current block在本地节点local instance被修改后(modify/update) 必须要将该current block相关的redo 写入到logfile 后（要求LGWR必须完成写入后才能返回)，才能由LMS进程传输给其他节点使用。

Oracle 数据技术 浅谈oracle技术系列 等待事件 | Guang Cai Li | |   log file sync