Skip to content

等待事件

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

latch:cache buffers chains

官网说明:

Latch: cache buffers chains
Identifier:
Registered In:

Description:
Blocks in the buffer cache are placed on linked lists
(cache buffer chains) which hang off a hash table.
The hash chain that a block is placed on is based on the DBA
and CLASS of the block. Each hash chain is protected by a
single child latch. Processes need to get the relevant latch
to allow them the scan a hash chain for a buffer so that the
linked list does not change underneath them.

Contention: Contention for these latches can be caused by:

– Very long buffer chains.
There is a known problem that can result in long
buffer chains –
– very very heavy access to a single block.
This would require the application to be reviewed.

To identify the heavily accessed buffer chain look at
the latch stats for this latch under
and match this to .

*** IMPORTANT: As of Oracle8i there are many hash buckets
to each latch and so there will be lots
of buffers under each latch.
In 8i the steps below will not help much.

Eg: Given ADDR from V$LATCH_CHILDREN for a heavily contended
child latch:
select dbafil, dbablk, class, state
from X$BH where HLADDR=’address of latch’;

One of these is ‘potentially’ a hot block in the database.

**Please see Note 163424.1 How To Identify a Hot Block Within The Database
to correctly identify this issue

Once the object/table is found you can reduce the number of blocks requested
on the particular object/table by redesigning the application or by
spreading the hits in the buffer cache over different hash chains.
You can achieve this by implementing PARTITIONING and storing segements of
the same table/object in different files.

*NOTE* IF YOU ARE RUNNING 8.1.7:

Please see Note 176129.1 ALERT: LATCH FREE And FREE_BUFFER_WAITS
Cause Performance Degradation/Hang

查找热点块所属对象的方法:

1、执行sql:

select CHILD#  "cCHILD"
,      ADDR    "sADDR"
,      GETS    "sGETS"
,      MISSES  "sMISSES"
,      SLEEPS  "sSLEEPS"
from v$latch_children
where name = 'cache buffers chains'
order by 5, 1, 2, 3;

找到sleep count较高的地址(ADDR),再执行下面的语句

column segment_name format a35
select /*+ RULE */
  e.owner ||'.'|| e.segment_name  segment_name,
  e.extent_id  extent#,
  x.dbablk - e.block_id + 1  block#,
  x.tch,
  l.child#
from
  sys.v$latch_children  l,
  sys.x$bh  x,
  sys.dba_extents  e
where
  x.hladdr  = 'ADDR' and
  e.file_id = x.file# and
  x.hladdr = l.addr and
  x.dbablk between e.block_id and e.block_id + e.blocks -1
  order by x.tch desc ;

2、由于上面的方法执行起来可能比较慢,而且有时候是针对某个session的事件进行查找的,因此可以用下面的方法:

v$session_wait中找到P1RAW地址,然后执行:

SELECT FILE# , dbablk, class, state ,tch
FROM x$bh WHERE hladdr='' order by tch;

找出touch较高的文件及数据块,最后执行

select * from dba_extents where file_id= and   between block_id and block_id + blocks -1

有关log file parallel write等待

该事件只在lgwr进程上发生的等待事件,为lgwr进程将内存中redo entry写进redo file的IO工作期间等待该事件。此等待事件与db file parallel write等待原理类似。比如在IO系统没达到高负荷时候,但是脏缓冲图的数据量过多时候,db file parallel write的等待事件就会增多,与此相同,当IO没问题时候,但是重做数据量过多的时候,log file parallel write等待就可能会增加。该问题一方面受限于oracle lgwr的处理能力,一方面受限于redo entry的产生量(归根到底还是应用方面)。

如果想要降低不是因为IO问题引起的log file parallel write的等待,一般都从以下几点思考

1.减少提交次数
2.尽量少产生redo entry
3.避免hot backup
4.提高redo所在文件系统的io性能

该等待事件在平常能留给我们调整的余地较小,在目前的OLTP容灾普及的情况下,nologging方式基本不可能。

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

浅谈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
....................................

浅谈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进程传输给其他节点使用。

浅谈log file sync等待事件诊断(一)

最近一个压力较大的数据库log file sync等待TOP 1.经过处理后也趁着这个时间把这个等待事件的一些信息整理一次。

什么是’log file sync’等待事件?

