我的DBA手记（熊军）

原创由迪 2020-10-21

3512

题记

有人说DBA行业的从业人员越老越值钱，其实值钱的不是他们的经验，而是他们的思维模式，只有经过长久的历练，分析问题才能一针见血。熊军十几年都在从事Oracle数据库专业技术工作，在此精选了他的成长历程、学习经验，以及分析问题的一些案例分享给大家，通过具体的案例我们可以看到一个运维的“老司机”如何精准有效地解读问题。
12.1 技术生涯有感

我最早是从事IT系统运维的，数据库、主机、网络都要维护。随着业务量和数据量的增加，系统也越来越慢，于是就尝试去优化系统。
优化系统最主要就是优化数据库，而优化数据库就需要全面深入地理解数据库。在优化的过程中，我不断地去学习数据库的知识，然后发现Oracle数据库提供了很多有趣的特性，利用这些特性来解决问题，给我带来了很多的满足感和成就感。这样我逐渐对Oracle数据库产生了很强的兴趣，就有一种内在的动力去更深入地学习Oracle数据库。在学习Oracle数据库的过程中，逐步提高自己的技术水平主要把握以下几点。
（1）对Oracle数据库有浓厚的兴趣，这个是很重要的一方面。
（2）学习Oracle的官方文档，最基本的有《Oracle Database Concepts》《Oracle Database Performance Tuning Guide》《Oracle Database Administrator’s Guide》，这3份官方文档，对于各个版本我都反复去读。
（3）学习其他技术专家的书，包括Tom Kyte、Eygle的书等。
（4）在学习和实验的过程中，将一些心得体会、学习方法记录在个人技术博客上，在博客上写技术文章，是对文章中涉及的知识进行总结、梳理的过程，这对提高技术水平有极大的帮助。
（5）在工作中不断思考，例如解决一个问题，需要从原理上去解释为什么，一个问题是否有多个解决方案，每种解决方案各有什么优缺点。在问题解决后，再把这些案例涉及的知识进行梳理并写成文档，在这种方式下，解决一个问题就能获得技术进步。
（6）从Oracle数据库论坛（例如ITPUB）中获得进步，在ITPUB上有一些很有价值的技术文章，以及有很多值得研究学习的案例，通过这些案例和文章学习其他人的思路和方法。
通过以上的一些方法，就逐渐地一步一步地提高了技术水平，并且通过在论坛上进行技术讨论，参与书籍的编写、通过个人博客进行分享，这些方式在一定程度上提高了自己的影响力，最后获得ACE称号也是水到渠成的事情。ACE是Oracle公司为那些在Oracle技术领域，除了数据库还包括其他产品（如中间件、JAVA等）颁发的一个荣誉称号。以表彰那些在Oracle技术领域内具有很强技术水平又乐于向技术社区分享技术的人。所以要成为ACE，需要具备两个条件，一是有有比较高的技术水平，二是乐于分享，让自己在技术社会里面有一定的影响力。获得ACE以及ACED的称号对我的职业生涯的影响很大，这种影响首先在于获得一种认同感和肯定，同时也能够有更多的机会认识更多同行业中的朋友，让自己有机会进入到真正重视技术、以技术为竞争力的公司。
12.2 自我定位及规划

我对自己的定位还是一个技术工程师，一方面是因为这样能最大化地发挥我的价值和在技术方面的能力及作用，另一方面是出于我个人的兴趣和爱好仍然是技术。虽然现在承担了公司西区整个团队的领导工作，但是我在技术的道路上也从没有止步。
而且随着个人承担职责的变化，团队的成长和个人的成长就更加紧密地结合在一起，在现在的技术团队中，需要随着团队的进步而进步，也要引领团队的进步。引领团队自然需要一直紧跟技术趋势，并且根据IT行业发展趋势，为客户提供更好的技术服务。例如随着企业信息化的方展，数据越来越重要。我们不光是围绕着数据库，还要围绕着数据来进行工作，挖掘数据本身的价值，这需要更深入的技术积累。
12.3 对数据库运维工作的认识

我个人认为数据库从业者工作中最应该做的事情是，把所有的操作和相关的数据都记录下来，这是一笔很宝贵的财富。最应该注意的事情自然是安全和测试。每一个操作，都尽可能地测试，因为一些操作看起来很简单，却可能产生不可预料的结果。对于安全，主要是指数据安全，要做好备份，这是很重要的一道防线，只有在有备份的情况下，操作错误时才有回退的可能。最应该杜绝的想法是，对于这一点，我觉得是不要有工作有捷径的想法。工作的捷径来自于技术的积累和经验的积累。很多从业者喜欢从百度、Google搜索到具体的操作方法并且不加思考地拿来就用，这样虽然能够解决问题，但是这会导致自己缺乏思考，缺乏对知识的系统掌握。而工作上的捷径应该是来自于自己对知识的全面掌握之后还有经验的积累，通过自动化、或者是通过脚本、自行开发的工具来帮助提升工作效率。
12.4 学习理念分享

我个人在学习Oracle的一些方法这里我简单总结一下，供大家参考借鉴。我打一个比方，Oracle的学习，就好比武侠小说中学武功，要从3个方面入手。
（1）内功：针以学习 Oracle 来说，内功就是对基本概念的掌握，Oracle架构的深入理解，原理的掌握。如果有兴趣和时间，可以研究一下 Internal 的东西，这好比修习易筋经，需要极大的毅力和长期的坚持。
（2）招式：如果光有内功，没有招式，则会陷入空有高深内力，却无从发招的尴尬。学习 Oracle 也一样，还是需要掌握功能的使用，具体到 SQL 的使用，各个性能视图的使用，数据字典的使用。如果没有这些，在进行操作时，会有找不到无从下手的感觉。
（3）实战经验：武侠世界中的高手，都是从无数次战斗中取得经验，再武功大进。学习 Oracle 也一样，如果没有充分的实验，实际生产环境的实战，仍然只能说是只能入了 Oracle 的门，算不上登入大堂。另外，学习过程中，多做笔记、多思考。做任何事，都需要多思考，学习 Oracle 也不例外。对 Oracle 的众多的功能和知识点，我们要经常思考，这个功能有什么好处，适用于什么地方，不适用于什么地方，每个知识点之间的联系等。甚至是要站在超越 Oracle的高度，去思考Oracle为什么会这样设计。另外，好记性不如烂笔头，除非是天才，否则很多东西，久了就忘记了。
12.5 RAC数据库频繁hang问题诊断案例

数据库的问题大体上可以分为两类，一类是数据库真的出了问题，不能正常运行，甚至影响到业务的。另一类是潜在的问题，也就是性能问题。对于这两类问题的分析，有相同也有不同之处。我们通过具体的案例来说明。
12.5.1 案例现象及概要
某客户的核心系统数据库是2节点的Oracle RAC数据库，版本为10.2.0.4，数据库主机平台为IBM AIX，数据量超过10TB。这套数据库在最近一段时间经常出现系统挂起的严重故障，严重影响了生产的运行。在近一个月内，几乎每天可能都会出现故障，甚至是在业务不繁忙的时候。本文主要分析了系统的故障原因，并提出了对应的解决方案，希望能给读者在故障诊断时提供一些思路。
下面是2014年1月7日早上8点至9点时间段的故障日志（为保护案例数据库的信息，将实际的数据库名字替换为orcl）。实例1日志信息。
Tue Jan 7 07:51:08 2014
ALTER SYSTEM ARCHIVE LOG
Tue Jan 7 07:51:08 2014
Thread 1 cannot allocate new log, sequence 75616
Checkpoint not complete
Current log# 1 seq# 75615 mem# 0: /dev/rlv9
Tue Jan 7 08:15:52 2014
PMON failed to delete process, see PMON trace file
Tue Jan 7 08:23:34 2014
WARNING: inbound connection timed out (ORA-3136)
Tue Jan 7 08:24:53 2014
Errors in file /u01/app/oracle10g/admin/orcldb/udump/orcldb1_ora_10503176.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-01013: user requested cancel of current operation
ORA-06512: at line 2
…省略部分内容…
Tue Jan 7 08:52:22 2014
Shutting down instance (abort)
License high water mark = 3510
Instance terminated by USER, pid = 5731764
Tue Jan 7 09:01:45 2014
Starting ORACLE instance (normal)
sskgpgetexecname failed to get name

早上7:51左右出现了“检查点未完成”而不能切换日志的信息，8:23左右出现会话不能登录的信息，而到8：52强制关闭了实例然后重启。
在数据库关闭之前，对数据库做了system state 转储，在跟踪文件orcldb1_ora_5727520.trc中有如下重要信息。
*** 2014-01-07 08:37:45.920
SYSTEM STATE
------------PROCESS 207:--------------
SO: 7000028079afb58, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=207, calls cur/top: 70000275222f680/70000275222f680, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 128
last post received-location: kclrget last process to post me: 70000280f9952b0 1 6
last post sent: 0 0 123 last post sent-location: kcrfw_redo_gen: wake LGWR after redo copy
last process posted by me: 7000028079a3e58 1 6 (latch info) wait_event=0 bits=2
holding (efd=10) 7000027ce79ac58 Child cache buffers chains level=1 child#=40228
Location from where latch is held: kcbgtcr: kslbegin excl:
Context saved from call: 2160934423
state=busy(exclusive) (val=0x20000000000000cf) holder orapid = 207
waiters [orapid (seconds since: put on list, posted, alive check)]:
40 (3851, 1389055081, 1) waiter count=1
Process Group: DEFAULT, pseudo proc: 70000280fb3a820
O/S info: user: oracle, term: pts/2, ospid: 5297410
OSD pid info: Unix process pid: 5297410, image: oracle@kjorcldb1 (TNS V1-V3)
…省略部分内容…
SO: 700002802e78798, type: 4, owner: 7000028079afb58, flag: INIT/-/-/0x00
(session) sid: 4339 trans: 700002775cc8cc8, creator: 7000028079afb58, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0001-00CF-00005C72, short-term DID: 0001-00CF-00005C73 txn branch: 0
oct: 6, prv: 0, SQL: 7000026e943b618, pSQL: 70000268a5dd9d0, user: 49/ORCLADM
service name: SYS$USERS
O/S info: user: oracle, term: pts/2, ospid: 3114266, machine: kjorcldb1
program: SQLplus@kjorcldb1 (TNS V1-V3) application name: SQL*Plus, hash value=3669949024
last wait for ‘db file sequential read’ blocking sess=0x0 seq=91 wait_time=26947 seconds since wait started=4456
file#=d5, block#=5b789, blocks=1
Dumping Session Wait History
for ‘db file sequential read’ count=1 wait_time=26947 file#=d5, block#=5b789, blocks=1
for ‘db file sequential read’ count=1 wait_time=426
…省略部分内容…
LIBRARY OBJECT LOCK: lock=700002752e1b380 handle=7000026e943b618 mode=N
call pin=0 session pin=0 hpc=0000 hlc=0000
htl=700002752e1b400[700002687a44a90,70000272d437c30] htb=700002687a44a90 ssga=700002687a44538
user=700002802e78798 session=700002802e78798 count=1 flags=[0000] savepoint=0x52cad289
LIBRARY OBJECT HANDLE: handle=7000026e943b618 mtx=7000026e943b748(1) cdp=1
name=
UPDATE jl_jlzzda_13 a SET zcbh =
(SELECT zcbh FROM pc_dnb_jg_13 b
WHERE a.zzbh = b.zzbh AND a.zcbh <> b.zcbh
AND ( TRIM (b.zcbh) = :“SYS_B_0” OR TRIM (b.zcbh) = :“SYS_B_1” OR TRIM (b.zcbh) = :“SYS_B_2”))
WHERE a.zcbh <> :“SYS_B_3” AND a.zcbh <> :“SYS_B_4” AND EXISTS
(SELECT :“SYS_B_5” FROM pc_dnb_jg_13 b WHERE a.zzbh = b.zzbh AND a.zcbh <> b.zcbh
AND ( TRIM (b.zcbh) = :“SYS_B_6” OR TRIM (b.zcbh) = :“SYS_B_7” OR TRIM (b.zcbh) = :“SYS_B_8”))

