分析trace日志的一个思路.docx

1、昨天还在跟 Andy 抱怨写书的人会在书里大量帖日志来充字数坑读者捞钱的事，不过刚才有一库挂了，开始查阅日志。在分析一个 trace 日志时，翻阅了下 eygle 的一个很经典的分析思路的文章，整理了下给大家。文章的重点不是导致报错的原因跟解决的办法，而是寻找问题的思路与手段，eygle 也是最擅长这样剥丝抽茧般地寻找问题。这才是最宝贵的，毕竟一旦知道真正的原因了，问题就立刻有办法迎刃而解了，而最难的是如何去发现问题的根源。在 Oracle 数据库的运行过程中，可能会因为一些异常遇到数据库挂起失去响应的状况，在这种状况下，我们可以通过对系统状态进行转储，获得跟踪文件进行数据库问题分析；很多时候

2、数据库也会自动转储出现问题的进程或系统信息；这些转储信息成为我们分析故障、排查问题的重要依据。1.1 状态转储的常用命令当数据库出现一些挂起状态时，往往会严重影响到数据库使用，进程级的问题影响范围较小，而系统级的问题则会影响全局。在出现数据库系统或进程失去响应时，如果 SQL*Plus 工具仍然可以连接，可能视图查询没有相应，但是可以通过 oradebug 工具来进行进程及系统状态信息的转储，从而可以进行 Hang 分析。 DUMP 进程状态可以使用： alter sessions set events immediate trace name processstate level ；或者使用

3、：oradebug setmypidoradebug ulimitoradebug dump processstate当诊断数据库挂起时，可以使用 DUMP 命令转储整个系统状态：alter sessions set events immediate trace name systemstate level ；或：oradebug setmypidoradebug ulimitoradebug dump systemstate 如果为了获取全面一点的信息，可以使用 Level 10 。SQL oradebug setmypidSQL oradebug unlimitSQL oradebug d

4、ump systemstate 10另外如果系统挂起，无法用 SQL*Plus 连接，从 Oracle 10g 开始，可以使用 sqlplus -prelim 选项强制登录，然后即可进行系统状态信息转储：sqlplus -prelim / as sysdbaoradebug setmypidoradebug unlimit;oradebug dump systemstate 101.2 WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! 案例在一次客户现场培训中，客户提出一个系统正遇到问题，请求我协助诊断解决，理论联系实践，这是我在培训中极力主张的，我们

5、的案例式培训业正好遇到了实践现场。问题是这样的：此前一个 Job 任务可以在秒级完成，而现在运行了数小时也无法结束，一直挂起在数据库中，杀掉进程重新手工执行，尝试多次，同样无法完成。客户的数据库环境为：Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit ProductionWith the Partitioning, OLAP and Data Mining optionsNode name: SF2900 Release: 5.9 Version: Generic_118558-33 Machine: sun4u

6、介入问题诊断首先需要收集数据，我最关注两方面的信息：1 告警日志文件，检查是否出现过异常2 生成 AWR 报告，检查数据库内部的运行状况通常有了这两部信息，我们就可以做出初步判断了。检查数据库的告警日志文件，我们发现其中出现过一个如下错误： WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! row cache enqueue: session: 6c10508e8, mo

7、de: N, request: S至此我们找到了出现问题的根源，这里也显示请求的对象是 object=4f4e57138 。1.4 ROW CACHE 对象的定位跟踪文件向下显示了更进一步的信息，地址为 4f4e57138 的 Row Cache Parent Object 紧跟着之前的信息显示出来，跟踪信息同时显示是在 DC_OBJECTS 层面出现的问题。跟踪信息显示对象的锁定模式为排他锁定（ mode=X ）。下图是跟踪文件的截取，我们可以看到 Oracle 的记录方式： 进一步的，跟踪文件里也显示了 29 号进程执行的 SQL 为 INSERT 操作：- SO: 4f2e82c88,

8、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=4f2e82d084f2de4dd8,4f2e844c0 htb=4e84c5db0 ssga=4e84c57c8 user=6c10508e8 session=6c10508e8 count=1 flags=0000 savepoint=0x4bad2ee7 LIBRARY OBJECT

9、 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=000

10、0-0001-0001 lock=N pin=0 latch#=12 hpc=ffec hlc=ffec lwt=4f528d5b84f528d5b8,4f528d5b8 ltm=4f528d5c84f528d5c8,4f528d5c8 pwt=4f528d5804f528d580,4f528d580 ptm=4f528d5904f528d590,4f528d590 ref=4f528d5e84f528d5e8,4f528d5e8 lnd=4f528d6004f581b4d8,4f5d190a8 LIBRARY OBJECT: object=4a7227a50 type=CRSR flags=

11、EXS0001 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 -好了，那么现在我们来看看是哪一个进程排他的锁定了之前的 4

12、f4e57138 对象。在跟踪文件中搜索 4f4e57138 就可以很容易的找到这个持有排他锁定的 SO 对象。以下显示了相关信息， Row Cache 对象的信息在此同样有所显示：-SO: 4e86f0508 , type: 50, owner: 8c183c258, flag: INIT/-/-/0x00row cache enqueue: count=1 session=8c005d7c8 object=4f4e57138, mode=Xsavepoint=0x2716row cache parent object: address=4f4e57138 cid=8(dc_objects)

