本节书摘来自异步社区出版社《循序渐进Oracle：数据库管理、优化与备份恢复》一书中的第1章，第1.5节，作者：盖国强，更多章节内容可以访问云栖社区“异步社区”公众号查看。

1.5　案例与实践分析　

在本节中，我将与本章有关的一些案例诊断、故障分析收录于此，供读者参考。

1.5.1　auto_space_advisor_job_proc案例一则

在数据库创建中所提到的“预防性指导报告”就包括空间指导报告，这一定时任务在很多客户系统中带来了极大的麻烦。

在以下客户的SAP系统中，某个高负载的时段，数据库就遇到了DBMS_SCHEDULER任务的一个Bug，其数据库版本为10.2.0.2。

在SQL Ordered By Elapsed Time的采样中，Top 6都是DBMS_SCHEDULER调度的任务，而且耗时显著，如图1-28所示。

处在第一位的，是auto_space_advisor_job_proc过程调用，CPU Time消耗高达4226秒：

call dbms_space.auto_space_advisor_job_proc ( )

执行花费了大量的时间，3000多秒，进而执行的SQL：

insert into wri$_adv_objspace_trend_data select timepoint, space_usage, space_alloc, quality from table(dbms_space.object_growth_trend(:1, :2, :3, :4, NULL, NULL, NULL, 'FALSE', :5, 'FALSE'))

也花费了2514秒的时间，这显然是不正常的。在正常情况下，单独跟踪一下SQL*Plus中手工执行这个过程，可以获得这个SQL的执行统计信息，跟踪过程可能如下：

SQL> alter session set events '10046 trace name context forever,level 12';
SQL> call dbms_space.auto_space_advisor_job_proc ( )
SQL> alter session set events '10046 trace name context off';

格式化跟踪文件，获得以下输出，如图1-29所图片 1

图1-29　输出信息
示。

注意到，这个Insert仍然消耗了389秒的时间，逻辑读429 297，性能是存在问题的。在Metalink上存在如下一个Bug：
**
Bug 5376783: DBMS_SPACE.OBJECT_GROWTH_TREND CALL TAKES A LOT OF DISK READS**
这个Bug在DBMS_SPACE.OBJECT_GROWTH_TREND进行空间分析时被触发，根本原因在于内部算法在执行空间检查时，耗费了大量的评估IO成本，导致了大量的IO资源使用。

临时的处理办法是，暂时关闭这个自动任务：

execute dbms_scheduler.disable('AUTO_SPACE_ADVISOR_JOB');
这个Bug在10.2.0.2之后的版本中被修正。

既然Oracle的缺省定时任务可能会带来如此多的问题，我们就很有必要去关注一下系统有哪些缺省的任务，执行情况如何。以下是一个10.2.0.5版本的数据库中一些自动任务的调度设置情况：

SQL> select job_name,state,enabled,last_start_date from dba_scheduler_jobs;　　　　　　JOB_NAME　　　　　　　　　　　 STATE　　　　　 ENABL LAST_START_DATE
------------------------------ --------------- ----- -----------------------------------
AUTO_SPACE_ADVISOR_JOB　　　　 SCHEDULED　　　 TRUE　07-AUG-10 06.00.03.792886 AM +08:00
GATHER_STATS_JOB　　　　　　　 SCHEDULED　　　 TRUE　07-AUG-10 06.00.03.783957 AM +08:00
FGR$AUTOPURGE_JOB　　　　　　　DISABLED　　　　FALSE
PURGE_LOG　　　　　　　　　　　SCHEDULED　　　 TRUE　07-AUG-10 03.00.00.353023 AM PRC
MGMT_STATS_CONFIG_JOB　　　　　SCHEDULED　　　 TRUE　01-AUG-10 01.01.01.822354 AM +08:00
MGMT_CONFIG_JOB　　　　　　　　SCHEDULED　　　 TRUE　07-AUG-10 06.00.03.767320 AM +08:00

在以上的调度任务中，GATHER_STATS_JOB是Oracle Database 10g开始引入的自动统计信息收集的任务，该任务缺省的调度是，工作日每晚22:00至凌晨6:00进行分析，周末全天进行分析。在以下输出中，我们可以看到任务无法完成，STOP的情况：