故障详细分析
从system dump的信息，反映出以下几点。
（1）oracle进程（orapid=207，ospid=5297410，session id=4339）持有一个cache buffers chains child latch，子latch号为40228，子latch的地址为：7000027ce79ac58。
（2）这个进程阻塞了一个进程（orapid=40），阻塞时间长为3851秒。
（3）这个进程上一个等待事件是磁盘单块读，到目前为止已经过了4456秒。system state dump是从2014年1月7日08:37:45开始的，那么4456秒之前即latch开始持有的时间是在2014年1月7日07:23:29至2014年1月7日07:28:29之间（由于system state dump本身需要消耗一定的时间，因此会有一定的时间误差，这个时间误差在5分钟之内）。
（4）这个进程的是由数据库主机本机上的SQLplus连接上来的，正在执行的SQL语句如下。
UPDATE jl_jlzzda_13 a
SET zcbh =
(SELECT zcbh
FROM pc_dnb_jg_13 b
WHERE a.zzbh = b.zzbh AND a.zcbh <> b.zcbh
AND ( TRIM (b.zcbh) = :“SYS_B_0”
OR TRIM (b.zcbh) = :“SYS_B_1”
OR TRIM (b.zcbh) = :“SYS_B_2”))
WHERE a.zcbh <> :“SYS_B_3” AND a.zcbh <> :“SYS_B_4”
AND EXISTS
(SELECT :“SYS_B_5”
FROM pc_dnb_jg_13 b
WHERE a.zzbh = b.zzbh AND a.zcbh <> b.zcbh
AND ( TRIM (b.zcbh) = :“SYS_B_6”
OR TRIM (b.zcbh) = :“SYS_B_7”
OR TRIM (b.zcbh) = :“SYS_B_8”))

这里很明显有一个异常，进程持有latch的时间过长。正常情况下latch持有时间在微秒级，而这个进程持有latch长达几千秒。这通常是由于进程异常或挂起所导致。
接下来，看看这个进程所阻塞的进程（orapid=40）的信息。
------------PROCESS 40: ----------------------------------------
SO: 7000028069d2bf8, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=40, calls cur/top: 70000280012d810/70000280012d810, flag: (6) SYSTEM
int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 114
last post received-location: kcbbza last process to post me: 7000028039b5570 1 6
last post sent: 504403329233300568 122 2 last post sent-location: kslges
last process posted by me: 7000028039b35f0 1 14
(latch info) wait_event=0 bits=0 Location from where call was made: kcbkzs:
waiting for 7000027ce79ac58 Child cache buffers chains level=1 child#=40228
Location from where latch is held: kcbgtcr: kslbegin excl:
Context saved from call: 2160934423
state=busy(exclusive) (val=0x20000000000000cf) holder orapid = 207
waiters [orapid (seconds since: put on list, posted, alive check)]:
40 (3837, 1389055067, 2) waiter count=1
gotten 7812722 times wait, failed first 65133 sleeps 380 gotten 36115 times nowait, failed: 14223
possible holder pid = 207 ospid=5297410
on wait list for 7000027ce79ac58
Process Group: DEFAULT, pseudo proc: 70000280fb3a820
O/S info: user: oracle, term: UNKNOWN, ospid: 2508016
OSD pid info: Unix process pid: 2508016, image: oracle@kjorcldb1 (CKPT)
SO: 70000280112aa90, type: 4, owner: 7000028069d2bf8, flag: INIT/-/-/0x00
(session) sid: 6567 trans: 0, creator: 7000028069d2bf8, flag: (51) USR/- BSY/-/-/-/-/-
DID: 0001-0028-00000004, short-term DID: 0001-0028-00000005 txn branch: 0
oct: 0, prv: 0, SQL: 0, pSQL: 0, user: 0/SYS
service name: SYS$BACKGROUND
waiting for ‘latch: cache buffers chains’ blocking sess=0x0 seq=26223 wait_time=0 seconds since wait started=3835
address=7000027ce79ac58, number=7a, tries=31f0
Dumping Session Wait History
for ‘latch: cache buffers chains’ count=1 wait_time=292977

从上面的信息可以确认以下几点：
（1）被阻塞的进程是CKPT进程，这是系统关键的后台进程——检查点进程。
（2）CKPT进程由于等待cache buffers chains latch而被阻塞，被阻塞的时间长为3837秒，也就是在大约2014年1月7日07:33:48时被阻塞（由于system state dump需要消耗时间，所以可能有5分钟之内的时间误差）。
很显然，由于CKPT进程被长时间阻塞，将不能完成检查点工作。
Tue Jan 7 07:18:53 2014
Thread 1 advanced to log sequence 75613 (LGWR switch)
Current log# 3 seq# 75613 mem# 0: /dev/rlv11
Tue Jan 7 07:31:01 2014
Thread 1 advanced to log sequence 75614 (LGWR switch)
Current log# 2 seq# 75614 mem# 0: /dev/rlv10
Tue Jan 7 07:43:04 2014
Thread 1 advanced to log sequence 75615 (LGWR switch)
Current log# 1 seq# 75615 mem# 0: /dev/rlv9
Tue Jan 7 07:51:08 2014
ALTER SYSTEM ARCHIVE LOG
Tue Jan 7 07:51:08 2014
Thread 1 cannot allocate new log, sequence 75616
Checkpoint not complete
Current log# 1 seq# 75615 mem# 0: /dev/rlv9

由于一个实例的在线日志文件只有3组，从7:31开始，经过3次切换，就不能再切换了。不能切换日志就意味着不能进行任何数据更改。由于数据库设置有登录触发器，对登录信息进行记录，会涉及数据插入。在这样的情况下，用户登录也不能成功，会一直挂起（或者直至超时）。
由于CKPT挂起，这导致了SMON这个关键后台进程也一直挂起。
-------------------------------------PROCESS 41:-------------------------------------
SO: 7000028059c6be8, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=41, calls cur/top: 70000280012dae8/70000280012dae8, flag: (16) SYSTEM
int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 154
last post received-location: ktmpsm last process to post me: 7000028039b35f0 1 14
last post sent: 0 0 90 last post sent-location: KJCS Post snd proxy to flush msg
last process posted by me: 7000028059c4488 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 70000280fb3a820
O/S info: user: oracle, term: UNKNOWN, ospid: 103858
OSD pid info: Unix process pid: 103858, image: oracle@kjorcldb1 (SMON)
(session) sid: 6566 trans: 7000027734e5c60, creator: 7000028059c6be8, flag: (100051) USR/- BSY/-/-/-/-/-
DID: 0001-0029-00000002, short-term DID: 0001-0029-00000003 txn branch: 0 oct: 0, prv: 0, SQL: 0, pSQL: 0, user: 0/SYS
service name: SYS$BACKGROUND
waiting for ‘DFS lock handle’ blocking sess=0x0 seq=59072 wait_time=0 seconds since wait started=3835 type|mode=43490005, id1=1, id2=2
Dumping Session Wait History
for ‘DFS lock handle’ count=1 wait_time=488290 type|mode=43490005, id1=1, id2=2
for ‘DFS lock handle’ count=1 wait_time=488291 type|mode=43490005, id1=1, id2=2
…省略部分内容…
----------------------------------------
SO: 7000027fd890990, type: 18, owner: 7000028003a2c80, flag: INIT/-/-/0x00
----------enqueue 0x7000027fd890990------------------------
lock version : 3392757 Owner node : 0
grant_level : KJUSERNL req_level : KJUSEREX
bast_level : KJUSERNL notify_func : 0
resp : 7000025f95f7e50 procp : 7000028003a2c80
pid : 103858 proc version : 0
oprocp : 0 opid : 0
group lock owner : 0 xid : 0000-0000-00000000
dd_time : 0.0 secs dd_count : 0
timeout : 0.0 secs On_timer_q? : N
On_dd_q? : N lock_state : OPENING CONVERTING
Open Options : KJUSERPROCESS_OWNED
Convert options : KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
History : 0x49a5149a Msg_Seq : 0x0
res_seq : 4090 valblk : 0x00000000000000000000000000000000 .
----------resource 0x7000025f95f7e50----------------------
resname : [0x1][0x2],[CI]
Local node : 0 dir_node : 1 master_node : 1 hv idx : 98
hv last r.inc : 4 current inc : 4 hv status : 0 hv master : 1
open options : Held mode : KJUSEREX
Cvt mode : KJUSERNL Next Cvt mode : KJUSERNL
msg_seq : f0010 res_seq : 4090
grant_bits : KJUSERNL KJUSERPR
grant mode : KJUSERNL KJUSERCR KJUSERCW KJUSERPR KJUSERPW KJUSEREX
count : 1 0 0 1 0 0
val_state : KJUSERVS_NOVALUE
valblk : 0x00000000000000000000000000000000 .
access_node : 0 vbreq_state : 0
state : x8 resp : 7000025f95f7e50
On Scan_q? : N Total accesses: 8014573 Imm. accesses: 7891534
Granted_locks : 1 Cvting_locks : 1 value_block: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 7000027fa0ce178 gl KJUSERPR rp 7000025f95f7e50 [0x1][0x2],[CI]
master 1 pid 2508016 bast 0 rseq 4090 mseq 0 history 0x95614956
open opt KJUSERPROCESS_OWNED
CONVERT_Q:
lp 7000027fd890990 gl KJUSERNL rl KJUSEREX rp 7000025f95f7e50 [0x1][0x2],[CI]
master 1 pid 103858 bast 0 rseq 4090 mseq 0 history 0x49a5149a
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
----------------------------------------

从上面的信息可以看到，资源的GRANTED_Q队列中有进程2508016。这个进程正是CKPT进程，即CKPT进程以PROTECT READ模式持有资源，但是SMON进程需要以EXCLUSIVE模式来持有资源。这两种模式是不兼容的，因此SMON进程就被阻塞。
到目前为止，可以确定是由于异常的进程（orapid=207）长时间持有cache buffers chains child latch，使得CKPT被长时间阻塞，导致不能完成检查点，最终导致不能进行任何数据更改和不能连接数据库。
导致系统故障的异常进程，其异常的原因，通常有：
（1）操作系统Bug导致，使得异常的进程不能调度。在trace文件中看到，使用procstack获取进程call stack失败，说明进程在操作系统一级异常，而不是在oracle内部存在spin或stuck hang的情况。
（2）Oracle的Bug，通过在MOS上查找，我们发现有如下Bug：Bug 6859515 Diagnostic collection may hang or crash the instance，可能会有影响。
如何认定一个Bug与故障是匹配的？我们需要从大量的日志和trace中去寻找。一般会去从diag进程的trace和system state dump中寻找：
在diag进程的trace文件中，我们发现现象与Bug 6859515比较匹配。
*** 2014-01-07 07:24:56.655
Dump requested by process [orapid=46]
REQUEST:custom dump [2] with parameters [46][207][2][2]
Dumping process info of pid[207.5297410] requested by pid[46.1008052]
Dumping process 207.5297410 info:
*** 2014-01-07 07:24:56.655
Dumping diagnostic information for ospid 5297410:
OS pid = 5297410
loadavg : 4.78 4.81 4.52
swap info: free_mem = 77226.37M rsv = 228.00M
alloc = 636.91M avail = 58368.00M swap_free = 57731.09M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
240001 A oracle 5297410 1 120 120 20 3acdbd4590 126808 23:46:25 - 27:22 oracleorcldb1 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
open: The file access permissions do not allow the specified action.
procstack: write(/proc/5297410/ctl): The requested resource is busy.
5297410: oracleorcldb1 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
0x0000000000000000 ???() + ??

从上面的数据可以看到，ospid=5297410这个进程正是异常的持有latch的进程。这个进程在2014年1月7日07:24:56被请求转储，从时间上看这与该进程异常的时间点在2014年1月7日07:23:29至2014年1月7日07:28:29之间匹配。诊断转储是由orapid=46，ospid=1008052这个进程请求diag进程发起的。
“procstack: write（/proc/5297410/ctl）: The requested resource is busy.”表明进程出现了异常。
PROCESS 46: ----------------------------------------
SO: 7000028079a4638, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=46, calls cur/top: 70000275b01c398/70000275b01c398, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 55
last post received-location: kjata: wake up enqueue owner
last process to post me: 7000028059c4488 1 6 last post sent: 0 0 90
last post sent-location: KJCS Post snd proxy to flush msg
last process posted by me: 7000028059c4488 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 70000280fb3a820
O/S info: user: oracle, term: pts/3, ospid: 1008052
OSD pid info: Unix process pid: 1008052, image: oracle@kjorcldb1 (TNS V1-V3)
SO: 70000280ffd40b0, type: 4, owner: 7000028079a4638, flag: INIT/-/-/0x00
(session) sid: 6122 trans: 70000276e23b848, creator: 7000028079a4638, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0001-002E-001DD0F9, short-term DID: 0001-002E-001DD0FA txn branch: 0
oct: 6, prv: 0, SQL: 7000026e943b618, pSQL: 70000268a5dd9d0, user: 49/ORCLADM
service name: SYS$USERS
O/S info: user: oracle, term: pts/3, ospid: 3371970, machine: kjorcldb1
program: SQLplus@kjorcldb1 (TNS V1-V3)
application name: SQL*Plus, hash value=3669949024
waiting for ‘enq: TX - row lock contention’ blocking sess=0x0 seq=4560 wait_time=0 seconds since wait started=5330 name|mode=54580006, usn<<16 | slot=2b70003, sequence=5324
Dumping Session Wait History
for ‘enq: TX - row lock contention’ count=1 wait_time=488292 name|mode=54580006, usn<<16 | slot=2b70003, sequence=5324
for ‘enq: TX - row lock contention’ count=1 wait_time=488292 name|mode=54580006, usn<<16 | slot=2b70003, sequence=5324