当一个用户session commit,会话事务相关生成的redo entry会从内存刷新到redo onlinelog。
在提交时,用户会话会通知 LGWR 把日志缓冲区中的信息写到重做日志文件(当前所有未被写入磁盘的 redo 信息,包括本次会话的 redo 信息)。当 LGWR 完成写操作后,它会通知用户会话。当等待 LGWR 通知确认所有 redo 已经全部保存到磁盘的过程时,用户会话会等待’log file sync’此时用户session显示等待’log file sync’,它是用户会话通知 LGWR 和 LGWR 通知用户的写操作完成之间的时间。

应该搜集那些信息来分析’log file sync’等待事件?

1.发生log file sync时间段的AWR/SP报告
2.当时的系统负载信息(最好有OSWATCH)
3.对应时间段的Alert.log日志信息

很高的’log file sync’等待的可能原因?

通常造成这类现象的原因有3个,具体如下:

1.Oracle 已知的bug造成
2.磁盘的IO负载过高,导致LGWR将REDO写入logfile的速度受影响
3.用户提交(commit)过于频繁

原因1:关于log file sync同步的bug

NB Bug Fixed Description
14823372 11.2.0.3.BP23, 11.2.0.4, 12.1.0.1 Adaptive “log file sync” picks inaccurate polling interval on RAC
13707904 11.2.0.4, 12.1.0.1 LGWR sometimes uses polling, sometimes post/wait
12614085 11.2.0.4, 12.1.0.1 Diagnostic enhancement to add new statistics for investigating “log file sync” and “log file parallel write” relationship
P 16102401 11.2.0.3.BP16, 11.2.0.4, 12.1.0.1 identify correct effective mutiplier for sparc t5 processor
13551402 11.2.0.3.9, 11.2.0.3.BP22, 11.2.0.4, 12.1.0.1 High “log file parallel write” and “log file sync” after upgrading 11.2 with Veritas/Symantec ODM
P 12951619 11.2.0.4, 12.1.0.1 Solaris: Enhancement to allow database to use critical threads feature in Solaris
12378147 11.2.0.2.7, 11.2.0.2.BP10, 11.2.0.3, 12.1.0.1 Long broadcast ack warning messages, and/or many Log File Sync timeouts in foregrounds in RAC
9095696 11.2.0.3.7, 11.2.0.3.BP08, 11.2.0.4, 12.1.0.1 “log file sync” wait time spikes with ARCHIVE_LAG_TARGET set
13074706 11.2.0.3.BP14, 11.2.0.4, 12.1.0.1 Long “log file sync” waits in RAC not correlated with slow writes
8490879 10.2.0.4.4, 10.2.0.5, 11.1.0.7.3, 11.2.0.1 Long “log file sync” latencies due to broadcast on commit scheme
8220734 10.2.0.4.4, 10.2.0.5, 11.1.0.7.3, 11.2.0.1 Long “log file sync” wait in RAC
7716356 10.2.0.5, 11.2.0.1 Long “log file sync” latencies with broadcast on commit scheme in RAC
7643632 10.2.0.4.1, 10.2.0.5, 11.1.0.7.4, 11.2.0.1 High log file sync in Data Guard maximum availability (sync) mode
7610362 10.2.0.4.4, 10.2.0.5, 11.1.0.7.3, 11.2.0.1 Long “log file sync” waits in RAC with broadcast on commit in RAC
P 7568734 10.2.0.5, 11.2.0.1 AIX: Sporadic spikes of ‘log file sync’ on AIX with heavy commit concurrency
7452373 10.2.0.5, 11.1.0.7.1, 11.2.0.1 “log file sync” timeout is not configurable
6319685 10.2.0.4, 11.1.0.7, 11.2.0.1 LGWR posts do not scale on some platforms
6193945 10.2.0.4.1, 10.2.0.5, 11.1.0.7, 11.2.0.1 High LGWR CPU use and long ‘log file sync’ latency in RAC
9776431 11.1.0.7.4 11.1.0.7.3 fix for 8220734 is incomplete – “log file sync” timeout set to 1 second
5896963 10.2.0.4, 11.1.0.6 High LGWR CPU and longer “log file sync” with fix for bug 5065930
5147386 10.2.0.4.1, 10.2.0.5, 11.1.0.6 Long waits on “log file sync” /random ORA-27152 “attempt to post process failed”
5087592 10.2.0.4, 11.1.0.6 “log file sync” waits from read only commits
5065930 10.2.0.3, 11.1.0.6 “log file sync” timeouts can occur
5061068 10.2.0.3, 11.1.0.6 RAC using “broadcast on commit” can see delayed commit times
3311210 9.2.0.5, 10.1.0.2 Unnecessary 0.5 seconds waits for “Broadcast on commit” SCN scheme
2663122 9.2.0.5, 10.1.0.2 Unneccessarily long waits on “log file sync” can occur
2640686 9.2.0.5, 10.1.0.2 Long waits for “log file sync” with broadcast SCN in RAC