13、hash=b363a728 typ=11 transaction=8c183c258 flags=00000002own=4f4e572084e86f0538,4e86f0538 wat=4f4e572184e86f0418,4e86f0418 mode=Xstatus=VALID/-/-/-/-/-/-/-/-set=0, complete=FALSEdata=00000038 00134944 585f4341 43495f49 4e565f42 4c425f44 43000000 0000000000000000 04000009 505f3230 31305f51 31000000 0

14、0000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000

15、 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 000209ca ffff0000 000209ca 14786e01 020e3239786e0102 0e323978 6e01020e 32390100 00000000 00000000 00000000 0000000000000000 00000006-再向上找到这个进程的信息，发现其进程号为 16 ：PROCESS 16:-SO: 8c00037d0, type: 2,

16、 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 4last post received-location: kslpsrlast process to post me: 6c1002800 1 6last post sent: 0 0 24last post

17、 sent-location: ksasndlast process posted by me: 6c1002800 1 6(latch info) wait_event=0 bits=0Process Group: DEFAULT, pseudo proc: 4f818c298O/S info: user: oracle, term: UNKNOWN, ospid: 8200OSD pid info: Unix process pid: 8200, image: oracleSF2900 (J000)在这里可以看到 16 号进程是一个 JOB 进程，其进程为 J000 ，那么这个 JOB 进

18、程在执行什么操作呢？下面的信息可以看出一些端倪， JOB 由 DBMS_SCHEDULER 调度，执行 AUTO_SPACE_ADVISOR_JOB 任务，处于 Wait for shrink lock 等待：Job Slave State ObjectSlave 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/-/-

19、/-/-/-DID: 0001-0010-0007BFA6, short-term DID: 0000-0000-00000000txn branch: 0oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYSO/S info: user: oracle, term: UNKNOWN, ospid: 8200, machine: SF2900program: oracleSF2900 (J000)application name: DBMS_SCHEDULER, hash value=2478762354action name: AUTO_SPACE_ADVI

20、SOR_JOB, hash value=348111556waiting for Wait for shrink lock blocking sess=0x0 seq=5909 wait_time=0 seconds since wait started=3101object_id=0, lock_mode=0, =0Dumping Session Wait Historyfor Wait for shrink lock count=1 wait_time=380596object_id=0, lock_mode=0, =0for Wait for shrink lock count=1 wa

21、it_time=107262object_id=0, lock_mode=0, =0for Wait for shrink lock count=1 wait_time=107263object_id=0, lock_mode=0, =0for Wait for shrink lock count=1 wait_time=107246object_id=0, lock_mode=0, =0for Wait for shrink lock count=1 wait_time=107139object_id=0, lock_mode=0, =0for Wait for shrink lock co

22、unt=1 wait_time=107248object_id=0, lock_mode=0, =0for Wait for shrink lock count=1 wait_time=107003object_id=0, lock_mode=0, =0for Wait for shrink lock count=1 wait_time=107169object_id=0, lock_mode=0, =0for Wait for shrink lock count=1 wait_time=107233object_id=0, lock_mode=0, =0for Wait for shrink

23、 lock count=1 wait_time=107069object_id=0, lock_mode=0, =0temporary 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=4e8a2c7404

24、e81436e0,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 CHECKhash=0ed1a6f7b2cf775661

25、d314b8d1b7659b 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=4c3c1cf084c3c1cf08,4c3c1cf08 ltm=4c3c1cf184c3c1cf18,4c3c1cf18 pwt=4c3c1ced04c3c1ced0,4c3c1ced0 ptm=4c3c1cee04c3c1cee0

26、,4c3c1cee0 ref=4c3c1cf384c3c1cf38,4c3c1cf38 lnd=4c3c1cf504c3c1cf50,4c3c1cf50 LIBRARY OBJECT: object=4aa2bf668 type=CRSR flags=EXS0001 pflags=0000 status=VALD load=0 CHILDREN: size=16 child# table reference handle - - - - 0 49efa3fe8 49efa3c58 4c3ad91a8 1 49efa3fe8 49efa3ed8 4c3941608 DATA BLOCKS: da

27、ta# 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 CHECK2 定时任务不能及时完成产生了排他锁定3 客户端执行的 INSERT 操作挂起I

28、NSERT 语句为：INSERT /*+ APPEND*/ INTO CACI_INV_BLB_DC NOLOGGING SELECT :B1 , T.*, SYSDATE FROM CACI_INV_BLB TShrink Space 的语句所以不能成功完成是因为该索引的相关数据表的数据量过为巨大。在 Oracle10g 中，缺省的有一个任务定时进行分析为用户提供空间管理建议，在进行空间建议前， Oracle 执行 Shrink Space Check ，这个检查工作和 Shrink 的具体内部工作完全相同，只是不执行具体动作。这个 Shrink Space 的检查对于客户环境显得多余。现场解决这个问题，只需要将 16 号进程（注意，这是 oracle 进程，用 sqlplus，alter system kill） Kill 掉，即可释放了锁定，后面的操作可以顺利进行下去。