从上面的数据可以看到，orapid=46，ospid=1008052这个进程一直在等待TX事务行锁，这个进程同样是SQLplus程序连接数据库产生的进程，执行的SQL语句也与异常进程一样。这个进程被异常进程（即orapid=207）阻塞，阻塞大约是在08:37:45的5330秒之前，即07:08:55左右。
SYS@xj11g> select to_char(sample_time,‘yyyy-mm-dd hh24:mi:ss’) sample_time,session_id, event,program,blocking_session
2 from dba_hist_active_sess_history where instance_number=1 and dbid=3516340257
3 and sample_id=144574100
4 order by sample_time,session_id;

SAMPLE_TIME SESSION_ID EVENT PROGRAM BLOCKING_SESSION

2014-01-07 07:15:32 3532 DFGD_LONG@kj_orcl_app2 (TNS V1-
V3)
2014-01-07 07:15:32 4323 jlzztb.d@kj_orcl_app1 (TNS V1-V
3)
2014-01-07 07:15:32 4339 SQLplus@kjorcldb1 (TNS V1-V3)
2014-01-07 07:15:32 4739 SQLplus@kjorcldb1 (TNS V1-V3)
2014-01-07 07:15:32 5009 enq: TX - row lock contention DFGD_LONG@kj_orcl_app1 (TNS V1- 3532
V3)
2014-01-07 07:15:32 6122 enq: TX - row lock contention SQLplus@kjorcldb1 (TNS V1-V3) 4339

会话6122在等待事务锁，阻塞的会话是4339，即orapid=207的会话进程。由于SQL执行性能的原因，数据锁时间过长，因此会话6122即orapid=46的进程向diag进程申请发起一个对orapid=207进程的转储操作，这样就触发了Bug，导致orapid=207的进程异常。
2014年1月9日12:30左右，数据库节点2的实例再次发生hang故障。从diag的信息来看，同样是因为diag触发Bug导致进程异常。异常进程持有redo copy latch使得其他所有进程，包括LGWR进程不能进行日志生成和写出，不能进行任何数据修改，短时间内堵塞了大量会话，同时数据库实例完全挂起。
*** 2014-01-09 12:25:06.473
Dumping diagnostic information for ospid 385380:
OS pid = 385380 loadavg : 12.82 13.52 16.37
swap info: free_mem = 31221.03M rsv = 256.00M alloc = 674.18M avail = 65536.00M swap_free = 64861.82M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
240001 A oracle 385380 1 56 88 20 1ea0cf7590 97272 19:08:20 - 39:10 oracleorcldb2 (LOCAL=NO)
open: The file access permissions do not allow the specified action.
procstack: write(/proc/385380/ctl): The requested resource is busy.
385380: oracleorcldb2 (LOCAL=NO)
0x0000000000000000 ???() + ??

*** 2014-01-09 12:25:06.624

SO: 7000028079acc18, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=165, calls cur/top: 700002641f86eb0/700002641f86eb0, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 136
last post received-location: kclrcvt
last process to post me: 7000028059c5448 1 6
last post sent: 0 0 117
last post sent-location: kcbzww
last process posted by me: 7000028049b5968 7 0
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 70000280fb3a820
O/S info: user: oracle, term: UNKNOWN, ospid: 385380
OSD pid info: Unix process pid: 385380, image: oracle@kjorcldb2

SO: 70000280fdaf820, type: 4, owner: 7000028079acc18, flag: INIT/-/-/0x00
(session) sid: 3252 trans: 700002775b06728, creator: 7000028079acc18, flag: (100141) USR/- BSY/-/-/-/-/-
DID: 0002-00A5-00000036, short-term DID: 0002-00A5-00000037
txn branch: 0
oct: 0, prv: 0, SQL: 0, pSQL: 70000262f26cbd8, user: 49/ORCLADM
O/S info: user: yxmis, term: , ospid: 25364, machine: kj_orcl_app1
program: DFGD_LONG@kj_orcl_app1 (TNS V1-V3)
application name: DFGD_LONG@kj_orcl_app1 (TNS V1-V3), hash value=3372202780
last wait for ‘gc current request’ blocking sess=0x0 seq=8372 wait_time=1086 seconds since wait started=0
file#=1f9, block#=2c0a, id#=2000008

在hang analyze的结果中可以看到，正是3252 这个会话产生了阻塞。
*** 2014-01-09 12:33:12.692

HANG ANALYSIS:

Found 416 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/6568/1/0x69d2bf8/4429090/latch: redo allocation>
Found 13 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<1/4035/5/0x7a51a38/1242406/log file sync>
Open chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<1/3252/61/0x79acc18/385380/No Wait>
– <1/6568/1/0x69d2bf8/4429090/latch: redo allocation>
– <1/2590/3/0x5a263a8/2778422/log file sync>

有416个会话在等待6568这个会话，即6568会话阻塞了416个进程，而6568会话在等待latch：redo allocation，而6568会话正是被3252这个会话阻塞。
6568会话是LGWR进程。毫无疑问，LGWR进程不能持有redo allocation latch，将不能写redo到日志文件，也就不能完成事务提交，所以在短时间内会产生大量的进程在等待log file sync，即等待LGWR完成日志写入。
接下来再看看2014年1月8日10:13左右开始，节点2数据库实例很慢然后发生hang故障，这同样是diag触发Bug引起的。
*** 2014-01-08 10:13:21.472
Dumping diagnostic information for ospid 652210:
OS pid = 652210
loadavg : 31.73 28.30 25.81
swap info: free_mem = 96209.99M rsv = 256.00M
alloc = 608.77M avail = 65536.00M swap_free = 64927.23M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
240001 A oracle 652210 1 68 94 20 3aff9d6590 97376 23:03:53 - 40:07 oracleorcldb2 (LOCAL=NO)
open: The file access permissions do not allow the specified action.
procstack: write(/proc/652210/ctl): The requested resource is busy.
652210: oracleorcldb2 (LOCAL=NO)

*** 2014-01-08 10:13:21.611

SO: 7000028069f3b98, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=509, calls cur/top: 70000261e0f2a90/70000261e0f2a90, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 55
last post received-location: kjata: wake up enqueue owner
last process to post me: 7000028059c4488 1 6
last post sent: 0 0 117
last post sent-location: kcbzww
last process posted by me: 7000028059e7b88 1 0
(latch info) wait_event=0 bits=30
Process Group: DEFAULT, pseudo proc: 70000280fb3a820
O/S info: user: oracle, term: UNKNOWN, ospid: 652210
OSD pid info: Unix process pid: 652210, image: oracle@kjorcldb2

SO: 700002805ff0c40, type: 4, owner: 7000028069f3b98, flag: INIT/-/-/0x00
(session) sid: 6064 trans: 70000276e1c5678, creator: 7000028069f3b98, flag: (100141) USR/- BSY/-/-/-/-/-
DID: 0002-01FD-00000001, short-term DID: 0002-01FD-00000002
txn branch: 0
oct: 0, prv: 0, SQL: 0, pSQL: 70000280daaa140, user: 49/ORCLADM
O/S info: user: yxmis, term: , ospid: 25365, machine: kj_orcl_app1
program: DFGD_LONG@kj_orcl_app1 (TNS V1-V3)
application name: DFGD_LONG@kj_orcl_app1 (TNS V1-V3), hash value=3372202780
last wait for ‘gc current request’ blocking sess=0x0 seq=22792 wait_time=315 seconds since wait started=0
file#=147, block#=11c2b2, id#=2000001

查看ASH数据。
SYS@xj11g> col program for a40
SYS@xj11g> select to_char(sample_time,‘yyyy-mm-dd hh24:mi:ss’) sample_time,session_id, event,program,blocking_session
2 from dba_hist_active_sess_history where sample_time>=sysdate-3
3 and instance_number=2 and dbid=3516340257
4 and sample_id=144689900
5 order by sample_time,session_id;

SAMPLE_TIME SESSION_ID EVENT PROGRAM BLOCKING_SESSION

2014-01-08 10:13:15 4218 KHFW_LONG@kj_orcl_web1 (TNS V1-V3)
2014-01-08 10:13:15 4541 db file sequential read BBGL_LONG_D@kj_orcl_cxbb3 (TNS V1-V3)
2014-01-08 10:13:15 4828 ZHCX_LONG_C@kj_orcl_cxbb1 (TNS V1-V3)
2014-01-08 10:13:15 5002 db file sequential read ORCL_TDGL_LONG@kj_orcl_cxbb2 (TNS V1-V3)
2014-01-08 10:13:15 5022 db file parallel read BBGL_LONG_A@kj_orcl_cxbb3 (TNS V1-V3)
2014-01-08 10:13:15 5237 gc cr multi block request JL_JLZC_LONG@kj_orcl_app2 (TNS V1-V3)
2014-01-08 10:13:15 5417 db file sequential read ZHCX_LONG_C@kj_orcl_app7 (TNS V1-V3)
2014-01-08 10:13:15 5440 ORCL_ZHCX_LONG@kj_orcl_app7 (TNS V1-V3)
2014-01-08 10:13:15 6064 enq: TX - row lock contention DFGD_LONG@kj_orcl_app1 (TNS V1-V3)
2014-01-08 10:13:15 6083 enq: TX - row lock contention DFGD_LONG@kj_orcl_app2 (TNS V1-V3)
2014-01-08 10:13:15 6181 db file sequential read BBGL_LONG_B@kj_orcl_app5 (TNS V1-V3)
2014-01-08 10:13:15 6205 enq: TX - row lock contention DFGD_LONG@kj_orcl_app1 (TNS V1-V3)
2014-01-08 10:13:15 6595 oracle@kjorcldb2 (LMS5)

SYS@xj11g> select to_char(sample_time,‘yyyy-mm-dd hh24:mi:ss’) sample_time,session_id, event,program,blocking_session
2 from dba_hist_active_sess_history where sample_time>=sysdate-3
3 and instance_number=2 and dbid=3516340257
4 and sample_id=144689910
5 order by sample_time,session_id;

SAMPLE_TIME SESSION_ID EVENT PROGRAM BLOCKING_SESSION

2014-01-08 10:13:25 3932 log file sync DFFX_LONG@ORCL-APP4 (TNS V1-V3) 6568
2014-01-08 10:13:25 3942 log file sync DFYW_SHORT@kj_orcl_cxbb3 (TNS V1-V3) 6568
2014-01-08 10:13:25 4056 db file scattered read plSQLdev.exe
2014-01-08 10:13:25 4061 log file sync process.d@kj_orcl_app1 (TNS V1-V3) 6568
2014-01-08 10:13:25 4134 log file sync DFYW_LONG_D@kj_orcl_cxbb1 (TNS V1-V3) 6568
…为节省篇幅，去掉大量类似数据…
2014-01-08 10:13:25 6460 YZX_LONG@kj_orcl_app1 (TNS V1-V3)
2014-01-08 10:13:25 6461 log file sync DFFX_SHORT@kj_orcl_app5 (TNS V1-V3) 6568
2014-01-08 10:13:25 6462 log file sync QXGL_SHORT@kj_orcl_app3 (TNS V1-V3) 6568
2014-01-08 10:13:25 6470 log file sync QXGL_SHORT@kj_orcl_app3 (TNS V1-V3) 6568
2014-01-08 10:13:25 6525 log file sync KHFW_SHORT@kj_orcl_web2 (TNS V1-V3) 6568
2014-01-08 10:13:25 6582 gcs log flush sync oracle@kjorcldb2 (LMSi) 6568
2014-01-08 10:13:25 6596 gcs log flush sync oracle@kjorcldb2 (LMS4) 6568

