简单的几条Insert语句引起的逻辑Standby应用延迟的诊断

一个逻辑Standby的库，运行在Redhat as4u4_x86_64的平台上，数据库版本10.2.0.2。主库运行的操作系统平台和数据库版本跟Standby库一致，运行在最大性能模式，使用 LGWR ASYNC方式传Redo到逻辑Standby库。逻辑Standby库使用Apply Immedite方式进行实时应用。因为这个库的压力很小，所以Standby库和主库之间的数据同步时间非常小，一般都在分钟级别以内，但这次因为一个 每分钟才运行几次的简单Insert语句却能引起Standby Apply的延迟，确实有些不同寻常，下面来看看到底发生了什么。[@more@]上午，收到报警邮件，说逻辑Standby库的Apply跟主库之间间隔已经有10分钟了，这说明数据同步出现问题。这种问题在逻辑Standby库的使用中经常碰到了，比如主库一句SQL更新了大批量的数据，那Redo传到Standby库后，会被解析成一条条SQL来进行执行，会导致Apply变慢；或者因为某些原因导致Apply停掉，同样也会出现延迟；或者Standby库负载过高，导致Apply变慢，也会延迟等等。但经过一个个的排查和确认后，上面的问题一一被否决，而且延迟变得越来越大。Apply还在进行，但是非常缓慢，同时数据库的负载明显升高。
那首先来看看Standby库在干啥吧，通过查询v$session_wait视图，看到几个很明显的正在被APPLY的SQL要么在等待latch: cache buffers chains，要么在等待db file sequential read，从这些事件来看跟发生大量全表扫描的的等待事件十分相似，那就来看看这些SQL导致是在干些什么吧（以下SQL中的所有表名、字段等全部使用替换过的命名）。SQL原文如下：
select "B" into loc_c from "TEST"."BEAR" where "A" = '264312' for update;
查看这个SQL的执行计划，果然是一个全表扫描，怪不得会出现上面那么多的等待事件了。看看表的结构，这个表上居然没有任何的索引或者主键，于是把开发同事抓过来，确认A字段应该是表的主键，当初创建表的时候忘记加主键了，于是为这个表创建了一个唯一索引，然后再来观察Standby上的等待事件，原先的等待事件都没有了，SQL Apply的速度明显加快，一会就跟主库的同步时间缩短到正常范围。
本来故事到这里就结束了，但跟开发人员交流中得知这个表是一个日志表，也就是说数据永远只会插入，只有碰见问题需要查询的时候才会来手工的查询这个表里的数据，而且根本不会去弄个for update的查询去加一个锁上去。
这问题就来了，跟开发再三确认，开发拿脑袋担保说前台引用只有INSERT操作，那这些for update的SQL哪里冒出来的呢？
最简单的办法就是使用Logminer去挖掘主库的日志，看看主库当时到底记录了什么东西到REDO。挖掘出来的结果是这样的（为了方便阅读，去掉了一些双引号；为了节省篇幅，CLOB字符串中很多abcabc的字符被---符号替代）：
set transaction read write;

insert into "TEST"."BEAR"("A","B") values ('264298',EMPTY_CLOB());

DECLARE
loc_c CLOB;
buf_c VARCHAR2(6168);
loc_b BLOB;
buf_b RAW(6168);
loc_nc NCLOB;
buf_nc NVARCHAR2(6168);
BEGIN
select ""B"" into loc_c from ""TEST"".""BEAR"" where ""A"" = '264298' for update;
buf_c := 'abcabc--------abcabcabca';
dbms_lob.write(loc_c, 4066, 1, buf_c);
END;

DECLARE
loc_c CLOB;
buf_c VARCHAR2(6168);
loc_b BLOB;
buf_b RAW(6168);
loc_nc NCLOB;
buf_nc NVARCHAR2(6168);
BEGIN
select ""B"" into loc_c from ""TEST"".""BEAR"" where ""A"" = '264298' for update;
dbms_lob.trim(loc_c, 1998);
END;

commit;

