DRM分析及案例讲解 - 数据库编程

P 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 receive

DRM分析及案例讲解(二)