原因2:磁盘的IO负载过高,导致LGWR将REDO写入logfile的速度受影响

情况1.比较’log file sync’和’log file parallel write’的平均等待时间结合诊断
等待事件’log file parallel write’表示 LGWR 正在等待写 redo 操作。该事件的持续时间就是等待 IO 操作部分的时间。结合事件“log file sync”看同步操作消耗在 IO 的时间,由此推断,有多少处理时间消耗在 CPU 上。

如果’log file sync’ 和 ‘log file parallel write’ 都有很高的等待时间,而且’log file sync’的时间消耗在’log file parallel write’上的比例高,那么大部分的等待时间是由于 IO(等待 redo 写入)。应该检查 LGWR 在 IO 方面的性能。Oracle官方的一个经验法则,’log file parallel write’平均时间超过 20 毫秒, 意味着 IO 子系统有问题。

这种情况下建议

  • 降低redolog所在的文件系统其他不必要的IO开销。
  • 建议redolog不放在raid5阵列上的卷组中,众所周知raid5的写惩罚是最高的。
  • 建议redolog不放在 SSD硬盘中,虽然通常情况下,SSD 写入性能好于平均水平,但是可能会遇到写峰值,从而导致大量的增加’log file sync’等待
  • 监控其他可能需要写到相同目录卷组的进程,确保该磁盘具有足够的IO吞吐量,足以应付所要求的容量。
  • 确保 LOG_BUFFER 不要太大,一个非常大的 log_buffer 的不利影响就是刷新需要更长的等待时间。当缓冲区满了的时候,它必须将所有数据写入到重做日志文件。LGWR 将一直等待,直到最后的 I/O 完成。
  • 避免redol log file member超过1个

尽管’log file parallel write’的平均等待时间可能在一个合理的区间范围内,在峰值时刻写操作时间还是可能会很长进而影响’log file sync’的等待时间。从10.2.0.4 开始如果写操作超过 500 毫秒我们会在 LGWR 的 trace 中写警告信息。这个阀值很高所以就算没有警告也不代表没有问题。警告信息如下:

*** 2012-11-13 20:13:41.718
Warning: log write elapsed time 21130ms, size 1KB
(set event 10468 level 4 to disable this warning)

*** 2012-11-13 20:13:42.929
Warning: log write elapsed time 4916ms, size 1KB
(set event 10468 level 4 to disable this warning)

注意:上面的峰值如果时间间隔的很远,可能不会对’log file parallel wait’有大的影响。 但是,如果有 100 个会话等待’log file parallel wait’完成,’log file sync’总等待可能就会很高,因为等待时间将被乘以会话的个数 100。因此,需要重点关注日志写 IO 高峰的原因。

此时建议:

  • 检查其他正在发生的可能会导致 LGWR 写磁盘峰值的操作,比如大量的导入操作,插入,或者系统级别的文件拷贝,以及大量的trace文件产生的情况
  • 当 LGWR 进程慢的时候,对其进行 Truss 操作会帮助确定时间消耗在什么方面

这些警告信息对于预防潜在问题的发生很有帮助。就算平均等待时间没问题,通过找到 I/O 性能峰值点,可以知道 LGWR 会间歇性的遇到性能问题,进而在它引发更大问题前将其解决。

情况2.redolog file 大小是否足够,这里和LGWR switch等待事件一起结合诊断

每次redolog切换到下一个日志时,会执行’log file sync’操作,以确保下一个日志开始写之前redo信息都写完。如果日志切换频繁,则预示着会产生更多的log file sync等待,这个时候就需要考虑增加redo logfile的大小,控制redolog file的切换频率保持在15分钟到20分钟左右一个。

 

 

浅谈RAC中 Gc block lost 的诊断

