Troubleshooting high “gc current grant 2-way” and “gc cr grant 2-way” 案例(二)

很久以前遇到过一个案例，也是一套RAC环境出现了非常高的GC cr/current grant 2-way 等待事件， 《Performance tuning ‘gc cr&current grant 2-way’ event (当主机扩容cpu后)》 当是这个案例是因为同一cluster的两个实例主机不同的CPU个数导致出现了不同的LMS进程数，负载能力不均衡导致， 这次要分享的案例是另个一种特殊情况。

来自SMARTDBOPS

持续较高的GC类等待，

NODE1

NODE2

Top 5 Timed Foreground Events

如果从节点1看会认为是并发争用enq index/row lock contention；还有gc cr/current grant 2-way, 该event表示Block is not in any cache，

Permission granted to read from the disk.

在诊断RAC问题时有几个黄金规则：

1. 谨防被TOP Event所欺骗

在RAC环境中有可能根本问题在另一个节点中隐藏，基于不会显示在top 5 event中, 被影响的等待事件可能比根本原因等待事件本身还要高， 实例的性能错综复杂， 很可能一个节点的后台进程出现问题（如LMS），而影响了其它所有节点出现Application class等待事件。

gc buffer busy xx 等待事件是RAC性能分析根本问题之前的主要证状， 简单认为在等待一个BLOCK的BL lock请求, 其它所有进程在等待这个BLOCK的BL lock可用其间的时间消耗都会记入gc buffer busy xx 等待事件中.

ASH和dump block trace 文件可以定位GC BUFFER BUSY等待， 主要是识别对象，对象类型，块类型信息

2. 消除基础架构环境问题

Gc cr grants 2-way  如果BLOCK没有在任何实例的Buffer cache中，时间会记入这个等待事件中，前台进程发送一个请求给远程LMS,   远程的LMS回复‘read from disk’. 出现gc 2-way 3-way这类意为着高并发出现的拥挤产生的等待，一个block和message传输的最小时间通常<2ms, (Exadata<0.5ms).  需要查看 AWR中的wait event histogram 查看2/3- way事件不同时间段的占比。排除网络问题

3. 识别问题实例

SELECT INSTANCE ||'->’ || inst_id transfer,
class, cr_block cr_blk,
Trunc(cr_block_time / cr_block / 1000, 2) avg_Cr,
current_block cur_blk,
Trunc(current_block_time / current_block / 1000, 2) avg_cur
FROM gv$instance_cache_transfer
WHERE cr_block > 0 AND current_block > 0
ORDER BY INSTANCE, inst_id, class
/

4. 检查发送端的性能指标，不只是接收端

发送端

gc cr block receive time=

Time to send message to a remote LMS process by FG

+ Time taken by LMS to build block (statistics: gc cr block build time)

+ LMS wait for LGWR latency ( statistics: gc cr block flush time)

+ LMS send time (Statistics: gc cr block send time)

+ Wire latency.

5. 用柱状图去识别异常情况，而不只是平均值

AWR中的wait event histogram

案例分析

接着分析一开始AAS 上显示GC wait问题案例，这是一个11.2.0.3 2-NODES  RAC  ON HPUX 11.31的数据库，

# instance 1

Global Cache Load Profile

Global Cache Efficiency Percentages (Target local+remote 100%)

Global Cache and Enqueue Services – Workload Characteristics

Global Cache and Enqueue Services – Messaging Statistics

TIPS:

AWR中的 Average message queue time 数据来自 (G)V$GES_STATISTICS. 该值是把indirect message到message队列和发送它所需的时间(GCS/GES communication layer). 我们需要查看KSXP消息统计时间，以确定IPC层中是否存在问题。 IPC时间通常<1ms，您可以查询X$KSXPCLIENT以获取更多数据， 该值很高时也有可能在这段时间内CPU非常繁忙（100％CPU）或者 interconnect达到顶峰, 这点需要结合OSW确认。

# instance 2

Global Cache Load Profile

Global Cache Efficiency Percentages (Target local+remote 100%)

Global Cache and Enqueue Services – Workload Characteristics

Global Cache and Enqueue Services – Messaging Statistics

Tips:

Avg global cache cr block receive time (ms) 从请求实例发送消息到mastering instance花费的时间。这个时间包括在holding instance生成数据块一致性读映像的时间。CR数据块获取耗费的时间不应该大于15ms。

Avg global cache current block receive time (ms): 从请求实例发送消息到mastering instance（2-way get）和一些到holding instance (3-way get)花费的时间。这个时间包括holding instance日志刷新花费的时间。Current Block获取耗费的时间不大于30ms.

Avg message sent queue time on ksxp (ms)对端IPC层确认收到的消息并返回ACK所花费的时间，通常是个很小的毫秒值，直接反应了网络延迟，一般小于1ms, The send time is measured when a block is handed to the IPC layer to be sent. The requests are queued in a completion queue, and the send time is measured from when a block is handed off to the IPC layer until the system call returns a completion, i.e. a status indicating that the send request has been successfully passed on to the network and control returns to the cache layer.

如果该值比较大，可能是CLUSTER INTERCONNECT和LMS进程出现了问题。

做ipc诊断：

oradebug setmypid

oradebug ipc