SQL> SELECT log_id, job_name, status, 2　　　　 TO_CHAR(ACTUAL_START_DATE,'DD-MON-YYYY HH24:MI') start_date,TO_CHAR (log_date, 'DD-MON-YYYY HH24:MI') log_date 3　　FROM dba_scheduler_job_run_details 4　 WHERE job_name = 'GATHER_STATS_JOB' order by 4; LOG_ID JOB_NAME　　　　　　 STATUS　　　　　　　 START_DATE　　　　　 LOG_DATE
---------- -------------------- -------------------- -------------------- -------------------- 1480 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　02-AUG-2010 22:00　　03-AUG-2010 00:581561 GATHER_STATS_JOB　　 STOPPED　　　　　　　03-AUG-2010 22:00　　04-AUG-2010 06:001640 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　04-AUG-2010 22:00　　05-AUG-2010 05:361680 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　05-AUG-2010 22:00　　05-AUG-2010 22:251741 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　06-AUG-2010 22:00　　06-AUG-2010 22:271800 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　07-AUG-2010 06:00　　07-AUG-2010 06:02384 GATHER_STATS_JOB　　 STOPPED　　　　　　　07-JUL-2010 22:00　　08-JUL-2010 06:00463 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　08-JUL-2010 22:00　　09-JUL-2010 05:06503 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　09-JUL-2010 22:00　　09-JUL-2010 22:05544 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　10-JUL-2010 06:00　　10-JUL-2010 06:02589 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　12-JUL-2010 22:00　　12-JUL-2010 22:04597 GATHER_STATS_JOB　　 SUCCEEDED　　　　　　13-JUL-2010 22:00　　13-JUL-2010 22:03

在一些大型数据库中，这个任务不一定能够有效执行，以下是某用户的数据库环境，输出显示，多日数据库都因为ORA-04031错误未能完成统计信息收集采样：

SQL> SELECT LOG_DATE,RUN_DURATION,JOB_NAME,STATUS,ERROR#　2　FROM DBA_SCHEDULER_JOB_RUN_DETAILS　3　WHERE JOB_NAME='GATHER_STATS_JOB' 4　order by 1 desc;　
LOG_DATE　　　　　　　　　　　　　　RUN_DURATION　　JOB_NAME　　　　　 STATUS　　　　　ERROR#
----------------------------------- --------------- ------------------ ----------- ----------
26-MAY-10 10.00.09.290291 PM +08:00 +000 00:00:05　 GATHER_STATS_JOB　 FAILED　　　　　 22303
25-MAY-10 10.00.08.973684 PM +08:00 +000 00:00:06　 GATHER_STATS_JOB　 FAILED　　　　　　4031
24-MAY-10 10.00.22.977244 PM +08:00 +000 00:00:18　 GATHER_STATS_JOB　 FAILED　　　　　　4031
22-MAY-10 06.00.16.950362 AM +08:00 +000 00:00:13　 GATHER_STATS_JOB　 FAILED　　　　　　4031
21-MAY-10 10.00.49.653788 PM +08:00 +000 00:00:47　 GATHER_STATS_JOB　 FAILED　　　　　　4031
20-MAY-10 10.00.14.028432 PM +08:00 +000 00:00:11　 GATHER_STATS_JOB　 FAILED　　　　　　4031
19-MAY-10 10.00.20.828607 PM +08:00 +000 00:00:18　 GATHER_STATS_JOB　 FAILED　　　　　　4031
19-MAY-10 05.54.27.871444 AM +08:00 +000 07:54:25　 GATHER_STATS_JOB　 SUCCEEDED　　　　　　0
18-MAY-10 05.36.01.494920 AM +08:00 +000 07:35:59　 GATHER_STATS_JOB　 SUCCEEDED　　　　　　0
15-MAY-10 07.06.05.793257 AM +08:00 +000 01:06:01　 GATHER_STATS_JOB　 SUCCEEDED　　　　　　0
15-MAY-10 03.56.50.898303 AM +08:00 +000 05:56:48　 GATHER_STATS_JOB　 SUCCEEDED　　　　　　0

在GATHER_STATS_JOB任务不能够有效地执行时，我们必须及时地介入去手工处理，不及时地统计信息可能使数据库产生错误的执行计划。

正常的AUTO_SPACE_ADVISOR_JOB调度可能应该有着类似以下输出的执行结果：

SQL> SELECT log_id, job_name, status,TO_CHAR(ACTUAL_START_DATE,'DD-MON-YYYY HH24:MI') start_date, 2　　　　 TO_CHAR (log_date, 'DD-MON-YYYY HH24:MI') log_date 3　　FROM dba_scheduler_job_run_details 4　 WHERE job_name = 'AUTO_SPACE_ADVISOR_JOB' order by 4; LOG_ID JOB_NAME　　　　　　　　　STATUS　　　　　START_DATE　　　　　 LOG_DATE
---------- ------------------------- --------------- -------------------- ---------------- 1460 AUTO_SPACE_ADVISOR_JOB　　SUCCEEDED　　　 02-AUG-2010 22:00　　02-AUG-2010 22:16 1520 AUTO_SPACE_ADVISOR_JOB　　SUCCEEDED　　　 03-AUG-2010 22:00　　03-AUG-2010 23:18 1600 AUTO_SPACE_ADVISOR_JOB　　SUCCEEDED　　　 04-AUG-2010 22:00　　04-AUG-2010 22:19 1681 AUTO_SPACE_ADVISOR_JOB　　SUCCEEDED　　　 05-AUG-2010 22:00　　05-AUG-2010 22:28 1740 AUTO_SPACE_ADVISOR_JOB　　SUCCEEDED　　　 06-AUG-2010 22:00　　06-AUG-2010 22:17