Oracle的RAC环境中,数据库会收集global cache 的工作负载统计信息,这些信息可以通过STATSPACK, AWRs 和 GRID CONTROL等工具。
对于每个节点,RAC都会对global cache中的数据传输信息进行监控和评估,global cache数据传输信息情况 代表了私有网络通信的包处理效率低或者包的处理存在异常。如果golbal cache与Enqueue服务的通信出现异常在相关的AWR和statspack中可以检测到相关的等待事件,这类等待事件基本为gc cr block lost 和/或 gc current block lost。数据库绝大部分的 global cache lost blocks的问题都可以直接联系到私网的故障和错误的配置。本文可以作为调查和评估常见原因(有时是非常明显)的指南。

尽管我们讨论的大部分都是性能问题,但是这些问题也有可能会导致节点或实例的驱逐。Oracle集群和RAC实例依赖于心跳来维持节点关系。如果网络心跳持续无法连通,那么实例/节点驱逐就会发生 。因此,以下的这些场景症状也和节点/实例驱逐相关。

主要现象:

“gc cr block lost” / “gc current block lost” 出现在AWR的top 5等待事件中或者产生了非常多的等待。

其次:

1.SQL traces 文件中多次出现 gc cr requests / gc current request
2.出现 gc cr multiblock requests 等待,每次等待时间都很长而且elapsed times 都一样。
3.应用的性能和吞吐量都很差
4.通过ifconfig或者其它第三方的工具能够看到网络上发送和接受包的错误
5.使用netstat命令会看到一些error/retransmits/reassembly failures
6.节点故障和节点通信错误
7.大量的CPU消耗在网络进程上

注意: 块丢失的问题通常会和gc cr multiblock requests 等待同时出现,如:等待连续的块扫描

可能的原因:

可能的原因已经在下面的诊断指南中列出(按照出现概率排序)

一.网线/网卡/交换机问题

描述: 坏掉的网线连接,错误的电缆,制作粗糙的电缆,过于冗长和错误的端口分配,有问题的交换机都会导致低下的传输率,块损坏,数据包丢失和性能问题。

解决: 敦促网络供应商对网络进行检查,更换坏掉的网络组件。集群私网应该使用CAT 5 级或者是更好的通信线缆.所有的设备都需要确保安全插牢,并且按照线缆和端口进行标识,线缆的长度需要符合供应商指定的要求。

二.UDP receive(rx) buffer sizes设置过小/UDP buffer socket溢出

描述: Oracle RAC Global cache块的处理是突发性的,因此,操作系统需要缓冲区来接受接收(RX)数据包并等待CPU的处理,如果缓冲区设置的不合理或者过小会导致块丢失和global cache 块丢失。通过’netstat -s’ 或者 ‘netstat -su’命令可以帮助我们在unix平台上获取到UDPInoverflows,package receive errors, dropped framces 或packets dropped due to buffer full errors信息。

解决: 数据包丢失往往是由于在接收服务器上设置的UDP缓冲区不足,从而导致了块在缓冲区中溢出而产生块丢失。当OS的缓冲区设置小于128k的时候,Oracle 在打开一个socket 时会设置 UDP receive buffer 尺寸为 128k。如果OS的缓冲区设置大于128k,Oracle会采用OS 的设置。如果数据库的块尺寸大于8k,那么缓冲区会自动的进行调整,但是不会超过OS的限制。当DB参数DB_FILE_MULTIBLOCK_READ_COUNT的值大于4时,如果发现 UDP buffer overflows, packet loss 和 lost blocks,并且数据库出现了大量的”global cache cr requests”等待超时,这是由于缓冲区设置过小导致的,我们可以通过调大OS的UDP缓冲区的或者调低数据库参数DB_FILE_MULTIBLOCK_READ_COUNT来解决问题 ,这个参数可以在系统或session级别调整。

对于大部分的unix平台,我们可以通过以下的一些命令来判断是否出现UDP缓冲区溢出或者block loss,执行:

‘netstat -s’ 或 ‘netstat -su’,并根据具体平台查看 “udpInOverflowsudpInOverflows”, “packet receive errors”, “fragments dropped” 或 “outgoing packet drop” 信息

注意:UDP丢包通常会引起更多的延迟,网络带宽减少,更高的CPU使用率(kernel 和user),以及消耗更多的内存来处理这些包的重传。
在系统运行时,如果工作节点(运行负载的节点)对应的远程节点上命令netstat –s的输出中 “outgoing packets dropped”值显著的增加,同时增加wmem_default 和 wmem_max到4M(Linux平台)可以解决问题。

