DRM 分析及案例讲解
-
什么是DRM
DRM（Dynamic Resource management）是oracle10.10.2里面推出来的一个新特性，一直到现在最新的12cR1，都存在，且bug非常多而著称。在10gR1 RAC是每个实例都有其自己的SGA和buffer cache。RAC为了确保这些块发生时的最大化性能,确保数据完整。每个缓冲区副本也称为缓存资源有一个主要的将做为一个主要的集群节点。在数据库版本10g(10.1.0.2)一个主要的缓存资源负责掌管一个实例,re-mastering或改变主节点只会发生在重新配置,会自动在两个正常操作实例启动或实例关闭，异常节点集群管理器将对其进行逐出。因此,如果节点B这个时候作为一个主缓存的资源,这个资源仍将掌握在节点B直到重新配置。10g中引入了一个新概念,通过DRM资源进行remaster。与DRM资源可以在另一个节点上重新优化,从节点B节点如果发现更频繁地访问缓存资源从节点a重新配置不再是资源重新优化的唯一原因。
到10gR2是基于相关对象的，下面是DRM的跟踪trace文件，在Oracle日志中的LMD进程信息里面。
Sample LMD trace file during a DRM operation
Begin DRM(202) - transfer pkey 4294951314 to0 oscan 1.1
*** 2006-08-01 17:34:54.645
Begin DRM(202) - transfer pkey 4294951315 to 0 oscan 1.1
*** 2006-08-01 17:34:54.646
Begin DRM(202) - transfer pkey 4294951316 to 0 oscan 1.1
*** 2006-08-01 17:34:54.646
Begin DRM(202) - transfer pkey 4294951317 to 0 oscan 1.1
-
remastering的发生:
Remastering问题发生时会影响性能。以下AWR报告显示了DRM重配置问题导致的实例冻结。同样类型的冻结在其它的所有节点上也都可以看见。gc buffer busy等待只是DRM冻结的副作用（不是总有，但是在这个case是这样）。
Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time Wait Class ------------------------------ ------------ ----------- ------ ------ ---------- gc buffer busy 1,826,073 152,415 83 62.0 Cluster CPU time 30,192 12.3 enq: TX - index contention 34,332 15,535 453 6.3 Concurrenc gcs drm freeze in enter server 22,789 11,279 495 4.6 Other enq: TX - row lock contention 46,926 4,493 96 1.8 Applicatio
在同一时刻，DRM大量发生，导致了重复的DRM冻结、实例重配置，从而引发严重的性能问题。
Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time Wait Class ------------------------------ ------------ ----------- ------ ------ ---------- latch: cache buffers lru chain 774,812 140,185 181 29.7 Other gc buffer busy 1,356,786 61,708 45 13.1 Cluster latch: object queue header ope 903,456 55,089 61 11.7 Other latch: cache buffers chains 360,522 49,016 136 10.4 Concurrenc gc current grant busy 112,970 19,893 176 4.2 Cluster
可以看到，TOP 5中，有3个是latch相关的等待，而另外2个则是跟RAC相关的等待。
如果再查看更细的等待数据，可以发现其他问题：
Avg
%Time Total Wait wait Waits
Event Waits -outs Time (s) (ms) /txn
---------------------------- -------------- ----- ----------- ------- ---------
latch: cache buffers lru cha 774,812 N/A 140,185 181 1.9
gc buffer busy 1,356,786 6 61,708 45 3.3
latch: object queue header o 903,456 N/A 55,089 61 2.2
latch: cache buffers chains 360,522 N/A 49,016 136 0.9
gc current grant busy 112,970 25 19,893 176 0.3
gcs drm freeze in enter serv 38,442 97 18,537 482 0.1
gc cr block 2-way 1,626,280 0 15,742 10 3.9
gc remaster 6,741 89 12,397 1839 0.0
row cache lock 52,143 6 9,834 189 0.1
从上面的数据还可以看到，除了TOP 5等待，还有”gcs drm freeze in enter servermode“以及”gc remaster”这2种比较少见的等待事件，从其名称来看，明显与DRM有关。那么这2种等待事件与TOP5的事件有没有什么关联？。MOS文档”Bug 6960699- “latch: cache buffers chains” contention/ORA-481/kjfcdrmrfg: SYNC TIMEOUT/OERI[kjbldrmrpst:!master] [ID 6960699.8]”提及，DRM的确可能会引起大量的”latch: cache buffers chains”、”latch: objectqueue header operation”等待，虽然文档没有提及，但不排除会引起”latch: cachebuffers lru chain“这样的等待。
为了进一步证实性能问题与DRM相关，使用tail -f命令监控LMD后台进程的trace文件。在trace文件中显示开始进行DRM时，查询v$session视图，发现大量的 “latch: cache buffers chains” 、”latch:object queue header operation”等待事件，同时有”gcs drm freezein enter server mode“和”gc remaster”等待事件，同时系统负载升高，前台反映性能下降。而在DRM完成之后，这些等待消失，系统性能恢复到正常。
* received DRM start msg from 2 (cnt 5, last 1, rmno 404) Rcvd DRM(404) Transfer pkey 1598477 from 3 to 2 oscan 1.1 Rcvd DRM(404) Dissolve pkey 6100030 from 2 oscan 0.1 Rcvd DRM(404) Dissolve pkey 5679943 from 2 oscan 0.1 Rcvd DRM(404) Transfer pkey 6561036 from 0 to 2 oscan 1.1 Rcvd DRM(404) Transfer pkey 5095243 to 2 oscan 0.1 ...
A small test case
我们来看一个测试，观察一下DRM的产生。使用了索引读路径的查询从一个大索引中读取了几乎所有数据块。
Session #1:
select data_object_id from dba_objects where object_name='WMS_N1';
DATA_OBJECT_ID
-------------
6099472
REM 还没有affinity统计信息
select * from x$object_affinity_statistics where object=6099472;
no rows selected.
REM 执行高代价的查询语句
select /*+ index(a WMS_N1) */ count(*) from big_table1 a;
Session #2: 观察DRM表:
REM DRM字段现在是409,。我们将持续观察这个数值。在这个视图中还有其它比较有趣的字段。
select drms from X$KJDRMAFNSTATS;
DRM
----
409
REM 观察到自从会话#1开始运行在该索引上已经有23442个OPENs
select * from x$object_affinity_statistics where object=6099472;
ADDR INDX INST_ID OBJECT NODE OPENS
---------------- ---------- ---------- ---------- ---------- ----------
FFFFFFFF7C05BFA8 14 1 6099472 1 23442
REM 该对象上还没有发生mastering
select * from v$gcspfmaster_info where object_id=6099472;
no rows selected
REM 几秒后，OPENs计数从23442上升到33344
select * from x$object_affinity_statistics where object=6099472;
ADDR INDX INST_ID OBJECT NODE OPENS
---------------- ---------- ---------- ---------- ---------- ----------
FFFFFFFF7C05BFA8 16 1 6099472 1 33344
REM该对象上还没有发生mastering
select * from v$gcspfmaster_info where object_id=6099472;
no rows selected
REM 让人诧异，会话#1还在运行，OPENs计数忽然清零即使DRM还未发生过
REM OPENs从0又升到1229因为会话#1还在运行
ADDR INDX INST_ID OBJECT NODE OPENS
---------------- ---------- ---------- ---------- ---------- ----------
FFFFFFFF7C05BFA8 0 1 6099472 1 1229
REM 大约10分钟以后，remastering发生了。DRMS从409上升到411。
select drms from X$KJDRMAFNSTATS;
DRM
----
411
REM 该索引的remastering发生了。现在该对象的属主是0，也就是实例1
select * from v$gcspfmaster_info where object_id=6099472;
FILE_ID OBJECT_ID CURRENT_MASTER PREVIOUS_MASTER REMASTER_CNT
---------- ---------- -------------- --------------- ------------
0 6099472 0 32767 1
REM OPENs还在上升，但是remastering已经发生了。
select * from x$object_affinity_statistics where object=6099472;
ADDR INDX INST_ID OBJECT NODE OPENS
---------------- ---------- ---------- ---------- ---------- ----------
FFFFFFFF7C05AF78 2 1 6099472 1 42335
FFFFFFFF7C05AF78 3 1 6099472 2 1
REM LMON trace文件也指出pkey的传递。注意pkey和object_id是相同的。
*** 2010-03-23 10:41:57.355
Begin DRM(411) - transfer pkey 6099472 to 0 oscan 0.0
ftd received from node 1 (4/0.30.0)
all ftds received
REM 几秒后，OPENs被再次重置。
select * from x$object_affinity_statistics where object=6099472;
ADDR INDX INST_ID OBJECT NODE OPENS
---------------- ---------- ---------- ---------- ---------- ----------
FFFFFFFF7C05BFA8 0 1 6099472 1 7437
REM 属主仍然是实例1。
select * from v$gcspfmaster_info where object_id=6099472;
FILE_ID OBJECT_ID CURRENT_MASTER PREVIOUS_MASTER REMASTER_CNT
---------- ---------- -------------- --------------- ------------
0 6099472 0 32767 1
我们的测试表明，该索引上发生了大量的BL锁请求，之后对象被remastering。
Undo and affinity
回滚段的Mastering和其它段不同。对于非回滚段而言，一个段上的所有数据块通过哈希算法被分散在各个实例间。只有在经过大量的BL锁请求以后，段才会被mastering。但是对于回滚段而言，激活了一个回滚段的实例立刻成为该段的属主。这是合乎情理的，因为在大多数情况下回滚段将会被打开这个segment的实例使用。初始化参数_gc_undo_affinity控制这种动态undo remastering动作是否发生。
因为回滚段没有真正的object_id，所以使用4294950912作为虚拟object_ids的基准值。比如说，回滚段1（usn=1）的object_id是4294950913，回滚段2（usn=2）的object_id就是4294950914，依次类推（4294950912 = power(2,32) – power (2,14)= xFFFFC000）。
select objecT_id, object_id-4294950912 usn, current_master, previous_master,
remaster_cnt from v$gcspfmaster_info where object_id>4294950912;
OBJECT_ID USN CURRENT_MASTER PREVIOUS_MASTER REMASTER_CNT
---------- ---------- -------------- --------------- ------------
4294950913 1 0 32767 1
4294950914 2 0 32767 1
4294950915 3 0 32767 1
4294950916 4 0 32767 1
4294950917 5 0 32767 1
4294950918 6 0 32767 1
4294950919 7 0 32767 1
4294950920 8 0 32767 1
4294950921 9 0 32767 1
4294950922 10 0 32767 1
4294950923 11 1 32767 1
4294950924 12 1 32767 1
4294950925 13 1 32767 1
...
REM 注意usn 0在两个实例中都存在，这是系统回滚段。
REM 下面结果显示，头10个回滚段被node1掌控，而接下来的3个被实例2掌控。
select inst_id, usn, gets from gv$rollstat where usn <=13 order by inst_id, usn;
INST_ID USN GETS
---------- ---------- ----------
1 0 3130
1 1 108407
1 2 42640
1 3 43985
1 4 41743
1 5 165166
1 6 43485
1 7 109044
1 8 23982
1 9 39279
1 10 48552
2 0 4433
2 11 231147
2 12 99785
2 13 1883
我没有成功试验出触发下一次回滚段remastering。我创建了一个活动事务在一个节点上产生了200K回滚数据块，然后另外一个节点在读这个表，我观察到在回滚数据块上有大量等待。但是我没有发现这个回滚段上有任何remastering事件。无法确认为什么没有产生，也许是回滚段remastering的条件有所不同吧。
译者注：回滚段的remastering是不会因为另外一个节点对于回滚段有大量读取而发生的，只有在某个实例失效，然后负责进行实例恢复的另外那个实例会暂时的成为这些回滚段的master，这是为了进行实例恢复的需要，在恢复完毕以后所有的undo buffers都会被flush到磁盘上。
PS：我能够使用后面将描述的lkdebug命令手动remaster回滚段，所以oracle也应该可以自动remaster回滚段，只是可能还有一个其它条件也必须满足。
select * from v$gcspfmaster_info where object_id=431+4294950912;
FILE_ID OBJECT_ID CURRENT_MASTER PREVIOUS_MASTER REMASTER_CNT
---------- ---------- -------------- --------------- ------------
0 4294951343 0 32767 1
Oradebug lkdebug –m pkey 4294951343
* kjdrchkdrm: found an RM request in the request queue
Transfer pkey 4294951343 to node 1
*** 2010-03-24 12:47:29.011
Begin DRM(520) - transfer pkey 4294951343 to 1 oscan 0.1
ftd received from node 0 (4/0.31.0)
all ftds received
select * from v$gcspfmaster_info where object_id=431+4294950912;
SQL> /
FILE_ID OBJECT_ID CURRENT_MASTER PREVIOUS_MASTER REMASTER_CNT
---------- ---------- -------------- --------------- ------------
0 4294951343 1 0 2
我不是在劝你们应该去修改这些隐含参数。只是要去理解这些参数，如果你们碰到诸如’gc remaster’, ‘gcs freeze for instancereconfiguration’这样的等待事件，那么应该知道是不是因为默认值太低了。跟技术支持沟通尝试是否能够调整。
Manual remastering
你可以使用oradebug命令来手动remaster一个对象：
oradebug lkdebug -m pkey
这会将一个对象remaster请求放入队列。LMD0和LMON进程会完成这个请求。
当前属主是从0开始计数的。
*** 2010-01-08 23:25:54.948 * received DRM start msg from 1 (cnt 1, last 1, rmno 191) Rcvd DRM(191) Transfer pkey 6984154 from 0 to 1 oscan 0.0 ftd received from node 1 (8/0.30.0) ftd received from node 0 (8/0.30.0) ftd received from node 3 (8/0.30.0) select * from v$gcspfmaster_info whereobject_id=6984154; SQL> / FILE_ID OBJECT_ID CURRENT_MASTERPREVIOUS_MASTER REMASTER_CNT ---------- ---------- ----------------------------- ------------ 0 6984154 1 0 2 SQL> oradebug lkdebug -m pkey 6984154 Statement processed. SQL> select * from v$gcspfmaster_info where object_id=6984154; FILE_ID OBJECT_ID CURRENT_MASTERPREVIOUS_MASTER REMASTER_CNT ---------- ---------- ----------------------------- ------------ 0 6984154 2 1 3
Summary
总结一下，remarstering是个很棒的功能。不过遗憾的是，我们有时候会成为它负面效果的受害者。所以，如果你碰到remastering引起的问题，不要直接就禁用它，而是应该去看看能否调优那些参数从而控制remastering事件。如果你仍然想完全禁用DRM，那么我建议设置_gc_affinity_limit和_gc_affinity_minimum参数到一个较高值，比如说1千万。将参数_gc_affinity_time设置为0也可以完全禁用DRM，但是这也意味着再也无法手工remaster对象了。另外，Arup也提到如果DRM被禁用那么x$object_affinity_statistics表也不会再被维护。
Update 1:
从11g开始，affinity管理更名为policy管理（策略管理）。比如说，x$object_affinity_statistics表改名为x$object_policy_statistics，与之相似的，初始化参数也发生了改变：参数_gc_affinity_limit改名为_gc_policy_limit；参数_gc_affinity_time改名为_gc_policy_time；出现了一个新的视图v$policy_history，其中所有policy_event = ‘initiate_affinity’的记录都是与DRM事件相关的。
本blog的其它部分仍然没问题，除了默认的_gc_policy_limit参数值降低为1500，这意味着，在理论上，11g可能会产生更多的DRM事件。
select * from v$policy_history
INST_ID POLICY_EVENT DATA_OBJECT_ID TARGET_INSTANCE_NUMBER EVENT_DATE
---------- -------------------- -------------- ---------------------- --------------------
2 glru_on 0 1 10/15/2010 10:58:28
2 glru_on 0 1 10/15/2010 11:21:32
2 initiate_affinity 74809 1 10/15/2010 13:27:44
-
与DRM有关的一些参数
10g：
看起来，只需要关闭DRM就能避免这个问题。怎么样来关闭/禁止DRM呢？很多MOS文档提到的方法是设置2个隐含参数：
_gc_affinity_time=0 _gc_undo_affinity=FALSE
不幸的是，这2个参数是静态参数，也就是说必须要重启实例才能生效。
实际上可以设置另外2个动态的隐含参数，来达到这个目的。按下面的值设置这2个参数之后，不能完全算是禁止/关闭了DRM，而是从”事实上“关闭了DRM。
甚至可以将以上2个参数值设置得更大。这2个参数是立即生效的，在所有的节点上设置这2个参数之后，系统不再进行DRM，经常一段时间的观察，本文描述的性能问题也不再出现。
11g
_gc_policy_limit=1500 _gc_policy_time=0
参考：
http://www.dbaleet.org/the_evolution_of_oracle_rac_drm_season_1/