1.5.2　systemstate转储案例分析一则

在Oracle数据库的运行过程中，可能会因为一些异常遇到数据库挂起失去响应的状况，在这种状况下，我们可以通过对系统状态进行转储，获得跟踪文件进行数据库问题分析；很多时候数据库也会自动转储出现问题的进程或系统信息；这些转储信息成为我们分析故障、排查问题的重要依据。

在一次客户现场培训中，客户提出一个系统正遇到问题，请求我协助诊断解决，理论联系实践，这是我在培训中极力主张的，我们的案例式培训业正好遇到了实践现场。

问题是这样的：此前一个Job任务可以在秒级完成，而现在运行了数小时也无法结束，一直挂起在数据库中，杀掉进程重新手工执行，尝试多次，同样无法完成。

客户的数据库环境为：

Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
With the Partitioning, OLAP and Data Mining options
Node name: SF2900　Release: 5.9　Version: Generic_118558-33 Machine: sun4u

介入问题诊断首先需要收集数据，我最关注两方面的信息：

boll 告警日志文件，检查是否出现过异常；

boll 生成AWR报告，检查数据库内部的运行状况。

通常有了这两部分信息，我们就可以做出初步判断了。

检查数据库的告警日志文件，我们发现其中出现过一个如下错误：

>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<

这个错误提示出现在7点左右，正是JOB的调度时间附近，显然这是一个高度相关的可能原因。这个异常生成了转储的DUMP文件，获得该文件进行进一步的详细分析。该文件的头部信息如下：

Redo thread mounted by this instance: 1
Oracle process number: 29
Unix process pid: 8371, image: oracleEDW@SF2900 *** 2010-03-27 06:54:00.114
*** ACTION NAME:() 2010-03-27 06:54:00.106
*** MODULE NAME:(SQL*Plus) 2010-03-27 06:54:00.106
*** SERVICE NAME:(EDW) 2010-03-27 06:54:00.106
*** SESSION ID:(120.46138) 2010-03-27 06:54:00.106
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<
row cache enqueue: session: 6c10508e8, mode: N, request: S

ROW CACHE队列锁无法获得，表明数据库在SQL解析时，遇到问题，DC层面出现竞争，导致超时。Row Cache位于Shared Pool中的Data Dictionary Cache，是用于存储表列定义、权限等相关信息的。

注意以上信息中的重要内容如下。

boll 超时告警的时间是06:54: 2010-03-27 06:54:00.106。

boll 出现等待超时的数据库进程号是29：Oracle process number: 29。

boll 等待超时的29号进程的OS进程号为8317：Unix process pid: 8371。

boll 进程时通过SQLPlus调度执行的：MODULE NAME:(SQLPlus)。

boll 会话的ID、Serial#信息为120.46138：SESSION ID:(120.46138)。

boll 进程的State Object为6c10508e8：row cache enqueue: session: 6c10508e8。

boll 队列锁的请求模式为共享（S）：mode: N, request: S。

有了这些重要的信息，我们就可以开始一些基本的分析。

首先可以在跟踪文件中找到29号进程，查看其中的相关信息。经过检查可以发现这些内容与跟踪文件完全相符合：

PROCESS 29: ---------------------------------------- SO: 6c1006740, type: 2, owner: 0, flag: INIT/-/-/0x00 (process) Oracle pid=29, calls cur/top: 6c1097430/6c1096bf0, flag: (0) - int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 109 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: 8371 OSD pid info: Unix process pid: 8371, image: oracleEDW@SF2900

进一步向下检查可以找到SO对象6c10508e8，这里显示该进程确实由客户端的SQL*Plus发起，并且客户端的主机名称及进程的OSPID都记录在案：

SO: 6c10508e8, type: 4, owner: 6c1006740, flag: INIT/-/-/0x00 (session) sid: 120 trans: 6c285ea98, creator: 6c1006740, flag: (100041) USR/- BSY/-/-/-/-/- DID: 0001-001D-001BC795, short-term DID: 0000-0000-00000000 txn branch: 0 oct: 2, prv: 0, sql: 4f528d510, psql: 491cbe3e8, user: 56/CACI O/S info: user: Administrator, term: HOST03, ospid: 37692:38132, machine:　program: sqlplus.exe
application name: SQL*Plus, hash value=3669949024

接下来的信息显示，进程一直在等待，等待事件为'ksdxexeotherwait'：