从ASH数据可以看到，10:13:15系统还处于正常状态，仅仅在10秒之后（在AWR中的ASH数据时间间隔为10秒），即10:13:25系统就产生了大量的阻塞。diag导致Bug被触发是在10:13:21这个时间。
12.5.2 案例总结
经过上述的深入分析，我们判断近段时间故障频发的主要原因是触发了Oracle的Bug 6859515，这个Bug为：Diagnostic collection may hang or crash the instance。具体如下所示。
（1）当Oracle的一个进程在等待某个资源（最常见的是事务锁，即TX锁）时间过长时，会向diag进程发起转储请求。diag进程对引起堵塞的进程发起转储（dump）操作，主要包括操作系统层面进程的信息、进程的call stack、在Oracle内部进程的状态和会话的状态等非常详细的数据，用于阻塞问题的诊断。
（2）diag进程会通过操作系统级的命令来收集被诊断进程的call stack信息，包括gdb调试工具或procstack等（不同的操作系统有所不同）。
gdb或procstack工具在取进程的call stack信息时是不安全的，可能会造成进程异常或挂起。如果此进程当时持有latch等重要资源，这些重要资源将不会被释放。因为进程只是异常或挂起，没有消失，因此Oracle的pmon进程不会清理和释放这些被一直占有的重要资源。
latch是Oracle内部一种低级的内存锁，使用非常频繁。通常latch的持有时间在毫秒级以下，如果进程长时间持有latch，将会使其他请求latch的进程也会一直挂起。最终关键的后台进程，如CKPT、LGWR等进程也会由于请求此latch获取无法得到响应而挂起，关键是后台进程的挂起会导致数据库挂起。
（3）异常进程持有的latch不同，系统的故障现象有所不同。
1）如果是持有cache buffer chains child latch，由于这种latch的子latch数量很多，每个子latch只是保护部分数据块头，所以只有在访问这个被持有的子latch保护的数据块时才会被阻塞（挂起）。进程一直会等待latch: cache buffer chains，随后会出现buffer busy waits、gc buffer busy等与数据块访问相关的等待。被挂起的进程如果处于事务之中，又会出现TX锁等待。如果这个latch保护的数据块是脏块，会导致DBWn（数据库写进程）进程等待这个latch而挂起。CKPT进程如果需要访问这个latch也会挂起，最终结果会导致不能完成检查点，日志不能切换，数据库挂起。cache buffer chains child latch数量众多，如果是由于一个child latch被异常进程持有一直到数据库挂起，历时时间较长，甚至可能达到数小时。
2）如果是持有redo copy latch、redo allocation latch等与redo相关的latch，由于这种latch只有一个或者是子latch数量极少，同时使用极为频繁，因此在短时间内LGWR这样的关键后台进程会挂起，大量进程出现log file sync等待，LMS等关键进程出现gcs log flush sync等待而挂起。其最终结果是短时间内出现大量进程挂起和系统挂起。
3）如果是持有shared pool latch、library cache latch等与SQL解析相关的latch，同样会在短时间内出现大量与解析相关的等待，导致大量进程挂起和系统挂起。
（4）在gdb或procstack导致进程异常的情况下，进程可能会被KILL命令杀掉，也可能不能被杀掉。如果进程能够被杀掉，那么数据库pmon进程会自动清理异常进程占用的资源，系统能够恢复正常。如果进程不能被杀掉，或者是pmon进程本身已经被阻塞而挂起，这样杀进程也不能使系统恢复正常，需要强制重启数据库才能使系统恢复运行。
要解决此问题，可以安装数据库补丁，补丁为8929701：TRACKING Bug FOR 6859515 ON AIX。安装这个补丁后，diag进程不再通过操作系统的gdb或procstack等工具获取被诊断进程的call stack等信息，而是改为使用Oracle内部的oradeBug short_stack命令来获取。如果不能打补丁，可以将隐含参数"_ksb_disable_diagpid"设置为TRUE作为临时解决方案。注意，这种设置之后，将不能自动收集进程诊断信息，这样当出现一些其他问题时可能会缺乏一些有效的诊断数据。
这个案例最终通过打补丁解决了问题。
通过这个案例，我想有如下的两点，对我们有些帮助。
1）很多朋友在安装数据库时，没有安装任何补丁。有些有经验的DBA，也只是安装了最新的PSU补丁，实际上有些对系统影响大的补丁并不在PSU中。比如在MOS文档“11.2.0.4 Patch Set - Availability and Known Issues (文档 ID 1562139.1)”中就列出了11.2.0.4这个版本中发现的出现频繁比较高的Bug。在可能的情况下，要把提到的Bug的补丁都打上。
2）在分析问题时，alert日志、system state dump、hang analyze trace、diagnostic进程trace和ASH（active session history）数据都是很有用的信息来源。多种数据交叉参考，可以避免单一数据形成的信息量不足没有思路，或者单一数据形成错误结论。
12.6 Exadata环境下SQL性能问题诊断案例
一位客户的Exadata数据库在大量数据处理期间经常出现部分SQL性能急剧下降的故障。正常执行只需要几分钟，但在故障时需要执行1小时至数小时。SQL异常会导致数据不能及时处理，严重影响了数据统计的及时性。
出现性能问题的SQL语句具体如下（由于SQL语句较长，仅列出了关键代码）。
create table TBAS.tmp_2_o_user_2_xxxx compress for query high nologging parallel as select /*+parallel (8) */ t1.ACC_NBR, ….
case when traffic_wlan/1024 > 20480 then 32 when t42.traffic_fund_type_id is not null then t42.traffic_fund_type_id else (select traffic_fund_type_id from pu_meta_dim.d_traffic_fund_type t where state = 1 andtraffic_wlan/1024 < t.max_value and traffic_wlan/1024 > t.min_value) end MBL_wlan_FUND_TYPE_ID, ….
from TBAS.tmp_1_o_user_2_xxx t1…

where关键字后面的代码通常很简单，甚至没有where条件。
分析SQL问题一般会从AWR报告、SQL的执行统计信息和SQL执行计划着手。
12.6.1 AWR报告
下列是检查故障时间段（比如：2014年10月15日11:00至12:00）的AWR报告。
2. Snap Id Snap Time Sessions Curs/Sess
3. --------- ------------------- -------- ---------
4. Begin Snap: 19332 05-Oct-14 11:00:18 257 1.8
5. End Snap: 19333 05-Oct-14 12:00:18 254 1.9
6. Elapsed: 59.99 (mins)
7. DB Time: 943.03 (mins)
8.
9. Cache Sizes Begin End
10. ~~~~~~~~~~~ ---------- ----------
11. Buffer Cache: 19,456M 19,456M Std Block Size: 8K
12. Shared Pool Size: 11,264M 11,264M Log Buffer: 227,180K
13.
14. Load Profile Per Second Per Transaction Per Exec Per Call
15. ~~~~~~~~~~~~ --------------- --------------- ---------- ----------
16. DB Time(s): 15.7 4.6 0.01 0.00
17. DB CPU(s): 6.6 1.9 0.00 0.00
18. Redo size: 441,825.6 127,927.9
19. Logical reads: 77,377.6 22,404.2
20. Block changes: 419.4 121.4
21. Physical reads: 9,898.7 2,866.1
22. Physical writes: 2,049.4 593.4
23. User calls: 9,804.6 2,838.9
24. Parses: 1,970.4 570.5
25. Hard parses: 0.7 0.2
26. W/A MB processed: 9.0 2.6
27. Logons: 1,959.8 567.4
28. Executes: 1,969.7 570.3
29. Rollbacks: 0.0 0.0
30. Transactions: 3.5
31.

从上面的数据可以看到，平均每秒Logons数达到1959次。这对于任何一个Oracle数据库来说，都是异常高的值，正常数据库的每秒Logon数都在30以下。出现这种情况的最可能的原因是空闲的并行进程加入到了会话当中，即数据库中频繁地发生大量的并发会话的启动和释放。
同时平均每秒1970次解析（parse）对数据仓库类应用来说也显得异常得高。
12.6.2 生成SQL报告
下列是生成故障SQL的SQL报告。
33. SQL ID: fym9dtwdyjpna DB/Inst: ORCLNEW/orclnew2 Snaps: 19321-19337
34. -> 1st Capture and Last Capture Snap IDs
35. refer to Snapshot IDs witin the snapshot range
36. -> create table TBAS.tmp_2_o_user_2_xxxx compress for query high nologgin…
37.
38. Plan Hash Total Elapsed 1st Capture Last Capture
39. # Value Time(ms) Executions Snap ID Snap ID
40. — ---------------- ---------------- ------------- ------------- --------------
41. 1 3675582523 12,699,298 0 19332 19337
42. -------------------------------------------------------------
43.
44. Plan 1(PHV: 3675582523)
45. -----------------------
46.
47. Plan Statistics DB/Inst: ORCLNEW/orclnew2 Snaps: 19321-19337
48. -> % Total DB Time is the Elapsed Time of the SQL statement divided
49. into the Total Database Time multiplied by 100
50.
51. Stat Name Statement Per Execution % Snap
52. ------------------------------- ---------- -------------- -------
53. Elapsed Time (ms) 1.2699E+07 N/A 0.9
54. CPU Time (ms) 6,176,679 N/A 0.9
55. Executions 0 N/A N/A
56. Buffer Gets 1.6908E+07 N/A 0.2
57. Disk Reads 1,378,166 N/A 0.1
58. Parse Calls 9,875,656 N/A 23.8
59. Rows 0 N/A N/A
60. User I/O Wait Time (ms) 1,707,961 N/A N/A
61. Cluster Wait Time (ms) 55 N/A N/A
62. Application Wait Time (ms) 840,484 N/A N/A
63. Concurrency Wait Time (ms) 746,191 N/A N/A
64. Invalidations 1 N/A N/A
65. Version Count 57 N/A N/A
66. Sharable Mem(KB) 28,536 N/A N/A
67. -------------------------------------------------------------
68. Execution Plan
69. --------------------------------------------------------------------------------
70. | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart|
71. --------------------------------------------------------------------------------
72. | 0 | CREATE TABLE STATEMENT | | | | 17915 (100)| | |
73. | 1 | PX COORDINATOR | | | | | | |
74. | 2 | PX SEND QC (RANDOM) | :TQ10000 | 1 | 52 | 2 (0)| 00:00:01 | |
75. | 3 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
76. | 4 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_CHARGE_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
77. | 5 | PX COORDINATOR | | | | | | |
78. | 6 | PX SEND QC (RANDOM) | :TQ20000 | 1 | 52 | 2 (0)| 00:00:01 | |
79. | 7 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
80. | 8 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_CHARGE_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
81. | 9 | PX COORDINATOR | | | | | | |
82. | 10 | PX SEND QC (RANDOM) | :TQ30000 | 1 | 52 | 2 (0)| 00:00:01 | |
83. | 11 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
84. | 12 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_CHARGE_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
85. | 13 | PX COORDINATOR | | | | | | |
86. | 14 | PX SEND QC (RANDOM) | :TQ40000 | 1 | 52 | 2 (0)| 00:00:01 | |
87. | 15 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
88. | 16 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_TRAFFIC_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
89. | 17 | PX COORDINATOR | | | | | | |
90. | 18 | PX SEND QC (RANDOM) | :TQ50000 | 1 | 52 | 2 (0)| 00:00:01 | |
91. | 19 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
92. | 20 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_TRAFFIC_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
93. | 21 | PX COORDINATOR | | | | | | |
94. | 22 | PX SEND QC (RANDOM) | :TQ60000 | 1 | 52 | 2 (0)| 00:00:01 | |
95. | 23 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
96. | 24 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_TRAFFIC_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
97. | 25 | PX COORDINATOR | | | | | | |
98. | 26 | PX SEND QC (RANDOM) | :TQ70000 | 1 | 52 | 2 (0)| 00:00:01 | |
99. | 27 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
100. | 28 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_TRAFFIC_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
101. | 29 | PX COORDINATOR | | | | | | |
102. | 30 | PX SEND QC (RANDOM) | :TQ80000 | 1 | 52 | 2 (0)| 00:00:01 | |
103. | 31 | PX BLOCK ITERATOR | | 1 | 52 | 2 (0)| 00:00:01 | |
104. | 32 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_TRAFFIC_FUND_TYPE | 1 | 52 | 2 (0)| 00:00:01 | |
105. | 33 | PX COORDINATOR | | | | | | |
106. | 34 | PX SEND QC (RANDOM) | :TQ90009 | 2088K| 4519M| 2839 (2)| 00:00:35 | |
107. | 35 | LOAD AS SELECT | | | | | | |
108. | 36 | HASH JOIN RIGHT OUTER | | 2088K| 4519M| 2839 (2)| 00:00:35 | |
109. | 37 | PX RECEIVE | | 44400 | 1127K| 2 (0)| 00:00:01 | |
110. | 38 | PX SEND BROADCAST | :TQ90000 | 44400 | 1127K| 2 (0)| 00:00:01 | |
111. | 39 | PX BLOCK ITERATOR | | 44400 | 1127K| 2 (0)| 00:00:01 | 34 |
112. | 40 | TABLE ACCESS STORAGE FULL | WT_FINANCIAL_CARD | 44400 | 1127K| 2 (0)| 00:00:01 | 34 |
113. | 41 | HASH JOIN RIGHT OUTER | | 2088K| 4467M| 2835 (2)| 00:00:35 | |
114. | 42 | PX RECEIVE | | 25 | 975 | 2 (0)| 00:00:01 | |
115. | 43 | PX SEND BROADCAST | :TQ90001 | 25 | 975 | 2 (0)| 00:00:01 | |
116. | 44 | PX BLOCK ITERATOR | | 25 | 975 | 2 (0)| 00:00:01 | |
117. | 45 | TABLE ACCESS STORAGE FULL | D_CHARGE_FUND_TYPE | 25 | 975 | 2 (0)| 00:00:01 | |
118. | 46 | HASH JOIN RIGHT OUTER | | 2088K| 4389M| 2832 (2)| 00:00:34 | |
119. | 47 | PX RECEIVE | | 25 | 975 | 2 (0)| 00:00:01 | |
120. | 48 | PX SEND BROADCAST | :TQ90002 | 25 | 975 | 2 (0)| 00:00:01 | |
121. | 49 | PX BLOCK ITERATOR | | 25 | 975 | 2 (0)| 00:00:01 | |
122. | 50 | TABLE ACCESS STORAGE FULL | D_CHARGE_FUND_TYPE | 25 | 975 | 2 (0)| 00:00:01 | |
123. | 51 | HASH JOIN RIGHT OUTER | | 2088K| 4312M| 2829 (2)| 00:00:34 | |
124. | 52 | PX RECEIVE | | 25 | 975 | 2 (0)| 00:00:01 | |
125. | 53 | PX SEND BROADCAST | :TQ90003 | 25 | 975 | 2 (0)| 00:00:01 | |
126. | 54 | PX BLOCK ITERATOR | | 25 | 975 | 2 (0)| 00:00:01 | |
127. | 55 | TABLE ACCESS STORAGE FULL | D_CHARGE_FUND_TYPE | 25 | 975 | 2 (0)| 00:00:01 | |
128. | 56 | HASH JOIN RIGHT OUTER | | 2088K| 4234M| 2826 (2)| 00:00:34 | |
129. | 57 | PX RECEIVE | | 16 | 832 | 2 (0)| 00:00:01 | |
130. | 58 | PX SEND BROADCAST | :TQ90004 | 16 | 832 | 2 (0)| 00:00:01 | |
131. | 59 | PX BLOCK ITERATOR | | 16 | 832 | 2 (0)| 00:00:01 | |
132. | 60 | TABLE ACCESS STORAGE FULL | D_TRAFFIC_FUND_TYPE | 16 | 832 | 2 (0)| 00:00:01 | |
133. | 61 | HASH JOIN RIGHT OUTER | | 2088K| 4131M| 2822 (1)| 00:00:34 | |
134. | 62 | PX RECEIVE | | 16 | 832 | 2 (0)| 00:00:01 | |
135. | 63 | PX SEND BROADCAST | :TQ90005 | 16 | 832 | 2 (0)| 00:00:01 | |
136. | 64 | PX BLOCK ITERATOR | | 16 | 832 | 2 (0)| 00:00:01 | |
137. | 65 | TABLE ACCESS STORAGE FULL | D_TRAFFIC_FUND_TYPE | 16 | 832 | 2 (0)| 00:00:01 | |
138. | 66 | HASH JOIN RIGHT OUTER | | 2088K| 4027M| 2819 (1)| 00:00:34 | |
139. | 67 | PX RECEIVE | | 16 | 832 | 2 (0)| 00:00:01 | |
140. | 68 | PX SEND BROADCAST | :TQ90006 | 16 | 832 | 2 (0)| 00:00:01 | |
141. | 69 | PX BLOCK ITERATOR | | 16 | 832 | 2 (0)| 00:00:01 | |
142. | 70 | TABLE ACCESS STORAGE FULL | D_TRAFFIC_FUND_TYPE | 16 | 832 | 2 (0)| 00:00:01 | |
143. | 71 | HASH JOIN RIGHT OUTER | | 2088K| 3923M| 2816 (1)| 00:00:34 | |
144. | 72 | PX RECEIVE | | 16 | 832 | 2 (0)| 00:00:01 | |
145. | 73 | PX SEND BROADCAST | :TQ90007 | 16 | 832 | 2 (0)| 00:00:01 | |
146. | 74 | PX BLOCK ITERATOR | | 16 | 832 | 2 (0)| 00:00:01 | |
147. | 75 | TABLE ACCESS STORAGE FULL | D_TRAFFIC_FUND_TYPE | 16 | 832 | 2 (0)| 00:00:01 | |
148. | 76 | HASH JOIN RIGHT OUTER | | 2088K| 3820M| 2813 (1)| 00:00:34 | |
149. | 77 | PX RECEIVE | | 16 | 832 | 2 (0)| 00:00:01 | |
150. | 78 | PX SEND BROADCAST | :TQ90008 | 16 | 832 | 2 (0)| 00:00:01 | |
151. | 79 | PX BLOCK ITERATOR | | 16 | 832 | 2 (0)| 00:00:01 | |
152. | 80 | TABLE ACCESS STORAGE FULL| D_TRAFFIC_FUND_TYPE | 16 | 832 | 2 (0)| 00:00:01 | |
153. | 81 | PX BLOCK ITERATOR | | 2088K| 3716M| 2809 (1)| 00:00:34 | |
154. | 82 | TABLE ACCESS STORAGE FULL | TMP_1_O_USER_2_0817 | 2088K| 3716M| 2809 (1)| 00:00:34 | |
155. --------------------------------------------------------------------------------
156.
157. Note
158. -----
159. - dynamic sampling used for this statement (level=4)
160. - automatic DOP: Computed Degree of Parallelism is 8

