eygle.com   eygle.com
eygle.com eygle
eygle.com  
 

« DBV 坏块检测:Corrupt block relative dba之源 | Blog首页 | Oracle RDBMS 2011年市场份额48.8% »

Oracle O001 / O00n 进程 100% CPU资源耗用

Oracle数据库的后台进程越来越多,上周在用户环境中,遇到一则 O001 进程 100% CPU占用的案例。

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尚未有修复补丁。


 

 
以下是一个完整的进程跟踪输出:
PROCESS 120: O002
  ----------------------------------------
  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                    [........]       

-The End-


历史上的今天...
    >> 2011-06-11文章:
    >> 2009-06-11文章:
    >> 2008-06-11文章:
           Oracle 10g RAC的相关概念
    >> 2007-06-11文章:
    >> 2006-06-11文章:
           中国移动之心-谁与争锋
    >> 2005-06-11文章:

无觅

By eygle on 2012-06-11 15:50 | Comments (0) | Case | 3017 |


CopyRight © 2004~2020 云和恩墨,成就未来!, All rights reserved.
数据恢复·紧急救援·性能优化 云和恩墨 24x7 热线电话:400-600-8755 业务咨询:010-59007017-7040 or 7037 业务合作: marketing@enmotech.com