UDP发送和接收缓冲区参数是和操作系统有关的,它们可以滚动(rolling)修改(例如:每次1个节点)。

三.私网性能差并且CPU使用率高,`netstat -s` 出现packet reassembly failures

描述: 根据MTU(Maximum Transmission Unit)的尺寸,大的UDP数据包可能被分片,并在多个帧中发送。这些零散的数据包需要在接收节点上重新组合。高CPU使用率(持续的或者是频繁的峰值),过小的reassembly buffer或者UDP buffer也会导致块重组失败。在接收节点’netstat -s’输出的 “IP Statistics”部分提示有大量的Internet Protocol (IP)上的”reassembles failed” 和 “fragments dropped after timeout”信息。分片的报文需要在指定时间(time-to-live)内完成重组(reassemble)。没有能够完成重组的分片报文会被丢弃并要求重传。已经收到,但是由于空间不足没有进行重组的数据分片会被直接丢弃。

`netstat -s` IP stat counters:
3104582 fragments dropped after timeout
34550600 reassemblies required
8961342 packets reassembled ok
3104582 packet reassembles failed.

解决: 增加reassemble buffer尺寸,给重组分配更多的空间。增加reassemble的时间,增加UDP receive buffer以避免由于网络延迟导致的reassemble失败,并找到对网络数据包处理产生负面影响的高CPU 利用率原因.
注意: 增加以下设置的同时也会增加内存的使用

LINUX:
我们可以通过以下设置来修改reassemble buffer大小
/proc/sys/net/ipv4/ipfrag_low_thresh (default = 196608)
/proc/sys/net/ipv4/ipfrag_high_thresh (default = 262144)

我们可以通过以下设置来修改reassemble的时间:
/proc/sys/net/ipv4/ipfrag_time (default = 30)

请参考OS文档了解不同平台的对应命令语法。

四.网络传输坏块(corruption)导致的UDP checksum errors 和/或 send (tx) / receive (rx) transmission errors

描述: UDP包传输的过程中,接受进程会读取数据包头的校验值。任何校验值损坏都会使这个包被丢弃,并导致重发,这会增加CPU的使用率并且延缓数据包处理。

解决: 使用 tcpdump,snoop等网络工具来捕获数据包的dump,定位这些checksum错误并确认checksum corruption。敦促OS或者网络管理员查找产生corruption的原因。 已知的问题是由于网卡上开启了Checksum offloading 导致了checksum 错误,如果出现这样的问题请检查checksum offloading的功能是否被禁用,测试后考虑关闭网卡上的该项功能。在Linux系统上执行ethtool -K rx off tx off可以关闭该功能.

五.在通信通道中设置了不匹配的MTU的值

描述: 不匹配的MTU大小设置会导致传输过程中出现 “packet too big” 错误并丢失数据包,导致global cache block丢失和大量的重传(retransmission)申请。.
解决: MTU 是”Maximum Transmission Unit” 或者是私网通信过程中帧的尺寸.

对于以太网(Ethernet),大多数UNIX平台的默认值是1500字节。私网链路中所有设备都应该定义相同的MTU。请确认并监控私网链路中的所有的设备。为ping ,tracepath,traceroute命令指定大的,非默认尺寸,ICMP probe 包来检查MTU设置是否存在不一致。使用ifconfig或者厂商推荐的工具为服务器网卡(NIC)的MTU设置合适的值。关于JUMBO Frames的设置,请见第12点的介绍。

注意:私网中不一致的MTU值会导致节点无法加入集群的问题。

六.使用非专用的私网链接

描述: 共享的公网和私网配置会导致应用性能低下,网络拥堵,在一些极端的情况下会导致global cache block loss.
解决:数据库/集群私网应该使用独占的VLAN,并定义在non-routed子网中。私网的交换机需要独立于其他的交换机,例如,私网交换机不应该是从接入层的交换机扩展出来,私网的交换机不应该和公网或者NAS的交换机共享。如果使用了VLANs,那么私网应该被划分在单独的VLAN中,并且位于独占的 ,non-routed 子网,独立于公网或者NAS网络。

七.服务器/交换机缺少“邻接”(adjacency)配置