可以看到，这条SQL语句执行了12699秒（即3个半小时）还没有执行完成，这条SQL语句产生的parse calls高达987万以上。
从SQL执行时间上看，CPU时间、IO时间、集群等待时间和并行争用等待时间的合计远小于SQL执行总时间。这种情况下通常是由于CPU利用率过高，执行SQL的进程不能得到足够的SQL，或者是由于执行SQL的进程在等待“空闲”事件，没有计入到等待时间中。
从执行计划上看，SQL是并行执行的执行计划，同时在SELECT字段列表部分有子查询存在，并且子查询同样是并行执行计划。
12.6.3 检查历史数据
检查SQL执行的话话历史数据的代码如下所示。
SYS@orclnew2> select sample_id,to_char(min(sample_time),‘yyyy-mm-dd hh24:mi:ss’) sample_time,instance_number,QC_SESSION_ID,event,count(*)
2 from dba_hist_active_sess_history a
3 where a.sample_time>=to_date(‘2014-10-05 09:00’,‘yyyy-mm-dd hh24:mi:ss’)
4 and SQL_id=‘fym9dtwdyjpna’
5 group by sample_id,event,instance_number,QC_SESSION_ID
6 order by 1 ;

SAMPLE_ID SAMPLE_TIME INSTANCE_NUMBER QC_SESSION_ID EVENT COUNT(*)

69710880 2014-10-05 10:24:31 69710890 2014-10-05 10:24:41 69710910 2014-10-05 10:25:01 69710920 2014-10-05 10:25:11 69710930 2014-10-05 10:25:21 69710940 2014-10-05 10:25:31 69710940 2014-10-05 10:25:31 69710950 2014-10-05 10:25:41 69710960 2014-10-05 10:25:51 69710970 2014-10-05 10:26:01 69710970 2014-10-05 10:26:01 69710980 2014-10-05 10:26:11 69710980 2014-10-05 10:26:11 69710990 2014-10-05 10:26:21 69710990 2014-10-05 10:26:21 69711000 2014-10-05 10:26:31 69711010 2014-10-05 10:26:41 69711010 2014-10-05 10:26:41 69711020 2014-10-05 10:26:51 69711020 2014-10-05 10:26:51 69711030 2014-10-05 10:27:01 69711040 2014-10-05 10:27:11 69711040 2014-10-05 10:27:11 69711050 2014-10-05 10:27:21 69711060 2014-10-05 10:27:31 69711080 2014-10-05 10:27:51 69711090 2014-10-05 10:28:01 69711100 2014-10-05 10:28:11 69711110 2014-10-05 10:28:21 69711120 2014-10-05 10:28:31 69711130 2014-10-05 10:28:41 69711140 2014-10-05 10:28:51 69711150 2014-10-05 10:29:01 69711150 2014-10-05 10:29:01 69711160 2014-10-05 10:29:11 69711160 2014-10-05 10:29:11 69711170 2014-10-05 10:29:21 69711180 2014-10-05 10:29:31 69711190 2014-10-05 10:29:41 69711200 2014-10-05 10:29:51 69711210 2014-10-05 10:30:01 69711220 2014-10-05 10:30:12 69711230 2014-10-05 10:30:22 69711240 2014-10-05 10:30:32 69711250 2014-10-05 10:30:42 69711260 2014-10-05 10:30:52 69711270 2014-10-05 10:31:02 69711280 2014-10-05 10:31:12 69711290 2014-10-05 10:31:22 69711300 2014-10-05 10:31:32 69711310 2014-10-05 10:31:42 69711310 2014-10-05 10:31:42 69711320 2014-10-05 10:31:52 69711330 2014-10-05 10:32:02 69711350 2014-10-05 10:32:22 69711370 2014-10-05 10:32:42 69711380 2014-10-05 10:32:52 69711390 2014-10-05 10:33:02 69711390 2014-10-05 10:33:02 2 406 1
2 406 1
2 406 5
2 406 2
2 406 1
2 406 PX Deq: Signal ACK RSG 1
2 406 2
2 406 6
2 406 PX Deq: Signal ACK RSG 1
2 406 PX Deq: Signal ACK RSG 1
2 406 1
2 406 PX Deq: Signal ACK RSG 1
2 406 2
2 406 PX Deq: Signal ACK RSG 1
2 406 3
2 406 PX Deq: Slave Session Stats 1
2 406 PX Deq: Signal ACK RSG 1
2 406 3
2 406 PX Deq: Signal ACK RSG 1
2 406 3
2 406 1
2 406 PX Deq: Signal ACK RSG 1
2 406 1
2 406 3
2 406 PX Deq: Signal ACK EXT 1
2 406 1
2 406 enq: KO - fast object checkpoint 1
2 406 cell smart table scan 1
2 406 PX Deq: Slave Session Stats 1
2 406 1
2 406 1
2 406 1
2 406 PX Deq: Signal ACK RSG 1
2 406 1
2 406 PX Deq: Signal ACK RSG 1
2 406 3
2 406 cell smart table scan 1
2 406 cell smart table scan 1
2 406 1
2 406 1
2 406 cell smart table scan 1
2 406 3
2 406 enq: KO - fast object checkpoint 1
2 406 1
2 406 1
2 406 cell smart table scan 1
2 406 cell smart table scan 1
2 406 1
2 406 reliable message 1
2 406 1
2 406 PX Deq: Signal ACK RSG 1
2 406 1
2 406 1
2 406 cell smart table scan 1
2 406 reliable message 1
2 406 cell smart table scan 1
2 406 cell smart table scan 1
2 406 PX Deq: Signal ACK RSG 1
2 406 1

从会话的历史数据来看，SQL语句的确是并行执行，但是各个时刻并行进程的数量各不相同。
12.6.4 判断问题产生的流程
由于此SQL语句产生了大量的parse calls，并且在SELECT字段列表部分有子查询，结合SQL执行的会话历史数据，初步判断问题的产生是这样一个流程。
（1）SQL语句执行主体查询部分。
（2）根据主体查询部分返回的数据，执行SELECT字段列表中的标量子查询。
（3）每次执行子查询都进行并行查询。并行查询每次都要启动并行进程、查询数据、释放并行进程这样的过程，这样大量的动作序列使得SQL执行非常缓慢。
（4）新启并行进程会进行SQL的解析，所以产生大量的parse calls。
并行查询表时，执行计划中有提示TABLE ACCESS STORAGE FULL FIRST ROWS，实际执行时也存在cell smart table scan。这表明由存储节点进行数据扫描，在扫描数据之前，需要对表做object checkpoint。会话历史中的enq: KO - fast object checkpoint等待事件表示该表正在进行object checkpoint。
因此，针对此故障，初步判断是语句的SELECT字段列表部分有子查询，在子查询执行时出现存在问题。那么需要验证以下两点。
（1）所有出现此类故障的SQL语句是否都是这一类SQL，即SELECT字段列表部分有标量子查询的SQL。
（2）同一条SQL在故障期间执行时与正常执行时的差别。
12.6.5 查询历史数据
由于故障SQL的parse calls较高，因此可以通过下列代码来查询历史数据。
select snap_id,parse_calls_delta,SQL_id,elapsed_time_delta/1000000 ela,executions_delta exec from dba_hist_SQLstat
where parse_calls_delta>=10000
and parse_calls_delta/decode(executions_delta,0,1,null,1,executions_delta)>10
and elapsed_time_delta/1000000>=500
order by 1;