last wait for 'ksdxexeotherwait' blocking sess=0x0 seq=36112 wait_time=5 seconds since wait started=3 =0, =0, =0 Dumping Session Wait History for 'ksdxexeotherwait' count=1 wait_time=5 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=5 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=3 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=5 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=4 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=3 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=4 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=4 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=3 =0, =0, =0 for 'ksdxexeotherwait' count=1 wait_time=3 =0, =0, =0 temporary object counter: 0

在这个进程跟踪信息的最后部分，有如下一个SO对象继承关系列表，注意这里的OWNER具有级联关系，下一层隶属于上一层的Owner，第一个SO对象的Owner 6c1006740就是PROCESS 29的SO号。

到了最后一个级别的SO 4e86f03e8上，请求出现阻塞。

Row cache enqueue有一个（count=1）共享模式（request=S）的请求被阻塞：

---------------------------------------- SO: 6c1096bf0, type: 3, owner: 6c1006740, flag: INIT/-/-/0x00 (call) sess: cur 6c10508e8, rec 6c10508e8, usr 6c10508e8; depth: 0 ---------------------------------------- SO: 6c1096eb0, type: 3, owner: 6c1096bf0, flag: INIT/-/-/0x00 (call) sess: cur 6c10508e8, rec 6c10691f8, usr 6c10508e8; depth: 1 ---------------------------------------- SO: 6c1097430, type: 3, owner: 6c1096eb0, flag: INIT/-/-/0x00 (call) sess: cur 6c10691f8, rec 6c10691f8, usr 6c10508e8; depth: 2 ---------------------------------------- SO: 4e86f03e8, type: 50, owner: 6c1097430, flag: INIT/-/-/0x00 row cache enqueue: count=1 session=6c10508e8 object=4f4e57138, request=S savepoint=0xf67b

回过头去对比一下跟踪文件最初的信息，注意这里的session信息正是跟踪文件头上列出的session信息：

>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<
row cache enqueue: session: 6c10508e8, mode: N, request: S

至此我们找到了出现问题的根源，这里也显示请求的对象是object=4f4e57138。

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

跟踪信息显示对象的锁定模式为排他锁定（mode=X）。图1-30是跟踪文件的截取，我们可以看到Oracle的记录方式：

进一步的，跟踪文件里也显示了29号进程执行的SQL为INSERT操作：

SO: 4f2e82c88, type: 53, owner: 6c10508e8, flag: INIT/-/-/0x00LIBRARY OBJECT LOCK: lock=4f2e82c88 handle=4f528d510 mode=Ncall pin=0 session pin=0 hpc=0000 hlc=0000htl=4f2e82d08[4f2de4dd8,4f2e844c0] htb=4e84c5db0 ssga=4e84c57c8user=6c10508e8 session=6c10508e8 count=1 flags=[0000] savepoint=0x4bad2ee7LIBRARY OBJECT HANDLE: handle=4f528d510 mtx=4f528d640(1) cdp=1name=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:54namespace=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=ffeclwt=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=4a7227a50type=CRSR flags=EXS[0001] pflags=[0000] status=VALD load=0CHILDREN: size=16　　child#　　table reference　 handle------ -------- --------- --------0 4a7227518 4a7227188 4ae9ed1f01 4a7227518 4a7227420 494cd5878DATA BLOCKS:　　　 data#　　 heap　pointer　　status pins change whr----- -------- -------- --------- ---- ------ ---0 4aebaa950 4a7227b68 I/P/A/-/-　　0 NONE　 00

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

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

　`javascript
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进程在执行什么操作呢？下面的信息可以看出一些端倪，JOB由DBMS_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的语句之所以不能成功完成，是因为该索引的相关数据表的数据量过为巨大。在Oracle 10g中，缺省的有一个任务定时进行分析，为用户提供空间管理建议，在进行空间建议前，Oracle会执行Shrink Space Check，这个检查工作和Shrink的具体内部工作完全相同，只是不执行具体的动作。这个Shrink Space的检查对于客户环境显得多余。现场解决这个问题，只需要将16号进程Kill掉，即可释放了锁定，后面的操作可以顺利进行下去。生成数据库出现问题时段的AWR报告，也可以辅助我们确定数据库的相关操作。如图1-31所示，Top 4 SQL都运行超过了3400秒而没有完成，第一个正是任务调度。![image](https://yqfile.alicdn.com/97dc0816029dcf3297be9d4325de092086d5dc32.png)相关的SQL简要列举如下：
**
call dbms_space.auto_space_advisor_job_proc ( )
alter index "CACI"."IDX_CACI_INV_BLB_DC" modify partition "P_2010_Q1" shrink space CHECK**
而如果你不关心空间建议，则可以取消这个定时任务，避免不必要的麻烦：exec**ute dbms_scheduler.disable('AUTO_SPACE_ADVISOR_JOB');**