描述: 通常,如果网络上的设备能够通过单跳链接,我们称为“邻接”(adjacency).多跳的配置会增加网络上的延迟,也会增加更多的节点故障风险.
解决: 所有的 GbE(千兆以太网)服务器的私网链接都应该邻接在交换机或者交换机组(如果配置了交换机冗余)上。在私网链路中,不应该出现中间网络设备,例如:路由器。在Unix平台上,我们可以通过tracetroute命令来确定“邻接”问题。
配置了 IPFILTER

描述:配置主机防火墙或网络地址转换(NAT)软件– IPFILTER (IPF)也是导致私网通信问题的原因之一。IPF还会导致严重的应用程序性能下降,丢包以及global cache block loss问题.
解决: 禁用 IPFILTER

八.过时的网卡驱动程序(Network driver)或者是网卡固件(firmware)

描述: 过时的网卡驱动程序或固件,是已知的私网数据包传输问题原因。不兼容的网卡驱动程序会导致节点间通信过程中数据包处理延迟,延迟增加和丢包。
解决: 所有节点上的网卡应该采用相同的制造商和型号,相同的性能参数,和对称的插槽(slot) ID。集群中所有节点的私网网卡固件和驱动程序都应该是一致的(最新的)。

九.特殊的私网链接和网络协议

描述: 非标准的,专享的网络协议,如LLT ,HMP等已经被证明是不稳定的而且很难debug。使用非标准的,专享的网络协议会导致应用的性能下降,丢包和节点重启等故障。
解决: Oracle使用1GbE UDP 作为传输和通信协议,这已经被证明是稳定的,可靠的和高性能的。请避免使用特别的和非标准的通信协议。 在一些平台上,基于Inifiniband 的IP和RDS协议是可用的并且是Oracle支持的,而且10GbE已经被认证(详细信息请参见OTN) – Oracle还在进行这方面的认证工作。
.
十.错误配置的网卡绑定/链路聚合

描述:服务器上错误的网卡绑定或链路聚合配置,邻接的私网交换机上错误的聚合配置会导致性能下降,出现由”port flapping”导致的block loss,交换机上构成私网端口的聚合链路发生频繁的”UP”/”DOWN”状态切换。
解决: 如果在集群服务器上为私网配置了链路聚合,那么交换机上的端口也应该支持这种配置,并按照聚合配置来配合私网的通信。交换机上构成私网端口的聚合链路配置错误会导致 ‘port flapping’,交换机端口会被随机删除,导致丢包.对于绑定和聚合,请参考驱动器(driver)文档进行配置,并且在有工作负载的环境下进行测试。 有很多公开的工具和软件可以协助进行带宽和性能延迟的测试(请参考iperf)。我们应该通过评估OS,网络和网络驱动器的统计数据来确定绑定的性能.

十一.错误的巨帧(Jumbo Frame)配置

描述: 错误的Jumbo Frames配置会产生之前提到的不一致的MTU问题

解决:Jumbo Frames 并不是IEEE 标准配置,所以配置的时候应该很小心。单个Jumb Frame的大小是9000 bytes左右。Frame 的大小取决于网络设备供应商,在不同的通信设备上的大小可能是不一致的。如果默认的MTU 尺寸不是9000bytes,请保证通信路径中的所有设备(例如:交换机/网络设备/网卡)都能够支持一个统一的MTU值,在操作的过程中必须把Frame Size(MTU Size)配置成这个值。不合适的MTU设置,例如:交换机上配置MTU=1500,但是服务器上的私网网卡配置成MTU=9000,这样会造成丢包,包的碎片和重组的错误,这些都会导致严重的性能问题和节点异常宕机。大部分的平台上我们都可以通过netstat –s命令的‘IP stats’输出发现包的碎片和重组的错误。大部分的平台上我们可以通过ifconfig –a命令找到frame size的设置。关于交换机上的配置查询,需要查看交换机提供商的文档来确定。

十二.网卡双工( Duplex)模式不匹配

描述:网卡的双工模式不匹配是指,在同一个交互的链路上,一端使用的是全双工模式,另外一端使用的是半双工模式。这通常是是手动配置错误导致的 或者是一端配置被修改成半双工模式时,另外一端配置成了auto-negotiate引起的。双工模式不匹配会导致严重的私网通信性能问题

