今天检查数据库中的备份输出脚本时，发现RMAN备份出现了错误。
这一篇跟踪错误信息，寻找定位问题的方向。
根据前面的问题描述，发现问题越来越复杂，从一个简单的RMAN备份报错，牵扯到系统中有3个长时间运行的JOB，以及RAC环境当前节点存在了大量的RACGMAIN CHECK进程的存在。
虽然问题很复杂，就不要急于盲目操作，先简单分析一下当前的状况。
发现问题是由于RMAN备份脚本报错造成的，但是根据错误信息和随后的测试发现，问题是可以重现的，并不是简单的RMAN问题，导致问题的原因应该是共享资源被占用，RMAN在长时间无法得多资源后被关闭。
在数据库中检查共享资源时，发现V$LOCK视图中有3个可疑会话持有锁信息，进一步查询发现是3个JOB对应的会话，这3个JOB都运行了很长时间，既没有结束，也没有报错。
而在检查操作系统的进程时，发现当前系统存在大量的racgmain check进程，数量居然有四百多个，这是很不正常的，检查其他正常的RAC环境并未发现这个进程的存在。
这3个问题可能是相互关联的，也可能是独立的3个问题，如果3个问题彼此没有联系，那么就要分别去分析并解决这3个问题，如果3个问题是关联的，那么需要寻找一个突破口来快速的定位问题的原因。
根据上一篇文章描述的现象进行推断，这3个问题多半是相关联的，因为RMAN报错并不是普通的RMAN配置问题，根据alert文件中给出的信息，问题是由于共享资源被占有所造成的，而随后查询V$LOCK时，就看到3个长时间没有完成的JOB，这并不是偶然的，虽然还没有看到这3个JOB在做什么，但是怀疑RMAN等待的资源正是被JOB所占用。这说明第一个问题和第二个问题是有联系的，而alert文件给出的共享资源信息本身就和RAC环境关系密切，LMD进程——GLOBAL ENQUEUE SERVICE DAEMON是RAC环境相关的进程，这说明3个问题并非是3个独立的问题，而是彼此相关的问题。
既然3个问题是有关的，那么从那个问题入手呢，原则上讲从哪个分析都可以，因为最终导致问题的原因是同一个。但是实际分析的问题的时候还是有选择的，而不是盲目选择一个问题就开始分析，那样的话很可能事倍功半。一般来说，选择问题的突破点有两个考虑，一个是寻找跟接近导致问题原因的现象来进行分析。如果现象A导致了现象B，那么就选择分析现象A，因为现象B分析的价值已经不大了，现在A更加进行导致问题的原因。另一点考虑就是入手的难易程度，优先分析那些很容易上手的现象，这样解决问题会更加迅速，而且即使发现走错了路，也可以很快的发现。
针对当前的3个问题，RMAN连接报错初步怀疑和JOB运行有关，也就是说RMAN的问题很可能就是JOB运行问题所引起的，那么这里就应该有限分析JOB问题。而JOB问题和RACGMAIN CHECK进程之间暂时无法确定依赖关系，因此不好确定分析的优先级。下面再来对应两个问题分析的难易程度，JOB运行的信息全部保存在数据库中，有很多的视图可供参考，分析起来轻车熟路；而racgmain check进程则完全的不透明，即使有个别的trace文件，其内容也有如天书一般，分析起来肯定会吃力得很。显然应该优先分析数据库中未完成的JOB。
顺便说一句，上面给出的方法适用于大多数的情况，但是有的时候则不尽然。还是以上面3个问题而言，根据目前所获取的信息来看，如果需要查询metalink来获取帮助的话，则应该有限考虑RMAN问题，因为RMAN问题中包含大量的明确的信息，既有RMAN报错信息，也有导致报错信息的命令，因此可以很容易的找到最相关的问题描述。对于racgmain check进程问题而言，racgmain check本身就是一个很好的查询关键词，很容易在metalink中找到相关的信息。而对于JOB问题而言，并不是搜索不到信息，而是当前获取的信息不足以通过搜索来找到有意义的信息，需要进一步发掘JOB未发成的其他原因，找到适合搜索的关键点信息。虽然RMAN问题和RACGMAIN CHECK进程问题适合进行搜索，但是不幸的是，搜索解决和当前情况比较类似的不多，而且很难确定当前的问题和metalink中描述的是同一个问题，因此还是应该继续分析Oracle中的JOB信息。
SQL> SELECT SID, JOB FROM DBA_JOBS_RUNNING;
SID JOB
---------- ----------
118 4
102 74
289 27
SQL>COLWHAT FORMAT A60
SQL> SELECT JOB, LOG_USER, WHAT
2 FROM DBA_JOBS
3 WHERE JOB IN (4, 27, 74);
JOB LOG_USER WHAT
---------- -------------------- --------------------------------------------------------
4 NDMAIN DBMS_STATS.GATHER_SCHEMA_STATS(USER, CASCADE => TRUE);
27ZHEJIANG dbms_stats.gather_schema_stats(user, cascade => true);
74 GPO P_Project_Stat;
根据JOB信息，前面两个JOB运行都是和统计信息有关，第3个JOB运行的过程是用户自定义的过程。
SQL> SELECT SID, TYPE, ID1, ID2, LMODE, REQUEST, CTIME, BLOCK
2 FROM V$LOCK
3 WHERE SID IN (102, 118, 289)
4 ORDER BY CTIME DESC;
SID TY ID1 ID2 LMODE REQUEST CTIME BLOCK
---------- -- ---------- ---------- ---------- ---------- ---------- ----------
118 JQ 0 4 6 0 151090 2
118 TO 196404 1 3 0 151087 2
118 TX 262181 87690 6 0 151087 2
118 TM 196404 0 3 0 151087 2
289 JQ 0 27 6 0 147490 2
102 JQ 0 74 6 0 147487 2
289 TO -40016215 1 3 0 147484 2
289 TX 458770 86777 6 0 147484 2
102 TM 70434 0 3 0 147466 2
已选择9行。
可以看到会话118持有锁的时间最长，对比DBA_JOBS_RUNNING信息：
SQL> SELECT SID, JOB, LAST_DATE, THIS_DATE
2 FROM DBA_JOBS_RUNNING;
SID JOB LAST_DATE THIS_DATE
---------- ---------- ------------------- -------------------
118 4 2009-05-10 00:00:05 2009-05-24 00:00:02
102 74 2009-05-23 01:00:00 2009-05-24 01:00:04
289 27 2009-05-17 01:00:03 2009-05-24 01:00:04
仔细观察后才发现，这个JOB运行的时间是在RMAN进程运行之后。根据上一篇文章的描述，RMAN语句的运行时间是23日的23点左右，而JOB运行时间是24日的0点到1点，显然RMAN语句报错并不是JOB未完成的原因，倒是有可能导致二者原因的问题都是同一个，再检查racgmain check进程问题：
bash-3.00$ ps -ef|grep racgmain
oracle 24085 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/crs/bin/racgmain check
oracle 20734 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/crs/bin/racgmain check
oracle 19021 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 19035 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 20207 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 25186 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/crs/bin/racgmain check
oracle 20385 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 18960 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 22094 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/crs/bin/racgmain check
oracle 23123 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
.
.
.
oracle 23166 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 23508 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 18643 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
oracle 18420 1 0 May 23 ? 0:00 /opt/oracle/product/10.2/database/bin/racgmain check
可以发现所有的racgmain check进程都是5月23日启动的，那么导致RMAN和JOB问题的真正原因很可能是racgmain check进程问题。
检查rac其他实例上，没有发现这个进程：
bash-3.00$ ps -ef|grep racgmain
oracle 12451 12157 0 17:36:19 pts/1 0:00 grep racgmain
看来问题就是发生在当前节点上。
虽然导致问题的原因多半和racgmain进程有关，但是racgmain进程很难进行诊断，所以还是先检查一些导致JOB未完成的真正原因，这对于解决问题也是有帮助的：
SQL> SELECT EVENT,
2 P1TEXT,
3 P1,
4 P2TEXT,
5 P2,
6 WAIT_CLASS,
7 SECONDS_IN_WAIT WAIT
8 FROM V$SESSION_WAIT
9 WHERE SID IN (102, 118, 289)
10 ORDER BY WAIT DESC;
EVENT P1TEXT P1 P2TEXT P2 WAIT_CLASS WAIT
-------------------- --------------- ---------- ------------ ---------- ----------- ------
gc cr request file# 14 block# 36545 Cluster 153419
enq: TO - contention name|mode 1414463491 object # 4254951081 Other 149816
library cache lock handle address 2.0935E+10 lock address 2.3357E+10 Concurrency 149798
可以看到，最先被锁住的JOB会话在等待gc cr request，而这个会话等待事件的类型正是CLUSTER，这说明第一个会话在尝试取得远端内存中的数据块时被锁住，而这个现象和大量的racgmain check进行显然有关系。
检查V$SESSION_LONGOPS视图，可以看到两个收集统计信息的会话停止的位置。
SQL> SELECT SID, MESSAGE
2 FROM V$SESSION_LONGOPS
3 WHERE TOTALWORK != SOFAR
4 AND SID IN (102, 118, 289);
SID MESSAGE
---------- ---------------------------------------------------------------------------
289 Gather Table's Index Statistics: Table ASS_NEWS : 1 out of 2 Indexes done
289 Gather Schema Statistics: Schema : 8 out of 444 Objects done
118 Gather Schema Statistics: Schema : 2 out of 138 Objects done
检查会话锁的对象信息：
SQL> SELECT * FROM DBA_DML_LOCKS WHERE SESSION_ID IN (102, 118, 289);
SESSION_ID OWNER NAME MODE_HELD MODE_REQUESTE LAST_CONVERT BLOCKING_OTHERS
---------- ----- -------------------- ------------- ------------- ------------ ---------------
102 GPO GPO_PROJECT_PRODUCT Row-X (SX) None 158825 Global
118 SYS ORA_TEMP_1_DS_143368 Row-X (SX) None 162446 Global
其中ORA_TEMP_1_DS_143368是SYS生成的临时表：
SQL>COLOBJECT_NAME FORMAT A30
SQL> SELECT OWNER, OBJECT_NAME, OBJECT_TYPE, OBJECT_ID
2 FROM DBA_OBJECTS
3 WHERE OBJECT_NAME = 'ORA_TEMP_1_DS_143368';
OWNER OBJECT_NAME OBJECT_TYPE OBJECT_ID
----- ------------------------------ ------------------- ----------
SYS ORA_TEMP_1_DS_143368 TABLE 196404
SQL> SELECT TABLE_NAME, TABLESPACE_NAME, TEMPORARY
2 FROM DBA_TABLES
3 WHERE WNER = 'SYS'
4 AND TABLE_NAME = 'ORA_TEMP_1_DS_143368';
TABLE_NAME TABLESPACE_NAME T
------------------------------ ------------------------------ -
ORA_TEMP_1_DS_143368 Y
正是这个临时表的操作，导致了会话的TO等待事件，而且这个临时表是Oracle收集统计信息时使用的，它的结构与当前正在访问的用户对象结构一致：
SQL> SELECT OWNER, SEGMENT_NAME
2 FROM DBA_EXTENTS
3 WHERE FILE_ID = 14
4 AND BLOCK_ID <= 36545
5 AND BLOCK_ID + BLOCKS >= 36545;
OWNER SEGMENT_NAME
---------- ------------------------------
NDMAIN CAT_AREA_MEDICARE
SQL> DESC NDMAIN.CAT_AREA_MEDICARE
名称 是否为空?类型
--------------------------------------- -------- ------------------------
ID NOT NULL CHAR(24)
PRODUCT_ID NOT NULL CHAR(24)
PLAT_ID NOT NULL CHAR(24)
INSURED_DRUG_NUBMER NOT NULL VARCHAR2(8)
INSURED_DRUG_TYPE NOT NULL CHAR(1)
LAST_UPDATE_USER CHAR(24)
LAST_UPDATE_DATE DATE
LAST_UPDATE_PLAT CHAR(24)
LAST_UPDATE_ORG CHAR(24)
SQL> DESC ORA_TEMP_1_DS_143368
名称 是否为空?类型
--------------------------------------- -------- -----------------------
ID NOT NULL CHAR(24)
PRODUCT_ID NOT NULL CHAR(24)
PLAT_ID NOT NULL CHAR(24)
INSURED_DRUG_NUBMER NOT NULL VARCHAR2(8)
INSURED_DRUG_TYPE NOT NULL CHAR(1)
LAST_UPDATE_USER CHAR(24)
LAST_UPDATE_DATE DATE
LAST_UPDATE_PLAT CHAR(24)
LAST_UPDATE_ORG CHAR(24)
虽然清楚了Oracle在做什么，但是还是不知道这个会话为什么会hang住，检查当前事务：
SQL> SELECT SID, TYPE, ID1, ID2, CTIME, START_DATE, XIDSQN
2 FROM V$TRANSACTION A, V$LOCK B
3 WHERE A.ADDR = B.ADDR;
SID TYPE ID1 ID2 CTIME START_DATE XIDSQN
---------- ---------- ---------- ---------- ---------- ------------------- ----------
144 TX 655449 137382 188527 2009-05-23 17:00:40 137382
118 TX 262181 87690 163364 2009-05-24 00:00:04 87690
289 TX 458770 86777 159761 2009-05-24 01:00:07 86777
277 TX 524320 89189 174678 2009-05-23 20:51:30 89189
除了刚才看到的JOB会话，当前事务还包括另外两个会话，而且这两个会话的启动时间更早：
SQL> SELECT SID, PROGRAM, ACTION, EVENT, SECONDS_IN_WAIT
2 FROM V$SESSION
3 WHERE SID IN (144, 277);
SID PROGRAM ACTION EVENT SECONDS_IN_WAIT
---------- -------------------- ----------------------- -------------------- ---------------
144 oracle@ahrac1 (m000) Auto-Flush Slave Action gc current request 188734
277 oracle@ahrac1 (m001) ASH Emergency-Flush row cache lock 174885
显然这是Oracle后台工具进行的操作，不过这两个会话的等待时间同样存在问题，而且根据V$TRANSACTION会话显示的时间，会话144的启动时间显然要远远早于RMAN启动的时间。而且会话144在gc current request，这个事件仍然和RAC环境有关。
（以上内容摘于网络，如有侵权，请告之，将第一时间删除）
总机：(010)-88589926，88589826，88587026 QQ讨论群：243729577 182441349 邮箱：cuug_bj@cuug.com
通信地址：北京市海淀区紫竹院路98号北京化工大学科技园609室（CUUG）邮政编码：100089
中国UNIX用户协会 Copyright 2010 ALL Rights Reserved 北京神脑资讯技术有限公司
京ICP备11008061号 京公网安备110108006275号