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

« DBA手记:System State转储分析之问题定位 | Blog首页 | DBA手记:System State之ass109.awk辅助分析 »

DBA手记:System State转储之ROW CACHE对象

在《Oracle DBA手记 3》即将出版之际,我将《Oracle DBA手记 2》上收录的一些文章发布出来,与大家分享。

前文参考: http://www.eygle.com/archives/2011/05/dbasystem_state_file.html


1.1          ROW CACHE对象的定位

跟踪文件向下显示了更进一步的信息,地址为 4f4e57138 Row Cache Parent Object紧跟着之前的信息显示出来,跟踪信息同时显示是在DC_OBJECTS层面出现的问题。

跟踪信息显示对象的锁定模式为排他锁定(mode=X)。

下图是跟踪文件的截取,我们可以看到Oracle的记录方式:

dbanotebook201.png

    进一步的,跟踪文件里也显示了29号进程执行的SQLINSERT操作:

----------------------------------------                                                                         

 SO: 4f2e82c88, type: 53, owner: 6c10508e8, flag: INIT/-/-/0x00                                                   

 LIBRARY OBJECT LOCK: lock=4f2e82c88 handle=4f528d510 mode=N                                                      

 call pin=0 session pin=0 hpc=0000 hlc=0000                                                                        

 htl=4f2e82d08[4f2de4dd8,4f2e844c0] htb=4e84c5db0 ssga=4e84c57c8                                                  

 user=6c10508e8 session=6c10508e8 count=1 flags=[0000] savepoint=0x4bad2ee7                                        

 LIBRARY OBJECT HANDLE: handle=4f528d510 mtx=4f528d640(1) cdp=1                                                   

 name=INSERT /*+ APPEND*/ INTO CACI_INV_BLB_DC NOLOGGING SELECT :B1 , T.*, SYSDATE FROM CACI_INV_BLB T             

 hash=6734e347f90993bcd607836585310c4d timestamp=03-24-2010 06:01:54                                              

 namespace=CRSR flags=RON/KGHP/TIM/PN0/MED/KST/DBN/MTX/[500100d0]                                                 

 kkkk-dddd-llll=0000-0001-0001 lock=N pin=0 latch#=12 hpc=ffec hlc=ffec                                           

 lwt=4f528d5b8[4f528d5b8,4f528d5b8] ltm=4f528d5c8[4f528d5c8,4f528d5c8]                                            

 pwt=4f528d580[4f528d580,4f528d580] ptm=4f528d590[4f528d590,4f528d590]                                            

 ref=4f528d5e8[4f528d5e8,4f528d5e8] lnd=4f528d600[4f581b4d8,4f5d190a8]                                            

   LIBRARY OBJECT: object=4a7227a50                                                                                

   type=CRSR flags=EXS[0001] pflags=[0000] status=VALD load=0                                                     

   CHILDREN: size=16                                                                                               

   child#    table reference   handle                                                                             

   ------ -------- --------- --------                                                                             

        0 4a7227518 4a7227188 4ae9ed1f0                                                                           

        1 4a7227518 4a7227420 494cd5878                                                                           

   DATA BLOCKS:                                                                                                    

   data#     heap  pointer    status pins change whr                                                              

   ----- -------- -------- --------- ---- ------ ---                                                               

       0 4aebaa950 4a7227b68 I/P/A/-/-    0 NONE   00                                                             

 ----------------------------------------                                                                          

 

好了,那么现在我们来看看是哪一个进程排他的锁定了之前的4f4e57138对象。在跟踪文件中搜索4f4e57138就可以很容易的找到这个持有排他锁定的SO对象。