解决: 集群中所有节点的私网网卡和交换机上的私网线路对应的双工模式都应该配置为auto-negotiate。千兆以太网标准要求auto-negotiate 设置为”on”。双工模式不匹配可能会导致严重的网络性能下降,数据冲突和丢包的情况出现。 每次进行网络硬件和软件升级后都应该检查auto-negotiate设置, Auto-negotiate 在所有的设备上都应该是1000全双工模式。

十三.私网通信链路流量控制(Flow-control)不匹配

描述: 流量控制是指,当一台服务器传输的速度比接收节点(或者是网络设备)的接受速度快 。接收设备会发送“暂停”帧来请求发送端暂时停止发送数据包.
解决:交换机和服务器网卡之间Flow-control设置不匹配的时候会导致丢包和严重的网络性能问题。大部分的情况下,默认的设置”ON”是最好的结果。例如:

tx flow control should be turned on
rx flow control should be turned on
tx/rx flow control should be turned on for the switch(es)

尽管如此,对于一些特殊的案例(例如 note 400959.1),例如一些OS或交换机固件的bug,设置成OFF(所有的网络路径)会有更好的结果。

注意:Flow control的设置在固件/网络驱动程序升级后会发生变化,网卡/交换机的设置应该在升级后重新检查。如果没有设备提供商的其它建议值,请使用默认的值。

十四.OS,网卡,交换机层面的数据包丢弃

描述:任何被OS,网卡或者交换机提示的包丢弃信息都应该被彻底的调查和解决。包丢失会导致私网性能降低,CPU使用过高以及节点异常宕机等情况

解决:具体的工具会帮助我们确定包或帧丢失问题发生在那个层面(process/OS/network/switch)。netstat ,ifconfig,ethtool,kstat(依赖于OS的平台)命令输出和交换机端口状态是首先要进行检查和评估的。您需要一些网络嗅探器(sniffer)跟踪点对点数据通信来排查问题(常见的工具:snoop/wireshare/ethereal).

注意:从底层来理解丢包的原因是我们找到根本原因不可缺少的步骤。在网络环境中,过小的网卡ring buffers或者receive queues是已知的导致网络上异常丢包的原因,比如:在所有层面都没有提示发生了丢包。请查看下面的网卡驱动问题和Kernel queue长度.这种情况,需要联系系统管理员和网络工程师来确定根本的原因.

十五.网卡驱动/固件配置问题

描述:不合适的配置或者网卡中一些可调属性的不恰当的默认也会导致丢包并增加重传的请求.

解决:大部分网络设备供应商提供的默认出厂配置是可以满足应用要求的。尽管如此,一些网络供应商提供的网卡设备需要修改interrupt coalescence设置和ring buffers描述符数量。interrupt coalescence是CPU发送和接受数据包的中断率。ring buffer在 CPU中断之间持有需要处理的rx 包。不合适的配置会导致在这个层面丢失数据包,诊断这个层面的问题需要系统管理员以及OS/设备提供商的参与。

十六.网卡发送(tx)和接受(rx)队列的长度

描述:设置过小的网卡tx/rx队列长度会导致在队列满的时候出现丢包的情况,这会导致gc block loss,增加重传并且降低私网的效率。

解决:在内核网络子系统(kernel network subsystem)和网络接口设备驱动程序之间移动数据时,发送(TX)和接收(Rx)队列用来实现对数据包的传输和处理进行管理.这些队列的大小是可以配置的。针对产生的网络流量或者配置了MTU的情况,如果这些队列的配置不合适或者过小,队列填满后会导致数据包的丢失或溢出。取决于设备的驱动程序和搜集到的统计信息数量,这类丢包是不容易被发现的,诊断这个层面的问题需要系统管理员和OS/设备的提供商的介入。(通常在linux上我们设置参数:iftxtqueue 和netdev_max_backlog)

十七.有限的负载能力和过于饱和的带宽

描述: 过载的网络使用也会导致私网的性能问题和丢包。

解决: 私网配置的最佳实践是您需要知道您的网络使用情况和带宽。这需要通过定期的监控来获取使用的趋势,瞬时值和恒定的值。私网上突然增加的使用请求可能是应用程序调整或异常导致的,如性能很差的SQL语句或者异常产生的数据流量。找到产生带宽饱和的原因并解决它。

十八.过度的CPU申请和调度延迟

描述: 持续的高负载和网络堆栈的调度延迟也会对私网的数据包传输产生负面的影响并且会导致私网的性能下降,丢包,gc block loss和节点的重启问题。