通过这个SQL语句查询出来的结果，可以证实是同一类SQL出现了问题。
12.6.6 并列执行的序列过程
对异常SQL的会话进行trace，会重复出现下列的等待事件。
165. WAIT nam=‘PX Deq: Join ACK’ ela= 643 sleeptime/senderid=268566613 passes=2 p3=36959538792 obj#=13123575
166. WAIT nam=‘PX Deq: Join ACK’ ela= 512 sleeptime/senderid=268566619 passes=5 p3=35004876592 obj#=13123575
167. WAIT nam=‘PX Deq: Join ACK’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575 tim=1412491416551083
168. WAIT nam=‘PX Deq: Join ACK’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575 tim=1412491416551095
169. WAIT nam=‘PX Deq: Join ACK’ ela= 0 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575 tim=1412491416551105
170. WAIT nam=‘PX Deq: Join ACK’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575 tim=1412491416551116
171. WAIT nam=‘PX Deq: Join ACK’ ela= 0 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575 tim=1412491416551126
172. WAIT nam=‘PX Deq: Join ACK’ ela= 0 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575 tim=1412491416551136
173. WAIT nam=‘PX Deq: Parse Reply’ ela= 3801 sleeptime/senderid=200 passes=1 p3=0 obj#=13123575
174. WAIT nam=‘PX Deq: Parse Reply’ ela= 2329 sleeptime/senderid=200 passes=1 p3=0 obj#=13123575
175. WAIT nam=‘PX Deq: Parse Reply’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
176. WAIT nam=‘PX Deq: Parse Reply’ ela= 514 sleeptime/senderid=200 passes=2 p3=0 obj#=13123575
177. WAIT nam=‘PX Deq: Parse Reply’ ela= 196 sleeptime/senderid=200 passes=1 p3=0 obj#=13123575
178. WAIT nam=‘PX Deq: Parse Reply’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
179. WAIT nam=‘PX Deq: Parse Reply’ ela= 472 sleeptime/senderid=200 passes=2 p3=0 obj#=13123575
180. WAIT nam=‘PX Deq: Parse Reply’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
181. WAIT nam=‘PX Deq: Execute Reply’ ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
182. WAIT nam=‘PX Deq: Execute Reply’ ela= 36 sleeptime/senderid=200 passes=3 p3=0 obj#=13123575
183. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 24 sleeptime/senderid=10 passes=2 p3=0 obj#=13123575
184. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
185. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
186. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 0 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
187. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
188. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123575
189. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 203 sleeptime/senderid=10 passes=3 p3=0 obj#=13123575
190. WAIT nam=‘PX Deq: Signal ACK RSG’ ela= 196 sleeptime/senderid=10 passes=2 p3=0 obj#=13123575
191. WAIT nam=‘reliable message’ ela= 365 channel context=38950850616 channel handle=38549009072 broadcast message=39084394200 obj#=13123575
192. WAIT nam=‘enq: KO - fast object checkpoint’ ela= 95 name|mode=1263468550 2=131327 0=1 obj#=13123575
193. WAIT nam=‘enq: KO - fast object checkpoint’ ela= 102 name|mode=1263468545 2=131327 0=2 obj#=13123575
194. WAIT nam=‘cell smart table scan’ ela= 447 cellhash#=88802347 p2=0 p3=0 obj#=13123562 tim=1412491416561265
195. WAIT nam=‘cell smart table scan’ ela= 498 cellhash#=88802347 p2=0 p3=0 obj#=13123562 tim=1412491416561821
196. WAIT nam=‘reliable message’ ela= 503 channel context=38950850616 channel handle=38549009072 broadcast message=31940845352 obj#=13123562
197. WAIT nam=‘enq: KO - fast object checkpoint’ ela= 174 name|mode=1263468550 2=131327 0=1 obj#=13123562
198. WAIT nam=‘enq: KO - fast object checkpoint’ ela= 100 name|mode=1263468545 2=131327 0=2 obj#=13123562
199. WAIT nam=‘cell smart table scan’ ela= 360 cellhash#=88802347 p2=0 p3=0 obj#=13123562 tim=1412491416563438
200. WAIT nam=‘cell smart table scan’ ela= 612 cellhash#=88802347 p2=0 p3=0 obj#=13123562 tim=1412491416564115
201. WAIT nam=‘PX Deq: Signal ACK EXT’ ela= 247 sleeptime/senderid=200 passes=1 p3=0 obj#=13123562
202. WAIT nam=‘PX Deq: Signal ACK EXT’ ela= 256 sleeptime/senderid=200 passes=2 p3=0 obj#=13123562
203. WAIT nam=‘PX Deq: Signal ACK EXT’ ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
204. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 3 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
205. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
206. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
207. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
208. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
209. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 2 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
210. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 1 sleeptime/senderid=0 passes=0 p3=0 obj#=13123562
211. WAIT nam=‘PX Deq: Slave Session Stats’ ela= 139 sleeptime/senderid=200 passes=3 p3=0 obj#=13123562

一个并行执行的序列过程如下。
（1）启动并行进程。
（2）QC进程（执行SQL的发起进程）向所有并行进程发送JOIN消息，使并行进程加入到Server Group（并行执行同一条SQL的所有并行查询进程加入到Server Group中）。这个时候QC进程会出现PX Deq：Join ACK等待，表示QC进程在等待并行查询进程加入到Server Group。
（3）QC进程向每个查询进程发送SQL语句，让每个并行查询进程解析SQL。这时QC进程出现PX Deq: Parse Reply，等待并行进程确认解析完毕。
（4）QC进程发送要执行的任务给每个并行进程，此时QC进程出现PX Deq: Execute Reply，表示QC进程在待待并行进程执行返回结果。
（5）执行完成后到最后并行进程退出Server Group，并收集并行查询会话的统计信息。此时QC进程出现的等待事件是PX Deq: Sinal ACK EXT和PX Deq: Slave Session Stats。
查询并行涉及的对象如下所示。
SQL> select owner,object_name,object_type from dba_objects where object_id=13123575;

OWNER OBJECT_NAME OBJECT_TYPE

PU_META_DIM D_CHARGE_FUND_TYPE TABLE
SQL> select owner,object_name,object_type from dba_objects where object_id=13123562;
OWNER OBJECT_NAME OBJECT_TYPE

PU_META_DIM D_TRAFFIC_FUND_TYPE TABLE

可以看出这些表正是SELECT字段列表中的标量子查询中的表。
12.6.7 检查call stack
检查SQL在故障期间执行时QC进程的call stack（通过oradeBug）：
SYS@orclnew2> oradeBug short_stack
ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-sendmsg()+16<-sskgxp_sndmsg()+444<-skgxpipost()+979<-skgxppost()+144<-ksxppst_real()+289<-ksxppst_one()+34<-kslpsprns()+521<-kskpthr()+112<-kslpspr()+9<-kxfprienq()+1926<-kxfpqrenq()+235<-kxfxpf()+145<-kxfxcp1()+4146<-kxfxcp()+491<-qerpxSendParse()+1059<-kxfpValidateSlaveGroup()+192<-kxfpgsg()+4707<-kxfrAllocSlaves()+483<-kxfrialo()+2589<-kxfralo()+318<-qerpx_rowsrc_start()+1379<-qerpxStart()+578<-subex1()+138<-subsr3()+183<-evaopn3()+2537<-expepr()+576<-evaand()+59<-expepr()+47<-evacssr()+128<-qerlt_snv()+85<-qerltRop()+320<-kdstf11001010011km()+3284<-kdsttgr()+133176<-qertbFetch()+2525<-qergiFetch()+317<-rwsfcd()+103<-qerltFetch()+599<-qertqoFetch()+952<-qerpxFetch()+11817<-ctcdrv()+13941<-opiexe()+21743<-opiosq0()+3932<-opipls()+11479<-opiodr()+916<-rpidrus()+211<-skgmstack()+148<-rpiswu2()+638<-rpidrv()+1384<-psddr0()+473<-psdnal()+457<-pevm_EXIM()+308<-pfrinstr_EXIM()+53<-pfrrun_no_tool()+63<-pfrrun()+627<-plSQL_run()+649<-peicnt()+301<-kkxexe()+525<-opiexe()+17667<-kpoal8()+2124<-opiodr()+916<-ttcpip()+2242<-opitsk()+1673<-opiino()+966<-opiodr()+916<-opidrv()+570<-sou2o()+103<-opimai_real()+133<-ssthrdmain()+252<-main()+201<-__libc_start_main()+244<-_start()+36

call stack中，函数的执行顺序是从后往前看。plSQL_run表明SQL是PL/SQL存储过程中的SQL语句，qerpxFetch表明是并行执行（此处要注意的是，Oracle根据执行计划以并行方式开始执行，但是可能会发生执行时没有足够的并行进程，结果降级为串行方式执行的情况）subex1表示在执行子查询，qerpx_rowsrc_start表示这个是真正的并行开始，kxfrAllocSlaves表示分配并行进程，qerpxSendParse表示发送SQL解析请求给并行进程。
call stack跟之前的现象是相符合的，的确是在子查询部分新启动了并行。如果是事先就分配好的并行进程，则不会出现kxfrAllocSlaves这样的函数。反复多次查看QC进程的call stack，都能确认是相同的结果。
12.6.8 检查并行会话
检查SQL异常执行时的并行会话具体如下。
SYS@orclnew2> select sid from v$px_session where qcsid=1044;

SID

SYS@orclnew2> /

SID

SYS@orclnew2> /

SID

可以看到，同一个QC会话对应的并行进程其会话SID会不停地发生变化，这表明并行进程不停地启用和释放，这跟之前的现象、描述以及结论是一致的。这也和AWR报告中的Logons非常高是一致的。
确认了子查询在不停地重启并行进程的问题后，还需要确认同一条SQL语句为什么大多数时候能正常？并且在故障后中止SQL运行再重新执行又能正常运行？
在故障期间，运行下面的测试代码。
alter session set events ‘trace[SQL_Compiler.] disk=highest’;
alter session set events 'trace[SQL_Execution.] disk=highest’;

create table tu_tbas.WT_P_OFFER_2014101802812_XJ compress for query high nologging parallel 64
as SELECT
SERV_ID….

检查生成的trace文件，在SQL开始尝试并行执行时，信息如下所示。
2014-10-22 04:58:23.701176*:PX_Messaging:kxfp.c@3325:kxfpqsod():
Query end, buffer cache support for numa enabled: YES
2014-10-22 04:58:23.701176*:PX_Messaging:kxfp.c@3329:kxfpqsod(end):
serial - no slave alloc’d for 1st server set
2014-10-22 04:58:23.701176*:PX_Messaging:kxfp.c@10797:kxfpgsg(end):
slave group q=(nil)
kxfrAllocSlaves [ 30/ 10]
actual num slaves alloc’d = 0 (kxfpqcthr)
kxfrialo [ 30/ 0]
Finish: allocated actual 0 slaves for non-GV query

可以看到，在分配第一组并行进程（1st server set）时，没有并行进程，只能以串行方式运行。
qerpxStart [ 30/ 0]
rwsrid:11 pxid:3 qbas:2339749:err:0
pgakid:1 pgadep:0

*** 2014-10-22 04:58:23.702
START no parallel resources
ksdftm:958862290
qertqoStart [ 30/ 0]

虽然没有分配到并行进程，但还是要以并行模式来执行SQL。因为SQL执行的入口已经是并行模式，只是在实际执行过程中没有并行进程，只能串行执行了。
在SQL执行过程中，会出现大量的类似下面的trace信息。
2014-10-22 04:58:23.772279*:PX_Granule:kxfr.c@2291:kxfrialo(): Start: building object table (1)
Start: building obj table for obj# 0
kxfrExtInfo [ 100/ 0]

    prefetch part:0 objn:13123568 objd:13123568 seghdr tsn:11 rdba:0x0a80d47
    a

kxfrExtInfo [ 100/ 0]

kxfrFileAdd [ 100/ 0]
filenum:42 #nodes:0 arch:255 test hard affinity:0
dumping object objn:13123568 PU_META_DIM.D_STATE
so:0x838788d70 mo:0x2b5257602150
flg:4201 (KXFRO_PSC/KXFRO_RID/KXFRO_HINT/)
nbparts:1 nfiles:1 nnodes:0 ninst:0
ecnt:1 size(blocks):1 mtfl:0

      files for object 1:
        kfil:42 size:1 nnodes:0 nodes:(nil) naff:65535
        
      partitions of object 1:
        part:0 (abs:-1 pnum:-1 spnum:-1 objn:-1 objd:13123568 tsn:11)
          ecnt:1  size:1  nfiles:1  naff:65535  flags: BIT 
          Files in partition 0:
            kfil:42  size:1
          Extent map of partition 0:
            afn:42  blk:54395    size:1   coalescable:1
      
      No nodes information.

kxfrialo [ 100/ 0]
DOP trace – requested thread from best ref obj = 16 (from kxfrIsBestR
ef())
…
kxfrialo [ 100/ 0]
best object 0x838788d70
hgt:0 blks:1 acp:0 nds:1 thr:16
kxfrialo [ 100/ 0]
threads requested = 16 (from kxfrComputeThread())
kxfrialo [ 100/ 0]
adjusted no. threads = 16 (from kxfrAdjustDOP())
kxfrAllocSlaves [ 100/ 0]
DOP trace – call kxfpgsg to get 16 slaves
2014-10-22 04:58:23.773172*:PX_Messaging:kxfp.c@9868:kxfpgsg(begin):
reqthreads=16 height=0 lsize=0 alloc_flg=0x230
2014-10-22 04:58:23.773172*:PX_Messaging:kxfp.c@9941:kxfpgsg():
reqthreads=16 KXFPLDBL/KXFPADPT/ load balancing=on adaptive=off
Getting instance info for open group
……
2014-10-22 04:58:24.436235*:PX_Messaging:kxfp.c@11465:kxfpg1sg():
got 4 servers (sync), errors=0x0 returning
Acquired 4 slaves on 1 instances avg height=4 #set=1 qser=2045742594
P011 inst 2 spid 16249
P016 inst 2 spid 16265
P017 inst 2 spid 16267
P018 inst 2 spid 12448
2014-10-22 04:58:24.436235*:PX_Messaging:kxfp.c@10671:kxfpgsg():
Instance(servers):
inst=2 #slvs=4