从上面的结果可以看出来，开发说的一个简单的Insert操作，却对应了一堆的SQL REDO，而且自己测试的结果也证明了这点，这说明开发说的是正确的，问题出现在有CLOB字段插入时候ORACLE记录REDO日志的方式，ORACLE是这么来记录REDO的：
1、 先设置事务为可读写
2、 执行INSERT语句，但是CLOB字段会先插入一个EMPTY_CLOB()来进行初始化
3、 把实际要插入CLOB中的内容调用dbms_lob.write来完成
4、 调用dbms_log.trim把clob列截断到实际插入的字符串的长度
5、 提交事务

但是，并不是所有的CLOB的插入全部是转换成上面的格式，其实我自己测试的时候是先得到的下面的格式的：
set transaction read write;

insert into "TEST"."BEAR"("A","B") values ('264355',EMPTY_CLOB());

update "TEST"."BEAR" set "B" = 'abcabc----bcabca' where "A" = '264355' and ROWID = 'AAAMvOAAEAAATzuAAA';

commit;
跟上面不同的是设置CLOB值的时候，是直接使用UPDATE来做的，而不是调用DBMS的包实现的，那么为什么相同的SQL会有两种不同的方式来记录REDO呢？

其实得到这两个简单的REDO花了不少力气的，过程就不详细描述了，这里只描述一下方法和步骤：
1、 创建一个表BEAR，包含两列，其中一个是顺序号--A，一个是CLOB字段--B
2、 随便插入一行值，假设a=1,b=’abc’,然后通过update bear set b=b||b的方式，使得插入的CLOB字段值变得足够大，基本上超过4000个字节就足够了，假设这里是5000个字节长
3、 然后创建一个SEQUENCE，用来生成A列的值
4、 写一个循环，从1循环到5000（对应上面的字节长度），然后开始insert into bear select sequence.nextval,substr(b,1,5000-i) from bear where a=1，这里的意思就是通过插入的第一行，来生成其他的插入数据，其中变化的地方就在CLOB列的插入，让它的长度不停的减小。
5、 完成后挖掘上面这段日志，会发现SQL REDO记录的不同格式发生在CLOB长度为1982到1983之间的时候，CLOB的长度>=1983的时候，生成的REDO是第一种格式，使用DMBS的格式；CLOB长度<=1982的时候，生成的REDO是第二种格式，直接使用UPDATE来更新的方式。

1982和1983，搞不明白了，为什么是一个三不沾的数字？为什么不是因为UPDATE的时候的字符串长度最大为4000，超过4000不能表示，所以4000应该是分界点啊；或者因为字符集的问题，一个字符占多个位，那也应该是4000/2或者UTF-8的时候是4000/3啊。想破了脑袋，最后还是在METALINK上找到了答案（ML: 66431.1）。

LOB字段的存储分为in line和out line，这个很多人都清楚，而且有个参数可以设置的，就是创建表的时候设置LOB的ENABLE STORAGE IN ROW或者DISABLE STORAGE IN ROW，也就是说，LOB是否跟其他对应的行数据一起存放，还是单独的开一个LOB类型的SEGMENT来存放。但即使你设置的是in line存储的，那LOB也不一定就和行数据一起存储在表的SEGMENT中的，因为LOB一般都很大，这么存储是不合理的，那么ORACLE就划分了一条分界线，注意，重点就在这条分界线了。当你设置out line存储的时候，LOB直接存储到单独的LOB SEGMENT；当设置in line存储的时候，以3964为分界线，长度小于或者等于3964的，那就是真正的in line存储，LOB数据和行其他数据存放在一起，长度大于3964的时候，即使设置是in line存储的，但ORACLE还是会把数据存放到单独的LOG SEGMENT中去。
3964/2=1982，到这里终于搞明白为什么这里会是日志记录格式的分界点，也就是说对于所有的LOB跟行数据一起存储的，ORACLE就使用UPDATE更新的方式来记录LOB相关的REDO；对于LOB是单独SEGMENT存储的，那就是使用DBMS包更新的方式。这么设计应该跟前面的猜测是一致的，因为VARCHAR最大支持的字符串长度就是4000，所以大于4000的话，单独的UPDATE没办法表示要插入的CLOB的正确的值，所以就需要使用DBMS的方式来更新。
那么还有一个问题，为什么不是以VARCHAR的长度限制4000为分割点呢？METALINK上还说了这么一句：
When a LOB is stored out-of-line in an 'enable storage in row' LOB column between 36 and 84 bytes of control data remain in-line in the row piece.
也就是说，当设置为in line的方式存储LOB的时候，万一因为LOB太大需要out line方式来存储，那么这时候就需要在原先的行空间中保留36到84字节的控制数据。当LOB真的是in line存储的时候，应该是以VARCHAR的替代方式来存储的，而VARCHAR最大只能存4000，然后保留36个字节的控制数据的空间，那么也就是说in line存储的LOG的最大长度只能有3964。