解决: 持续的高CPU使用率导致的调度延迟也会导致网络上数据包的延迟处理。过度,持续的延迟会导致严重的性能下降,并可能导致群集节点故障。关键是要找到持续的高CPU使用率的原因。使用uptime命令能够列出大部分操作系统的平均负载情况,和网络堆栈处理相关的CPU问题,可以通过NIC interrupt coalescence或者绑定网络到单个CPU得到缓解,请和网络设备的供应商一起来进行此类的优化。调度延迟会导致数据包重组错误。请参见本文的第2点。

十九.和交换机相关的数据包处理问题

描述:交换机的端口缓冲区溢出,交换机拥堵和配置问题,比如MTU大小,网络聚合和VLANS 都能导致低效率的数据包处理和集群节点故障。

解决:Oracle私网需要一个包含交换机的以太网网络。交换机是私网中点对点通信至关重要的组成部分。作为一个网络设备,这个交换机会受到多种因素的影响并导致私网通信性能和高可用性出现异常。监控交换机的异常,数据包处理事件,临时的或持续的吞吐量信息是非常重要的。交换机的状态统计信息,应该定期进行检查并评估是否正常,并找出异常情况。

二十.QoS对私网数据包处理产生的负面影响

描述:在交换机上定义的QoS会共享私网通信的带宽并影响私网处理能力,导致私网性能的下降。

解决: 如果私网布置在共享交换机的VLAN上,QoS应该通过优先级配置来避免对私网通信产生负面的影响。任何QoS的定义在布置前都应该进行评估,确保不会影响私网通信.

二十一.重聚(reconvergence)过程中生成树(Spanning tree)限电

描述:以太网使用生成树协议(STP)来避免网络环路,确保交换机和冗余的交换机能直接路由到服务器。任何包含在STP拓扑中的设备故障都会导致重新计算路由到主机的重聚。如果STP协议在局域网中被起用,但是配置的有
问题或未经优化,网络重聚事件可能需要长达1分钟或者更长的时间(取决于网络的规模和参与设备)。这种延迟会导致私网问题和集群范围的中断。

解决:很多交换机供应商提供优化的扩展,使STP能够实现更快的网络重聚。例如: Rapid Spanning Tree (RSTP), Per-VLAN Spanning Tree (PVST)和Multi-Spanning Tree (MSTP) 可以避免集群大范围的异常出现。

二十二.STREAMS队列的sq_max_size 配置太小

描述: AWR 提示 “gc cr block lost” 和/或”gc current block lost”等待时间很高。 netstat 并没有提示有任何数据包处理的错误. `kstat -p -s ‘*nocanput*` 返回非0值. nocanput 说明streaming message队列已满,并且包被丢弃。 客户在Solaris平台RAC环境下使用STREAMS。
解决: 增加UDP max buffer space,并且把STREAMS队列设置成unlimited能够解决问题,并且消除”nocanput” lost messges。以下是Solaris平台下对应的命令:
`ndd -set /dev/udp udp_max_buf `
set sq_max_size to 0 (unlimited) in /etc/system. Default = 2

udp_max_buf 控制UDP socket发送和接受缓冲区的大小,默认值是262,144 bytes,这个值对于使用STREAMS的应用来说是不够用的。sq_max_size 控制message的队列的长度。

二十三.VIPA和DGD设置不正确(仅限Aix平台)

如果您在AIX平台上使用了VIPA(Virtual IP Address),那么Dead Gateway Detection (DGD)必须配置成允许UDP failover模式。

默认的DGD参数可以作为配置起始值,但是在一些客户的环境中,这些参数可能需要调整,但是无论何种情况,都必须设置成大于1的值。默认的设置如下:
dgd_packets_lost = 3
dgd_ping_time = 5
dgd_retry_time = 5

更多配置信息,请参考文章Using VIPA and Dead Gateway Detection on AIX for High Availability Networks, including Oracle RAC: http://www-03.ibm.com/support/techdocs/atsmastr.nsf/WebIndex/WP102177

Solaris+Vertis LLT的环境上,交换机的错误配置

当VCS命令lltstat的输出显示”Snd retransmit data”增加时,gc block lost 也会增加。把私网交换机的速度从fixed修改成auto-negotiate,更均匀地分布电缆到每个模块的链接,这样有助于解决”gc blocks lost”的问题