上述trace信息表明，在执行子查询时，在不停地启用并行进程并释放并行进程。并且随着系统负载的不同，每次获得的并行进程数不一样，这跟会话历史信息中检查发现的不同时刻并行进程数不同的现象是一致的。
至此，故障原因已经明确，是由于在SELECT字段列表有子查询的SQL语句，在主体查询以串行方式执行时，子查询SQL以并行方式查询所引起的。
在此，我们小结一下这个问题，这个故障的出现需要同时满足以下两个条件。
（1）SQL语句的SELECT字段列表部分有子查询。类似于：
create table TBAS.tmp_2_o_user_2_xxxx compress for query high nologging parallel as select /*+parallel (8) */ t1.ACC_NBR, ….
case when traffic_wlan/1024 > 20480 then 32 when t42.traffic_fund_type_id is not null then t42.traffic_fund_type_id else (select traffic_fund_type_id from pu_meta_dim.d_traffic_fund_type t where state = 1 andtraffic_wlan/1024 < t.max_value and traffic_wlan/1024 > t.min_value) end MBL_wlan_FUND_TYPE_ID, ….
from TBAS.tmp_1_o_user_2_xxxx t1…

实例上的并行进程用完，即所有的并行进程全部处于活动状态。
当SELECT字段列表部分带有子查询的SQL执行时，正常情况下，Oracle会发起两组并行进程（parallel slave sets）。一组进程为数据的生产者（比如从表读数据），一组进程为数据的消费者（比如对“生产者”进程传过来的表数据进行汇总排序等）。在有并行进程时，SQL语句运行正常。
在实例的并行进程用完后，由于没有并行进程，因此SQL语句的主体部分就会降级到串行方式运行。但是在提取SELECT字段列表中的子查询数据时，子查询的表需要使用并行进程。这个时候Oracle会尝试以并行方式运行子查询。Oracle对主查询中返回的每一行数据，都要经过“启动并行进程，查询子查询数据，释放并行进程”的过程。这个过程效率非常低，导致SQL语句执行需要非常长的时间。
下面是另一条出现故障的SQL语句的执行计划（为了便于排版，对执行计划做了剪裁）。

| Id | Operation | Name | Rows | Bytes |

| 0 | CREATE TABLE STATEMENT | | | |
| 1 | PX COORDINATOR | | | |
| 2 | PX SEND QC (RANDOM) | :TQ10000 | 1 | 19 |
| 3 | PX BLOCK ITERATOR | | 1 | 19 |
|* 4 | TABLE ACCESS STORAGE FULL FIRST ROWS | D_STATE | 1 | 19 |
|* 5 | COUNT STOPKEY | | | |
| 6 | PX COORDINATOR | | | |
| 7 | PX SEND QC (RANDOM) | :TQ20000 | 11 | 209 |
|* 8 | COUNT STOPKEY | | | |
| 9 | PX BLOCK ITERATOR | | 11 | 209 |
|* 10 | TABLE ACCESS STORAGE FULL FIRST ROWS| D_STATE | 11 | 209 |
| 11 | PX COORDINATOR | | | |
| 12 | PX SEND QC (RANDOM) | :TQ30000 | 14M| 3644M|
| 13 | LOAD AS SELECT | | | |
| 14 | PX BLOCK ITERATOR | | 14M| 3644M|
|* 15 | TABLE ACCESS STORAGE FULL | F_2_OFFER_SERV_D | 14M| 3644M|

上面的执行计划中，第11～15步是SQL主体查询部分，第2～4步是SELECT字段列表中的子查询执行部分。正常情况下，是由两组并行进程负责，一组负责主体查询，然后将结果发送到另一组进程来进行子查询。但是在主体查询部分以串行方式进行时，SQL语句的主进程即QC进程，对F_2_OFFER_SERV_ID返回的每一行数据都要以并行方式执行一次子查询。这种方式的效率极为低下。
针对这样的问题，解决方案有如下几种。
（1）避免SELECT字段列表带有子查询的SQL以串行方式执行。在数据仓库应用中，串行执行的SQL语句，不管何种情况性能都比较差，因此要避免此种情况的产生。具体方法是在并行进程用光时，对并行执行的SQL进行排队。有以下几种方法。
1）将PARALLEL_DEGREE_POLICY参数设置为AUTO，开启自动并行。在系统级设置此参数在没有经过充分测试的情况下有比较大的风险，但是可以考虑在会话级设置此参数。在调度具有故障类SQL语句的脚本中设置会话级参数。
2）在故障类SQL中加上Hint “parallel(auto)”。
3）在故障类SQL中加上Hint “STATEMENT_QUEUING”。
（2）避免SELECT字段列表中使用子查询，尽量改为表关联。或者是针对此类子查询使用Hint no_parallel(表别名)”，但是需要测试此种更改对性能的影响。
在数据仓库应用中，需要控制并行度来避免单条SQL占用过多的并行进程。控制SQL并行度的方法有以下两种（以下两个方法都要同时采用）。
（1）设置自动并行时的并行度限制，这是通过设置参数PARALLEL_DEGREE_LIMIT来实现，比如将此参数设置为8。
（2）通过资源管理限制来限制并行度。
exec dbms_resource_manager.clear_pending_area();
exec dbms_resource_manager.create_pending_area();
exec dbms_resource_manager.create_plan( plan =>‘LIMIT_DOP’, comment => ‘Limit Degree of Parallelism’);
exec dbms_resource_manager.create_plan_directive(plan=> ‘LIMIT_DOP’, group_or_subplan => ‘OTHER_GROUPS’ , comment => ‘limits the parallelism’, parallel_degree_limit_p1=> 8);
exec dbms_resource_manager.validate_pending_area();
exec dbms_resource_manager.submit_pending_area();

调整前建议进行充分测试，调整后需要密切关注系统的运行。
此外，此类的SQL应该比较多，我们可以通过下列代码查询出现过此类故障的SQL。
select snap_id,parse_calls_delta,SQL_id,elapsed_time_delta/1000000 ela,executions_delta exec from dba_hist_SQLstat
where parse_calls_delta>=10000
and parse_calls_delta/decode(executions_delta,0,1,null,1,executions_delta)>10
and elapsed_time_delta/1000000>=500
order by 1;
12.7 关于RAC数据库load balance案例分析
在这一节我将通过两个案例入手，来讲一下RAC数据库load balance相关的问题。两个案例会以比较直接简单的方式进行描述，对于案例中涉及的深入的知识将在后面展开。
案例一：一套2节点的Oracle 10g RAC数据库。系统维护人员报告称不能实现负载均衡，大部分的会话都连接到了第二个节点上。环境是Oracle 10.2.0.3 for AIX。
分析过程如下所示。
（1）连接到数据库，检查数据库连接，发现实例resrac2的连接数超过2000，而实例resrac1的连接数不到300。相差非常大。
（2）检查2个节点的监听状态，没有异常。
（3）查看应用的的TNS配置，没有发现异常。
（4）仔细检查2个节点的连接，发现几乎所有的JAVA应用都连接到了resrac2，而其他的非JAVA应用，大部分也同样是连接到了resrac2。
（5）使用SQL*Plus进行连接测试，发现所有的连接都被重定向了resrac2。但是修改TNSNAME，指定INSTANCE_NAME为resrac1时，能够正常连接resrac1，这表明实例resrac1本身连接接受连接。
（6）检查listener.log日志，发现PMON能够正常进行监听注册和服务更新（Service Update）。
（7）检查发现ONS没有启动，手工启动ONS后，问题依然存在。
（8）重启监听，问题依然存在。
（9）检查服务状态，具体如下所示。
SQL> select name,goal,clb_goal from dba_services;

NAME GOAL CLB_G

SYS$BACKGROUND NONE SHORT
SYS$USERS NONE SHORT
seeddataXDB LONG
seeddata LONG
resracXDB LONG
resrac NONE LONG
可以看到resrac服务配置正常。
（10）检查Service Metric数据，具体如下所示。
SQL> select inst_id,service_name,goodness,delta from
gv$servicemetric where service_name=‘resrac’;

INST_ID SERVICE_NAME GOODNESS DELTA

     1 resrac                6999          1
     1 resrac                6999          1
     2 resrac                1976          1
     2 resrac                1976          1

从上面的数据可以看出，第1个实例resrac1存在问题。实例resrac2的goodness值与以resrac服务连接的连接数是接近相等的（这跟更新的周期有关）。但实例resrac1的goodness值远远大于resrac1的实际连接数。
Goodness值有如下两个特点。
Goodness值在Service的CLB_GOAL为CLB_GOAL_LONG时表示实例中该服务的会话连接数。此值越大，连接越多，那么连接时就不会连接到goodness值大的实例上，而是连接到值小的实例上。
Goodness值由MMON进程进行计算，然后定期由PMON发布给监听。
检查MMON进程没有发现异常。
$ truss -p 1467404
thread_wait(3000) (sleeping…)
thread_wait(3000) = 1
thread_wait(3000) Err#4 EINTR
Received signal #14, SIGALRM [caught]
sigprocmask(0, 0x0FFFFFFFFFFFC1E0, 0x0000000000000000) = 0
_poll(0x0FFFFFFFFFFFB250, 1, 0) = 0
sigprocmask(0, 0x0FFFFFFFFFFFBEB8, 0x0000000000000000) = 0
incinterval(0, 0x0FFFFFFFFFFFBC50, 0x0FFFFFFFFFFFBC70) = 0
sigprocmask(1, 0x0FFFFFFFFFFFBDF0, 0x0000000000000000) = 0
incinterval(0, 0x0FFFFFFFFFFFC060, 0x0FFFFFFFFFFFC080) = 0
sigprocmask(1, 0x0FFFFFFFFFFFC1E0, 0x0000000000000000) = 0
ksetcontext_sigreturn(0x0FFFFFFFFFFFC320, 0x000000011023F1C8, 0x0000000000000000, 0x800000000000D0B2, 0x0000000000000000, 0x0000000000000134, 0x0000000000000000, 0x0000000000000000)
thread_wait(1230) = 1
times(0x0FFFFFFFFFFFC8B0) = 1776218558
times(0x0FFFFFFFFFFFC800) = 1776218558
thread_wait(3000) (sleeping…)
thread_wait(3000) = 1
thread_wait(3000) Err#4 EINTR
Received signal #14, SIGALRM [caught]
sigprocmask(0, 0x0FFFFFFFFFFFC1E0, 0x0000000000000000) = 0

（11）从上面的分析可以看到，Service Metric的数据异常，导致了实例resrac1不能接受新的连接。由于resrac1实例的resrac服务的goodness值异常得高，怀疑是Bug引起。
（12）搜索Oracle的Bug数据库，发现与下面的Bug匹配。
Bug 6442431 A node may stop receiving connections with RAC load balancing
Details: In a RAC cluster using server side load balancing, one of the nodes may stop receiving any new connections even though it is idle.
Fixed-Releases: 10.2.0.4 & 11.1.0.7 & 11.2

但是当前的版本没有此Bug的补丁，只有升级到10.2.0.4才能解决。
（13）解决办法有如下3种。
1）重启实例resrac1，但是以后Bug可能被再次触发。
2）将Oracle数据库升级到10.2.0.4。
3）关闭服务端（Server Side）的Load balancing，修改应用的连接配置，使用客户端连接时负载均衡（Connection Time Load Balancing）。
案例二：一套2节点的Oracle 11g RAC Active Data Guard，应用通过SCAN 地址连接到数据库，绝大部分连接都连到了节点1上。
环境：某银行重要交易系统，Oracle 11.2.0.4 for Linux，2节点RAC主库+2节点本地RAC ADG+2节点同城异机房RAC ADG，读写分离架构，ADG用于只读查询，主库实现事务交易，分布式存储架构，同城异机房实现容灾。SCAN地址通过域名解析。
问题分析和处理思路与前面的案例大体一致，关键的差异在于如下一些要点。
（1）Active Data Guard指定与主库不同的db_unique_name，那么默认注册到监听的服务与db_unique_name是一致的。但是这个服务名通过dba_services视图查询并没有。
INST_ID TYPE SERVICE_NAME COUNT(*)

     1 USER       cusr                                  226
     1 USER       SYS$USERS                               4
     2 USER       cusr                                  218
     1 BACKGROUND SYS$BACKGROUND                         50
     2 USER       SYS$USERS                               2
     2 BACKGROUND SYS$BACKGROUND                         50