以下显示了相关信息,Row Cache 对象的信息在此同样有所显示:

        ----------------------------------------

        SO: 4e86f0508, type: 50, owner: 8c183c258, flag: INIT/-/-/0x00

        row cache enqueue: count=1 session=8c005d7c8 object=4f4e57138, mode=X

        savepoint=0x2716

        row cache parent object: address=4f4e57138 cid=8(dc_objects)

        hash=b363a728 typ=11 transaction=8c183c258 flags=00000002

        own=4f4e57208[4e86f0538,4e86f0538] wat=4f4e57218[4e86f0418,4e86f0418] mode=X

        status=VALID/-/-/-/-/-/-/-/-

        set=0, complete=FALSE

        data=

        00000038 00134944 585f4341 43495f49 4e565f42 4c425f44 43000000 00000000

        00000000 04000009 505f3230 31305f51 31000000 00000000 00000000 00000000

        00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

        00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

        00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

        00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

        00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

        00000000 00000000 00000000 000209ca ffff0000 000209ca 14786e01 020e3239

        786e0102 0e323978 6e01020e 32390100 00000000 00000000 00000000 00000000

        00000000 00000006

      ----------------------------------------

 

再向上找到这个进程的信息,发现其进程号为16

PROCESS 16:

  ----------------------------------------

  SO: 8c00037d0, type: 2, owner: 0, flag: INIT/-/-/0x00

  (process) Oracle pid=16, calls cur/top: 8c0095028/8c0094aa8, flag: (0) -

            int error: 0, call error: 0, sess error: 0, txn error 0

  (post info) last post received: 115 0 4

              last post received-location: kslpsr

              last process to post me: 6c1002800 1 6

              last post sent: 0 0 24

              last post sent-location: ksasnd

              last process posted by me: 6c1002800 1 6

    (latch info) wait_event=0 bits=0

    Process Group: DEFAULT, pseudo proc: 4f818c298

    O/S info: user: oracle, term: UNKNOWN, ospid: 8200

    OSD pid info: Unix process pid: 8200, image: oracle@SF2900 (J000)

在这里可以看到16号进程是一个JOB进程,其进程为J000,那么这个JOB进程在执行什么操作呢?下面的信息可以看出一些端倪,JOBDBMS_SCHEDULER调度,执行AUTO_SPACE_ADVISOR_JOB任务,处于Wait for shrink lock等待:

Job Slave State Object

Slave ID: 0, Job ID: 8913

    ----------------------------------------

    SO: 8c005d7c8, type: 4, owner: 8c00037d0, flag: INIT/-/-/0x00

    (session) sid: 45 trans: 8c183c258, creator: 8c00037d0, flag: (48100041) USR/- BSY/-/-/-/-/-

              DID: 0001-0010-0007BFA6, short-term DID: 0000-0000-00000000

              txn branch: 0

              oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS

    O/S info: user: oracle, term: UNKNOWN, ospid: 8200, machine: SF2900

              program: oracle@SF2900 (J000)

    application name: DBMS_SCHEDULER, hash value=2478762354

    action name: AUTO_SPACE_ADVISOR_JOB, hash value=348111556

    waiting for 'Wait for shrink lock' blocking sess=0x0 seq=5909 wait_time=0 seconds since wait started=3101

                object_id=0, lock_mode=0, =0

    Dumping Session Wait History

     for 'Wait for shrink lock' count=1 wait_time=380596

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107262

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107263

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107246

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107139

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107248

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107003

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107169

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107233

                object_id=0, lock_mode=0, =0

     for 'Wait for shrink lock' count=1 wait_time=107069

                object_id=0, lock_mode=0, =0

    temporary object counter: 3

 

进一步向下查找,可以找到Shrink操作执行的SQL语句:

----------------------------------------                                                      

SO: 4e8a2c6c0, type: 53, owner: 8c005d7c8, flag: INIT/-/-/0x00                               

LIBRARY OBJECT LOCK: lock=4e8a2c6c0 handle=4c3c1ce60 mode=N                                  

call pin=0 session pin=0 hpc=0000 hlc=0000                                                    

htl=4e8a2c740[4e81436e0,4e8c80c98] htb=4e8937910 ssga=4e8936e48                              

