本文详细介绍了在客户现场一次因为resmgr:cpu quantum等待事件而导致CPU大量被消耗，在确认原因并将导致CPU冲高的Resource Manager资源管理器特性关闭后，后续导致了后台alert日志中大量的自动定时JOB没有执行并报错：
| ORA-12012: error on auto execute of job "SYS"."ORA$AT_OS_OPT_SY_255" ORA-29373: resource manager is not on |
客户操作系统：RHEL6
数据库版本：11.2.0.3.11
以下我们将描述并说明Resource Manager资源管理器以及后续的解决处理排查等一系列的过程。
概念普及
Resource Manager资源管理器是oracle在10g推出，并在11g中得以完善的一项功能。资源管理器通过控制数据库内部的执行调度任务控制资源在各个会话之间的分配。通过控制所要运行的会话以及会话运行的时间长度，数据库资源管理器可以确保资源利用及分配和我们计划中的配置一样，有效利用资源，当然，Resource Manager主要控制资源包括如下几块：
Oracle会话的CPU使用率
并行度
SQL语句操作执行时间
会话空闲时间
活跃会话(session)数
UNDO管理
当然，在真正的生产环境中，Resource Manager还没有被大量的使用起来，但是在11g（11.1.0.6 to 11.1.0.7 and 11gR2）开始，oracle默认开启Resource Manager计划，如下显示oracle后台日志：
| Setting Resource Manager plan SCHEDULER[0x51B5]:DEFAULT_MAINTENANCE_PLAN via scheduler window Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter Thu Feb 05 22:00:03 2009 Begin automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK" Thu Feb 05 22:00:39 2009 End automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK" |
如下显示在10g和11g中，oracle对Resource Manager采用的不同策略：
| Subject |
10G |
11G |
| Maintenance Window |
2 windows, WEEK and WEEKEND |
Each day has its own window |
| Resource manager |
Not enabled per default |
Default resource plan specified |
故障详解
客户新系统上线，在上线后，发现数据库出现大量的等待事件：resmgr:cpu quantum，这个等待事件是在11g中一个比较常见的等待事件，消耗大量CPU 系统性能变差，在和客户沟通后，决定对该特性进行关闭，以下为关闭该特性步骤：
| ALTER SYSTEM SET “_resource_manager_always_on”=FALSE SCOPE=SPFILE SID=‘*‘;
#1,Change the active windows to use the null resource manager plan (or other nonrestrictive plan) using:
execute dbms_scheduler.set_attribute(‘WEEKNIGHT_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘WEEKEND_WINDOW‘,‘RESOURCE_PLAN‘,‘‘);
#2,Since in 11g there are more Maintenance Windows, we should add them too:
execute dbms_scheduler.set_attribute(‘SATURDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘SUNDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘MONDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘TUESDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘WEDNESDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘THURSDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘FRIDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘);
#3. Then, for each window_name (WINDOW_NAME from DBA_SCHEDULER_WINDOWS), run:
execute dbms_scheduler.set_attribute(‘<window name>‘,‘RESOURCE_PLAN‘,‘‘); |
以上关掉Resource Manager后效果确实很明显，系统运行稳定，CPU处于正常水平。但是运行一段时间后后台开始报错：
| ORA-12012: error on auto execute of job "SYS"."ORA$AT_SQ_SQL_SW_186" ORA-29373: resource manager is not on |
从报错上看，似乎和Resource Manager有一定的关系，从JOB的命名来看，这个JOB是"SQL Tuning Advisor Job", 用于诊断和监控高负载的SQL， 并为ADDM提供SQL优化建议的JOB，第一次，我们对该报错的JOB，也就是SQL Tuning Advisor进行了关闭，关闭过程如下：
| exec DBMS_AUTO_TASK_ADMIN.DISABLE(‘SQL TUNING ADVISOR‘,NULL, NULL); |
关闭完后又有相应新的JOB开始报错：
| ORA-12012: error on auto execute of job "SYS"."ORA$AT_OS_OPT_SY_255" ORA-29373: resource manager is not on |
我们检查后台最近的JOB执行情况：
| SQL> select client_name,window_name,job_name,job_status from dba_autotask_job_history ;
CLIENT_NAME WINDOW_NAME JOB_NAME JOB_STATUS ----------------------------- ------------------------------------- -------- auto optimizer stats collection WEDNESDAY_WINDOW ORA$AT_OS_OPT_SY_102 FAILED auto optimizer stats collection FRIDAY_WINDOW ORA$AT_OS_OPT_SY_105 FAILED auto optimizer stats collection TUESDAY_WINDOW ORA$AT_OS_OPT_SY_99 FAILED auto optimizer stats collection MONDAY_WINDOW ORA$AT_OS_OPT_SY_96 FAILED |
在以上的脚本输出中，我们发现大量的后台JOB报错，而以上JOB报错从告警日志上看，基本都是由于Resource Manager关闭造成。但是我们知道，Resource Manager的开启关闭应该不至于影响JOB的正常调度，而且在相同的数据库版本下，我们在AIX上却没有发现问题，而在检查过程中，我们发现，虽然我们已经关闭了Resource Manager，但是相关的DBRM进程却依旧存在，ORACLE的DBRM进程进程即为Resource Manager的管理进程，在某种情况下，关闭了Resource Manager却发现该进程依旧存在，这本身就存在一定的问题。这从一定程度上给予我们一定的怀疑方向，可能存在resource并没有完全关闭，而且从详细的trace文件中的从call stack trace里来看， 当前进程也没有没有关于resource manager的函数调用，而是一直在向另外一个进程post message。
所以，我们怀疑错误很有可能是由于DBRM没有正常关闭造成。
| #ps -ef|grep dbrm oracle 34920 1 0 Apr18 ? 00:00:59 ora_dbrm_nfdb1 |
在对问题进行了详细的跟踪及分析后，我们向ORACLE提交了SR，ORACLE反馈给我们第二个隐含参数:_resource_manager_always_on设置为FALSE
我们尝试对该参数进行设置，并重启了数据库生效该参数后，DBRM进程消失：
| # ps -ef | grep dbrm root 4650 3647 0 21:58 pts/2 00:00:00 grep dbrm |
且相关的JOB执行正常。为了确认问题，我们分别进行了3个实验,分别为：
1. 设置“_resource_manager_always_on隐含参数，关闭resource manager windows 调用计划
2. 删除隐含参数，只设置resource manager windows 调用计划
3. 添加2个隐含参数，关闭resource manager windows 调用计划
关闭数据库，调整时间，设置_resource_manager_always_on隐含参数，关闭windows 计划
| 关闭数据库： SQL> shutdown immediate Database closed. Database dismounted. ORACLE instance shut down.
调整时间： [root@rhel6 ~]# date -s 2014/05/14 [root@rhel6 ~]# date -s 21:57:00 [root@rhel6 ~]# clock -w [root@rhel6 ~]# date Wed May 14 21:57:35 CST 2014
添加隐含参数，启动至open： SQL> ALTER SYSTEM SET "_resource_manager_always_on"=FALSE SCOPE=SPFILE; SQL> startup force（测试环境，直接force启动，生产环境勿如此操作）
设置resource manager plan： execute dbms_scheduler.set_attribute(‘SATURDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘SUNDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘MONDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘TUESDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘WEDNESDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘THURSDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); execute dbms_scheduler.set_attribute(‘FRIDAY_WINDOW‘,‘RESOURCE_PLAN‘,‘‘); |
我们观察22点的alert信息，确实开始报错：
| Wed May 14 22:00:03 2014 Errors in file /oracle/ora11g/base/diag/rdbms/ora11g/ora11g/trace/ora11g_j003_4452.trc: ORA-12012: error on auto execute of job "SYS"."ORA$AT_OS_OPT_SY_27" ORA-29373: resource manager is not on Wed May 14 22:00:03 2014 Errors in file /oracle/ora11g/base/diag/rdbms/ora11g/ora11g/trace/ora11g_j004_4454.trc: ORA-12012: error on auto execute of job "SYS"."ORA$AT_SA_SPC_SY_28" ORA-29373: resource manager is not on Wed May 14 22:00:03 2014 Errors in file /oracle/ora11g/base/diag/rdbms/ora11g/ora11g/trace/ora11g_j005_4456.trc: ORA-12012: error on auto execute of job "SYS"."ORA$AT_SQ_SQL_SW_29" ORA-29373: resource manager is not on Wed May 14 22:00:04 2014 XDB installed. XDB initialized. |
检查DBRM进程已经存在：
| [root@rhel6 ~]# ps -ef | grep dbrm ora11g 4346 1 0 21:57 ? 00:00:00 ora_dbrm_ora11g
|
检查后台JOB执行记录视图：
| SQL> select CLIENT_NAME,WINDOW_NAME,JOB_NAME,JOB_STATUS,JOB_START_TIME from DBA_AUTOTASK_JOB_HISTORY where CLIENT_NAME=‘auto optimizer stats collection‘ order by JOB_START_TIME desc;
CLIENT_NAME WINDOW_NAME JOB_NAME JOB_STATUS JOB_START_TIME ----------------------------------- ------------------------------ ------------------------------ ------------------------------ ---------------------------------------- auto optimizer stats collection WEDNESDAY_WINDOW ORA$AT_OS_OPT_SY_27 FAILED 14-MAY-14 10.00.03.233570 PM PRC |
模拟过程与当前环境产生效果一致
接下来我们进行第二个模拟：
关闭数据库，调整时间，去除隐含参数，关闭windows 计划
| 关闭数据库： SQL> shutdown immediate Database closed. Database dismounted. ORACLE instance shut down.
调整时间： [root@rhel6 ~]# date -s 2014/05/14 [root@rhel6 ~]# date -s 21:57:00 [root@rhel6 ~]# clock -w [root@rhel6 ~]# date Wed May 14 21:57:35 CST 2014
去除隐含参数，启动至open： 隐含参数去除采用create pfile from spfile; 删除spfile，编辑pfile文件，删除隐含参数，以pfile启动数据库
设置resource manager plan：（由于前面已经设置过，无需再设置） |
我们观察22点的alert信息，发现没有报错
| Tue May 13 22:00:03 2014 Begin automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK" End automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK" Tue May 13 22:00:05 2014 XDB installed. XDB initialized.
|
检查 DBRM进程：
| [root@rhel6 ~]# ps -ef | grep dbrm ora11g 3844 1 0 21:55 ? 00:00:00 ora_dbrm_ora11g |
说明：此时resource manager由于只是关闭了resource manager plan计划，没有真正关闭resource manager 因此该进程依旧存在。
检查后台JOB执行视图信息：
| SQL> select CLIENT_NAME,WINDOW_NAME,JOB_NAME,JOB_STATUS,JOB_START_TIME from DBA_AUTOTASK_JOB_HISTORY where CLIENT_NAME=‘auto optimizer stats collection‘ order by JOB_START_TIME desc;
CLIENT_NAME WINDOW_NAME JOB_NAME JOB_STATUS JOB_START_TIME ---------------------------------------- ------------------------------ ------------------------- -------------------- ---------------------------------------- auto optimizer stats collection TUESDAY_WINDOW ORA$AT_OS_OPT_SY_24 SUCCEEDED 13-MAY-14 10.00.02.102741 PM PRC |
说明在隐含参数除掉的情况下，JOB可以正常执行，后台没有报错。
模拟隐含参数及resource manager plan均存在的情况
关闭数据库，调整时间，添加隐含参数，关闭windows 计划
| 关闭数据库： SQL> shutdown immediate Database closed. Database dismounted. ORACLE instance shut down. 调整时间： [root@rhel6 ~]# date -s 2014/05/15 [root@rhel6 ~]# date -s 21:57:00 [root@rhel6 ~]# clock -w [root@rhel6 ~]# date Thu May 15 21:57:35 CST 2014 添加隐含参数，启动至open： SQL> alter system set "_resource_manager_always_off"=true scope=spfile; SQL> ALTER SYSTEM SET "_resource_manager_always_on"=FALSE SCOPE=SPFILE; SQL> startup force（测试环境，直接force启动，生产环境勿如此操作） 设置resource manager plan：（由于前面已经设置过，无需再设置） |
我们观察22点的alert信息，发现没有报错
| Thu May 15 22:00:03 2014 Begin automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK" Thu May 15 22:00:05 2014 XDB installed. XDB initialized. End automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK" |
检查 DBRM进程：
| [root@rhel6 ~]# ps -ef | grep dbrm root 4650 3647 0 21:58 pts/2 00:00:00 grep dbrm |
说明：此时DBRM进程消失
检查后台JOB执行视图信息：
| SQL> select CLIENT_NAME,WINDOW_NAME,JOB_NAME,JOB_STATUS,JOB_START_TIME from DBA_AUTOTASK_JOB_HISTORY where CLIENT_NAME=‘auto optimizer stats collection‘ order by JOB_START_TIME desc;
CLIENT_NAME WINDOW_NAME JOB_NAME JOB_STATUS JOB_START_TIME ----------------------------------- ------------------------------ ------------------------------ ------------------------------ ---------------------------------------- auto optimizer stats collection THURSDAY_WINDOW ORA$AT_OS_OPT_SY_30 SUCCEEDED 15-MAY-14 10.00.02.115232 PM PRC |
说明在隐含参数两个都添加的情况下，完全屏蔽resource manager的的情况下，JOB可以正常执行，后台没有报错。
技术结论
以上测试分析结果证明，后台报错JOB执行失败原因应该是DBRM进程依旧活动，而DBRM进程是管理Resource Manager当去除"_resource_manager_always_off"=true及"_resource_manager_always_on"=FALSE
或者将两个参数全部添加，均可避免该错误，统计信息自动收集也可以自动执行
在对以为问题进行分析及确认后，我们向 ORACLE 提交了相关的 SR ，最终， ORACLE 对此，确认相关的一个 BUG ， BUG 号为 : Bug 18748456 : AUTO TASK JOBS FAILED WITH ORA-29373 ERROR