1）如果网络配置没有问题，可以检查一下TCP 和UDP的buffer是否不足

root#netstat -s | grep overflow 值为了0一般情况下。

root#netstat -i

2) 查看负载ps aux | grep lms

查看是否是有某些表产生了过多的global cr request

select  STATISTIC_NAME stat,
            OWNER,
            OBJECT_NAME obj,
            sum(value) val
       from v$segment_statistics
      where STATISTIC_NAME like 'global%'
        and value > 10000
      group by  STATISTIC_NAME,OWNER,OBJECT_NAME
      order by val desc;

2、查看一段时间内，CR的值是否很大。

select CR_REQUESTS cr,
          CURRENT_REQUESTS cur,
          DATA_REQUESTS data,
         UNDO_REQUESTS undo,
          TX_REQUESTS tx
     from v$cr_block_server;

确认问题节点

Node:

RAC环境中， 慢的节点会导致其他节点出现gc性能问题， 根据这个逻辑，确认是节点1 出了问题。

#查看当时的LMS进程CPU使用

# node1
oracle@qdty1:/home/oracle:11G> ps -efl|head -n 1;ps -efl|grep lms
  F S      UID   PID  PPID  C PRI NI             ADDR   SZ            WCHAN    STIME TTY       TIME COMD
1401 S   oracle  5117     1 237 178 20 e000001c934ba340 94816 e000000792a7f050  Jul 13  ?        15776:29 ora_lms1_tyjc1
1401 S     grid 23810     1  0 178 20 e000001c9de0e040 90895 e000000792a7f1d0  Jan 25  ?        1550:30 asm_lms0_+ASM1
1401 R   oracle  5119     1 254 178 20 e000001ce7c1b9c0 94816                -  Jul 13  ?        16214:17 ora_lms2_tyjc1
401 S   oracle  9366  7730  0 154 20 e000001cdb304c40   30 e000000da0da6472 10:50:38 pts/4     0:00 grep lms
1401 R   oracle  5115     1 252 178 20 e000001cf7042a00 94752                -  Jul 13  ?        16329:36 ora_lms0_tyjc1

# node 2
oracle@qdty2:/home/oracle:11G> ps -efl|head -n 1;ps -efl|grep lms|grep -v grep
  F S      UID   PID  PPID  C PRI NI             ADDR   SZ            WCHAN    STIME TTY       TIME COMD
1401 S     grid 12516     1  0 178 20 e000001b43146400 90854 e000000792d71348  Jan 25  ?        1461:04 asm_lms0_+ASM2
1401 S   oracle  6446     1 24 178 20 e000001ef09b0d00 95666 e000000792d710d0  Jul 13  ?        16447:18 ora_lms2_tyjc2
1401 S   oracle  6444     1 30 178 20 e000001ebe6c7d00 95666 e000000792d71248  Jul 13  ?        17583:22 ora_lms1_tyjc2
1401 S   oracle  6442     1 43 178 20 e000001e7bc97c80 95666 e000000792d71240  Jul 13  ?        17764:57 ora_lms0_tyjc2

Note:

当前为HPUX 11.31平台，节点1所以PS显示的C[PU] 列会超过100%现象， 但也表明了当前的CPU是非常繁忙。节点2是正常的。

# node1

Instance Activity Stats

# node 2

Instance Activity Stats

如果不是应用 SQL 和网络问题，那为什么LMS会占用那么高的cpu呢？ 去MOS中搜，不难发现，又命中了一个bug 14672057 .

原因是因为从11.2.0.2版本开始为了解决之前的bug 9569316,而引入了_max_cr_rollbacks参数， 该参数默认为0。 表示最大cr block rolback blocks.没有找到过多的关于该参数的解释。如果当出现花费大量的时间在undo cr block生成时，把该参数调整为非0值，会启用light work 规则，有助于减少lms进程压力。 该bug只影响11.2.0.2和11.2.0.3, 解决解决方法可以动态的修改 “_max_cr_rollbacks”参数解决，所以没有再提供one-off patch, 该bug 在11.2.0.4版本已修复， 当执行完如下修改后，GC 等待和enq 瞬间消失，恢复了正常状态。所以问题不是节点1 top event中表现的index split问题。

SQL> alter system set "_max_cr_rollbacks"=200;
System altered.

# 修改后LMS 进程 node1

oracle@qdty1:/home/oracle:11G> ps -efl|head -n 1;ps -efl|grep lms|grep -v grep
  F S      UID   PID  PPID  C PRI NI             ADDR   SZ            WCHAN    STIME TTY       TIME COMD
1401 S   oracle  5117     1 55 178 20 e000001c934ba340 94816 e000000792a7f0d0  Jul 13  ?        15778:04 ora_lms1_tyjc1
1401 S     grid 23810     1  0 178 20 e000001c9de0e040 90895 e000000792a7f350  Jan 25  ?        1550:30 asm_lms0_+ASM1
1401 S   oracle  5119     1 76 178 20 e000001ce7c1b9c0 94816 e000000792a7f1c8  Jul 13  ?        16216:40 ora_lms2_tyjc1
1401 S   oracle  5115     1 80 178 20 e000001cf7042a00 94752 e000000792a7f3c0  Jul 13  ?        16331:29 ora_lms0_tyjc1