« DBV 坏块检测:Corrupt block relative dba之源 | Blog首页 | Oracle RDBMS 2011年市场份额48.8% »
Oracle O001 / O00n 进程 100% CPU资源耗用
作者:eygle | 【转载请注出处】|【云和恩墨 领先的zData数据库一体机 | zCloud PaaS云管平台 | SQM SQL审核平台 | ZDBM 数据库备份一体机】
链接:https://www.eygle.com/archives/2012/06/oracle_o001_o00n_cpu.html
Oracle数据库的后台进程越来越多,上周在用户环境中,遇到一则 O001 进程 100% CPU占用的案例。链接:https://www.eygle.com/archives/2012/06/oracle_o001_o00n_cpu.html
O00n 进程是RDBMS实例和ASM实例进行通讯的后台进程,其含义为 ASM Connection Pool Process - ASM连接池进程,主要用于维护从实例到ASM的元数据操作。
在进程的状态信息中,可以看到进程的操作相关信息:
Session Wait History:
elapsed time of 0.000018 sec since current wait
0: waited for 'ASM file metadata operation'
msgop=0xf, locn=0x0, =0x0
wait_id=93046 seq_num=3771 snap_id=1
wait times: snap=0.000679 sec, exc=0.000679 sec, total=0.000679 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000009 sec of elapsed time
1: waited for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93045 seq_num=3770 snap_id=1
wait times: snap=0.000052 sec, exc=0.000052 sec, total=0.000052 sec
wait times: max=infinite
wait counts: calls=1 os=1
occurred after 0.000023 sec of elapsed time
在跟踪诊断中,发现100% CPU占用的进程的运行时间都超长,以下进程等待时间超过 400115 分钟,合计约278天:
Current Wait Stack:
0: waiting for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93047 seq_num=3772 snap_id=1
wait times: snap=400115 min 52 sec, exc=400115 min 52 sec, total=400115 min 52 sec
wait times: max=infinite, heur=400115 min 52 sec
wait counts: calls=14855 os=14855
in_wait=1 iflags=0x15a0
经过确认,O001 、Onnn、或这说 O00n 进程在持续运行约 250 天之后,可能就会出现 100% CPU耗用的情况。
在这种情况下,可以选择直接Kill -9 杀掉该进程,目前Oracle尚未有修复补丁。
以下是一个完整的进程跟踪输出:
历史上的今天...
>> 2011-06-11文章:
>> 2009-06-11文章:
>> 2008-06-11文章:
>> 2007-06-11文章:
>> 2006-06-11文章:
>> 2005-06-11文章:
PROCESS 120: O002-The End-
----------------------------------------
SO: 0xc88ab1960, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=process, file=ksu.h LINE:12451, pg=0
(process) Oracle pid:120, ser:18, calls cur/top: 0xc3b814e00/0xc3b814e00
flags : (0x2) SYSTEM
flags2: (0x0), flags3: (0x0)
intr error: 0, call error: 0, sess error: 0, txn error 0
intr queue: empty
ksudlp FALSE at location: 0
(post info) last post received: 0 0 47
last post received-location: ksv2.h LINE:1661 ID:ksvpst: send
last process to post me: ce8b27fa0 1 6
last post sent: 0 0 48
last post sent-location: ksv2.h LINE:1664 ID:ksvpst: dmsgdone
last process posted by me: ce8b27fa0 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 0xc98b7f8f0
O/S info: user: oracle, term: UNKNOWN, ospid: 25789
OSD pid info: Unix process pid: 25789, image: oracle@settle-1 (O002)
----------------------------------------
SO: 0xce8dffd50, type: 4, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=session, file=ksu.h LINE:12459, pg=0
(session) sid: 1155 ser: 2201 trans: (nil), creator: 0xc88ab1960
flags: (0x51) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x80408) -/-
DID: , short-term DID:
txn branch: (nil)
oct: 0, prv: 0, sql: (nil), psql: (nil), user: 0/SYS
ksuxds FALSE at location: 0
service name: SYS$BACKGROUND
Current Wait Stack:
0: waiting for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93047 seq_num=3772 snap_id=1
wait times: snap=400115 min 52 sec, exc=400115 min 52 sec, total=400115 min 52 sec
wait times: max=infinite, heur=400115 min 52 sec
wait counts: calls=14855 os=14855
in_wait=1 iflags=0x15a0
Wait State:
fixed_waits=0 flags=0x22 boundary=(nil)/-1
Session Wait History:
elapsed time of 0.000018 sec since current wait
0: waited for 'ASM file metadata operation'
msgop=0xf, locn=0x0, =0x0
wait_id=93046 seq_num=3771 snap_id=1
wait times: snap=0.000679 sec, exc=0.000679 sec, total=0.000679 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000009 sec of elapsed time
1: waited for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93045 seq_num=3770 snap_id=1
wait times: snap=0.000052 sec, exc=0.000052 sec, total=0.000052 sec
wait times: max=infinite
wait counts: calls=1 os=1
occurred after 0.000023 sec of elapsed time
2: waited for 'ASM file metadata operation'
msgop=0xf, locn=0x0, =0x0
wait_id=93044 seq_num=3769 snap_id=1
wait times: snap=0.000799 sec, exc=0.000799 sec, total=0.000799 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000009 sec of elapsed time
3: waited for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93043 seq_num=3768 snap_id=1
wait times: snap=0.000113 sec, exc=0.000113 sec, total=0.000113 sec
wait times: max=infinite
wait counts: calls=1 os=1
occurred after 0.000024 sec of elapsed time
4: waited for 'ASM file metadata operation'
msgop=0x12, locn=0x0, =0x0
wait_id=93042 seq_num=3767 snap_id=1
wait times: snap=0.000350 sec, exc=0.000350 sec, total=0.000350 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000015 sec of elapsed time
5: waited for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93041 seq_num=3766 snap_id=1
wait times: snap=0.000343 sec, exc=0.000343 sec, total=0.000343 sec
wait times: max=infinite
wait counts: calls=1 os=1
occurred after 0.000020 sec of elapsed time
6: waited for 'ASM file metadata operation'
msgop=0xf, locn=0x0, =0x0
wait_id=93040 seq_num=3765 snap_id=1
wait times: snap=0.000943 sec, exc=0.000943 sec, total=0.000943 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000010 sec of elapsed time
7: waited for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93039 seq_num=3764 snap_id=1
wait times: snap=0.001378 sec, exc=0.001378 sec, total=0.001378 sec
wait times: max=infinite
wait counts: calls=1 os=1
occurred after 0.000022 sec of elapsed time
8: waited for 'ASM file metadata operation'
msgop=0x29, locn=0x0, =0x0
wait_id=93038 seq_num=3763 snap_id=1
wait times: snap=0.004394 sec, exc=0.004394 sec, total=0.004394 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000009 sec of elapsed time
9: waited for 'class slave wait'
slave id=0x0, =0x0, =0x0
wait_id=93037 seq_num=3762 snap_id=1
wait times: snap=0.000090 sec, exc=0.000090 sec, total=0.000090 sec
wait times: max=infinite
wait counts: calls=1 os=1
occurred after 0.000023 sec of elapsed time
Sampled Session History of session 1155 serial 2201
---------------------------------------------------
The sampled session history is constructed by sampling
the target session every 1 second. The sampling process
captures at each sample if the session is in a non-idle wait,
an idle wait, or not in a wait. If the session is in a
non-idle wait then one interval is shown for all the samples
the session was in the same non-idle wait. If the
session is in an idle wait or not in a wait for
consecutive samples then one interval is shown for all
the consecutive samples. Though we display these consecutive
samples in a single interval the session may NOT be continuously
idle or not in a wait (the sampling process does not know).
The history is displayed in reverse chronological order.
sample interval: 1 sec, max history 120 sec
---------------------------------------------------
[121 samples, 17:10:40 - 17:12:40]
idle wait at each sample
temporary object counter: 0
----------------------------------------
Virtual Thread:
kgskvt: 0xc911d5a80, sess: 0xce8dffd50 sid: 1155 ser: 2201
vc: (nil), proc: 0xc88ab1960, id: 1155
consumer group cur: _ORACLE_BACKGROUND_GROUP_ (upd? 0), mapped: _ORACLE_BACKGROUND_GROUP_, orig:
vt_state: 0x100, vt_flags: 0x4030, blkrun: 0, numa: 1
inwait: 0
location where insched last set: kgskthrrun
location where insched last cleared: kgskthrrun1
location where inwait last set: NULL
location where inwait last cleared: NULL
is_assigned: 0, in_sched: 0 (0)
qcls: (nil), qlink: FALSE
vt_active: 0 (pending: 0)
vt_pq_active: 0, dop: 0
used quanta: 0 (cg: 0) usec, num penalty: 0
cpu start time: 0
idle time: 0, active time: 0 (cg: 0)
cpu yields: 0 (cg: 0), waits: 0 (cg: 0), wait time: 0 (cg: 0) usec
io waits: 0 (cg: 0), wait time: 0 (cg: 0) usec
ASL queued time outs: 0, time: 0 (cur 0, cg 0)
PQQ queued time outs: 0, time: 0 (cur 0, cg 0)
Queue timeout violation: 0
calls aborted: 0, num est exec limit hit: 0
undo current: 0k max: 0k
I/O credits acquired:small=0 large=0
I/O credits waiting for:small=0 large=0
KTU Session Commit Cache Dump for IDLs:
KTU Session Commit Cache Dump for Non-IDLs:
----------------------------------------
KKS-UOL used : 0 locks(used=0, free=0)
KGX Atomic Operation Log 0xcbe281d68
Mutex (nil)(0, 0) idn 7fff00000000 oper NONE
FSO mutex uid 1155 efd 0 whr 0 slp 0
KGX Atomic Operation Log 0xcbe281db8
Mutex (nil)(0, 0) idn 7fff00000000 oper NONE
FSO mutex uid 1155 efd 0 whr 0 slp 0
KGX Atomic Operation Log 0xcbe281e08
Mutex (nil)(0, 0) idn 7fff00000000 oper NONE
FSO mutex uid 1155 efd 0 whr 0 slp 0
KGX Atomic Operation Log 0xcbe281e58
Mutex (nil)(0, 0) idn 7fff00000000 oper NONE
FSO mutex uid 1155 efd 0 whr 0 slp 0
----------------------------------------
KGL-UOL SO Cache(total=0, free=0)
KGX Atomic Operation Log 0xcb524d258
Mutex (nil)(0, 0) idn be2f97e300000000 oper NONE
Library Cache uid 1155 efd 0 whr 0 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
pt4=(nil) pt5=(nil) ub4=0
KGX Atomic Operation Log 0xcb524d2b0
Mutex (nil)(0, 0) idn be2f97e300000000 oper NONE
Library Cache uid 1155 efd 0 whr 0 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
pt4=(nil) pt5=(nil) ub4=0
KGX Atomic Operation Log 0xcb524d308
Mutex (nil)(0, 0) idn be2f97e300000000 oper NONE
Library Cache uid 1155 efd 0 whr 0 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
pt4=(nil) pt5=(nil) ub4=0
KGX Atomic Operation Log 0xcb524d360
Mutex (nil)(0, 0) idn be2f97e300000000 oper NONE
Library Cache uid 1155 efd 0 whr 0 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
pt4=(nil) pt5=(nil) ub4=0
KGX Atomic Operation Log 0xcb524d3b8
Mutex (nil)(0, 0) idn be2f97e300000000 oper NONE
Library Cache uid 1155 efd 0 whr 0 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
pt4=(nil) pt5=(nil) ub4=0
KGX Atomic Operation Log 0xcb524d410
Mutex (nil)(0, 0) idn be2f97e300000000 oper NONE
Library Cache uid 1155 efd 0 whr 0 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
pt4=(nil) pt5=(nil) ub4=0
KGX Atomic Operation Log 0xcb524d468
Mutex (nil)(0, 0) idn be2f97e300000000 oper NONE
Library Cache uid 1155 efd 0 whr 0 slp 0
oper=0 pt1=(nil) pt2=(nil) pt3=(nil)
pt4=(nil) pt5=(nil) ub4=0
----------------------------------------
SO: 0xc74a73d18, type: 56, owner: 0xce8dffd50, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=dummy, file=ktccts.h LINE:412, pg=0
(dummy) nxc=0, nlb=0
----------------------------------------
SO: 0xca120d3a0, type: 15, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xce8b35620, name=ksv slave, file=ksv2.h LINE:1247, pg=0
KSV Slave Object State: 0x0000000CA120D3A0
----------------------
hdl: 0x000000000002456D class: 16 ctx: 0x0000000C993311C8
type: 2 state: 2 msgflg: 17 proc: 0x0000000C88AB1960
creator - hdl: 0x00000000800D0001 proc: 0x0000000CE8B35620
run - arg: 0x0000000000000000 termevt: 0 status: 0x0000000000000000 indicator: 25
local slave flags: 2 session: 0xce8dffd50 serial: 2201
dmsg allocq: 0xca120d438 Is Empty [ca120d438,ca120d438]
dmsg readq: 0xca120d458 Is Empty [ca120d458,ca120d458]
dmsg rcvq: 0xca120d448 Is Empty [ca120d448,ca120d448]
dmsg missedq: 0xca120d478 Is Empty [ca120d478,ca120d478]
dmsg failedq: 0xca120d488 Is Empty [ca120d488,ca120d488]
dmsg returnq: 0xca120d468 Is Empty [ca120d468,ca120d468]
KSV Class Dump - cctx: 0x0000000C993311C8 dpptr: 0x0000000C99352528
SGA dp=0x0000000000000000 sdp=0x0000000000000000 last spawn err: 448 flags=0
class#: 16 prefix: O desc: ASM Connection Pool
max: 30 flags: 8 exitcond: 0 minw: 1 maxw: 30 fail: 0
dmsghdl: 0x0000000CA0BBB3B0 dmsgsz: 0 wmsghdl: 0x0000000CA0BBB420 wmsgsz: 0 cnt: 458878430
idle: 6 pend: 0 rmt: 0 trm: 0 fail: 0
btm: 2 btw: 0 work: 0 msp: 0
work queue (0)
ksvmqd: 0x0000000C99331478 length: 0 ins: 457109910 cancels: 0
queue msgs: 0xc99331578 Is Empty [c99331578,c99331578]
work queue (1)
ksvmqd: 0x0000000C993315A0 length: 0 ins: 1321516 cancels: 0
queue msgs: 0xc993316a0 Is Empty [c993316a0,c993316a0]
work queue (2)
ksvmqd: 0x0000000C993316C8 length: 0 ins: 53 cancels: 0
queue msgs: 0xc993317c8 Is Empty [c993317c8,c993317c8]
----------------------------------------
SO: 0xc992790e0, type: 14, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
proc=0xc88ab1960, name=channel handle, file=ksr2.h LINE:347, pg=0
(broadcast handle) 0xc992790e0 flag: (12) INACTIVE SUBSCRIBER,
owner: 0xc88ab1960 - ospid: 25789
event: 28489, last message event: 28489,
last message waited event: 28489,
next message: (nil)(0), messages read: 0
channel: (0xc8908c698) system events broadcast channel [name: 1]
scope: 2, event: 2375459, last mesage event: 69229,
publishers/subscribers: 1/180,
messages published: 7
oldest msg (?): 0xca97732d8 id: 1 pub: 0xce8b2a0a0
heuristic msg queue length: 7
----------------------------------------
SO: 0xc3b7fb190, type: 126, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=ASM kfk state object, file=kfk2.h LINE:656, pg=0
kfkso: 0xc3b7fb190
kfklsodtab:0xca49f5d10
----------------------------------------
SO: 0xce922e270, type: 30, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=ges process, file=kji.h LINE:3520, pg=0
GES MSG BUFFERS: st=emp chunk=(nil) hdr=(nil) lnk=(nil) flags=0x0 inc=0
outq=0 sndq=0 opid=0 prmb=(nil)
mbg[i]=(0 0) mbg[b]=(0 0) mbg[r]=(0 0)
fmq[i]=(0 0) fmq[b]=(0 0) fmq[r]=(0 0)
mop[s]=0 mop[q]=0 pendq=0 zmbq=0
nonksxp_recvs=0
------------process 0xce922e270--------------------
proc version : 7
Local inst : 1
pid : 25789
lkp_inst : 1
svr_mode : 0
proc state : KJP_FROZEN
Last drm hb acked : 0
flags : x10
ast_rcvd_svrmod : 0
current lock op : (nil)
Total accesses : 702
Imm. accesses : 701
Locks on ASTQ : 0
Locks Pending AST : 0
Granted locks : 0
AST_Q:
PENDING_Q:
GRANTED_Q:
----------------------------------------
SO: 0xc5f3f3a30, type: 24, owner: 0xc88ab1960, flag: -/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=ksz parent, file=ksz2.h LINE:408, pg=0
----------------------------------------
SO: 0xca9778c28, type: 17, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=ksxp IPC state object, file=ksxp2.h LINE:1495, pg=0
KSXP Context allocated
Owner: 0xc88ab1960 (pid: 120) [flg: 1 sg: 1]
----------------------------------------
SO: 0xc3b814e00, type: 3, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xc88ab1960, name=call, file=ksu.h LINE:12455, pg=0
(call) sess: cur ce8dffd50, rec 0, usr ce8dffd50; flg:20 fl2:1; depth:0
svpt(xcb:(nil) sptn:0x2 uba: 0x00000000.0000.00)
ksudlc FALSE at location: 0
----------------------------------------
SO: 0xc3b7fbae8, type: 20, owner: 0xc88ab1960, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
proc=0xc88ab1960, name=OS proc request holder, file=kso2.h LINE:516, pg=0
(osp req holder)
PSO child state object changes :
Dump of memory from 0x0000000C98A89BB0 to 0x0000000C98A89DB8
C98A89BB0 00000000 00000000 00000000 00000000 [................]
Repeat 31 times
C98A89DB0 00000000 00000000 [........]
历史上的今天...
>> 2011-06-11文章:
>> 2009-06-11文章:
>> 2008-06-11文章:
>> 2007-06-11文章:
>> 2006-06-11文章:
>> 2005-06-11文章:
By eygle on 2012-06-11 15:50 | Comments (0) | Case | 3017 |