user=8c005d7c8 session=8c005d7c8 count=1 flags=[0000] savepoint=0x4bad2eec                   

LIBRARY OBJECT HANDLE: handle=4c3c1ce60 mtx=4c3c1cf90(1) cdp=1                               

name=alter index "CACI"."IDX_CACI_INV_BLB_DC" modify partition "P_2010_Q1" shrink space CHECK

hash=0ed1a6f7b2cf775661d314b8d1b7659b timestamp=03-25-2010 22:05:09                           

namespace=CRSR flags=RON/KGHP/TIM/PN0/MED/KST/DBN/MTX/[500100d0]                             

kkkk-dddd-llll=0000-0001-0001 lock=N pin=0 latch#=15 hpc=0002 hlc=0002                       

lwt=4c3c1cf08[4c3c1cf08,4c3c1cf08] ltm=4c3c1cf18[4c3c1cf18,4c3c1cf18]                        

pwt=4c3c1ced0[4c3c1ced0,4c3c1ced0] ptm=4c3c1cee0[4c3c1cee0,4c3c1cee0]                        

ref=4c3c1cf38[4c3c1cf38,4c3c1cf38] lnd=4c3c1cf50[4c3c1cf50,4c3c1cf50]                        

  LIBRARY OBJECT: object=4aa2bf668                                                           

  type=CRSR flags=EXS[0001] pflags=[0000] status=VALD load=0                                 

  CHILDREN: size=16                                                                           

  child#    table reference   handle                                                         

  ------ -------- --------- --------                                                         

       0 49efa3fe8 49efa3c58 4c3ad91a8                                                        

       1 49efa3fe8 49efa3ed8 4c3941608                                                       

  DATA BLOCKS:                                                                               

  data#     heap  pointer    status pins change whr                                          

  ----- -------- -------- --------- ---- ------ ---                                          

      0 4c3589b38 4aa2bf780 I/P/A/-/-    0 NONE   00                                         

----------------------------------------                                                     

至此,真相大白于天下:

1.  系统通过DBMS_SCHEDULER调度执行AUTO_SPACE_ADVISOR_JOB任务

发出了SQL语句:

alter index "CACI"."IDX_CACI_INV_BLB_DC" modify partition "P_2010_Q1" shrink space CHECK

2.  定时任务不能及时完成产生了排他锁定

3.  客户端执行的INSERT操作挂起

INSERT语句为:

INSERT /*+ APPEND*/ INTO CACI_INV_BLB_DC NOLOGGING SELECT :B1 , T.*, SYSDATE FROM CACI_INV_BLB T

 

Shrink Space的语句所以不能成功完成是因为该索引的相关数据表的数据量过为巨大。在Oracle10g中,缺省的有一个任务定时进行分析为用户提供空间管理建议,在进行空间建议前,Oracle执行Shrink Space Check,这个检查工作和Shrink的具体内部工作完全相同,只是不执行具体动作。

这个Shrink Space的检查对于客户环境显得多余。

现场解决这个问题,只需要将16号进程Kill掉,即可释放了锁定,后面的操作可以顺利进行下去。


历史上的今天...
    >> 2010-05-26文章:
    >> 2008-05-26文章:
    >> 2006-05-26文章:
           和你一起去草原

无觅

By eygle on 2011-05-26 08:26 | Comments (3) | Case | 2804 |

3 Comments

鄙人觉得仿佛有更简洁的办法.

比如11gR1的v$session(BLOCKING_SESSION_STATUS,BLOCKING_SESSION,ROW_WAIT_OBJ#).
比如11gR2的V$SESSION_BLOCKERS.

或者 v$lock, v$latch 和 V$LATCH_CHILDREN and v$session,

"在出现数据库系统或进程失去响应时,如果SQL*Plus工具仍然可以连接,可能视图查询没有相应"

对不起, 忽略了上下文.

eygle大师,其实我不太认同你这个分析过程,明显你找到的这个process不是导致系统hang住的主要原因!能否将trace文件分享一下?


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