（2）查询v$servicemetric视图也没有这个服务的统计数据。
INST_ID SERVICE_NAME GOODNESS DELTA

     1 cusrXDB                                 0          1
     1 cusrXDB                                 0          1
     1 SYS$BACKGROUND                       2150         50
     1 SYS$BACKGROUND                       2150         50
     1 SYS$USERS                            4100         50
     1 SYS$USERS                            4100         50
     2 cusrXDB                                 0          1
     2 cusrXDB                                 0          1
     2 SYS$BACKGROUND                       2100         50
     2 SYS$BACKGROUND                       2100         50
     2 SYS$USERS                               0        100
     2 SYS$USERS                               0        100

那么，会不会是因为pmon不能发布服务的负载信息呢？好在有这样一个事件10257。
SQL> oradeBug setospid <pmon的pid>
SQL> oradeBug event 10257 trace name context forever,level 16

在pmon的trace文件中不断重复出现如下信息。
err=-300 lbflgs=0x0 tbtime=0 tntime=0 etime=300 srvs=1 nreqs=0 sreqs=0 asrvs=1
error=-300 etime=300 control=0 integral=0 lasterr=-300 lastetm=300
kmmlrl: status: succ=4, wait=0, fail=0

我们需要有点耐心，一会儿会出现下示情况。
err=-300 lbflgs=0x0 tbtime=0 tntime=0 etime=300 srvs=1 nreqs=0 sreqs=0 asrvs=1
error=-300 etime=300 control=0 integral=0 lasterr=-301 lastetm=301
kmmlrl: status: succ=4, wait=0, fail=0
kmmlrl: update for time delta: 60019
kmmgdnu: cusrXDB
goodness=0, delta=1,
flags=0x5:unblocked/not overloaded, update=0x6:G/D/-
kmmlrl: node load 284
kmmlrl: D000 load 0
kmmlrl: nsgr update returned 0

如果我们手工执行alter system register命令，会产生如下日志。
kmmlrl: status: succ=4, wait=0, fail=0
kmmlrl: register now
kmmgdnu: cusrXDB
goodness=0, delta=1,
flags=0x5:unblocked/not overloaded, update=0x6:G/D/-
kmmlrl: 556 processes
kmmlrl: node load 266
kmmlrl: instance load 508
kmmlrl: nsgr update returned 0
kmmlrl: nsgr register returned 0

应用连的服务名是cusrdg，很显然这个并不在里面。以上输出信息中，kmmlrl是Kernel Message Monitor Listener Register Load的含义，kmmgdnu 是 KMM GooDNess Update的含义。
那么，到现在要的方向就是pmon没有发布cusrdg这个服务，如何来验证这个问题？好在有一套测试环境，是同样的架构。在测试环境中，使用ADG的db_unique_name指定的服务，同样不能达到负载均衡。但是如果用dbms_service.add_service增加一个服务（需要在主库上操作），然后在备库启用这个服务，使用这个服务则可以正常进行负载均衡。
当然也可以用srvctl add service来增加服务，但使用srvctl start service时，同样会去调用dbms_service的add_service命令。
使用的测试脚本具体如下所示。
#!/bin/sh
SQLplus system/xxxx/@SCAN域名/service_name << EOF
exec dbms_lock.sleep(120);
EOF

将上述脚本在后台跑上几十个，检查gv$session就可以发现负载均衡是否起作用。我们在测试ADG库上看到的10257 event trace的输出如下所示。
kmmlrl: status: succ=4, wait=0, fail=0
kmmlrl: status: succ=4, wait=0, fail=0
kmmlrl: register now
kmmgdnu: drtestsvc
goodness=0, delta=1,
flags=0x4:unblocked/not overloaded, update=0x6:G/D/-
kmmgdnu: oradbXDB
goodness=0, delta=1,
flags=0x5:unblocked/not overloaded, update=0x6:G/D/-
kmmlrl: node load 10
kmmlrl: nsgr update returned 0
kmmlrl: nsgr register returned 0

可以看到有drtestsvc这个单独建的服务名，这个服务名出现在pmon向监听注册的信息中。
要继续解析这个问题，还必须了解RAC数据库负载均衡原理。负载均衡分两种，Client Side Load Balance和Server Side Load Balance。
客户端的负载均衡通过连接描述符来指定，具体如下所示。
(DESCRIPTION =
(ADDRESS_LIST =
(ADDRESS = (PROTOCOL = TCP)(HOST = 192.168.22.24)(PORT = 1521))
(ADDRESS = (PROTOCOL = TCP)(HOST = 192.168.22.44)(PORT = 1521))
)
(LOAD_BALANCE = yes)
(CONNECT_DATA =
(SERVER = DEDICATED)
(SERVICE_NAME = resrac)
)

LOAD_BALANCE=yes表示连接时会随机从ADRESS LIST中选择一个地址进行连接。要实现LOAD BALANCE，那么不能指定INSTANCE_NAME，也不能指定SID，同时连接时“面向服务”。客户端连接描述符在指定多个地址还默认打开了failover，也就是一个地址连接不上就会连接另一个地址。
服务器端的负载均衡，又是怎么一种机制呢? 10g和11g有很大的不同，这里以11g RAC为例来解释，如图12-1所示。

图12-1
我们配合监听的信息来展示一下（这是在第2个节点上获得的信息）。
lsnrctl services LISTENER_SCAN1

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER_SCAN1)))
Services Summary…
Service “appadb” has 2 instance(s).
Instance “appadb1”, status READY, has 2 handler(s) for this service…
Handler(s):
“DEDICATED” established:0 refused:0 state:ready
REMOTE SERVER
(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=192.168.233.143)(PORT=1521)))
“DEDICATED” established:0 refused:0 state:ready
REMOTE SERVER
(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=192.168.233.143)(PORT=1522)))
Instance “appadb2”, status READY, has 2 handler(s) for this service…
Handler(s):
“DEDICATED” established:0 refused:0 state:ready
REMOTE SERVER
(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=192.168.233.145)(PORT=1521)))
“DEDICATED” established:0 refused:0 state:ready
REMOTE SERVER
(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=192.168.233.145)(PORT=1522)))

VIP监听信息如下所示。
lsnrctl services LISTENER

LSNRCTL for Linux: Version 11.2.0.3.0 - Production on 17-DEC-2015 17:16:35

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER)))
Services Summary…
Service “+ASM” has 1 instance(s).
Instance “+ASM2”, status READY, has 1 handler(s) for this service…
Handler(s):
“DEDICATED” established:0 refused:0 state:ready
LOCAL SERVER
Service “appadb” has 1 instance(s).
Instance “appadb2”, status READY, has 1 handler(s) for this service…
Handler(s):
“DEDICATED” established:1858112 refused:0 state:ready
LOCAL SERVER
The command completed successfully

打开数据库后，pmon进程会向监听注册服务。
SQL> show parameter listener

NAME TYPE VALUE

listener_networks string
local_listener string (DESCRIPTION=(ADDRESS_LIST=(AD
DRESS=(PROTOCOL=TCP)(HOST=133.
37.233.145)(PORT=1522))(ADDRES
S=(PROTOCOL=TCP)(HOST=192.168.2
33.145)(PORT=1521))))
remote_listener string appadb-scan:1521

remote_listener指向SCAN LISTENER，local_listener指向本节点VIP监听。这里有一个PORT为1522的是一个单独的监听，这里可以先忽略。
我们会看到，VIP监听上的服务只有一个实例，即本节点的实例的服务。
Service “appadb” has 1 instance(s).
Instance “appadb2”, status READY, has 1 handler(s) for this service…
Handler(s):
“DEDICATED” established:1858112 refused:0 state:ready
LOCAL SERVER

但是SCAN监听上有两个实例。
Service “appadb” has 2 instance(s).
Instance “appadb1”, status READY, has 2 handler(s) for this service…
….
Instance “appadb2”, status READY, has 2 handler(s) for this service…
Handler(s):
“DEDICATED” established:0 refused:0 state:ready
REMOTE SERVER
(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=192.169.233.145)(PORT=1521)))
“DEDICATED” established:0 refused:0 state:ready
REMOTE SERVER
(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=192.169.233.145)(PORT=1522)))

REMOTE SERVER表示，这个实例是需要通过另一个监听来跳转的。这个监听不能直接连接到该实例上。对于SCAN监听，所有的实例都是远程实例。
那么REMOTE SERVER中的信息是从哪里来，实际上是PMON进程将local listener的信息告诉SCAN监听。大家可以看到，local listener设定的信息跟SCAN LISTENER中Remote Server的信息是一样的。
了解了这些之后，下面来看一下如何实例负载均衡，客户端与数据库的交互顺序如下所示。
（1）客户端连接到SCAN监听。
（2）SCAN监听根据客户端连接时指定的条件（SERVICE_NAME），选择一个实例。
（3）SCAN监听把选定的实例的信息，包括地址，端口，协议，实例名发给客户端。
（4）客户端根据这个信息，重新发起一次网络连接，这次连接到实例的VIP监听上，VIP监听的服务是LOCAL SERVER，所以它会建立真正的连接。
（5）接下来就是登录验证。
这个过程有2个关键点。
（1）上述第2步的实例选择中，监听是根据从PMON得到的实例的负载信息来选择实例的。这一步实现了负载均衡。如果连接SCAN时，指定了INSTANCE NAME参数，那SCAN监听只会重定向到指定参数。
（2）如果local listener参数设置不对（正常情况下，11g不需要显式设置，由Grid Infrastructure设置好就行），那么将不能连接，会报错。这个参数正常指向VIP地址，如果设置为主机名或域名，但是客户端不能解析，就连接不上。
到这里，会有一个跟网络安全相关的话题。有的企业的应用是在另外的网络，中间有网闸或NAT，连接SCAN监听时，用的一个外网地址，外网地址通过NAT转换，得到内网的地址。例如，外网是10.10.100.144:1521，内网是192.168.100.144:1521，有一个NAT设备进行转换。SCAN监听会返回一个VIP监听地址，不幸的是，它会返回内网local listener地址——192.168.100.141:1521，客户端在外网连接这个地址肯定是不通的。那是否可以将数据库的参数设置为外网地址呢？这样的话它就注册不到vip 监听上了。这个解决方案也有问题。
这样的方式下，用客户端的负载均衡，直接连接VIP地址是更好的选择。另外，一些比较老的JDBC驱动，不能识别SCAN监听发回的要求重定向的协议，这种驱动连接数据库也有问题。
在监听的信息中，会有如下这样的信息。
Handler(s):
“DEDICATED” established:0 refused:0 state:ready

这条信息表示接受这个服务的处理器（实例）的状态ready，已经拒绝多少个连接，建立了多少连接。显然这个应用没有连接SCAN 监听，因为这个监听的所有服务的连接数都是0.
只有本地的VIP监听才显示有连接。
Handler(s):
“DEDICATED” established:1858112 refused:0 state:ready
LOCAL SERVER

另外，在VIP监听日志中会出现如下所示的信息。
10-DEC-2015 22:29:01 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=jdbc) (USER=app))(SERVER=DEDICATED)(SERVICE_NAME=cusrdg)(FAILOVER_MODE=(TYPE=session)(METHOD=basic))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.13.33)(PORT=44885)) * establish * cusrdg * 0

这表示直接连接或本机SCAN LISTENER连接的。如果有INSTANCE_NAME=这样的字样，则表示是另一个节点转发过来的。我们去检查监听日志，可以查看这个有用的信息。
grep “service update” listener.log
grep INSTANCE_NAME= listener.log

如果有这样的数据，表明客户端连接指定了INSTANCE_NAME，这个可能是连接串指定了（当前这种很少）。对于负载均衡来说，更多的是客户端开始连接到另外节点的SCAN LISTENER上然后重定向过来的。
12.8 总结
数据库的故障和性能问题千差万别，导致问题的原因也多种多样。所以我个人的建议是，虽然我们可以在不同的案例中总结一些规律，帮助我们处理问题，但生产环境很忌讳经验论。任何具体的问题都需要具体分析，不可以偏概全。希望这一章的内容分享对大家的工作学习有帮助。

oracle

最后修改时间：2020-10-21 12:25:34

「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」

关注作者

文章被以下合辑收录

Oracle 性能优化与案例精选（共15篇）

简介：如果有一个专题，把一批高级技术专家把他们每个人的职业生涯中最深刻的技艺，感悟、经验都呈现出来，是不是对数据库从业者来说是一种帮助。答案显而易见。所以我们针对对Oracle数据库技术有一定的了解，希望深入学习的数据库从业人员，在墨天轮中创建了一个新的专栏栏目——Oracle 性能优化与案例精选。

我的DBA手记（熊军）

*** 2014-01-09 12:25:06.624

在hang analyze的结果中可以看到，正是3252 这个会话产生了阻塞。 *** 2014-01-09 12:33:12.692

HANG ANALYSIS:

*** 2014-01-08 10:13:21.611

| Id | Operation | Name | Rows | Bytes |

文章被以下合辑收录

评论

在hang analyze的结果中可以看到，正是3252 这个会话产生了阻塞。
*** 2014-01-09 12:33:12.692