近期比较有空闲时间，记录下之前的一个DRM导致insert插入语句执行时间波动的案例。
某用户反映OLTP系统某业务正常只需要ms级可以完成，偶尔出现需要5-10s左右才能完成，导致后续关联业务执行错误的情况，近期此问题出现频率每天有几次，需要介入调查出现此问题的原因。通过与客户沟通了解到此业务只是简单的插入数据的SQL语句，此业务模块有日志记录完成所需时间，客户通过后续业务模块报错信息找到此业务，进而找到的SQL语句。
对于oracle数据库来说，一般出现sql执行时间的波动，通常会考虑sql执行计划是否发生了变化、sql执行时对应的等待事件有哪些、数据库系统性能情况(如当时DB出现严重的性能问题)、主机负载情况(如CPU使用率很高或内存出现严重swap换页或IO使用率基本在99% 100%或者集群环境私网流量异常高等)，一般通过这几个大的层面的排查，是可以定位到sql执行时间出现波动的原因的，再针对性的进行解决即可。下面回顾下当时的处理过程及思路：
1.查看问题发生时的AWR报告及相关OS监控的信息
此部分信息比较容易获得，也比较直观，本case数据库及主机性能当时未发现明显异常，如下使用出现问题的2016/09/19 11-12点的AWR。仅有awr,os监控截图没记录：
DB Name | DB Id | Instance | Inst num | Startup Time | Release | RAC |
TEST | 1439020164 | TEST1 | 1 | 25-Mar-16 09:03 | 11.2.0.4.0 | YES |
Host Name | Platform | CPUs | Cores | Sockets | Memory (GB) |
TEST1 | HP-UX IA (64-bit) | 32 | 32 | 4 | 63.83 |
| Snap Id | Snap Time | Sessions | Cursors/Session | Instances |
Begin Snap: | 6939 | 19-Sep-16 11:00:34 | 338 | 1.5 | 2 |
End Snap: | 6940 | 19-Sep-16 12:00:08 | 335 | 1.6 | 2 |
Elapsed: |
| 59.56 (mins) |
|
|
|
DB Time: |
| 67.99 (mins) |
|
|
|
Report Summary
Load Profile
| Per Second | Per Transaction | Per Exec | Per Call |
DB Time(s): | 1.1 | 0.1 | 0.00 | 0.00 |
DB CPU(s): | 1.0 | 0.1 | 0.00 | 0.00 |
Redo size (bytes): | 238,686.8 | 18,710.3 |
|
|
Logical read (blocks): | 48,451.2 | 3,798.0 |
|
|
Block changes: | 688.4 | 54.0 |
|
|
Physical read (blocks): | 111.1 | 8.7 |
|
|
Physical write (blocks): | 48.7 | 3.8 |
|
|
Read IO requests: | 111.1 | 8.7 |
|
|
Write IO requests: | 25.3 | 2.0 |
|
|
Read IO (MB): | 0.9 | 0.1 |
|
|
Write IO (MB): | 0.4 | 0.0 |
|
|
Global Cache blocks received: | 93.3 | 7.3 |
|
|
Global Cache blocks served: | 26.8 | 2.1 |
|
|
User calls: | 1,590.2 | 124.7 |
|
|
Parses (SQL): | 592.4 | 46.4 |
|
|
Hard parses (SQL): | 1.2 | 0.1 |
|
|
SQL Work Area (MB): | 8.5 | 0.7 |
|
|
Logons: | 2.9 | 0.2 |
|
|
Executes (SQL): | 509.4 | 39.9 |
|
|
Rollbacks: | 2.1 | 0.2 |
|
|
Transactions: | 12.8 |
|
|
|
Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: | 100.00 | Redo NoWait %: | 100.00 |
Buffer Hit %: | 99.78 | In-memory Sort %: | 100.00 |
Library Hit %: | 99.25 | Soft Parse %: | 99.81 |
Execute to Parse %: | -16.28 | Latch Hit %: | 99.81 |
Parse CPU to Parse Elapsd %: | 32.17 | % Non-Parse CPU: | 97.88 |
2.排查sql的执行计划变动情况及对应的等待事件信息
可以通过在内存中、awr中的信息，来查看SQL的历史执行计划变动情况(某些执行频率不够高或执行时间较快的SQL可能没有被AWR采集到)。本案例中我们是可以通过业务模块定位到SQL语句，进而在数据库层面查询此SQL的相关信息。我们通过SQL文本，可以从V$SQL中查出SQL_ID(AWR中如果此SQL被采集了也可以从AWR执行中查看)。此处我们查出的SQL_ID是3fyprqv8g369d。可以使用如下相应SQL语句从内存、AWR中查询ASH基表数据来确认此SQL的执行计划及等待事件：
根据SQL文本查SQL_ID：
col sql_text for a100
SELECT SQL_ID,SQL_TEXT,hash_value FROM V$SQL WHERE SQL_TEXT LIKE '%select * from DCDATA%';
根据SQL_ID从内存shared_pool中查出是否有多个执行计划的语句：
set linesize 300
col sql_text for a100
select SQL_ID,hash_value,child_number,SQL_TEXT from v$sql where sql_text like '%select count(*) from t1 where%';
根据SQL_ID从AWR中查SQL的执行计划波动情况：
set linesize 150
set pagesize 1000
col SQL_PROFILE for a15
col BEGIN_INTERVAL_TIME for a25
select a.INSTANCE_NUMBER,a.snap_id,a.sql_id,a.plan_hash_value,a.VERSION_COUNT,a.BIND_DATA,a,EXECUTIONS_TOTAL,a.SQL_PROFILE,b.begin_interval_time
from dba_hist_sqlstat a, dba_hist_snapshot b
where a.sql_id ='cdwjdd67x27mh'
and a.snap_id = b.snap_id
order by instance_number,begin_interval_time desc;
根据SQL_ID从AWR中查ASH基表获得指定时间的相应SQL对应的等待事件：
select distinct to_char(b.sample_time,'yyyymmdd hh24:mi:ss'),b.sql_exec_start,
b.session_id,b.session_type,b.user_id,b.sql_id,b.event,b.blocking_session,
b.module,b.program from dba_hist_active_sess_history b
where b.sample_time >= TO_DATE ('2013-06-28 15:40:00', 'yyyy-mm-dd hh24:mi:ss')
AND b.sample_time < TO_DATE ('2013-06-28 15:40:10', 'yyyy-mm-dd hh24:mi:ss')
AND b.sql_id='aaaaaaaaa';
本次问题SQL执行计划没有发生变化，但是SQL对应的等待事件有异常，如下图：
SQL ordered by Cluster Wait Time
- %Total - Cluster Time as a percentage of Total Cluster Wait Time
- %Clu - Cluster Time as a percentage of Elapsed Time
- %CPU - CPU Time as a percentage of Elapsed Time
- %IO - User I/O Time as a percentage of Elapsed Time
- Only SQL with Cluster Wait Time > .005 seconds is reported
- Total Cluster Wait Time (s): 108
- Captured SQL account for 95.9% of Total
Cluster Wait Time (s) | Executions | %Total | Elapsed Time(s) | %Clu | %CPU | %IO | SQL Id | SQL Module | SQL Text |
87.56 | 3 | 80.96 | 252.83 | 34.63 | 38.11 | 34.71 | 1vyvz28gjfh4y | AAAAAAAAAAAAA | SELECT LH.testAME, LH.CARRIERN... |
9.60 | 10,985 | 8.87 | 24.22 | 39.63 | 13.38 | 0.07 | 3fyprqv8g369d | AAAAAAAAAAAA | insert into testory (lotNam... |
2.18 | 12,874 | 2.01 | 3.94 | 55.24 | 44.43 | 0.02 | 1nwwqwc0qay94 | AAAAAAAAAAAAA | select * from testuct where pr... |
3.DRM问题的解决及DRM相关介绍
DRM是存在于RAC环境中的问题，10gR2以上，DRM(dynamic remastering)特性可以使PCM资源的主节点信息依据每个节点对资源的访问频率被动态修改；
DRM的过程涉及：1.LCK0进程负责维护数据库对象在每个实例的访问情况，并比较实例间访问数据库对象次数；如果发现满足DRM条件的数据库对象，则将此对象对应的信息-数据库块信息添加到DRM队列；对应参数-_gc_policy_minimum ，gc_affinity_ratio
2.在每次DRM时间点到达时，LMD进程检查DRM队列；如果有需要处理的DRM请求，开始对相应数据块信息以windows为单位进行迁移remaster；通过LMON进程、LMS进程完成对数据块信息的迁移remaster；
迁移过程可以细分为：
静默阶段quiesce, 此阶段LMON进程准备进行DRM操作，通知所有节点的LMS进程在结束对需要进行主节点信息迁移的数据块的当前操作后，不要再接收对这些块的新请求；
冻结阶段freeze, 所有节点的LMS进程在接收到LMON发送的消息后，完成对需要进行DRM操作的数据块的请求后，冻结这些数据块(DRM以window为单位，不是DRM队列中所有块被一次冻结)；此时如果用户进程需要操作对应的数据块时发生的等待事件为gcs drm freeze in enter server mode;
清除阶段cleanup, 将对应块在所有节点上的旧的节点信息清除
重建阶段rebulid, 所有实例的LMS进程将本地持有的对应数据块的锁信息发送给新的主节点，构建出新的主节点信息；
解冻阶段unfreeze, 结束阶段，之前被冻结的数据块已经完成主节点信息的迁移，之前锁定解除；用户进程可以开始访问这些数据块
了解到DRM特性的这些信息后，结合SQL语句的等待事件，简单来说我们可以认为是INSERT语句在执行过程中触发了DRM特性，此时DRM特性在改变数据块的主节点信息时会出现短暂的freeze冻结数据块的过程，因此引起sql出现间歇性的执行变慢，从而影响了业务的正常运行；
在10g/11g RAC实施时，一般我们建议用户关闭DRM特性，或者将DRM特性涉及的参数(如11gR2_gc_policy_minimum参数--每分钟数据库对象被访问的次数达到此值才达到DRM的阀值)设置为一个比较大的值，从而避免触发DRM特性及其引起的SQL性能波动。
不停机关闭DRM特性的方法是将触发DRM特性的参数阀值提高：_gc_policy_minimum (10gR2:_gc_affinity_minimum)，即每分钟数据库对象被访问的次数达到此值才达到DRM的阀值；10gR2--默认6000次，11gR2--默认1500次
10g:
alter system set "_gc_affinity_limit"=250;
alter system set "_gc_affinity_minimum"=10485760;
11g:
alter system set "_gc_policy_minimum"=90000000;
11G彻底关闭DRM参数：
关闭DRM
alter system set "_gc_policy_time"=0 scope=spfile;
alter system set "_gc_read_mostly_locking"=false scope=spfile;
本次的问题是在11g rac上发生的，通过设置_gc_policy_minimum为一个较高的值后，后续没有再出现因DRM问题导致的SQL性能波动
