1.分析hanganalyze日志:

Chains most likely to have caused the hang:《《《最终阻塞源都是由于resmgr:cpu quantum引起。

[a] Chain 1 Signature: 'resmgr:cpu quantum'<='buffer busy waits'<='buffer busy waits'<='enq: TX - index contention'

Chain 1 Signature Hash: 0xe7466825

[b] Chain 2 Signature: 'resmgr:cpu quantum'<='buffer busy waits'

Chain 2 Signature Hash: 0x23972dee

[c] Chain 3 Signature: 'resmgr:cpu quantum'<='buffer busy waits'

Chain 3 Signature Hash: 0x23972dee

====================================================================

Chain 1:

-------------------------------------------------------------------------------

Oracle session identified by:

{

instance: 1 (jfdb.jfdb1)

os id: 78941

process id: 1240, oracle@XXX-JF-DB03

session id: 22 <<<< session 22

session serial #: 32445

}

is waiting for 'enq: TX - index contention' with wait info:

{

p1: 'name|mode'=0x54580004

p2: 'usn<<16 | slot'=0x1cb0015

p3: 'sequence'=0xf3fa7

time in wait: 0.122389 sec

timeout after: never

wait id: 199367

blocking: 0 sessions

wait history:

* time between current wait and wait #1: 0.000318 sec

………

}

and is blocked by <<<<被阻塞

=> Oracle session identified by:

{

instance: 1 (jfdb.jfdb1)

os id: 1349

process id: 2756, oracle@XXX-JF-DB03

session id: 3320 <<<<session 3320

session serial #: 3849

}

which is waiting for ‘buffer busy waits’ with wait info:

{

p1: ‘file#’=0x8c

p2: ‘block#’=0x286540

p3: ‘class#’=0x1

time in wait: 0.218850 sec

timeout after: never

wait id: 51286

blocking: 58 sessions

wait history:

……….

}

and is blocked by <<<<被阻塞

=> Oracle session identified by:

{

instance: 1 (jfdb.jfdb1)

os id: 3182

process id: 2975, oracle@XXX-JF-DB03

session id: 5658 <<<session 5658

session serial #: 181

}

which is waiting for 'buffer busy waits' with wait info:

{

p1: 'file#'=0x8c

p2: 'block#'=0x285b1f

p3: 'class#'=0x1

time in wait: 0.219271 sec

timeout after: never

wait id: 38737

blocking: 63 sessions

wait history:

。。。。。。

}

and is blocked by<<<<被阻塞

=> Oracle session identified by:

{

instance: 1 (jfdb.jfdb1)

os id: 27602

process id: 2384, oracle@XXX-JF-DB03

session id: 334 《《《session 334

session serial #: 757

}

which is waiting for 'resmgr:cpu quantum' with wait info:

{

p1: 'location'=0x2

p2: 'consumer group id'=0x3259

p3: ' '=0x0

time in wait: 0.040860 sec

timeout after: never

wait id: 95941

blocking: 114 sessions

wait history:

。。。。。。。

}

Chain 1 Signature: 'resmgr:cpu quantum'<='buffer busy waits'<='buffer busy waits'<='enq: TX - index contention'

Chain 1 Signature Hash: 0xe7466825

对以上hanganalyze 会话进行整理:

session : 334

同时阻塞114个会话

阻塞了》

session : 5658

同时阻塞63个会话

阻塞了》

session : 3320

同时阻塞58个会话

阻塞了》

session id: 22

resmgr:cpu quantum

buffer busy waits

buffer busy waits

enq: TX - index contention

从以上hanganalyze 日志可以看出,enq: TX - index contention和buffer busy waits的等待堆积最终的源头是由于resmgr:cpu quantum等待引起,并且这些等待同时又阻塞了多个其他会话。

2.关于resmgr:cpu quantum等待事件解释:

以下从文档 ID 2097889.1可以获得该等待事件的说明:

《WAITEVENT: "resmgr:cpu quantum" Reference Note (文档 ID 2097889.1)》

· Event 'resmgr: cpu quantum' is a standard event used by resource manager to control the allocation of CPU to processes. When a session waits for 'resmgr: cpu quantum' that session is waiting to be allocated a quantum of CPU time.

等待事件'resmgr:cpu quantum'是资源管理器用来控制CPU分配给进程的标准事件。 当会话等待'resmgr:cpu quantum'时,会话正在等待分配一个CPU时间额度。

This wait occurs when the resource manager is enabled and is throttling CPU consumption. To reduce the occurrence of this wait event, increase the CPU allocation for the session's current consumer group.

当启用资源管理器并限制CPU消耗时会发生此等待。 为了减少此等待事件的发生,请增加会话当前消费组的CPU分配。

该等待事件存在的意义是当resource manager控制CPU调度时,需要控制对应进程暂时不使用CPU而进程到内部运行队列中,以保证该进程对应的consumer group(消费组)没有消耗比指定resource manager指令更多的CPU。此时session就会以”resmgr:cpu quantum”的名义等待在内部运行队列中,wait一段时间以减少对CPU的争用,直到再次获得CPU时该等待事件结束。

3.分析为何会出现资源管理:

《11g: Scheduler Maintenance Tasks or Autotasks (文档 ID 756734.1)》

