Extract SQL Plan from AWR

之前有用户在AWR中定位到问题SQL语句后想要了解该SQL statement的具体执行计划,于是就用AWR报告中得到的SQL ID去V$SQL等几个动态性能视图中查询,但发现V$SQL或V$SQL_PLAN视图都已经找不到对应SQL ID的记录,一般来说这些语句已经从shared pool共享池中被替换出去了。

这个时候我们可以尝试使用DBMS_XPLAN.DISPLAY_AWR存储过程来将Oracle Automatic Workload Repository自动负载仓库中记录的SQL语句相关信息抽取出来,如:

SQL> set linesize 200 pagesize 2000;

SQL> select * from global_name;

GLOBAL_NAME
--------------------------------------------------------------------------------
askmac.cn

SQL> select /* extract_me */ count(*) from maclean;

  COUNT(*)
----------
      9564

SQL> select sql_id from v$sql where sql_text like '%extract_me%' and sql_text not like '%like%';

SQL_ID
-------------
8vff23q8qp9fj

SQL> exec dbms_workload_repository.create_snapshot;
PL/SQL procedure successfully completed.

QL> select * from table(dbms_xplan.display_cursor('8vff23q8qp9fj',0));

PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  8vff23q8qp9fj, child number 0
-------------------------------------
select /* extract_me */ count(*) from maclean

Plan hash value: 1679547536

----------------------------------------------------------------------
| Id  | Operation          | Name    | Rows  | Cost (%CPU)| Time     |
----------------------------------------------------------------------
|   0 | SELECT STATEMENT   |         |       |    34 (100)|          |
|   1 |  SORT AGGREGATE    |         |     1 |            |          |
|   2 |   TABLE ACCESS FULL| MACLEAN | 10438 |    34   (0)| 00:00:01 |
----------------------------------------------------------------------

Note
-----
   - dynamic sampling used for this statement

18 rows selected.

/* 冲刷共享池后v$SQL/V$SQL_PLAN等动态视图内的记录会消失,
     需要注意的是如果在AWR快照自动生成之前冲刷了共享池,那么可能丢失SQL的执行统计信息
 */

SQL> alter system flush shared_pool;
System altered.

SQL> select * from table(dbms_xplan.display_cursor('8vff23q8qp9fj',0));

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------
SQL_ID: 8vff23q8qp9fj, child number: 0 cannot be found

/* 此时就可以利用dbms_xplan.display_awr存储过程来抓取该SQL_ID对应的执行计划 */

SQL>  select * from table(dbms_xplan.display_awr('8vff23q8qp9fj'));

PLAN_TABLE_OUTPUT
--------------------------------------------------
SQL_ID 8vff23q8qp9fj
--------------------
select /* extract_me */ count(*) from maclean

Plan hash value: 1679547536

----------------------------------------------------------------------
| Id  | Operation          | Name    | Rows  | Cost (%CPU)| Time     |
----------------------------------------------------------------------
|   0 | SELECT STATEMENT   |         |       |    34 (100)|          |
|   1 |  SORT AGGREGATE    |         |     1 |            |          |
|   2 |   TABLE ACCESS FULL| MACLEAN | 10438 |    34   (0)| 00:00:01 |
----------------------------------------------------------------------

Note
-----
   - dynamic sampling used for this statement

18 rows selected.

/* 这里可以代入'all'选项获取更细致的计划信息 */