到这里为止，这一切都全部串起来了。还剩最后一个疑问，既然METALINK上说当该in line的LOB被out line存储的时候，才会保留36-84字节的空间给控制信息使用，那还是应该in line存储的时候能存储到4000字节，而不是只能存储到3964字节才对啊。下面通过另一个方法来证明下其实METALINK说的不是那么准确的。
1、随便插入一行数据，LOB字段插入为空 ，然后把这个BLOCK DUMP的结果如下：
col 0: [ 2] c1 03
这说明空的LOB是不占用空间的，接下来UPDATE LOB字段为一个字符“a”。
2、然后再次DUMP，结果如下：
col 0: [ 2] c1 03
col 1: [38]
00 54 00 01 02 0c 80 00 00 02 00 00 00 01 00 00 00 04 05 02 00 12 09 00 00
00 00 00 00 02 00 00 00 00 00 01 00 61
可以看到，除了插入的字符“a”的ASCII码61以外，LOB列还多了36个控制字符，一共长度是38个字符，这也正好说明了为什么in line的时候LOB的长度最大只能到3964而不是到4000。
3、然后UPDATE LOB字段长度到1983，让它刚刚从in line跳到out line，这个时候DUMP结果如下：
col 0: [ 2] c1 03
col 1: [40]
00 54 00 01 02 0c 80 00 00 02 00 00 00 01 00 00 00 04 05 03 00 14 05 00 00
00 00 00 0f 7e 00 00 00 00 00 02 01 00 e0 01
这个说明只要是out line存储的，那至少是需要40个字节的控制字符空间的
4、然后不停的update bear set b=b||b where a=1来膨胀LOB的大小，然后再次DUMP，结果如下：
col 0: [ 2] c1 03
col 1: [84]
00 54 00 01 02 0c 80 00 00 02 00 00 00 01 00 00 00 04 05 00 00 40 05 00 00
00 3e 95 0a ec 00 00 00 00 00 02 01 00 a4 4c 01 00 a4 5c 01 00 a4 6c 01 00
a4 7c 01 00 a4 8c 01 00 a4 2c 01 00 a4 9c 01 00 a4 3c 01 00 a5 28 01 00 a5
09 01 00 a5 19 01 00 a5 29
从上面的结果可以看到，这个时候，控制字符占用的空间已经膨胀到了84个字节了。
那么当in line存储LOB的时候，只要LOB不为空，那么就会有36个字节的控制字符，所以LOB最大只能存放3964字节的内容；当LOB扩张到需要out line存储的时候，控制字符才会超过36个字节的大小，并且随着LOB的膨胀而膨胀，最终膨胀到84字节。

写总结前先引用一段Data Guard Concepts and Administration 10g Release 2 (10.2)中的一段话，说明了SQL产生的REDO在逻辑Standby上应用的情况：
1、If a table has a primary key defined, then the primary key is logged along with the modified columns as part of the UPDATE statement to identify the modified row.
2、In the absence of a primary key, the shortest nonnull unique-constraint/index is logged along with the modified columns as part of the UPDATE statement to identify the modified row.
3、In the absence of both a primary key and a nonnull unique constraint/index, all columns of bounded size are logged as part of the UPDATE statement to identify the modified row. In other words, all columns except those with the following types are logged: LONG, LOB, LONG RAW, object type, and collections.

在这个案例中，因为所有的SQL只是简单的插入，所以表上没有建主键或者任何索引（插入快嘛），但偏偏因为CLOB的特殊性，导致主库上的插入的SQL在逻辑Standby库上会被拆分成包含select …. For update或者update …的格式来进行LOB字段的更新，那么如果这个表上没有任何索引或者主键，这些for update或者update就会变成一个全表扫描，而且随着数据量的不断增加，扫描的成本越来越高，最终导致SQL Apply越来越慢，从而引起了主备库不同步的问题。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/25016/viewspace-1023518/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/25016/viewspace-1023518/