oracle技术之一次RMAN备份报错的诊断过程（二）

最新推荐文章于 2021-04-12 05:22:15 发布

weixin_34291004

最新推荐文章于 2021-04-12 05:22:15 发布

阅读量369

点赞数

文章标签：数据库操作系统

原文链接：http://blog.51cto.com/19880614/1207564

版权

今天检查数据库中的备份输出脚本时，发现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环境有关。

oracle视频教程请关注:http://u.youku.com/user_video/id_UMzAzMjkxMjE2.html

转载于:https://blog.51cto.com/19880614/1207564

weixin_34291004

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
oracle技术之一次RMAN备份报错的诊断过程（二）

今天检查数据库中的备份输出脚本时，发现RMAN备份出现了错误。这一篇跟踪错误信息，寻找定位问题的方向。根据前面的问题描述，发现问题越来越复杂，从一个简单的RMAN备份报错，牵扯到系统中有3个长时间运行的JOB，以及RAC环境当前节点存在了大量的RACGMAIN CHECK进程的存在。虽然问题很复杂，就不要急于盲目操作，先简单分析一下当前的状况。发现问题是由于RMAN备份脚本报...
复制链接

扫一扫