SQL> select * from table(dbms_xplan.display_awr('8vff23q8qp9fj',null,null,'all'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------
SQL_ID 8vff23q8qp9fj
--------------------
select /* extract_me */ count(*) from maclean

Plan hash value: 1679547536

----------------------------------------------------------------------
| Id  | Operation          | Name    | Rows  | Cost (%CPU)| Time     |
----------------------------------------------------------------------
|   0 | SELECT STATEMENT   |         |       |    34 (100)|          |
|   1 |  SORT AGGREGATE    |         |     1 |            |          |
|   2 |   TABLE ACCESS FULL| MACLEAN | 10438 |    34   (0)| 00:00:01 |
----------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$1
   2 - SEL$1 / MACLEAN@SEL$1

Note
-----
   - dynamic sampling used for this statement

24 rows selected.

/* 也可以从 dba_hist_sql_plan/dba_hist_sqltext等awr历史视图中直接观察该SQL ID对应的语句 */

SQL> select OPERATION,OPTIONS,OBJECT_NAME from dba_hist_sql_plan where sql_id='8vff23q8qp9fj';

OPERATION                      OPTIONS                        OBJECT_NAME
------------------------------ ------------------------------ -------------------------------
SELECT STATEMENT
SORT                           AGGREGATE
TABLE ACCESS                   FULL                           MACLEAN

常用工具收集页面

DBA在性能调优或诊断过程中多少会使用一些成品工具,以下列出一些我工作中使用较为频繁的工具:

Program platform download URL
nmon AIX POWER http://www.ibm.com/developerworks/wikis/download/attachments/53871937/nmon4aix12e.zip?version=1
nmon Linux http://nmon.sourceforge.net/docs/MPG_nmon_for_Linux_14a_binaries.zip
sarmon Solaris http://sourceforge.net/projects/sarmon/files/
putty Interl x86 http://the.earth.li/~sgtatham/putty/latest/x86/putty.exe
OS watcher Non Windows https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=REFERENCE&id=301137.1
Procwatcher Non Windows https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=BULLETIN&id=459694.1
SQLTXPLAIN ALL https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=TROUBLESHOOTING&id=215187.1
TRCANLZR ALL https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=TROUBLESHOOTING&id=224270.1
STRMMON Non Windows https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=BULLETIN&id=290605.1
Oracle Cluster Verification Utility ALL http://www.oracle.com/technetwork/database/clustering/downloads/cvu-download-homepage-099973.html
Oracle Cluster Health Monitor (CHM) Linux and Windows http://www.oracle.com/technetwork/database/clustering/downloads/ipd-download-homepage-087212.html
RDA 4 ALL https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=DIAGNOSTIC%20TOOLS&id=250262.1
Latest Opatch ALL https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=BULLETIN&id=224346.1
RAC Diagnostic Information (racdiag.sql) ALL https://www.askmac.cn/archives/script-to-collect-rac-diagnostic-information-racdiag-sql.html
ass.awk ALL https://www.askmac.cn/archives/oracle-systemstate-dump-analytic-tool-ass-awk-v1-09.html
LTOM ALL https://support.oracle.com/CSP/main/article?cmd=show&type=NOT&doctype=DIAGNOSTIC%20TOOLS&id=352363.1

今后还会不断更新!

Oracle RAC Brain Split Resolution

大约是一周前,一位资深的Oracle工程师向我和客户介绍RAC中脑裂的处理过程,据他介绍脑裂发生时通过各节点对voting disk(投票磁盘)的抢夺,那些争抢到(n/2+1)数量voting disk的节点就可以survive(幸存)下来,而没有争抢到voting disk的节点则被evicted踢出节点。

不得不说以上这番观点,来得太过随意了,一位从Oracle 6就开始从事维护工作的老工程师也会犯这样的概念性错误,只能说Oracle技术的更新过于日新月异了。

在理解脑裂(Brain Split)处理过程前,有必要介绍一下Oracle RAC Css(Cluster Synchronization Services)的工作框架:

Oracle RAC CSS提供2种后台服务包括群组管理(Group Managment简称GM)和节点监控(Node Monitor简称NM),其中GM管理组(group)和锁(lock)服务。在集群中任意时刻总有一个节点会充当GM主控节点(master node)。集群中的其他节点串行地将GM请求发送到主控节点(master node),而master node将集群成员变更信息广播给集群中的其他节点。组成员关系(group membership)在每次发生集群重置(cluster reconfiguration)时发生同步。每一个节点独立地诠释集群成员变化信息。

而节点监控NM服务则负责通过skgxn(skgxn-libskgxn.a,提供节点监控的库)与其他厂商的集群软件保持节点信息的一致性。此外NM还提供对我们熟知的网络心跳(Network heartbeat)和磁盘心跳(Disk heartbeat)的维护以保证节点始终存活着。当集群成员没有正常Network heartbeat或Disk heartbeat时NM负责将成员踢出集群,被踢出集群的节点将发生节点重启(reboot)。

NM服务通过OCR中的记录(OCR中记录了Interconnect的信息)来了解其所需要监听和交互的端点,将心跳信息通过网络发送到其他集群成员。同时它也监控来自所有其他集群成员的网络心跳Network heartbeat,每一秒钟都会发生这样的网络心跳,若某个节点的网络心跳在misscount(by the way:10.2.0.1中Linux上默认misscount为60s,其他平台为30s,若使用了第三方vendor clusterware则为600s,但10.2.0.1中未引入disktimeout;10.2.0.4以后misscount为60s,disktimeout为200s;11.2以后misscount为30s:CRS-4678: Successful get misscount 30 for Cluster Synchronization Services,CRS-4678: Successful get disktimeout 200 for Cluster Synchronization Services)指定的秒数中都没有被收到的话,该节点被认为已经”死亡”了。NM还负责当其他节点加入或离开集群时初始化集群的重置(Initiates cluster reconfiguration)。

在解决脑裂的场景中,NM还会监控voting disk以了解其他的竞争子集群(subclusters)。关于子集群我们有必要介绍一下,试想我们的环境中存在大量的节点,以Oracle官方构建过的128个节点的环境为我们的想象空间,当网络故障发生时存在多种的可能性,一种可能性是全局的网络失败,即128个节点中每个节点都不能互相发生网络心跳,此时会产生多达128个的信息”孤岛”子集群。另一种可能性是局部的网络失败,128个节点中被分成多个部分,每个部分中包含多于一个的节点,这些部分就可以被称作子集群(subclusters)。当出现网络故障时子集群内部的多个节点仍能互相通信传输投票信息(vote mesg),但子集群或者孤岛节点之间已经无法通过常规的Interconnect网络交流了,这个时候NM Reconfiguration就需要用到voting disk投票磁盘。

因为NM要使用voting disk来解决因为网络故障造成的通信障碍,所以需要保证voting disk在任意时刻都可以被正常访问。在正常状态下,每个节点都会进行磁盘心跳活动,具体来说就是会到投票磁盘的某个块上写入disk心跳信息,这种活动每一秒钟都会发生,同时CSS还会每秒读取一种称作”kill block”的”赐死块”,当”kill block”的内容表示本节点被驱逐出集群时,CSS会主动重启节点。

为了保证以上的磁盘心跳和读取”kill block”的活动始终正常运作CSS要求保证至少(N/2+1)个投票磁盘要被节点正常访问,这样就保证了每2个节点间总是至少有一个投票磁盘是它们都可以正常访问的,在正常情况下(注意是风平浪静的正常情况)只要节点所能访问的在线voting disk多于无法访问的voting disk,该节点都能幸福地活下去,当无法访问的voting disk多于正常的voting disk时,Cluster Communication Service进程将失败并引起节点重启。所以有一种说法认为voting disk只要有2个足以保证冗余度就可以了,没有必要有3个或以上voting disk,这种说法是错误的。Oracle推荐集群中至少要有3个voting disks。

补充1:

Question:
有同学问那么voting disk  必须是奇数个呢?

Answer:
实际上我们仅仅是推荐使用奇数个vote disk ,而非必须是奇数个。10gR2中vote disk的数目上限是32个。

Question
我们可以使用2或4个vote disk吗?

Answer:
可以的。 但是2、4这样的数目在“至少(N/2+1)个投票磁盘要被节点正常访问”这一disk heartbeat的硬性算法下是不利的:
当我们使用2个vote disk 时,不能发生任意个vote disk的心跳失败
当我们使用3个vote disk 时,不能发生大于1个的vote disk心跳失败
当我们使用4个vote disk 时,不能发生大于1个的vote disk心跳失败 ,这和3个时的容错率是一样,但是因为我们有更多的vote disk,这会导致管理成本和引入的风险增长
当我们使用5个vote disk 时,不能发生大于2个的vote disk心跳失败
当我们使用6个vote disk 时,仍然不能发生大于2个的vote disk心跳失败, 同样的因为比5时多出一个 ,也会引入不合理的管理成本和风险

补充2:
Question:
若节点间的网络心跳正常,且节点所能正常心跳的vote disk 大于 不能正常访问的 ,如3个votedisk 时 恰巧有1个vote disk 的disk heartbeat 超时,此时Brain split 会发生吗?

Answer:
这种情况即不会触发Brain Split,也不会引发节点驱逐协议(eviction protocol)。 当单个或小于(N/2+1)个的voting disk心跳失败(disk heartbeat failure)时,这种心跳失败可能是由于短期内节点访问voting disk发生I/O error错误而引起的,此时css会立刻将这些失败的voting disk标记为OFFLINE。虽然有一定数量的voting disk OFFLINE了,但是我们仍有至少(N/2+1)个投票磁盘可用,这保证了eviction protocol不会被调用,所以没有节点会被reboot重启。紧接着node monitor模块的Disk ping Monitor Thread(DPMT-clssnmDiskPMT)会重复尝试访问这些失败的OFFLINE voting disk,若这些投票磁盘变得再次可I/O访问且经过验证其上的数据也没有讹误,那么css会再次将此voting disk标记为ONLINE;但是如果在45s( 这里的45s是基于misscount和 内部算法获得的) 内仍不能正常访问相关的voting disk,那么DMPT将在cssd.log中生成警告信息,如:

 

CSSD]2011-11-11 20:11:20.668 >
WARNING: clssnmDiskPMT: long disk latency >(45940 ms) to voting disk (0//dev/asm-votedisk1)

 

假设以上发生clssnmDiskPMT警告的RAC场景共有3个voting disk,现已有一个asm-votedisk1因为I/O error或其他原因而被标记为OFFLINE,若此时再有一个votedisk也出现了问题并disk heartbeat 失败,那么节点会因为少于规定数目(2)的votedisk而引发eviction protocol,进而重启reboot。

单个或小于(N/2+1)个的voting disk心跳失败都仅仅生成警告(Warning),而非致命的错误。因为仍有绝大数量的vote disk可被访问,因此生成的警告都是非致命的,eviction protocol将不会被触发。

 

当实际的NM Reconfiguration集群重置情况发生时所有的active节点和正在加入集群的节点都会参与到reconfig中,那些没有应答(ack)的节点都将不再被归入新的集群关系中。实际上reconfig重置包括多个阶段:
1.初始化阶段 — reconfig manager(由集群成员号最低的节点担任)向其他节点发送启动reconfig的信号
2.投票阶段 — 节点向reconfig manager发送该节点所了解的成员关系
3.脑裂检查阶段 — reconfig manager检查是否脑裂
4.驱逐阶段 — reconfig manager驱逐非成员节点
5.更新阶段 — reconfig manager向成员节点发送权威成员关系信息

 

在脑裂检查阶段Reconfig Manager会找出那些没有Network Heartbeat而有Disk Heartbeat的节点,并通过Network Heartbeat(如果可能的话)和Disk Heartbeat的信息来计算所有竞争子集群(subcluster)内的节点数目,并依据以下2种因素决定哪个子集群应当存活下去:

  1. 拥有最多节点数目的子集群(Sub-cluster with largest number of Nodes)
  2. 若子集群内数目相等则为拥有最低节点号的子集群(Sub-cluster with lowest node number),举例来说在一个2节点的RAC环境中总是1号节点会获胜。
  3. 采用Stonith algorithm 的IO fencing(remote power reset)

 

补充:

STONITH算法是一种常用的I/O Fencing algorithm,是RAC中必要的远程关闭节点的接口。其想法十分简单,当某个节点上运行的软件希望确保本集群内的其他节点不能使用某种资源时,拔出其他节点的插座即可。这是一种简单、可靠且有些残酷的算法。Stonith 的优势是其没有特定的硬件需求,也不会限制集群的扩展性。

Oracle Clusterware的Process Monitor模块负责实现IO fencing,保证不会因节点/实例的不协调工作而产生corruption。Process Monitor的工作具体由hangcheck timer或者oprocd 完成, 在Linux平台上10.2.0.4 之前都没有oprocd的存在(其他Unix平台在10.2.0.1就有了),在安装RAC之前需要额外安装hangcheck timer软件以保证IO fencing, 到10.2.0.4 时Linux上也有了oprocd,具体见<Know about RAC Clusterware Process OPROCD> 一文。 这些负责IO fencing的进程一般都会被锁定在内存中(locked in memory)、实时运行(Real time)、休眠固定的时间(Sleep a fixed time)、以root身份运行;若进程唤醒后发现时间已经太晚,那么它会强制reboot;若这些进程发生失败,则也会重启,所以在RAC环境中oprocd是一个很重要的进程,不要失去手动去kill这个进程。

 

 

在完成脑裂检查后进入驱逐阶段,被驱逐节点会收到发送给它们的驱逐信息(如果网络可用的话),若无法发送信息则会通过写出驱逐通知到voting disk上的”kill block”来达到驱逐通知的目的。同时还会等待被驱逐节点表示其已收到驱逐通知,这种表示可能是通过网络通信的方式也可能是投票磁盘上的状态信息。

可以看到Oracle CSS中Brain Split Check时会尽可能地保证最大的一个子集群存活下来以保证RAC系统具有最高的可用性,而并不如那位资深工程师所说的在Cluster Reconfiguration阶段会通过节点对投票磁盘的抢占来保证哪个节点存活下来。

以下为一个三节点RAC环境中的2个示例场景:

1.1号节点网络失败,2,3号节点形成子集群;2,3节点通过voting disk向1号节点发起驱逐:

以下为1号节点的ocssd.log日志:
[    CSSD]2011-04-23 17:11:42.943 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 50 3.280308e-268artbeat fatal, eviction in 29.610 seconds
[    CSSD]2011-04-23 17:11:42.943 [3042950032] >TRACE:   clssnmPollingThread: node vrh2 (2) is impending reconfig, flag 1037, misstime 30390
[    CSSD]2011-04-23 17:11:42.943 [3042950032] >WARNING: clssnmPollingThread: node vrh3 (3) at 50 3.280308e-268artbeat fatal, eviction in 29.150 seconds

对2,3号节点发起misscount计时

[    CSSD]2011-04-23 17:11:42.943 [3042950032] >TRACE:   clssnmPollingThread: node vrh3 (3) is impending reconfig, flag 1037, misstime 30850
[    CSSD]2011-04-23 17:11:42.943 [3042950032] >TRACE:   clssnmPollingThread: diskTimeout set to (57000)ms impending reconfig status(1)
[    CSSD]2011-04-23 17:11:44.368 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 50 3.280308e-268artbeat fatal, eviction in 28.610 seconds
[    CSSD]2011-04-23 17:12:04.778 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 75 3.280308e-268artbeat fatal, eviction in 14.580 seconds
[    CSSD]2011-04-23 17:12:04.779 [3042950032] >WARNING: clssnmPollingThread: node vrh3 (3) at 75 3.280308e-268artbeat fatal, eviction in 14.120 seconds
[    CSSD]2011-04-23 17:12:06.207 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 75 3.280308e-268artbeat fatal, eviction in 13.580 seconds
[    CSSD]2011-04-23 17:12:17.719 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 3.280308e-268artbeat fatal, eviction in 5.560 seconds
[    CSSD]2011-04-23 17:12:17.719 [3042950032] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 3.280308e-268artbeat fatal, eviction in 5.100 seconds
[    CSSD]2011-04-23 17:12:19.165 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 3.280308e-268artbeat fatal, eviction in 4.560 seconds
[    CSSD]2011-04-23 17:12:19.165 [3042950032] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 3.280308e-268artbeat fatal, eviction in 4.100 seconds
[    CSSD]2011-04-23 17:12:20.642 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 3.280308e-268artbeat fatal, eviction in 3.560 seconds
[    CSSD]2011-04-23 17:12:20.642 [3042950032] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 3.280308e-268artbeat fatal, eviction in 3.100 seconds
[    CSSD]2011-04-23 17:12:22.139 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 3.280308e-268artbeat fatal, eviction in 2.560 seconds
[    CSSD]2011-04-23 17:12:22.139 [3042950032] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 3.280308e-268artbeat fatal, eviction in 2.100 seconds
[    CSSD]2011-04-23 17:12:23.588 [3042950032] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 3.280308e-268artbeat fatal, eviction in 1.550 seconds
[    CSSD]2011-04-23 17:12:23.588 [3042950032] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 3.280308e-268artbeat fatal, eviction in 1.090 seconds

2号节点的ocssd.log日志:

[    CSSD]2011-04-23 17:11:53.054 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 50 8.910601e-269artbeat fatal, eviction in 29.800 seconds
[    CSSD]2011-04-23 17:11:53.054 [3053439888] >TRACE:   clssnmPollingThread: node vrh1 (1) is impending reconfig, flag 1037, misstime 30200
[    CSSD]2011-04-23 17:11:53.054 [3053439888] >TRACE:   clssnmPollingThread: diskTimeout set to (57000)ms impending reconfig status(1)
[    CSSD]2011-04-23 17:11:54.516 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 50 8.910601e-269artbeat fatal, eviction in 28.790 seconds
[    CSSD]2011-04-23 17:12:14.826 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 75 8.910601e-269artbeat fatal, eviction in 14.800 seconds
[    CSSD]2011-04-23 17:12:16.265 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 75 8.910601e-269artbeat fatal, eviction in 13.800 seconds
[    CSSD]2011-04-23 17:12:27.755 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 8.910601e-269artbeat fatal, eviction in 5.800 seconds
[    CSSD]2011-04-23 17:12:29.197 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 8.910601e-269artbeat fatal, eviction in 4.800 seconds
[    CSSD]2011-04-23 17:12:30.658 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 8.910601e-269artbeat fatal, eviction in 3.800 seconds
[    CSSD]2011-04-23 17:12:32.133 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 8.910601e-269artbeat fatal, eviction in 2.800 seconds
[    CSSD]2011-04-23 17:12:33.602 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 8.910601e-269artbeat fatal, eviction in 1.790 seconds
[    CSSD]2011-04-23 17:12:35.126 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 8.910601e-269artbeat fatal, eviction in 0.800 seconds

[    CSSD]2011-04-23 17:12:35.399 [117574544] >TRACE:   clssnmHandleSync: diskTimeout set to (57000)ms
[    CSSD]2011-04-23 17:12:35.399 [117574544] >TRACE:   clssnmHandleSync: Acknowledging sync: src[3] srcName[vrh3] seq[21] sync[10]

clssnmHandleSyn应答3号节点发送的同步信息

[    CSSD]2011-04-23 17:12:35.399 [5073104] >USER:    NMEVENT_SUSPEND [00][00][00][0e]

发生Node Monitoring SUSPEND事件

[    CSSD]2011-04-23 17:12:35.405 [117574544] >TRACE:   clssnmSendVoteInfo: node(3) syncSeqNo(10)

通过clssnmSendVoteInfo向3号节点发送投票信息Vote mesg

[    CSSD]2011-04-23 17:12:35.415 [117574544] >TRACE:   clssnmUpdateNodeState: node 0, state (0/0) unique (0/0) prevConuni(0) birth (0/0) (old/new)
[    CSSD]2011-04-23 17:12:35.415 [117574544] >TRACE:   clssnmUpdateNodeState: node 1, state (3/0) unique (1303592601/1303592601) prevConuni(0) birth (9/9) (old/new)
[    CSSD]2011-04-23 17:12:35.415 [117574544] >TRACE:   clssnmDiscHelper: vrh1, node(1) connection failed, con (0xb7e80ae8), probe((nil))
[    CSSD]2011-04-23 17:12:35.415 [117574544] >TRACE:   clssnmDeactivateNode: node 1 (vrh1) left cluster

确认1号节点离开了集群cluster

[    CSSD]2011-04-23 17:12:35.415 [117574544] >TRACE:   clssnmUpdateNodeState: node 2, state (3/3) unique (1303591210/1303591210) prevConuni(0) birth (2/2) (old/new)
[    CSSD]2011-04-23 17:12:35.415 [117574544] >TRACE:   clssnmUpdateNodeState: node 3, state (3/3) unique (1303591326/1303591326) prevConuni(0) birth (3/3) (old/new)
[    CSSD]2011-04-23 17:12:35.415 [117574544] >USER:    clssnmHandleUpdate: SYNC(10) from node(3) completed
[    CSSD]2011-04-23 17:12:35.416 [117574544] >USER:    clssnmHandleUpdate: NODE 2 (vrh2) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2011-04-23 17:12:35.416 [117574544] >USER:    clssnmHandleUpdate: NODE 3 (vrh3) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2011-04-23 17:12:35.416 [117574544] >TRACE:   clssnmHandleUpdate: diskTimeout set to (200000)ms
[    CSSD]2011-04-23 17:12:35.416 [3021970320] >TRACE:   clssgmReconfigThread:  started for reconfig (10)
[    CSSD]2011-04-23 17:12:35.416 [3021970320] >USER:    NMEVENT_RECONFIG [00][00][00][0c]
[    CSSD]2011-04-23 17:12:35.417 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock crs_version type 2
[    CSSD]2011-04-23 17:12:35.417 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(crs_version) birth(9/9)
[    CSSD]2011-04-23 17:12:35.418 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_FAILOVER type 3
[    CSSD]2011-04-23 17:12:35.418 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock EVMDMAIN type 2
[    CSSD]2011-04-23 17:12:35.418 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(EVMDMAIN) birth(9/9)
[    CSSD]2011-04-23 17:12:35.418 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock CRSDMAIN type 2
[    CSSD]2011-04-23 17:12:35.418 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(CRSDMAIN) birth(9/9)
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh1 type 3
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh2 type 3
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh3 type 3
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock ocr_crs type 2
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(ocr_crs) birth(9/9)
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock #CSS_CLSSOMON type 2
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(#CSS_CLSSOMON) birth(9/9)
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmEstablishConnections: 2 nodes in cluster incarn 10
[    CSSD]2011-04-23 17:12:35.419 [3063929744] >TRACE:   clssgmPeerDeactivate: node 1 (vrh1), death 10, state 0x80000000 connstate 0xa
[    CSSD]2011-04-23 17:12:35.419 [3063929744] >TRACE:   clssgmPeerListener: connects done (2/2)
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmEstablishMasterNode: MASTER for 10 is node(2) birth(2)
[    CSSD]2011-04-23 17:12:35.419 [3021970320] >TRACE:   clssgmMasterCMSync: Synchronizing group/lock status
[    CSSD]2011-04-23 17:12:35.428 [3021970320] >TRACE:   clssgmMasterSendDBDone: group/lock status synchronization complete
[    CSSD]CLSS-3000: reconfiguration successful, incarnation 10 with 2 nodes

[    CSSD]CLSS-3001: local node number 2, master node number 2

完成reconfiguration

[    CSSD]2011-04-23 17:12:35.440 [3021970320] >TRACE:   clssgmReconfigThread:  completed for reconfig(10), with status(1)

以下为3号节点的ocssd.log:

[    CSSD]2011-04-23 17:12:36.303 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 50 1.867300e-268artbeat fatal, eviction in 29.220 seconds
[    CSSD]2011-04-23 17:12:36.303 [3053439888] >TRACE:   clssnmPollingThread: node vrh1 (1) is impending reconfig, flag 1037, misstime 30780
[    CSSD]2011-04-23 17:12:36.303 [3053439888] >TRACE:   clssnmPollingThread: diskTimeout set to (57000)ms impending reconfig status(1)
[    CSSD]2011-04-23 17:12:57.889 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 75 1.867300e-268artbeat fatal, eviction in 14.220 seconds
[    CSSD]2011-04-23 17:13:10.674 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 1.867300e-268artbeat fatal, eviction in 5.220 seconds
[    CSSD]2011-04-23 17:13:12.115 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 1.867300e-268artbeat fatal, eviction in 4.220 seconds
[    CSSD]2011-04-23 17:13:13.597 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 1.867300e-268artbeat fatal, eviction in 3.210 seconds
[    CSSD]2011-04-23 17:13:15.024 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 1.867300e-268artbeat fatal, eviction in 2.220 seconds
[    CSSD]2011-04-23 17:13:16.504 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 1.867300e-268artbeat fatal, eviction in 1.220 seconds
[    CSSD]2011-04-23 17:13:17.987 [3053439888] >WARNING: clssnmPollingThread: node vrh1 (1) at 90 1.867300e-268artbeat fatal, eviction in 0.220 seconds
[    CSSD]2011-04-23 17:13:18.325 [3053439888] >TRACE:   clssnmPollingThread: Eviction started for node vrh1 (1), flags 0x040d, state 3, wt4c 0
[    CSSD]2011-04-23 17:13:18.326 [3032460176] >TRACE:   clssnmDoSyncUpdate: Initiating sync 10
[    CSSD]2011-04-23 17:13:18.326 [3032460176] >TRACE:   clssnmDoSyncUpdate: diskTimeout set to (57000)ms
[    CSSD]2011-04-23 17:13:18.326 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (11)
[    CSSD]2011-04-23 17:13:18.326 [3032460176] >TRACE:   clssnmSetupAckWait: node(2) is ALIVE
[    CSSD]2011-04-23 17:13:18.326 [3032460176] >TRACE:   clssnmSetupAckWait: node(3) is ALIVE
[    CSSD]2011-04-23 17:13:18.327 [3032460176] >TRACE:   clssnmSendSync: syncSeqNo(10)
[    CSSD]2011-04-23 17:13:18.329 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(11), ackCount(2)
[    CSSD]2011-04-23 17:13:18.329 [89033616] >TRACE:   clssnmHandleSync: diskTimeout set to (57000)ms
[    CSSD]2011-04-23 17:13:18.329 [89033616] >TRACE:   clssnmHandleSync: Acknowledging sync: src[3] srcName[vrh3] seq[21] sync[10]
[    CSSD]2011-04-23 17:13:18.330 [8136912] >USER:    NMEVENT_SUSPEND [00][00][00][0e]
[    CSSD]2011-04-23 17:13:18.332 [3032460176] >TRACE:   clssnmWaitForAcks: done, msg type(11)
[    CSSD]2011-04-23 17:13:18.332 [3032460176] >TRACE:   clssnmDoSyncUpdate: Terminating node 1, vrh1, misstime(60010) state(5)
[    CSSD]2011-04-23 17:13:18.332 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (13)
[    CSSD]2011-04-23 17:13:18.332 [3032460176] >TRACE:   clssnmSetupAckWait: node(2) is ACTIVE
[    CSSD]2011-04-23 17:13:18.332 [3032460176] >TRACE:   clssnmSetupAckWait: node(3) is ACTIVE
[    CSSD]2011-04-23 17:13:18.334 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(13), ackCount(2)
[    CSSD]2011-04-23 17:13:18.335 [89033616] >TRACE:   clssnmSendVoteInfo: node(3) syncSeqNo(10)
[    CSSD]2011-04-23 17:13:18.337 [3032460176] >TRACE:   clssnmWaitForAcks: done, msg type(13)

以上完成了2-3节点间的Vote mesg通信,这些信息包含Node identifier,GM peer to peer listening endpoint以及
View of cluster membership。

[    CSSD]2011-04-23 17:13:18.337 [3032460176] >TRACE:   clssnmCheckDskInfo: Checking disk info...

开始检测voting disk上的信息

[ CSSD]2011-04-23 17:13:18.337 [3032460176] >TRACE: clssnmCheckDskInfo: node 1, vrh1, state 5 with leader 1 has smaller cluster size 1; my cluster size 2 with leader 2

发现其他子集群,包含1号节点且1号节点为该子集群的leader,为最小子集群;3号与2号节点组成最大子集群,2号节点为leader节点

[    CSSD]2011-04-23 17:13:18.337 [3032460176] >TRACE:   clssnmEvict: Start
[ CSSD]2011-04-23 17:13:18.337 [3032460176] >TRACE: clssnmEvict: Evicting node 1, vrh1, birth 9, death 10, 
impendingrcfg 1, stateflags 0x40d 
发起对1号节点的驱逐

[    CSSD]2011-04-23 17:13:18.337 [3032460176] >TRACE:   clssnmSendShutdown: req to node 1, kill time 443294
[    CSSD]2011-04-23 17:13:18.339 [3032460176] >TRACE:   clssnmDiscHelper: vrh1, node(1) connection failed, con (0xb7eaf220), probe((nil))
[    CSSD]2011-04-23 17:13:18.340 [3032460176] >TRACE:   clssnmWaitOnEvictions: Start
[    CSSD]2011-04-23 17:13:18.340 [3032460176] >TRACE:   clssnmWaitOnEvictions: node 1, vrh1, undead 1
[    CSSD]2011-04-23 17:13:18.340 [3032460176] >TRACE:   clssnmCheckKillStatus: Node 1, vrh1, down, LATS(443144),timeout(150)

clssnmCheckKillStatus检查1号节点是否down了

[    CSSD]2011-04-23 17:13:18.340 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (15)
[    CSSD]2011-04-23 17:13:18.340 [3032460176] >TRACE:   clssnmSetupAckWait: node(2) is ACTIVE
[    CSSD]2011-04-23 17:13:18.340 [3032460176] >TRACE:   clssnmSetupAckWait: node(3) is ACTIVE
[    CSSD]2011-04-23 17:13:18.340 [3032460176] >TRACE:   clssnmSendUpdate: syncSeqNo(10)
[    CSSD]2011-04-23 17:13:18.341 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(15), ackCount(2)
[    CSSD]2011-04-23 17:13:18.341 [89033616] >TRACE:   clssnmUpdateNodeState: node 0, state (0/0) unique (0/0) prevConuni(0) birth (0/0) (old/new)
[    CSSD]2011-04-23 17:13:18.341 [89033616] >TRACE:   clssnmUpdateNodeState: node 1, state (5/0) unique (1303592601/1303592601) prevConuni(1303592601) birth (9/9) (old/new)
[    CSSD]2011-04-23 17:13:18.341 [89033616] >TRACE:   clssnmDeactivateNode: node 1 (vrh1) left cluster

[    CSSD]2011-04-23 17:13:18.341 [89033616] >TRACE:   clssnmUpdateNodeState: node 2, state (3/3) unique (1303591210/1303591210) prevConuni(0) birth (2/2) (old/new)
[    CSSD]2011-04-23 17:13:18.341 [89033616] >TRACE:   clssnmUpdateNodeState: node 3, state (3/3) unique (1303591326/1303591326) prevConuni(0) birth (3/3) (old/new)
[    CSSD]2011-04-23 17:13:18.342 [89033616] >USER:    clssnmHandleUpdate: SYNC(10) from node(3) completed
[    CSSD]2011-04-23 17:13:18.342 [89033616] >USER:    clssnmHandleUpdate: NODE 2 (vrh2) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2011-04-23 17:13:18.342 [89033616] >USER:    clssnmHandleUpdate: NODE 3 (vrh3) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2011-04-23 17:13:18.342 [89033616] >TRACE:   clssnmHandleUpdate: diskTimeout set to (200000)ms
[    CSSD]2011-04-23 17:13:18.347 [3032460176] >TRACE:   clssnmWaitForAcks: done, msg type(15)
[    CSSD]2011-04-23 17:13:18.348 [3032460176] >TRACE:   clssnmDoSyncUpdate: Sync 10 complete!
[    CSSD]2011-04-23 17:13:18.350 [3021970320] >TRACE:   clssgmReconfigThread:  started for reconfig (10)
[    CSSD]2011-04-23 17:13:18.350 [3021970320] >USER:    NMEVENT_RECONFIG [00][00][00][0c]
[    CSSD]2011-04-23 17:13:18.351 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock crs_version type 2
[    CSSD]2011-04-23 17:13:18.352 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(crs_version) birth(9/9)
[    CSSD]2011-04-23 17:13:18.353 [3063929744] >TRACE:   clssgmDispatchCMXMSG(): got message type(7) src(2) incarn(10) during incarn(9/9)
[    CSSD]2011-04-23 17:13:18.354 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_FAILOVER type 3
[    CSSD]2011-04-23 17:13:18.355 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock EVMDMAIN type 2
[    CSSD]2011-04-23 17:13:18.355 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(EVMDMAIN) birth(9/9)
[    CSSD]2011-04-23 17:13:18.355 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock CRSDMAIN type 2
[    CSSD]2011-04-23 17:13:18.355 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(CRSDMAIN) birth(9/9)
[    CSSD]2011-04-23 17:13:18.355 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh1 type 3
[    CSSD]2011-04-23 17:13:18.355 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh2 type 3
[    CSSD]2011-04-23 17:13:18.356 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh3 type 3
[    CSSD]2011-04-23 17:13:18.356 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock ocr_crs type 2
[    CSSD]2011-04-23 17:13:18.356 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(ocr_crs) birth(9/9)
[    CSSD]2011-04-23 17:13:18.356 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock #CSS_CLSSOMON type 2
[    CSSD]2011-04-23 17:13:18.356 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(#CSS_CLSSOMON) birth(9/9)
[    CSSD]2011-04-23 17:13:18.357 [3021970320] >TRACE:   clssgmEstablishConnections: 2 nodes in cluster incarn 10
[    CSSD]2011-04-23 17:13:18.366 [3063929744] >TRACE:   clssgmPeerDeactivate: node 1 (vrh1), death 10, state 0x80000000 connstate 0xa
[    CSSD]2011-04-23 17:13:18.367 [3063929744] >TRACE:   clssgmHandleDBDone(): src/dest (2/65535) size(68) incarn 10
[    CSSD]2011-04-23 17:13:18.367 [3063929744] >TRACE:   clssgmPeerListener: connects done (2/2)
[    CSSD]2011-04-23 17:13:18.369 [3021970320] >TRACE:   clssgmEstablishMasterNode: MASTER for 10 is node(2) birth(2)

更新阶段   

[    CSSD]CLSS-3000: reconfiguration successful, incarnation 10 with 2 nodes

[    CSSD]CLSS-3001: local node number 3, master node number 2

[    CSSD]2011-04-23 17:13:18.372 [3021970320] >TRACE:   clssgmReconfigThread:  completed for reconfig(10), with status(1)

2.另一场景为1号节点未加入集群,2号节点的网络失败,因2号节点的member number较小故其通过voting disk向3号节点发起驱逐

以下为2号节点的ocssd.log日志

[    CSSD]2011-04-23 17:41:48.643 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 50 8.910601e-269artbeat fatal, eviction in 29.890 seconds
[    CSSD]2011-04-23 17:41:48.643 [3053439888] >TRACE:   clssnmPollingThread: node vrh3 (3) is impending reconfig, flag 1037, misstime 30110
[    CSSD]2011-04-23 17:41:48.643 [3053439888] >TRACE:   clssnmPollingThread: diskTimeout set to (57000)ms impending reconfig status(1)
[    CSSD]2011-04-23 17:41:50.132 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 50 8.910601e-269artbeat fatal, eviction in 28.890 seconds
[    CSSD]2011-04-23 17:42:10.533 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 75 8.910601e-269artbeat fatal, eviction in 14.860 seconds
[    CSSD]2011-04-23 17:42:11.962 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 75 8.910601e-269artbeat fatal, eviction in 13.860 seconds
[    CSSD]2011-04-23 17:42:23.523 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 8.910601e-269artbeat fatal, eviction in 5.840 seconds
[    CSSD]2011-04-23 17:42:24.989 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 8.910601e-269artbeat fatal, eviction in 4.840 seconds
[    CSSD]2011-04-23 17:42:26.423 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 8.910601e-269artbeat fatal, eviction in 3.840 seconds
[    CSSD]2011-04-23 17:42:27.890 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 8.910601e-269artbeat fatal, eviction in 2.840 seconds
[    CSSD]2011-04-23 17:42:29.382 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 8.910601e-269artbeat fatal, eviction in 1.840 seconds
[    CSSD]2011-04-23 17:42:30.832 [3053439888] >WARNING: clssnmPollingThread: node vrh3 (3) at 90 8.910601e-269artbeat fatal, eviction in 0.830 seconds
[    CSSD]2011-04-23 17:42:32.020 [3053439888] >TRACE:   clssnmPollingThread: Eviction started for node vrh3 (3), flags 0x040d, state 3, wt4c 0
[    CSSD]2011-04-23 17:42:32.020 [3032460176] >TRACE:   clssnmDoSyncUpdate: Initiating sync 13
[    CSSD]2011-04-23 17:42:32.020 [3032460176] >TRACE:   clssnmDoSyncUpdate: diskTimeout set to (57000)ms
[    CSSD]2011-04-23 17:42:32.020 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (11)
[    CSSD]2011-04-23 17:42:32.020 [3032460176] >TRACE:   clssnmSetupAckWait: node(2) is ALIVE
[    CSSD]2011-04-23 17:42:32.020 [3032460176] >TRACE:   clssnmSendSync: syncSeqNo(13)
[    CSSD]2011-04-23 17:42:32.021 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(11), ackCount(1)
[    CSSD]2011-04-23 17:42:32.021 [117574544] >TRACE:   clssnmHandleSync: diskTimeout set to (57000)ms
[    CSSD]2011-04-23 17:42:32.021 [117574544] >TRACE:   clssnmHandleSync: Acknowledging sync: src[2] srcName[vrh2] seq[13] sync[13]
[    CSSD]2011-04-23 17:42:32.021 [3032460176] >TRACE:   clssnmWaitForAcks: done, msg type(11)
[    CSSD]2011-04-23 17:42:32.021 [3032460176] >TRACE:   clssnmDoSyncUpdate: Terminating node 3, vrh3, misstime(60000) state(5)
[    CSSD]2011-04-23 17:42:32.021 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (13)
[    CSSD]2011-04-23 17:42:32.021 [3032460176] >TRACE:   clssnmSetupAckWait: node(2) is ACTIVE
[    CSSD]2011-04-23 17:42:32.021 [5073104] >USER:    NMEVENT_SUSPEND [00][00][00][0c]
[    CSSD]2011-04-23 17:42:32.021 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(13), ackCount(1)
[    CSSD]2011-04-23 17:42:32.022 [117574544] >TRACE:   clssnmSendVoteInfo: node(2) syncSeqNo(13)
[    CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE:   clssnmWaitForAcks: done, msg type(13)
[    CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE:   clssnmCheckDskInfo: Checking disk info...
[ CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE: clssnmCheckDskInfo: node 3, vrh3, state 5 with leader 3 
has smaller cluster size 1; my cluster size 1 with leader 2 检查voting disk后发现子集群3为最小"子集群"(3号节点的node number较2号大);2号节点为最大子集群 [ CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE: clssnmEvict: Start [ CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE: clssnmEvict: Evicting node 3, vrh3, birth 3, death 13, impendingrcfg 1, stateflags 0x40d [ CSSD]2011-04-23 17:42:32.022 [3032460176] >TRACE: clssnmSendShutdown: req to node 3, kill time 1643084 发起对3号节点的驱逐和shutdown request

[    CSSD]2011-04-23 17:42:32.023 [3032460176] >TRACE:   clssnmDiscHelper: vrh3, node(3) connection failed, con (0xb7e79bb0), probe((nil))
[    CSSD]2011-04-23 17:42:32.023 [3032460176] >TRACE:   clssnmWaitOnEvictions: Start
[    CSSD]2011-04-23 17:42:32.023 [3032460176] >TRACE:   clssnmWaitOnEvictions: node 3, vrh3, undead 1
[    CSSD]2011-04-23 17:42:32.023 [3032460176] >TRACE:   clssnmCheckKillStatus: Node 3, vrh3, down, LATS(1642874),timeout(210)
[    CSSD]2011-04-23 17:42:32.023 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (15)
[    CSSD]2011-04-23 17:42:32.023 [3032460176] >TRACE:   clssnmSetupAckWait: node(2) is ACTIVE
[    CSSD]2011-04-23 17:42:32.023 [3032460176] >TRACE:   clssnmSendUpdate: syncSeqNo(13)
[    CSSD]2011-04-23 17:42:32.024 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(15), ackCount(1)
[    CSSD]2011-04-23 17:42:32.024 [117574544] >TRACE:   clssnmUpdateNodeState: node 0, state (0/0) unique (0/0) prevConuni(0) birth (0/0) (old/new)
[    CSSD]2011-04-23 17:42:32.024 [117574544] >TRACE:   clssnmUpdateNodeState: node 1, state (0/0) unique (0/0) prevConuni(0) birth (0/0) (old/new)
[    CSSD]2011-04-23 17:42:32.024 [117574544] >TRACE:   clssnmUpdateNodeState: node 2, state (3/3) unique (1303591210/1303591210) prevConuni(0) birth (2/2) (old/new)
[    CSSD]2011-04-23 17:42:32.024 [117574544] >TRACE:   clssnmUpdateNodeState: node 3, state (5/0) unique (1303591326/1303591326) prevConuni(1303591326) birth (3/3) (old/new)
[    CSSD]2011-04-23 17:42:32.024 [117574544] >TRACE:   clssnmDeactivateNode: node 3 (vrh3) left cluster

[    CSSD]2011-04-23 17:42:32.024 [117574544] >USER:    clssnmHandleUpdate: SYNC(13) from node(2) completed
[    CSSD]2011-04-23 17:42:32.024 [117574544] >USER:    clssnmHandleUpdate: NODE 2 (vrh2) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2011-04-23 17:42:32.024 [117574544] >TRACE:   clssnmHandleUpdate: diskTimeout set to (200000)ms
[    CSSD]2011-04-23 17:42:32.024 [3032460176] >TRACE:   clssnmWaitForAcks: done, msg type(15)
[    CSSD]2011-04-23 17:42:32.024 [3032460176] >TRACE:   clssnmDoSyncUpdate: Sync 13 complete!
[    CSSD]2011-04-23 17:42:32.024 [3021970320] >TRACE:   clssgmReconfigThread:  started for reconfig (13)
[    CSSD]2011-04-23 17:42:32.024 [3021970320] >USER:    NMEVENT_RECONFIG [00][00][00][04]
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock crs_version type 2
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(2) grock(crs_version) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_FAILOVER type 3
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(_ORA_CRS_FAILOVER) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock EVMDMAIN type 2
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(3) grock(EVMDMAIN) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock CRSDMAIN type 2
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(3) grock(CRSDMAIN) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh1 type 3
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(_ORA_CRS_MEMBER_vrh1) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_vrh3 type 3
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(_ORA_CRS_MEMBER_vrh3) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock ocr_crs type 2
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(3) grock(ocr_crs) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupGrocks: cleaning up grock #CSS_CLSSOMON type 2
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(3) grock(#CSS_CLSSOMON) birth(3/3)
[    CSSD]2011-04-23 17:42:32.025 [3021970320] >TRACE:   clssgmEstablishConnections: 1 nodes in cluster incarn 13
[    CSSD]2011-04-23 17:42:32.026 [3063929744] >TRACE:   clssgmPeerDeactivate: node 3 (vrh3), death 13, state 0x0 connstate 0xf
[    CSSD]2011-04-23 17:42:32.026 [3063929744] >TRACE:   clssgmPeerListener: connects done (1/1)
[    CSSD]2011-04-23 17:42:32.026 [3021970320] >TRACE:   clssgmEstablishMasterNode: MASTER for 13 is node(2) birth(2)
[    CSSD]2011-04-23 17:42:32.026 [3021970320] >TRACE:   clssgmMasterCMSync: Synchronizing group/lock status
[    CSSD]2011-04-23 17:42:32.026 [3021970320] >TRACE:   clssgmMasterSendDBDone: group/lock status synchronization complete
[    CSSD]CLSS-3000: reconfiguration successful, incarnation 13 with 1 nodes

[    CSSD]CLSS-3001: local node number 2, master node number 2

完成reconfiguration

[    CSSD]2011-04-23 17:42:32.027 [3021970320] >TRACE:   clssgmReconfigThread:  completed for reconfig(13), with status(1)

以下为3号节点的ocssd.log日志:

[    CSSD]2011-04-23 17:42:33.204 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 50 1.867300e-268artbeat fatal, eviction in 29.360 seconds
[    CSSD]2011-04-23 17:42:33.204 [3053439888] >TRACE:   clssnmPollingThread: node vrh2 (2) is impending reconfig, flag 1039, misstime 30640
[    CSSD]2011-04-23 17:42:33.204 [3053439888] >TRACE:   clssnmPollingThread: diskTimeout set to (57000)ms impending reconfig status(1)
[    CSSD]2011-04-23 17:42:55.168 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 75 1.867300e-268artbeat fatal, eviction in 14.330 seconds
[    CSSD]2011-04-23 17:43:08.182 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 1.867300e-268artbeat fatal, eviction in 5.310 seconds
[    CSSD]2011-04-23 17:43:09.661 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 1.867300e-268artbeat fatal, eviction in 4.300 seconds
[    CSSD]2011-04-23 17:43:11.144 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 1.867300e-268artbeat fatal, eviction in 3.300 seconds
[    CSSD]2011-04-23 17:43:12.634 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 1.867300e-268artbeat fatal, eviction in 2.300 seconds
[    CSSD]2011-04-23 17:43:14.053 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 1.867300e-268artbeat fatal, eviction in 1.300 seconds
[    CSSD]2011-04-23 17:43:15.467 [3053439888] >WARNING: clssnmPollingThread: node vrh2 (2) at 90 1.867300e-268artbeat fatal, eviction in 0.300 seconds
[    CSSD]2011-04-23 17:43:15.911 [3053439888] >TRACE:   clssnmPollingThread: Eviction started for node vrh2 (2), flags 0x040f, state 3, wt4c 0
[    CSSD]2011-04-23 17:43:15.911 [3032460176] >TRACE:   clssnmDoSyncUpdate: Initiating sync 13
[    CSSD]2011-04-23 17:43:15.911 [3032460176] >TRACE:   clssnmDoSyncUpdate: diskTimeout set to (57000)ms
[    CSSD]2011-04-23 17:43:15.911 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (11)
[    CSSD]2011-04-23 17:43:15.911 [3032460176] >TRACE:   clssnmSetupAckWait: node(3) is ALIVE
[    CSSD]2011-04-23 17:43:15.911 [3032460176] >TRACE:   clssnmSendSync: syncSeqNo(13)
[    CSSD]2011-04-23 17:43:15.911 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(11), ackCount(1)
[    CSSD]2011-04-23 17:43:15.912 [89033616] >TRACE:   clssnmHandleSync: diskTimeout set to (57000)ms
[    CSSD]2011-04-23 17:43:15.912 [89033616] >TRACE:   clssnmHandleSync: Acknowledging sync: src[3] srcName[vrh3] seq[29] sync[13]
[    CSSD]2011-04-23 17:43:15.912 [8136912] >USER:    NMEVENT_SUSPEND [00][00][00][0c]
[    CSSD]2011-04-23 17:43:15.912 [3032460176] >TRACE:   clssnmWaitForAcks: done, msg type(11)
[    CSSD]2011-04-23 17:43:15.912 [3032460176] >TRACE:   clssnmDoSyncUpdate: Terminating node 2, vrh2, misstime(60010) state(5)
[    CSSD]2011-04-23 17:43:15.912 [3032460176] >TRACE:   clssnmSetupAckWait: Ack message type (13)
[    CSSD]2011-04-23 17:43:15.912 [3032460176] >TRACE:   clssnmSetupAckWait: node(3) is ACTIVE
[    CSSD]2011-04-23 17:43:15.913 [89033616] >TRACE:   clssnmSendVoteInfo: node(3) syncSeqNo(13)
[    CSSD]2011-04-23 17:43:15.912 [3032460176] >TRACE:   clssnmWaitForAcks: Ack message type(13), ackCount(1)
[    CSSD]2011-04-23 17:43:15.913 [3032460176] >TRACE:   clssnmCheckDskInfo: Checking disk info...
[ CSSD]2011-04-23 17:43:15.913 [3032460176] >ERROR: clssnmCheckDskInfo: Aborting local node to avoid splitbrain. [ CSSD]2011-04-23 17:43:15.913 [3032460176] >ERROR: : my node(3), Leader(3), Size(1) VS Node(2), Leader(2), Size(1) 读取voting disk后发现kill block,为避免split brain,自我aborting!

[    CSSD]2011-04-23 17:43:15.913 [3032460176] >ERROR:   ###################################
[    CSSD]2011-04-23 17:43:15.913 [3032460176] >ERROR:   clssscExit: CSSD aborting
[    CSSD]2011-04-23 17:43:15.913 [3032460176] >ERROR:   ###################################
[    CSSD]--- DUMP GROCK STATE DB ---
[    CSSD]----------
[    CSSD]  type 2, Id 4, Name = (crs_version)
[    CSSD]  flags: 0x1000
[    CSSD]  grant: count=0, type 0, wait 0
[    CSSD]  Member Count =2, master 2
[    CSSD]   . . . . .
[    CSSD]     memberNo =2, seq 2
[    CSSD]     flags = 0x0, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 0
[    CSSD]   . . . . .
[    CSSD]     memberNo =1, seq 12
[    CSSD]     flags = 0x1000, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 2, nodeBirth 2
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 0
[    CSSD]----------
[    CSSD]----------
[    CSSD]  type 3, Id 11, Name = (_ORA_CRS_FAILOVER)
[    CSSD]  flags: 0x0
[    CSSD]  grant: count=1, type 3, wait 1
[    CSSD]  Member Count =1, master -3
[    CSSD]   . . . . .
[    CSSD]     memberNo =0, seq 0
[    CSSD]     flags = 0x12, granted 1
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 0
[    CSSD]----------
[    CSSD]----------
[    CSSD]  type 2, Id 2, Name = (EVMDMAIN)
[    CSSD]  flags: 0x1000
[    CSSD]  grant: count=0, type 0, wait 0
[    CSSD]  Member Count =2, master 2
[    CSSD]   . . . . .
[    CSSD]     memberNo =2, seq 1
[    CSSD]     flags = 0x0, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 2, nodeBirth 2
[    CSSD]     privateDataSize = 508
[    CSSD]     publicDataSize = 504
[    CSSD]   . . . . .
[    CSSD]     memberNo =3, seq 2
[    CSSD]     flags = 0x0, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 508
[    CSSD]     publicDataSize = 504
[    CSSD]----------
[    CSSD]----------
[    CSSD]  type 2, Id 5, Name = (CRSDMAIN)
[    CSSD]  flags: 0x1000
[    CSSD]  grant: count=0, type 0, wait 0
[    CSSD]  Member Count =1, master 3
[    CSSD]   . . . . .
[    CSSD]     memberNo =3, seq 2
[    CSSD]     flags = 0x0, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 128
[    CSSD]     publicDataSize = 128
[    CSSD]----------
[    CSSD]----------
[    CSSD]  type 3, Id 12, Name = (_ORA_CRS_MEMBER_vrh1)
[    CSSD]  flags: 0x0
[    CSSD]  grant: count=1, type 3, wait 1
[    CSSD]  Member Count =1, master -3
[    CSSD]   . . . . .
[    CSSD]     memberNo =0, seq 0
[    CSSD]     flags = 0x12, granted 1
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 0
[    CSSD]----------
[    CSSD]----------
[    CSSD]  type 3, Id 12, Name = (_ORA_CRS_MEMBER_vrh3)
[    CSSD]  flags: 0x0
[    CSSD]  grant: count=1, type 3, wait 1
[    CSSD]  Member Count =1, master -3
[    CSSD]   . . . . .
[    CSSD]     memberNo =0, seq 0
[    CSSD]     flags = 0x12, granted 1
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 0
[    CSSD]----------
[    CSSD]----------
[    CSSD]  type 2, Id 3, Name = (ocr_crs)
[    CSSD]  flags: 0x1000
[    CSSD]  grant: count=0, type 0, wait 0
[    CSSD]  Member Count =2, master 3
[    CSSD]   . . . . .
[    CSSD]     memberNo =3, seq 2
[    CSSD]     flags = 0x0, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 32
[    CSSD]   . . . . .
[    CSSD]     memberNo =2, seq 12
[    CSSD]     flags = 0x1000, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 2, nodeBirth 2
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 32
[    CSSD]----------
[    CSSD]----------
[    CSSD]  type 2, Id 1, Name = (#CSS_CLSSOMON)
[    CSSD]  flags: 0x1000
[    CSSD]  grant: count=0, type 0, wait 0
[    CSSD]  Member Count =2, master 2
[    CSSD]   . . . . .
[    CSSD]     memberNo =2, seq 1
[    CSSD]     flags = 0x1000, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 2, nodeBirth 2
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 0
[    CSSD]   . . . . .
[    CSSD]     memberNo =3, seq 2
[    CSSD]     flags = 0x1000, granted 0
[    CSSD]     refCnt = 1
[    CSSD]     nodeNum = 3, nodeBirth 3
[    CSSD]     privateDataSize = 0
[    CSSD]     publicDataSize = 0
[    CSSD]----------
[    CSSD]--- END OF GROCK STATE DUMP ---
[    CSSD]------- Begin Dump -------

ORA-20001错误一例

一套11.1.0.7上的Oracle Application Object Library应用程序,在收集schema统计信息时出现了ORA-20001错误,具体错误日志如下:

SQL> exec fnd_stats.gather_schema_statistics('AP');

PL/SQL procedure successfully completed.

SQL> show error
No errors.
============================================
Concurrent request error Log
------------------------------------
**Starts**14-APR-2011 02:20:53
**Ends**14-APR-2011 04:40:43
ORA-0000: normal, successful completion
+---------------------------------------------------------------------------+
Start of log messages from FND_FILE
+---------------------------------------------------------------------------+
In GATHER_SCHEMA_STATS , schema_name= ALL percent= 10 degree = 8 internal_flag= NOBACKUP
stats on table AQ$_WF_CONTROL_P is locked 
stats on table FND_CP_GSM_IPC_AQTBL is locked 
stats on table WF_NOTIFICATION_OUT is locked 
Error #1: ERROR: While GATHER_TABLE_STATS:
object_name=AP.JE_FR_DAS_010***ORA-20001: invalid column name or 
duplicate columns/column groups/expressions in method_opt***
Error #2: ERROR: While GATHER_TABLE_STATS:
object_name=AP.JE_FR_DAS_010_NEW***ORA-20001: invalid column name or 
duplicate columns/column groups/expressions in method_opt***
Error #3: ERROR: While GATHER_TABLE_STATS:
object_name=AP.JG_ZZ_SYS_FORMATS_ALL_B***ORA-20001: invalid column name or 
duplicate columns/column groups/expressions in method_opt***
+---------------------------------------------------------------------------+
End of log messages from FND_FILE
+---------------------------------------------------------------------------+

经确认该问题由bug 7601966: GATHER SCHEMA STATS ON AP SCHEMA FAILS WITH ORA-20001: INVALID COLUMN NAME 引起,可以通过follow文档<Gather Schema Statistics fails with Ora-20001 errors after 11G database upgrade [ID 781813.1]>解决该问题。

Probe how does your PGA consume

前2天有客户报一套10.2.0.3的数据库个别服务进程PGA使用量暴涨,疑似内存泄露(memory leak);遂提供on-site service,赶到用户现场时问题进程已经消失,系统内存使用量恢复正常,客户之前除了保留了v$process动态性能视图的信息外未抓取其他有用的诊断信息。

查看保存的v$process视图信息可以看到进程991714的PGA内存使用量达到13个G:

select spid,program,PGA_USED_MEM,PGA_ALLOC_MEM from v$process;
SPID                     PROGRAM                                          PGA_USED_MEM PGA_ALLOC_MEM
------------------------ ------------------------------------------------ ------------ -------------
991714                         oracleBTS@oam_app_a             14427510986 14432001786

oracle@oam_app_a@/oracle/product/10.2.0/dbs $ ulimit -a
time(seconds)        unlimited
file(blocks)         unlimited
data(kbytes)         unlimited
stack(kbytes)        4194304
memory(kbytes)       unlimited
coredump(blocks)     unlimited
nofiles(descriptors) unlimited

SQL> select x.ksppinm name,y.ksppstvl value
  2  from sys.x$ksppi x, sys.x$ksppcv y
  3  where x.inst_id=USERENV('Instance')
  4  and y.inst_id = USERENV('Instance')
  5  and x.indx = y.indx
  6  and x.ksppinm like '%pga%';

pga_aggregate_target
200715200

NAME
--------------------------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
_pga_max_size
209715200

SQL> select x.ksppinm name,y.ksppstvl value
  2  from sys.x$ksppi x, sys.x$ksppcv y
  3  where x.inst_id=USERENV('Instance')
  4  and y.inst_id = USERENV('Instance')
  5  and x.indx = y.indx
  6  and x.ksppinm like '%hash_join%';

NAME
--------------------------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
_hash_join_enabled
TRUE

SQL> show parameter work

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
fileio_network_adapters              string
workarea_size_policy                 string      AUTO

可以看到该系统使用自动PGA管理且pga_aggregate_target参数值为较小的191M,查询隐藏参数_pga_max_size可发现该参数值也为191M。

从告警日志alert.log中找不到任何信息,单个服务进程PGA使用量达到13G居然没有报ORA-04030错误!

到实例的user_dump目录下ls -ltr了一把有意外收获,找到了该991714进程最近的trace文件:

Dump file /oracle/product/10.2.0/admin/BTS/udump/bts_ora_991714.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /oracle/product/10.2.0
System name:    AIX
Node name:      oam_app_a
Release:        3
Version:        5
Machine:        0000E5DBD600
Instance name: BTS
Redo thread mounted by this instance: 1
Oracle process number: 46
Unix process pid: 991714, image: oracleBTS@oam_app_a

*** 2011-04-19 18:27:07.766
*** SERVICE NAME:(SYS$USERS) 2011-04-19 18:27:07.733
*** SESSION ID:(248.45987) 2011-04-19 18:27:07.733
WARNING: out of private memory [1]

以上trace文件中唯一有用的信息就是”WARNING: out of private memory [1]”了,但在metalink上搜索”out of private memory”找不到任何有用的信息;因为未发生ORA-04030错误,而用户也没有手动去收集过PGA Heap的堆使用情况,所以未产生任何对该进程PGA内存使用细节描述的转储信息文件,难以从dump信息中获取线索继续探索,线索断裂。

通过查询PGA状态历史记录视图可以发现在之前的2个快照时间窗口内,inused PGA总量为13G,之后PGA内存使用量又恢复正常:

select * from dba_hist_pgastat where name='total PGA inuse' order by value asc
 SNAP_ID       DBID INSTANCE_NUMBER NAME                                                                  VALUE
---------- ---------- --------------- ---------------------------------------------------------------- ----------
     16048 3731271451               1 total PGA inuse                                                  1.4883E+10
     16047 3731271451               1 total PGA inuse                                                  1.4888E+10

查询在以上时间窗口中991714的活动会话记录,可以发现该进程一直处于”cursor: pin S wait on X”中;Oracle 10.2.0.2以后利用mutex来替代latch保护SQL游标,当硬解析发生时会出现”cursor: pin s wait on X”等待。这里可以看到需要硬解析的SQL的ID为”bp7y9fvtqra1h”,而且此处SQL_CHILD_NUMBER为-1,说明Oracle共享池中之前没有缓存该SQL游标,该问题进程是首次为该SQL语句执行硬解析。

     	SNAP_ID	DBID	INSTANCE_NUMBER	SAMPLE_ID	SAMPLE_TIME	SESSION_ID	SESSION_SERIAL#	USER_ID	SQL_ID	SQL_CHILD_NUMBER	SQL_PLAN_HASH_VALUE	FORCE_MATCHING_SIGNATURE	SQL_OPCODE	PLSQL_ENTRY_OBJECT_ID	PLSQL_ENTRY_SUBPROGRAM_ID	PLSQL_OBJECT_ID	PLSQL_SUBPROGRAM_ID	SERVICE_HASH	SESSION_TYPE	SESSION_STATE	QC_SESSION_ID	QC_INSTANCE_ID	BLOCKING_SESSION	BLOCKING_SESSION_STATUS	BLOCKING_SESSION_SERIAL#	EVENT	EVENT_ID	SEQ#	P1TEXT	P1	P2TEXT	P2	P3TEXT	P3	WAIT_CLASS	WAIT_CLASS_ID	WAIT_TIME	TIME_WAITED	XID	CURRENT_OBJ#	CURRENT_FILE#	CURRENT_BLOCK#	PROGRAM	MODULE	ACTION	CLIENT_ID
1	16047	3731271451	1	57716200	19-4月 -11 04.00.35.625 下午	248	45987	25	bp7y9fvtqra1h	-1	0	0	0					3427055676	FOREGROUND	WAITING				UNKNOWN		cursor: pin S wait on X	1729366244	1140	idn	4083918896	value	1.14676E+12	where|sleeps	21474836525	Concurrency	3875070507	0	9772		-1	0	0
2	16047	3731271451	1	57716210	19-4月 -11 04.00.45.629 下午	248	45987	25	bp7y9fvtqra1h	-1	0	0	0					3427055676	FOREGROUND	WAITING				UNKNOWN		cursor: pin S wait on X	1729366244	2137	idn	4083918896	value	1.14676E+12	where|sleeps	21474837522	Concurrency	3875070507	0	9773		-1	0	0
3	16047	3731271451	1	57716220	19-4月 -11 04.00.55.633 下午	248	45987	25	bp7y9fvtqra1h	-1	0	0	0					3427055676	FOREGROUND	WAITING				UNKNOWN		cursor: pin S wait on X	1729366244	3134	idn	4083918896	value	1.14676E+12	where|sleeps	21474838519	Concurrency	3875070507	0	9775		-1	0	0
4	16047	3731271451	1	57716230	19-4月 -11 04.01.05.637 下午	248	45987	25	bp7y9fvtqra1h	-1	0	0	0					3427055676	FOREGROUND	WAITING				UNKNOWN		cursor: pin S wait on X	1729366244	4126	idn	4083918896	value	1.14676E+12	where|sleeps	21474839511	Concurrency	3875070507	0	9772		-1	0	0

但无论是从SQL历史记录视图(Workload Repository)还是v$SQL中都无法找到该条语句,可以判断该问题进程最后也没能成功完成对该’bp7y9fvtqra1h’语句的解析!因为没有该SQL的记录,所以也无法了解该SQL的执行计划和workarea工作区的使用状况,线索再次断裂!

SQL> select * from dba_hist_sqltext where sql_id='bp7y9fvtqra1h';

no rows selected

SQL> select * From v$sql where sql_id='bp7y9fvtqra1h';

no rows selected

通过查询进程内存使用总结历史视图dba_hist_process_mem_summary可以发现占用主要内存的分类是Other,猜测这些Other内存是用来解析游标使用的临时内存(call heap).

SQL> select snap_id,category,num_processes,non_zero_allocs,used_total,allocated_total,allocated_max from dba_hist_process_mem_summary where snap_id in (16047,16048,16049) order by allocated_total desc ,snap_id ;

   SNAP_ID CATEGORY        NUM_PROCESSES NON_ZERO_ALLOCS USED_TOTAL ALLOCATED_TOTAL ALLOCATED_MAX
---------- --------------- ------------- --------------- ---------- --------------- -------------
     16047 Other                      95              95                 1.5062E+10    1.4665E+10
     16048 Other                      96              96                 1.5053E+10    1.4664E+10
     16049 Other                      94              94                  386117660      53794202
     16047 Freeable                   36              36          0        36372480       3670016
     16048 Freeable                   33              33          0        32112640       3670016
     16047 SQL                        78              31   27346656        29785568      28016616
     16048 SQL                        79              34   26812992        29240400      27885544
     16049 Freeable                   27              27          0        26738688       3670016
     16049 SQL                        77              31     591528         1242168        125816
     16048 PL/SQL                     96              96     272224          601040         68944
     16049 PL/SQL                     94              94     218104          536592         68944
     16047 PL/SQL                     95              95     212816          506536         68800

因为证据断裂,无法根据现有的信息为该服务进程过量使用PGA内存来定位Bug。到MOS上搜索找不到类似的Bug,但即使有也很难定论,因为没有heapdump的话即便提交SR,Oracle GCS(Global Customer Service)也不太愿定位到Bug。

那么如果出现以上类似的PGA内存泄露的问题,我们因当如何第一时间收集有用的信息,以供后续诊断呢?我在这里提供一些可选的方案:

  1. 定期收集系统内PGA/UGA的使用情况,具体可以使用脚本<Script To Monitor RDBMS Session UGA and PGA Current And Maximum Usage>
  2. 防御式地在系统级别设置4030 dump heapdump 536870917级别的event dump事件,虽然此案例中未发生ORA-04030错误,但不代表下一次也不发生
  3. 在问题发生时,第一时间使用oradebug PGA_DETAIL_GET命令填充v$process_memory_detail视图,以便了解问题进程PGA内存的使用细节
  4. 若觉得v$process_memory_detail动态性能视图的信息还不够丰富的话,也可以做systemstate 266和heapdump 536870917级别的dump

虽然以上我们介绍了一些针对PGA内存泄露问题发生时的诊断方法,但可能你还是不了解具体要如何实践,接下来我们通过实践来体会一下,首先我们特意构建一个PGA内存泄露的假象(测试说明,不要用于生产环境!!):

[oracle@rh2 ~]$ wc -l very_large.sql 
18526 very_large.sql

/* 这里very_large.sql是我们"精心"构造的一条万分复杂的SQL语句,解析该SQL语句需要消耗大量的PGA内存 !!* /

SQL> @very_large

/* 执行very_large SQL语句开始模拟内存泄露,将持续较长时间  */

SQL> @MEMORY_USAGE_SCRIPT.SQL

Oracle Memory Usage Report: PGA And UGA Memory Usage Per Session

Host........: rh2.oracle.com

Name........: PROD1

Version.....: 11.2.0.2.0

Startup Time: 2011-04-20 19:41:32

Current Time: 2011.04.21-19:57:16

Worst possible value of concurrent PGA + UGA memory usage per session:

SID AND SERIAL#     USERNAME OR PROGRAM                              SUM(VALUE) SESSION START TIME
------------------- ------------------------------------------------ ---------- -------------------
29,465              SYS                                               180444688 2011-04-21 19:52:16
152,987             SYS                                                67781616 2011-04-21 18:40:59
146,1               oracle@rh2.oracle.com (ARC3)                       37598184 2011-04-20 19:41:43
19,5                oracle@rh2.oracle.com (ARC2)                       36484072 2011-04-20 19:41:43
17,7                oracle@rh2.oracle.com (ARC0)                       33141736 2011-04-20 19:41:42
145,1               oracle@rh2.oracle.com (ARC1)                       19837928 2011-04-20 19:41:43
125,7               oracle@rh2.oracle.com (CJQ0)                       15826432 2011-04-20 19:41:50
135,1               oracle@rh2.oracle.com (LGWR)                       13480936 2011-04-20 19:41:33
131,1               oracle@rh2.oracle.com (LMS0)                       11973608 2011-04-20 19:41:33
7,1                 oracle@rh2.oracle.com (LMS1)                       11973608 2011-04-20 19:41:33
6,1                 oracle@rh2.oracle.com (LMD0)                       11842536 2011-04-20 19:41:33
5,1                 oracle@rh2.oracle.com (DIA0)                       10580296 2011-04-20 19:41:33
25,57               SYS                                                 9854112 2011-04-21 19:56:59
10,1                oracle@rh2.oracle.com (DBW0)                        9105992 2011-04-20 19:41:33
136,1               oracle@rh2.oracle.com (SMON)                        8777056 2011-04-20 19:41:33
140,1               oracle@rh2.oracle.com (MARK)                        8565736 2011-04-20 19:41:33
130,1               oracle@rh2.oracle.com (LMON)                        8238120 2011-04-20 19:41:33
138,1               oracle@rh2.oracle.com (MMON)                        7215184 2011-04-20 19:41:33
31,1                oracle@rh2.oracle.com (SMCO)                        7123896 2011-04-20 19:43:52
3,1                 oracle@rh2.oracle.com (DIAG)                        6730728 2011-04-20 19:41:33
16,1                oracle@rh2.oracle.com (RSMN)                        5420008 2011-04-20 19:41:35
150,5               oracle@rh2.oracle.com (Q000)                        5001608 2011-04-20 19:41:46
23,1                oracle@rh2.oracle.com (Q001)                        3445984 2011-04-20 19:41:46
22,1                oracle@rh2.oracle.com (QMNC)                        3314960 2011-04-20 19:41:45
12,1                oracle@rh2.oracle.com (RECO)                        3249448 2011-04-20 19:41:33
11,1                oracle@rh2.oracle.com (CKPT)                        3086120 2011-04-20 19:41:33
128,1               oracle@rh2.oracle.com (DBRM)                        2667304 2011-04-20 19:41:33
14,1                oracle@rh2.oracle.com (MMNL)                        2143208 2011-04-20 19:41:33
127,1               oracle@rh2.oracle.com (GEN0)                        2012136 2011-04-20 19:41:33
158,183             SYS                                                 1758344 2011-04-21 07:44:57
143,23              SYS                                                 1692808 2011-04-21 07:45:01
142,1               oracle@rh2.oracle.com (LCK0)                        1299288 2011-04-20 19:41:34
149,1               oracle@rh2.oracle.com (RCBG)                        1160120 2011-04-20 19:41:45
33,59               oracle@rh2.oracle.com (W000)                         963512 2011-04-21 19:55:14
4,1                 oracle@rh2.oracle.com (PING)                         898024 2011-04-20 19:41:33
126,1               oracle@rh2.oracle.com (PSP0)                         832488 2011-04-20 19:41:32
13,1                oracle@rh2.oracle.com (ASMB)                         832488 2011-04-20 19:41:33
134,1               oracle@rh2.oracle.com (MMAN)                         832488 2011-04-20 19:41:33
144,1               oracle@rh2.oracle.com (O000)                         832488 2011-04-20 19:41:36
129,1               oracle@rh2.oracle.com (ACMS)                         832488 2011-04-20 19:41:33
133,1               oracle@rh2.oracle.com (RMS0)                         832488 2011-04-20 19:41:33
1,1                 oracle@rh2.oracle.com (PMON)                         832488 2011-04-20 19:41:32
9,1                 oracle@rh2.oracle.com (LMHB)                         832488 2011-04-20 19:41:33
21,1                oracle@rh2.oracle.com (GTX0)                         832488 2011-04-20 19:41:45
18,3                oracle@rh2.oracle.com (O001)                         832488 2011-04-20 19:41:37
137,1               oracle@rh2.oracle.com (RBAL)                         832488 2011-04-20 19:41:33
2,1                 oracle@rh2.oracle.com (VKTM)                         832488 2011-04-20 19:41:33

Worst possible total and average values of concurrent PGA + UGA memory usage:

564679192 bytes (total) and ~6007225 bytes (average), for ~47 sessions.

Approximate value of current PGA + UGA memory usage per session:

SID AND SERIAL#     USERNAME OR PROGRAM                              SUM(VALUE) SESSION START TIME
------------------- ------------------------------------------------ ---------- -------------------
29,465              SYS                                               178083824 2011-04-21 19:52:16
146,1               oracle@rh2.oracle.com (ARC3)                       36484072 2011-04-20 19:41:43
19,5                oracle@rh2.oracle.com (ARC2)                       35369960 2011-04-20 19:41:43
17,7                oracle@rh2.oracle.com (ARC0)                       33141736 2011-04-20 19:41:42
145,1               oracle@rh2.oracle.com (ARC1)                       19837928 2011-04-20 19:41:43
135,1               oracle@rh2.oracle.com (LGWR)                       13480936 2011-04-20 19:41:33
7,1                 oracle@rh2.oracle.com (LMS1)                       11973608 2011-04-20 19:41:33
131,1               oracle@rh2.oracle.com (LMS0)                       11973608 2011-04-20 19:41:33
6,1                 oracle@rh2.oracle.com (LMD0)                       11842536 2011-04-20 19:41:33
5,1                 oracle@rh2.oracle.com (DIA0)                       10580296 2011-04-20 19:41:33
10,1                oracle@rh2.oracle.com (DBW0)                        8712776 2011-04-20 19:41:33
140,1               oracle@rh2.oracle.com (MARK)                        8565736 2011-04-20 19:41:33
130,1               oracle@rh2.oracle.com (LMON)                        8238120 2011-04-20 19:41:33
3,1                 oracle@rh2.oracle.com (DIAG)                        6730728 2011-04-20 19:41:33
152,987             SYS                                                 6224040 2011-04-21 18:40:59
16,1                oracle@rh2.oracle.com (RSMN)                        5420008 2011-04-20 19:41:35
125,7               oracle@rh2.oracle.com (CJQ0)                        4854824 2011-04-20 19:41:50
25,57               SYS                                                 4738504 2011-04-21 19:56:59
138,1               oracle@rh2.oracle.com (MMON)                        4165448 2011-04-20 19:41:33
136,1               oracle@rh2.oracle.com (SMON)                        3863504 2011-04-20 19:41:33
150,5               oracle@rh2.oracle.com (Q000)                        3108848 2011-04-20 19:41:46
11,1                oracle@rh2.oracle.com (CKPT)                        2561832 2011-04-20 19:41:33
12,1                oracle@rh2.oracle.com (RECO)                        2538120 2011-04-20 19:41:33
31,1                oracle@rh2.oracle.com (SMCO)                        2536376 2011-04-20 19:43:52
128,1               oracle@rh2.oracle.com (DBRM)                        2339768 2011-04-20 19:41:33
23,1                oracle@rh2.oracle.com (Q001)                        2339672 2011-04-20 19:41:46
22,1                oracle@rh2.oracle.com (QMNC)                        2242336 2011-04-20 19:41:45
127,1               oracle@rh2.oracle.com (GEN0)                        2012136 2011-04-20 19:41:33
14,1                oracle@rh2.oracle.com (MMNL)                        1946600 2011-04-20 19:41:33
158,183             SYS                                                 1692856 2011-04-21 07:44:57
143,23              SYS                                                 1561784 2011-04-21 07:45:01
142,1               oracle@rh2.oracle.com (LCK0)                        1299288 2011-04-20 19:41:34
149,1               oracle@rh2.oracle.com (RCBG)                        1160120 2011-04-20 19:41:45
33,59               oracle@rh2.oracle.com (W000)                         963512 2011-04-21 19:55:14
4,1                 oracle@rh2.oracle.com (PING)                         898024 2011-04-20 19:41:33
13,1                oracle@rh2.oracle.com (ASMB)                         832488 2011-04-20 19:41:33
134,1               oracle@rh2.oracle.com (MMAN)                         832488 2011-04-20 19:41:33
129,1               oracle@rh2.oracle.com (ACMS)                         832488 2011-04-20 19:41:33
1,1                 oracle@rh2.oracle.com (PMON)                         832488 2011-04-20 19:41:32
9,1                 oracle@rh2.oracle.com (LMHB)                         832488 2011-04-20 19:41:33
21,1                oracle@rh2.oracle.com (GTX0)                         832488 2011-04-20 19:41:45
18,3                oracle@rh2.oracle.com (O001)                         832488 2011-04-20 19:41:37
137,1               oracle@rh2.oracle.com (RBAL)                         832488 2011-04-20 19:41:33
126,1               oracle@rh2.oracle.com (PSP0)                         832488 2011-04-20 19:41:32
133,1               oracle@rh2.oracle.com (RMS0)                         832488 2011-04-20 19:41:33
2,1                 oracle@rh2.oracle.com (VKTM)                         832488 2011-04-20 19:41:33
144,1               oracle@rh2.oracle.com (O000)                         832488 2011-04-20 19:41:36

Current total and average values of concurrent PGA + UGA memory usage:

463473320 bytes (total) and ~4930567 bytes (average), for ~47 sessions.

Maximum value of PGA memory usage per session:

SID AND SERIAL#     USERNAME OR PROGRAM                                   VALUE SESSION START TIME
------------------- ------------------------------------------------ ---------- -------------------
29,465              SYS                                               177212856 2011-04-21 19:52:16
152,987             SYS                                                57208040 2011-04-21 18:40:59
146,1               oracle@rh2.oracle.com (ARC3)                       37416168 2011-04-20 19:41:43
19,5                oracle@rh2.oracle.com (ARC2)                       36302056 2011-04-20 19:41:43
17,7                oracle@rh2.oracle.com (ARC0)                       32959720 2011-04-20 19:41:42
145,1               oracle@rh2.oracle.com (ARC1)                       19655912 2011-04-20 19:41:43
135,1               oracle@rh2.oracle.com (LGWR)                       13298920 2011-04-20 19:41:33
125,7               oracle@rh2.oracle.com (CJQ0)                       13045176 2011-04-20 19:41:50
131,1               oracle@rh2.oracle.com (LMS0)                       11791592 2011-04-20 19:41:33
7,1                 oracle@rh2.oracle.com (LMS1)                       11791592 2011-04-20 19:41:33
6,1                 oracle@rh2.oracle.com (LMD0)                       11660520 2011-04-20 19:41:33
5,1                 oracle@rh2.oracle.com (DIA0)                       10398280 2011-04-20 19:41:33
10,1                oracle@rh2.oracle.com (DBW0)                        8923976 2011-04-20 19:41:33
140,1               oracle@rh2.oracle.com (MARK)                        8383720 2011-04-20 19:41:33
130,1               oracle@rh2.oracle.com (LMON)                        8056104 2011-04-20 19:41:33
31,1                oracle@rh2.oracle.com (SMCO)                        6876392 2011-04-20 19:43:52
3,1                 oracle@rh2.oracle.com (DIAG)                        6548712 2011-04-20 19:41:33
25,57               SYS                                                 6163896 2011-04-21 19:56:59
136,1               oracle@rh2.oracle.com (SMON)                        5893352 2011-04-20 19:41:33
138,1               oracle@rh2.oracle.com (MMON)                        5294872 2011-04-20 19:41:33
16,1                oracle@rh2.oracle.com (RSMN)                        5237992 2011-04-20 19:41:35
150,5               oracle@rh2.oracle.com (Q000)                        3910216 2011-04-20 19:41:46
11,1                oracle@rh2.oracle.com (CKPT)                        2904104 2011-04-20 19:41:33
23,1                oracle@rh2.oracle.com (Q001)                        2551016 2011-04-20 19:41:46
22,1                oracle@rh2.oracle.com (QMNC)                        2485480 2011-04-20 19:41:45
12,1                oracle@rh2.oracle.com (RECO)                        2485480 2011-04-20 19:41:33
128,1               oracle@rh2.oracle.com (DBRM)                        2223336 2011-04-20 19:41:33
14,1                oracle@rh2.oracle.com (MMNL)                        1961192 2011-04-20 19:41:33
127,1               oracle@rh2.oracle.com (GEN0)                        1830120 2011-04-20 19:41:33
158,183             SYS                                                 1510840 2011-04-21 07:44:57
143,23              SYS                                                 1445304 2011-04-21 07:45:01
142,1               oracle@rh2.oracle.com (LCK0)                        1117272 2011-04-20 19:41:34
149,1               oracle@rh2.oracle.com (RCBG)                         912616 2011-04-20 19:41:45
33,59               oracle@rh2.oracle.com (W000)                         716008 2011-04-21 19:55:14
4,1                 oracle@rh2.oracle.com (PING)                         716008 2011-04-20 19:41:33
144,1               oracle@rh2.oracle.com (O000)                         650472 2011-04-20 19:41:36
137,1               oracle@rh2.oracle.com (RBAL)                         650472 2011-04-20 19:41:33
134,1               oracle@rh2.oracle.com (MMAN)                         650472 2011-04-20 19:41:33
133,1               oracle@rh2.oracle.com (RMS0)                         650472 2011-04-20 19:41:33
129,1               oracle@rh2.oracle.com (ACMS)                         650472 2011-04-20 19:41:33
126,1               oracle@rh2.oracle.com (PSP0)                         650472 2011-04-20 19:41:32
21,1                oracle@rh2.oracle.com (GTX0)                         650472 2011-04-20 19:41:45
18,3                oracle@rh2.oracle.com (O001)                         650472 2011-04-20 19:41:37
13,1                oracle@rh2.oracle.com (ASMB)                         650472 2011-04-20 19:41:33
9,1                 oracle@rh2.oracle.com (LMHB)                         650472 2011-04-20 19:41:33
2,1                 oracle@rh2.oracle.com (VKTM)                         650472 2011-04-20 19:41:33
1,1                 oracle@rh2.oracle.com (PMON)                         650472 2011-04-20 19:41:32

Worst possible total and average values of concurrent PGA memory usage:

528694504 bytes (total) and ~11248819 bytes (average), for ~47 sessions.

Maximum value of UGA memory usage per session:

SID AND SERIAL#     USERNAME OR PROGRAM                                   VALUE SESSION START TIME
------------------- ------------------------------------------------ ---------- -------------------
152,987             SYS                                                10573576 2011-04-21 18:40:59
25,57               SYS                                                 3690216 2011-04-21 19:56:59
29,465              SYS                                                 3231832 2011-04-21 19:52:16
136,1               oracle@rh2.oracle.com (SMON)                        2883704 2011-04-20 19:41:33
125,7               oracle@rh2.oracle.com (CJQ0)                        2781256 2011-04-20 19:41:50
138,1               oracle@rh2.oracle.com (MMON)                        1920312 2011-04-20 19:41:33
150,5               oracle@rh2.oracle.com (Q000)                        1091392 2011-04-20 19:41:46
23,1                oracle@rh2.oracle.com (Q001)                         894968 2011-04-20 19:41:46
22,1                oracle@rh2.oracle.com (QMNC)                         829480 2011-04-20 19:41:45
12,1                oracle@rh2.oracle.com (RECO)                         763968 2011-04-20 19:41:33
128,1               oracle@rh2.oracle.com (DBRM)                         443968 2011-04-20 19:41:33
158,183             SYS                                                  247504 2011-04-21 07:44:57
149,1               oracle@rh2.oracle.com (RCBG)                         247504 2011-04-20 19:41:45
143,23              SYS                                                  247504 2011-04-21 07:45:01
33,59               oracle@rh2.oracle.com (W000)                         247504 2011-04-21 19:55:14
31,1                oracle@rh2.oracle.com (SMCO)                         247504 2011-04-20 19:43:52
146,1               oracle@rh2.oracle.com (ARC3)                         182016 2011-04-20 19:41:43
145,1               oracle@rh2.oracle.com (ARC1)                         182016 2011-04-20 19:41:43
144,1               oracle@rh2.oracle.com (O000)                         182016 2011-04-20 19:41:36
142,1               oracle@rh2.oracle.com (LCK0)                         182016 2011-04-20 19:41:34
140,1               oracle@rh2.oracle.com (MARK)                         182016 2011-04-20 19:41:33
137,1               oracle@rh2.oracle.com (RBAL)                         182016 2011-04-20 19:41:33
135,1               oracle@rh2.oracle.com (LGWR)                         182016 2011-04-20 19:41:33
134,1               oracle@rh2.oracle.com (MMAN)                         182016 2011-04-20 19:41:33
133,1               oracle@rh2.oracle.com (RMS0)                         182016 2011-04-20 19:41:33
131,1               oracle@rh2.oracle.com (LMS0)                         182016 2011-04-20 19:41:33
130,1               oracle@rh2.oracle.com (LMON)                         182016 2011-04-20 19:41:33
129,1               oracle@rh2.oracle.com (ACMS)                         182016 2011-04-20 19:41:33
127,1               oracle@rh2.oracle.com (GEN0)                         182016 2011-04-20 19:41:33
126,1               oracle@rh2.oracle.com (PSP0)                         182016 2011-04-20 19:41:32
21,1                oracle@rh2.oracle.com (GTX0)                         182016 2011-04-20 19:41:45
19,5                oracle@rh2.oracle.com (ARC2)                         182016 2011-04-20 19:41:43
18,3                oracle@rh2.oracle.com (O001)                         182016 2011-04-20 19:41:37
17,7                oracle@rh2.oracle.com (ARC0)                         182016 2011-04-20 19:41:42
16,1                oracle@rh2.oracle.com (RSMN)                         182016 2011-04-20 19:41:35
14,1                oracle@rh2.oracle.com (MMNL)                         182016 2011-04-20 19:41:33
13,1                oracle@rh2.oracle.com (ASMB)                         182016 2011-04-20 19:41:33
11,1                oracle@rh2.oracle.com (CKPT)                         182016 2011-04-20 19:41:33
10,1                oracle@rh2.oracle.com (DBW0)                         182016 2011-04-20 19:41:33
9,1                 oracle@rh2.oracle.com (LMHB)                         182016 2011-04-20 19:41:33
7,1                 oracle@rh2.oracle.com (LMS1)                         182016 2011-04-20 19:41:33
6,1                 oracle@rh2.oracle.com (LMD0)                         182016 2011-04-20 19:41:33
5,1                 oracle@rh2.oracle.com (DIA0)                         182016 2011-04-20 19:41:33
4,1                 oracle@rh2.oracle.com (PING)                         182016 2011-04-20 19:41:33
3,1                 oracle@rh2.oracle.com (DIAG)                         182016 2011-04-20 19:41:33
2,1                 oracle@rh2.oracle.com (VKTM)                         182016 2011-04-20 19:41:33
1,1                 oracle@rh2.oracle.com (PMON)                         182016 2011-04-20 19:41:32

Worst possible total and average values of concurrent UGA memory usage:

35984688 bytes (total) and ~765631 bytes (average), for ~47 sessions.

Current value of PGA memory usage per session:

SID AND SERIAL#     USERNAME OR PROGRAM                                   VALUE SESSION START TIME
------------------- ------------------------------------------------ ---------- -------------------
29,465              SYS                                               177802680 2011-04-21 19:52:16
146,1               oracle@rh2.oracle.com (ARC3)                       36302056 2011-04-20 19:41:43
19,5                oracle@rh2.oracle.com (ARC2)                       35187944 2011-04-20 19:41:43
17,7                oracle@rh2.oracle.com (ARC0)                       32959720 2011-04-20 19:41:42
145,1               oracle@rh2.oracle.com (ARC1)                       19655912 2011-04-20 19:41:43
135,1               oracle@rh2.oracle.com (LGWR)                       13298920 2011-04-20 19:41:33
131,1               oracle@rh2.oracle.com (LMS0)                       11791592 2011-04-20 19:41:33
7,1                 oracle@rh2.oracle.com (LMS1)                       11791592 2011-04-20 19:41:33
6,1                 oracle@rh2.oracle.com (LMD0)                       11660520 2011-04-20 19:41:33
5,1                 oracle@rh2.oracle.com (DIA0)                       10398280 2011-04-20 19:41:33
10,1                oracle@rh2.oracle.com (DBW0)                        8530760 2011-04-20 19:41:33
140,1               oracle@rh2.oracle.com (MARK)                        8383720 2011-04-20 19:41:33
130,1               oracle@rh2.oracle.com (LMON)                        8056104 2011-04-20 19:41:33
3,1                 oracle@rh2.oracle.com (DIAG)                        6548712 2011-04-20 19:41:33
16,1                oracle@rh2.oracle.com (RSMN)                        5237992 2011-04-20 19:41:35
152,987             SYS                                                 4582632 2011-04-21 18:40:59
125,7               oracle@rh2.oracle.com (CJQ0)                        3935672 2011-04-20 19:41:50
25,57               SYS                                                 3787544 2011-04-21 19:56:59
136,1               oracle@rh2.oracle.com (SMON)                        3140840 2011-04-20 19:41:33
138,1               oracle@rh2.oracle.com (MMON)                        3066648 2011-04-20 19:41:33
150,5               oracle@rh2.oracle.com (Q000)                        2468424 2011-04-20 19:41:46
11,1                oracle@rh2.oracle.com (CKPT)                        2379816 2011-04-20 19:41:33
31,1                oracle@rh2.oracle.com (SMCO)                        2288872 2011-04-20 19:43:52
12,1                oracle@rh2.oracle.com (RECO)                        2223336 2011-04-20 19:41:33
128,1               oracle@rh2.oracle.com (DBRM)                        2092264 2011-04-20 19:41:33
23,1                oracle@rh2.oracle.com (Q001)                        1961192 2011-04-20 19:41:46
22,1                oracle@rh2.oracle.com (QMNC)                        1961192 2011-04-20 19:41:45
127,1               oracle@rh2.oracle.com (GEN0)                        1830120 2011-04-20 19:41:33
14,1                oracle@rh2.oracle.com (MMNL)                        1764584 2011-04-20 19:41:33
158,183             SYS                                                 1510840 2011-04-21 07:44:57
143,23              SYS                                                 1379768 2011-04-21 07:45:01
142,1               oracle@rh2.oracle.com (LCK0)                        1117272 2011-04-20 19:41:34
149,1               oracle@rh2.oracle.com (RCBG)                         912616 2011-04-20 19:41:45
33,59               oracle@rh2.oracle.com (W000)                         716008 2011-04-21 19:55:14
4,1                 oracle@rh2.oracle.com (PING)                         716008 2011-04-20 19:41:33
144,1               oracle@rh2.oracle.com (O000)                         650472 2011-04-20 19:41:36
137,1               oracle@rh2.oracle.com (RBAL)                         650472 2011-04-20 19:41:33
134,1               oracle@rh2.oracle.com (MMAN)                         650472 2011-04-20 19:41:33
133,1               oracle@rh2.oracle.com (RMS0)                         650472 2011-04-20 19:41:33
129,1               oracle@rh2.oracle.com (ACMS)                         650472 2011-04-20 19:41:33
126,1               oracle@rh2.oracle.com (PSP0)                         650472 2011-04-20 19:41:32
21,1                oracle@rh2.oracle.com (GTX0)                         650472 2011-04-20 19:41:45
18,3                oracle@rh2.oracle.com (O001)                         650472 2011-04-20 19:41:37
13,1                oracle@rh2.oracle.com (ASMB)                         650472 2011-04-20 19:41:33
9,1                 oracle@rh2.oracle.com (LMHB)                         650472 2011-04-20 19:41:33
2,1                 oracle@rh2.oracle.com (VKTM)                         650472 2011-04-20 19:41:33
1,1                 oracle@rh2.oracle.com (PMON)                         650472 2011-04-20 19:41:32

Current total and average values of concurrent PGA memory usage:

449247816 bytes (total) and ~9558464 bytes (average), for ~47 sessions.

Current value of UGA memory usage per session:

SID AND SERIAL#     USERNAME OR PROGRAM                                   VALUE SESSION START TIME
------------------- ------------------------------------------------ ---------- -------------------
152,987             SYS                                                 1641408 2011-04-21 18:40:59
138,1               oracle@rh2.oracle.com (MMON)                        1098800 2011-04-20 19:41:33
25,57               SYS                                                  950960 2011-04-21 19:56:59
125,7               oracle@rh2.oracle.com (CJQ0)                         919152 2011-04-20 19:41:50
136,1               oracle@rh2.oracle.com (SMON)                         722664 2011-04-20 19:41:33
150,5               oracle@rh2.oracle.com (Q000)                         640424 2011-04-20 19:41:46
23,1                oracle@rh2.oracle.com (Q001)                         378480 2011-04-20 19:41:46
12,1                oracle@rh2.oracle.com (RECO)                         314784 2011-04-20 19:41:33
29,465              SYS                                                  281144 2011-04-21 19:52:16
22,1                oracle@rh2.oracle.com (QMNC)                         281144 2011-04-20 19:41:45
149,1               oracle@rh2.oracle.com (RCBG)                         247504 2011-04-20 19:41:45
128,1               oracle@rh2.oracle.com (DBRM)                         247504 2011-04-20 19:41:33
33,59               oracle@rh2.oracle.com (W000)                         247504 2011-04-21 19:55:14
31,1                oracle@rh2.oracle.com (SMCO)                         247504 2011-04-20 19:43:52
158,183             SYS                                                  182016 2011-04-21 07:44:57
146,1               oracle@rh2.oracle.com (ARC3)                         182016 2011-04-20 19:41:43
145,1               oracle@rh2.oracle.com (ARC1)                         182016 2011-04-20 19:41:43
144,1               oracle@rh2.oracle.com (O000)                         182016 2011-04-20 19:41:36
143,23              SYS                                                  182016 2011-04-21 07:45:01
142,1               oracle@rh2.oracle.com (LCK0)                         182016 2011-04-20 19:41:34
140,1               oracle@rh2.oracle.com (MARK)                         182016 2011-04-20 19:41:33
137,1               oracle@rh2.oracle.com (RBAL)                         182016 2011-04-20 19:41:33
135,1               oracle@rh2.oracle.com (LGWR)                         182016 2011-04-20 19:41:33
134,1               oracle@rh2.oracle.com (MMAN)                         182016 2011-04-20 19:41:33
133,1               oracle@rh2.oracle.com (RMS0)                         182016 2011-04-20 19:41:33
131,1               oracle@rh2.oracle.com (LMS0)                         182016 2011-04-20 19:41:33
130,1               oracle@rh2.oracle.com (LMON)                         182016 2011-04-20 19:41:33
129,1               oracle@rh2.oracle.com (ACMS)                         182016 2011-04-20 19:41:33
127,1               oracle@rh2.oracle.com (GEN0)                         182016 2011-04-20 19:41:33
126,1               oracle@rh2.oracle.com (PSP0)                         182016 2011-04-20 19:41:32
21,1                oracle@rh2.oracle.com (GTX0)                         182016 2011-04-20 19:41:45
19,5                oracle@rh2.oracle.com (ARC2)                         182016 2011-04-20 19:41:43
18,3                oracle@rh2.oracle.com (O001)                         182016 2011-04-20 19:41:37
17,7                oracle@rh2.oracle.com (ARC0)                         182016 2011-04-20 19:41:42
16,1                oracle@rh2.oracle.com (RSMN)                         182016 2011-04-20 19:41:35
14,1                oracle@rh2.oracle.com (MMNL)                         182016 2011-04-20 19:41:33
13,1                oracle@rh2.oracle.com (ASMB)                         182016 2011-04-20 19:41:33
11,1                oracle@rh2.oracle.com (CKPT)                         182016 2011-04-20 19:41:33
10,1                oracle@rh2.oracle.com (DBW0)                         182016 2011-04-20 19:41:33
9,1                 oracle@rh2.oracle.com (LMHB)                         182016 2011-04-20 19:41:33
7,1                 oracle@rh2.oracle.com (LMS1)                         182016 2011-04-20 19:41:33
6,1                 oracle@rh2.oracle.com (LMD0)                         182016 2011-04-20 19:41:33
5,1                 oracle@rh2.oracle.com (DIA0)                         182016 2011-04-20 19:41:33
4,1                 oracle@rh2.oracle.com (PING)                         182016 2011-04-20 19:41:33
3,1                 oracle@rh2.oracle.com (DIAG)                         182016 2011-04-20 19:41:33
2,1                 oracle@rh2.oracle.com (VKTM)                         182016 2011-04-20 19:41:33
1,1                 oracle@rh2.oracle.com (PMON)                         182016 2011-04-20 19:41:32

Current total and average values of concurrent UGA memory usage:

14225504 bytes (total) and ~302670 bytes (average), for ~47 sessions.

Current SGA structure sizings:

Total System Global Area  939495424 bytes
Fixed Size                  2232088 bytes
Variable Size             398459112 bytes
Database Buffers          532676608 bytes
Redo Buffers                6127616 bytes

Some initialization parameter values at instance startup:

large_pool_size=0
pga_aggregate_target=0
sga_target=0
shared_pool_size=0
sort_area_size=65536
streams_pool_size=0

Current Time: 2011.04.21-19:57:16

/* 可以从以上输出看到sid,serial=29,465会话的PGA内存使用量异常,达到了170M,
    虽然跟以上案例中的PGA泄露情况比较不算什么  */

/* 使用sid和serial定位到具体的操作系统进程号 */

SQL> select spid,pid,PGA_USED_MEM,PGA_MAX_MEM from v$process
  2  where addr=(select paddr from v$session where sid=&1 and serial#=&2);
Enter value for 1: 29
Enter value for 2: 465
old   2: where addr=(select paddr from v$session where sid=&1 and serial#=&2)
new   2: where addr=(select paddr from v$session where sid=29 and serial#=465)

SPID                            PID PGA_USED_MEM PGA_MAX_MEM
------------------------ ---------- ------------ -----------
26932                            48    129716228   130034996

1 row selected.

SQL> oradebug setospid 26932;
Oracle pid: 48, Unix process pid: 26932, image: oracle@rh2.oracle.com (TNS V1-V3)

SQL> oradebug dump heapdump 536870917;
Statement processed.

SQL> oradebug dump processstate 10;
Statement processed.

SQL> oradebug tracefile_name;
/s01/orabase/diag/rdbms/prod/PROD1/trace/PROD1_ora_26932.trc

/* 接下来对堆转储文件进行分析,通过grep可以找出其中较大的SubHEAP子堆  */

[oracle@rh2 ~]$ egrep "HEAP DUMP heap name|Total heap size|Permanent space"
/s01/orabase/diag/rdbms/prod/PROD1/trace/PROD1_ora_26932.trc

HEAP DUMP heap name="session heap"  desc=0x2ac0b37a67f8
Total heap size    =   130840
Permanent space    =    62680
HEAP DUMP heap name="Alloc environm"  desc=0x2ac0b37ce090
Total heap size    =     4040
Permanent space    =     4040
HEAP DUMP heap name="PLS UGA hp"  desc=0x2ac0b37be7f0
Total heap size    =     1992
Permanent space    =     1080
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2ac0b37cf660
Total heap size    =     1128
Permanent space    =       80
HEAP DUMP heap name="pga heap"  desc=0xb7c8ba0
Total heap size    =  2689432
Permanent space    =   660560
HEAP DUMP heap name="Alloc environm"  desc=0x2ac0b35ba5c8
Total heap size    =  1706816
Permanent space    =      464
HEAP DUMP heap name="Alloc server h"  desc=0x2ac0b35b9000
Total heap size    =  1704400
Permanent space    =  1694816
HEAP DUMP heap name="diag pga"  desc=0x2ac0b32537e0
Total heap size    =    65448
Permanent space    =     3672
HEAP DUMP heap name="KFK_IO_SUBHEAP"  desc=0x2ac0b35eb2b0
Total heap size    =    10992
Permanent space    =       80
HEAP DUMP heap name="peshm.c:Proces"  desc=0x2ac0b35e7ad0
Total heap size    =     4000
Permanent space    =       80
HEAP DUMP heap name="KSFQ heap"  desc=0x2ac0b35c6d70
Total heap size    =     3256
Permanent space    =     3256
HEAP DUMP heap name="top call heap"  desc=0xb7ce3c0
Total heap size    =155918560
Permanent space    =      448
HEAP DUMP heap name="callheap"  desc=0xb7cd4c0
Total heap size    =152906784
Permanent space    =       80
HEAP DUMP heap name="TCHK^30c42b7a"  desc=0x2ac0b378ff48
Total heap size    =151414512
Permanent space    =       80
HEAP DUMP heap name="kggec.c.kggfa"  desc=0x2ac0b4e76ec8
Total heap size    =     1016
Permanent space    =      736
HEAP DUMP heap name="kxs-heap-c"  desc=0x2ac0b37800c0
Total heap size    =  1489464
Permanent space    =  1485928
HEAP DUMP heap name="top uga heap"  desc=0xb7ce5e0
Total heap size    =   131024
Permanent space    =       80
HEAP DUMP heap name="session heap"  desc=0x2ac0b37a67f8
Total heap size    =   130840
Permanent space    =    62680
HEAP DUMP heap name="Alloc environm"  desc=0x2ac0b37ce090
Total heap size    =     4040
Permanent space    =     4040
HEAP DUMP heap name="PLS UGA hp"  desc=0x2ac0b37be7f0
Total heap size    =     1992
Permanent space    =     1080
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2ac0b37cf660
Total heap size    =     1128
Permanent space    =       80
HEAP DUMP heap name="SQLA^30c42b7a"  desc=0x6f4c3ab8
Total heap size    =  4919904
Permanent space    =       80
HEAP DUMP heap name="KGLH0^30c42b7a"  desc=0x6ef44290
Total heap size    =     4032
Permanent space    =     2648


/* 以上heapdump表明TCHK^30c42b7a子堆占用了PGA中绝大多数的内存,
    其中子堆的包含结构为PGA->top call heap -> call heap  -> TCHK 
*/

/* 接着processstate dump还可以让我们了解该问题进程的最近活动历史,及之前所运行的SQL语句
    以便进一步诊断,以下为其调用堆栈      */

ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1900<-sspuser()+112<-__sighandler()<-qcsfccc()+206
<-qcsIsColInFro()+309<-qcsRslvColWithinQbc()+179<-qcsWeakColRslv()+94<-qcsRslvName()+2541<-qcsridn()+105
<-qcsraic()+455<-qcspqbDescendents()+527<-qcspqb()+260<-qcspqbDescendents()+2744<-qcspqb()+260
<-kkmdrv()+182<-opiSem()+1947<-opiprs()+293<-__PGOSF632_kksParseChildCursor()+572<-rpiswu2()+1618
<-kksLoadChild()+5167<-kxsGetRuntimeLock()+2066<-kksfbc()+14527<-kkspsc0()+2025<-kksParseCursor()+144
<-opiosq0()+2027<-kpooprx()+274<-kpoal8()+800<-opiodr()+910<-ttcpip()+2289<-opitsk()+1670<-opiino()+966
<-opiodr()+910<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244
<-_start()+36

通过以上获取的信息"call heap-> TCHK"可以从MOS查找到11.2上的”Bug 11782790: ORA-4030 IS GENERATED IN HARD PARSE"和"Bug 12360198: ORA-04030 (TCHK^82665CD8,CHEDEF : QCUATC)";虽然我们这里故意为之而非真实的Bug,也可以看出"TCHK subheap"在11.2中充当SQL解析时的临时调用子堆(parse call subheap)。

to be continued.....

Oracle Patch Set Update and Critical Patch Update April 2011 Released

2011 April的Oracle Patch set Update与Critical Patch Update发布了,本次发布包括了对Oracle Database Server, Oracle Fusion Middleware, Oracle Enterprise Manager Grid Control, Oracle E-Business Suite and Supply Chain Products Suite, Oracle PeopleSoft Enterprise, and Oracle JDEdwards EntepriseOne, Oracle Siebel CRM, Oracle Industry Applications, Oracle Sun products suite, and Oracle OpenOffice Suite等多个产品的补丁更新。

其中与数据库相关的主要有补丁集更新和紧急补丁更新如下:

  1. Database 11.2.0.2上的CPU Patch 11724984, or PSU Patch 11724916
  2. Database 11.2.0.1上的CPU Patch 11724991, or PSU Patch 11724930
  3. Database 11.1.0.7上的CPU Patch 11724999, or PSU Patch 11724936
  4. Database 10.2.0.5上的CPU Patch 11725006, or PSU Patch 11724962
  5. Database 10.2.0.4上的CPU Patch 11725015, or PSU Patch 11724977

ORA-07445:[SIGFPE] [Integer divide by zero]内部错误一例

一套SUNOS 5.10上的单节点10.2.0.3系统出现了ORA-07445: exception encountered: core dump [SIGFPE] [Integer divide by zero] [42788866] [] [] []内部错误,具体trace日志如下:

mon_ora_17633.trc

Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /oracle/oracle/product/10.2.0
System name: SunOS
Node name: monitor-a
Release: 5.10
Version: Generic_139556-08
Machine: i86pc

ksedmp: internal or fatal error
ORA-07445: exception encountered: core dump [SIGFPE] [Integer divide by zero] [42788866] [] [] []
Current SQL statement for this session:
select req_time into :b0 from t_FIX_TranSerial where
((((tran_bank=:b1 and tran_type=:b2) and term_no=:b3)
and trace_no=:b4) and local_time='0')
----- Call Stack Trace -----

sigsetjmp <- call_user_handler
<- sigacthandler <- kpopfr <- kposdi <- kpopsdi <- opiefn0
<- kpoal8 <- opiodr <- ttcpip <- opitsk <- opiino
<- opiodr <- opidrv <- sou2o <- opimai_real <- main
<- 0000000000E54FE7

PROCESS STATE
-------------
O/S info: user: monitor, term: pts/5, ospid: 17621, machine: monitor-a
program: CTPDATA@monitor-a (TNS V1-V3)
application name: CTPDATA@monitor-a (TNS V1-V3), hash value=0
last wait for 'SQL*Net message to client' blocking sess=0x0 seq=6213 wait_time=1 seconds since wait started=0
driver id=62657100, #bytes=1, =0

通过在MOS上查询以上ORA-07445错误的arguement可以发现Note <ORA-7445 [KPOPFR] [SIGFPE] [INTEGER DIVIDE BY ZERO] When Repeatedly Executing a Query (Doc ID 421203.1)> :

Applies to:

Oracle Server - Enterprise Edition - Version: 10.2.0.1 to 10.2.0.3
This problem can occur on any platform.
Symptoms

1. Repeatedly executing a query can lead to the following error: 

ORA-7445 [kpopfr] [SIGFPE] [INTEGER DIVIDE BY ZERO]

2. The call stack from the ORA-07445 trace file should contain the following functions:
kposdi  kpopsdi

The error is caused by BUG 5753629.
Abstract: QUERY FAILS BY ORA-7445 [KPOPFR]
Repeatedly executing a query can lead to an ORA-7445[kpopfr] error.

Solution
To implement the solution, do one of the following: 

1. Upgrade to 11.1 or 10.2.0.4, when available.
At the time of writing the article these version were not yet available. (July 2007).
2. Apply one-off Patch 5753629 from MetaLink, if available for your platform and version.

There is no known workaround available for this bug.

References

BUG:5753629 - QUERY FAILS BY ORA-7445 [KPOPFR].

Hdr: 5753629 10.2.0.2 RDBMS 10.2.0.2 PRG INTERFACE PRODID-5 PORTID-23 ORA-7445
Abstract: QUERY FAILS BY ORA-7445 [KPOPFR].

*** 01/09/07 06:12 pm ***
TAR:
----

PROBLEM:
--------
When executing query again and again from one session, query fails
by ORA-7445[kpopfr].

  ====================================================================
  Sat Dec 30 00:22:39 2006
  Errors in file /var/log/oracle/trace/felica2_ora_6156.trc:
  ORA-7445: exception encountered: core dump [kpopfr()+536] [SIGFPE]
  [Integer divide by zero] [0x1023BCE18] [] []
  ====================================================================

DIAGNOSTIC ANALYSIS:
--------------------
From disassemble, %o3 is devided by %o0 and %o0 seems to be 0x0.

  0x1023f43d0 :       umul  %g5, %g4, %o0
  0x1023f43d4 :       mov  %g0, %y
  0x1023f43d8 :       udiv  %o3, %o0, %o3

%o0 is calcurated by %g5 X %g4 at kpopfr+528.

From our trace file, this value(%g5) is 0x100000.

  ub4 kponc_p [FFFFFFFF7B22AAAC, FFFFFFFF7B22AAB0) = 00100000

And %g4 seems to be 0x1000 from below trace file output.
 ========== FRAME [6] (kpopsdi()+148 -> kposdi()) ==========
  %l0 0000000100302B00 %l1 0000000000000002 %l2 FFFFFFFF7B263CA8
  %l3 00000003C36AFB80 %l4 0000000105D7CE20 %l5 0000000000000001
  %l6 0000000000000007 %l7 0000000105D7A920 %i0 0000000000000000
  %i1 FFFFFFFF7FFFB9EC %i2 0000000000001000 %i3 0000000105E03220
                       ~~~~~~~~~~~~~~~~~~~~ <--(*) here
  %i4 0000000000800000 %i5 0000000000105C00 %fp FFFFFFFF7FFFB241 

If %g4=0x1000 and %g5=0x100000, %g4 X %g5 = 0x100000000.
0x100000000 is 0x0 as ub4, and this may bring 0 divide and ORA-7445.

I can reproduce the similar problem in my house, so I'll upload testcase.
Problem reproduce at the following case.

 * sum of all column size is 1048576(0x100000)
 * run query again and again from one session (about 4096(0x1000) times)

From this results, above guess seems to be correct.

WORKAROUND:
-----------
n/a

RELATED BUGS:
-------------
n/a

REPRODUCIBILITY:
----------------
I have confirmed that this problem reproduces at the below env.

 * Linux x86 32bit, 10.2.0.3 : ORA-7445[kpopfr()+300]
 * Linux x86 64bit, 10.2.0.2 : ORA-7445[kpopfr()+339]
 * Solaris 64bit, 10.2.0.2   : ORA-7445[kpopfr()+536]
 * HP-UX Itanium, 10.2.0.2   : ORA-7445[_div32U()+34]

TEST CASE:
----------
At first, creating table like follows.

conn scott/tiger
drop table test;
create table test
( c000 char(2000),
  c001 char(2000),
    ... 
  c523 char(2000),
  c524 char(576));

  --> sum of all column size is 1048576(0x100000).

Run next shell script.

  while [ 1 ]
  do
  echo "set feedback off"
  echo "select * from test where c001 = 'A';"
  done | sqlplus -s scott/tiger

It takes 3-10 minutes to reproduce the problem.
Required time for reproducing depends on hardware spec.

STACK TRACE:
------------
 ksedmp ssexhd sighndlr call_user_handler kposdi kpopsdi kpoal8
 opiodr ttcpip opitsk opiino opiodr opidrv sou2o opimai_real
 main start

具体向Oracle GCS提交SR以后确认为 BUG 5753629. Oracle GCS给出了2种解决方案:
1.升级到10.2.0.4或更高版本
2.应用Apply one-off Patch 5753629

为Oracle Clusterware修改公用及私有网络接口

出于种种原因我们可能需要为已安装的Oracle集群软件修改其使用的公用或私有网络所使用的网络接口(How to Change Interconnect/Public Interface IP or Subnet in Oracle Clusterware),这些共有或私有网络(public/private network)被保存在ocr中,我们需要以root用户的身份执行oifcfg命令来对这些网络接口信息进行修改:

/* 使用ocrdump命令转储ocr信息 */

[oracle@vrh1 ~]$ ocrdump ocr

[oracle@vrh1 ~]$ cat ocr

[SYSTEM.css.interfaces]UNDEF 
[SYSTEM.css.interfaces.global]UNDEF 
[SYSTEM.css.interfaces.global.eth0]UNDEF 
[SYSTEM.css.interfaces.global.eth0.131|d32|d1|d0]UNDEF 
[SYSTEM.css.interfaces.global.eth0.131|d32|d1|d0]ORATEXT : public

[SYSTEM.css.interfaces.global.eth1]UNDEF
[SYSTEM.css.interfaces.global.eth1.131|d33|d1|d0]UNDEF :
[SYSTEM.css.interfaces.global.eth1.131|d33|d1|d0]ORATEXT : cluster_interconnect

.............

/* 实际上css的misscount参数和voting disk所在的位置也存在ocr文件中  */

[SYSTEM.css.misscount]UB4 (10) : 60
[SYSTEM.css.diskfile]ORATEXT : /dev/raw/raw2

1.首先我们可以通过oifcfg getif了解当前的public/interconnect网络配置情况:

[root@vrh1 ~]# who am i
root     pts/1        2011-04-18 18:23 (192.168.0.1)

[root@vrh1 ~]# cd $ORA_CRS_HOME/bin

[root@vrh1 bin]# oifcfg getif
eth0  131.32.1.0  global  public
eth1  131.33.1.0  global  cluster_interconnect

/* 可以看到这里分别用131.32.1/2网段配置了public和cluster_interconnect网络  */

2.确认在/etc/hosts文件中为新的网络接口IP做了必要的修改,之后我们要保证当前CRS已经启动(否则将出现PRIF-10: failed to initialize the cluster registry错误而无法配置),使用oifcfg setif命令首先添加新的public公用网络接口:

[root@vrh1 bin]# oifcfg delif -global eth0

/* 首先删除旧有的公用网络接口信息  */

[root@vrh1 bin]# oifcfg setif -global eth0/192.168.1.0:public

/* 注意这里制定192.168.1.0这个网段即可,不用输入完整的ip */

/* 因为以上操作是global全局操作,在单个节点完成即可 */

3.修改内联网络(cluster_interconnect)接口的方法也是类似的:

[root@vrh1 bin]# oifcfg delif -global eth1

[root@vrh1 bin]# oifcfg setif -global eth1/192.168.0.0:cluster_interconnect

/* 与public network配置时类似指定网段即可  */

4.确认网络接口的修改情况,以及当前数据库使用的inter connecter状况:

[oracle@vrh1 ~]$ oifcfg getif
eth0  192.168.1.0  global  public
eth1  192.168.0.0  global  cluster_interconnect

SQL> select * from x$skgxpia;

ADDR           INDX    INST_ID PUB_SKGXPI PICKED_SKGXPIA
-------- ---------- ---------- ---------- -----------------------------------
NAME_SKGXPIA    IP_SKGXPIA
--------------- ----------------
4572EC54          0          1 N          OSD
eth1            131.33.1.107

/* 可以看到当前数据库实例仍使用旧有的inter connect网络 */

[root@vrh1 ~]# crsctl stop crs

[root@vrh1 ~]# crsctl start crs

[oracle@vrh1 ~]$ sqlplus / as sysdba

Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options

SQL> 
SQL> select * from x$skgxpia;

ADDR           INDX    INST_ID PUB_SKGXPI PICKED_SKGXPIA
-------- ---------- ---------- ---------- -----------------------------------
NAME_SKGXPIA    IP_SKGXPIA
--------------- ----------------
4572EC54          0          1 N          OSD
eth1            192.168.0.107

/* 这里需要重启CRS后实例才能正确使用更新后的cluster interconnect网络接口 */

ORA-07274 spdcr:access error错误一例

下午在客户office遭遇了ORA-07274错误,那是一套AIX 5.3上10.2.0.4的2节点RAC系统,乍看到7274还以为是ORA-7445的孪生兄弟,心中暗想10.2.0.4的RAC问题还真是不少:

Errors in file /s01/oracle/product/10.2.0/db_1/rdbms/log/prod21_psp0_4272.trc:
ORA-07274: spdcr: access error, access to oracle denied.
No such file or directory

Mon Apr 18 17:05:44 2011
PSP0: terminating instance due to error 7274
Mon Apr 18 17:05:44 2011
Errors in file /s01/oracle/product/10.2.0/db_1/rdbms/log/prod21_lms1_4285.trc:
ORA-07274: spdcr: access error, access to oracle denied.
Mon Apr 18 17:05:44 2011
Errors in file /s01/oracle/product/10.2.0/db_1/rdbms/log/prod21_lms0_4279.trc:
ORA-07274: spdcr: access error, access to oracle denied.
Mon Apr 18 17:05:44 2011
Errors in file /s01/oracle/product/10.2.0/db_1/rdbms/log/prod21_lmd0_4276.trc:
ORA-07274: spdcr: access error, access to oracle denied.
Mon Apr 18 17:05:44 2011
Errors in file /s01/oracle/product/10.2.0/db_1/rdbms/log/prod21_lmon_4274.trc:
ORA-07274: spdcr: access error, access to oracle denied.
Mon Apr 18 17:05:45 2011
System state dump is made for local instance
System State dumped to trace file /s01/oracle/product/10.2.0/db_1/rdbms/log/prod21_diag_4270.trc
Mon Apr 18 17:05:45 2011
Trace dumping is performing id=[cdmp_20110418170545]
Mon Apr 18 17:05:46 2011
Instance terminated by PSP0, pid = 4272


====/s01/oracle/product/10.2.0/db_1/rdbms/log/prod21_psp0_4272.trc======

error 7274 detected in background process
ORA-07274: spdcr: access error, access to oracle denied.
ksuitm: waiting up to [5] seconds before killing DIAG


[oracle@vrh1 ~]$ oerr ora 7274
07274, 00000, "spdcr: access error, access to oracle denied."
// *Cause:  Unable to access "oracle" program. Verify ?/bin/oracle or
//          $ORABCKPRG exist, and are executable.
// *Action: Check errno returned.

以上ORA-07274错误直接导致RAC的2号节点实例意外终止!

引起ORA-07274错误的唯一直接原因是$ORACLE_HOME/bin目录下的oracle 2进制文件在错误发生时无法正常访问,可能造成该重要文件无法访问的原因可能有:

1.文件系统被umount或者ORACLE_HOME所在磁盘出现错误
2.oracle 2进制文件的权限设置错误,其正确权限应为6751
3.oracle 2进制文件被意外删除;当然relink oracle程序需要短暂移动该文件,所以也可能造成以上问题

在发生以上ORA-07274错误后我们第一时间使用ls命令查看了oracle 2进制文件的状态:

[oracle@vrh1 bin]$ ls -l $ORACLE_HOME/bin/oracle     
-rwsr-s--x 1 oracle oinstall 96789226 Apr 18 17:03 /s01/oracle/product/10.2.0/db_1/bin/oracle

[oracle@vrh1 bin]$ stat $ORACLE_HOME/bin/oracle
  File: `/s01/oracle/product/10.2.0/db_1/bin/oracle'
  Size: 96789226        Blocks: 189248     IO Block: 4096   regular file
Device: fd00h/64768d    Inode: 4434759     Links: 1
Access: (6751/-rwsr-s--x)  Uid: (  500/  oracle)   Gid: (  500/oinstall)
Access: 2011-04-18 17:04:55.000000000 -0400
Modify: 2011-04-18 17:03:44.000000000 -0400
Change: 2011-04-18 17:25:09.000000000 -0400

[oracle@vrh1 bin]$ date
Mon Apr 18 17:25:30 EDT 2011

并发现该文件在近期内被修改过(Modify: 2011-04-18 17:03:44.000000000 -0400),首先我想到的是可能有人在实例启动的情况下重新编译了oracle 2进制程序,但虽然的调查发现$ORACLE_HOME下大部分的目录修改时间(Modify time)都变成了最近。

这个时候一副”案件现场”已经呈现在我脑海中了,很明显是有人误删除了$ORACLE_HOME下的文件,在发现是误操作后立即终止了rm命令,但这个时候Oracle instance已经因为oracle 2进制程序文件丢失而意外终止terminated了,为了让现场恢复到原样,其又试图通过将1号节点上的Oracle Software传输到2号节点上来解决问题。

为了进一步证明我的想法,我求助于OS管理人员,希望通过传说中的系统命令审计来”锁定”问题。OS管理人员打开一个文本文件同我一起开始review起来,但在我看来这个审计文件的信息似乎过于简单了,只记录操作用户名下运行过的shell命令;一开始我们浏览了root用户的审计记录,没有发现任何问题;在准备查看oracle用户的审计文件时,系统管理人员才告之我,我们在查看的审计文件其实是用户home目录下的.sh_history,天哪!这就是传说中的审计文件,真神奇!

一般来说UNIX上的shell history只保留最近1000条的命令记录,为了不让这些唯一的证据丢失,我们首先将该.sh_history复制了一份,之后review历史记录文件后发现oracle用户执行过如下命令:

..............
rm -rf *
rcp -r node:/s01/oracle/product/10.2.0/db_1/* ./

rm -rf命令的确应当成为DBA的禁忌,无论是旧历江湖的老鸟还是初出茅庐的嫩头青都可能栽在rm手上。根据抽屉原理,最坏的情况总会发生,而我们又无法真正绝对意义上杜绝对rm命令的使用(我之前的文章介绍过由hostname误操作修改了RAC中一个节点的主机名的例子,这样的情况推荐使用uname -n来获取主机名字,可以杜绝使用hostname),那么我们真的很有必要在敲下rm命令前思考那么几秒,或者请另一位头脑清醒的仁兄帮自己确认一下,当然常年在船上走没有不湿鞋的,特别是当操作者处在一种panic模式的情景中时。

这个case因为oracle用户的密码只有少数几个人拥有,所以之后很容易能定位到责任人。多年之前在我第一家服务的公司中,office中到处贴着各种IT从业人员应当知晓的守则,其中就有一条”Passwords are like bubble gum”,是的密码就像是吹泡泡糖!

Oracle 12c coming soon?

Oracle的扛鼎产品Database Software数据库软件12c版本何时会发布?

就这一问题,我们来回顾一下Oracle数据库产品发布的历史年表:

Release Release Date Elapsed Years
Oracle 6 1988
Oracle 7 1992 4
Oracle 8 1997 5
Oracle 8i 1998 1
Oracle 9i 2001 3
Oracle 10g 2004 3
Oracle 11g 2007 3
Oracle 12c Unknown till now 4

 

到11g为止(Oracle 11g的Beta版本最早在2006年招募内部测试者),Oracle平均每3.6年发布新的一代数据库产品。

根据以往的经验以及一些小道消息(部分来自于Oracle Staff),我们有理由相信在今年(2011)的第三或第四季度Oracle可能会展开对Database 12c的Beta测试,并且会在2012年的第一季度为其下一代的重量级数据库产品Oracle Database 12c揭开序幕!

在2012同期可能发布的重量级产品还有Microsoft微软公司的旗舰产品Windows 8。

如果不出意料的话我们有幸在2012-Dec-21之前体验到以上这2款软件,俗套地说:”神马都是浮云啊!“
Apocalypse2012

沪ICP备14014813号-2

沪公网安备 31010802001379号