根据以上说明,可以发现在Oracle 11g中,在默认情况下会启用自动化维护任务,数据库会在工作日的每晚22:00到第二天的凌晨2:00,周末的凌晨6:00到第二天的凌晨2:00,自动开启自动化维护窗口对数据库进行诸如优化器的统计信息收集、自动SQL的优化。在此期间数据库中便由resource manager来控制CPU的调度,启用资源管理计划主要是为了保障维护窗口内的任务有充分的资源进行使用。

从告警日志中可以看出,4月1日 6:00 启动自动化维护窗口的信息:

Current log# 6 seq# 23750 mem# 0: +DG_DATA/jfdb/onlinelog/group_6.279.909112437

Sun Apr 01 05:51:29 2018

Archived Log entry 46019 added for thread 1 sequence 23749 ID 0x4d5ab97e dest 1:

Sun Apr 01 06:00:00 2018 《《《《6点整开启自动化维护窗口

Setting Resource Manager plan SCHEDULER[0x32DF]:DEFAULT_MAINTENANCE_PLAN via scheduler window

Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter

Sun Apr 01 06:00:00 2018

Starting background process VKRM《《《启动相应的进程

Sun Apr 01 06:00:00 2018

VKRM started with pid=361, OS id=48797

那么资源管理计划是如何限制资源的呢? 需要了解RESOURCE MANAGER的机制。

4.关于RESOURCE MANAGER的机制: Oracle 开启自动维护任务是使用的资源管理计划是DEFAULT_MAINTENANCE_PLAN,这个资源管理计划控制CPU方法是使用是默认EMPHASIS法,这种方法是多级计划,它以百分比形式指定CPU如何在使用者组之间分布。CPU 占用率的分配级别为从1到8,级别1的优先级最高,将CPU资源在给定级别按指定的百分比分配,把给定级别上没有使用的使用者资源可供下一级别的使用者组使用。在当前数据库中DEFAULT_MAINTENANCE_PLAN的资源管理计划只用到了2个级别。 在oracle 11g中,实际上CPU_P*的参数已经是失效了,而应该是MGMT_P*的参数,所以我们之前参考的是旧的参数,但实际是同样效果。



以下当前资源管理计划所使用MGMT_P*的情况:

在这个资源管理计划DEFAULT_MAINTENANCE_PLAN中,主要存在四个CPU使用组:1.ORA$AUTOTASK_SUB_PLAN和ORA$DIAGNOSTICS 实际是用于自动维护任务的。

2.SYS_GROUP是SYS和SYSTEM用户的初始使用者组,组中的会话都是sys或system账号创建的会话。

3.OTHER_GROUPS用于在活动资源计划之外的所有使用者组拥有的会话,即使其他业务用户及个人用户的会话。

资源管理计划中MGMT_P*设置的百分比值并不是一个固定限制的值是一个在资源紧张时的限制值,但在资源空闲时有可能超出这个值。

例如,在DEFAULT_MAINTENANCE_PLAN中ORA$AUTOTASK_SUB_PLAN分配了25%,但此时如果数据库比较空闲,SYS_GROUP和OTHER_GROUPS等其他组没有什么资源占用,ORA$AUTOTASK_SUB_PLAN则可能增长到50%,但如果此时资源比较紧张OTHER_GROUPS且已经占用50%以上,ORA$AUTOTASK_SUB_PLAN则需下降到25%。

因此,在这个资源管理计划中,ORA$AUTOTASK_SUB_PLAN和ORA$DIAGNOSTICS设了MAX_UTILIZATION_LIMIT最大使用限制为90。这样即使cpu是空闲的,该组或计划也不能分配90%以上的cpu资源。

对于资源计划而言,为某个消耗组或者子计划分配的份额若没有使用,就可以被其他的消耗组或子计划使用。

再次分析这个资源管理计划DEFAULT_MAINTENANCE_PLAN,SYS_GROUP优先级最高在级别1,分配75%,在当时的情况,sys或system账号创建的会话占用的CPU资源并不一定达到了75%,其剩余的资源则分配给级别2。在级别2中ORA$AUTOTASK_SUB_PLAN和ORA$DIAGNOSTICS的自动维护任务在资源紧张的情况下用了30%,而其余70%则分配给了OTHER_GROUPS的业务会话。

资源管理计划中MGMT_P*设置的百分比值可以理解为依据CPU个数的百分比来计算,这CPU个数则来自CPU_COUNT参数设置的值。


5.发现CPU_COUNT参数异常:

在排查的过程中,发现当前数据库的CPU_COUNT仅设置为8,而实际上这台主机有32个CPU 核数,64个逻辑CPU。

CPU_COUNT:

实际CPU Cores及逻辑cpu个数:


在oracle 官方文档中已说明CPU_COUNT是依据CPU cores 的数量来指定的,并且也说明很多组件包括Resource Manager都是依靠这个cpu个数的。

这说明了,在资源管理计划开启时,受CPU_COUNT 为8的限制,数据库只能使用到了主机 32个CPU 核数中的8个,即为1/4。

分析故障期间主机的CPU 使用情况,发现在资源管理计划开启后,CPU使用率逐渐升高,但始终不超过25%,直到9:30后手工禁用了资源管理计划,CPU资源被放开,CPU使用率则立即上升到45%左右。



因此,可以看出,资源管理计划打开期间,由于CPU_COUNT的设置过小,导致了数据库只能最多使用到了主机25%的CPU资源,并且受以上资源管理计划控制CPU机制的影响,业务会话可能只能用到这25% CPU资源中的70%,这就是导致数据库在4月1日高峰期时数据库达到了CPU了资源瓶颈的原因。