通过一个问题，发现两个BUG，ORA-00240: 控制文件入队被持有的时间超过了 120 秒...

1、alert日志报错信息
 Sat Aug 25 02:02:05 2012
 Errors in file /u01/app/11.1.0/diag/rdbms/roadshow/roadshow1/trace/roadshow1_arc3_13131.trc  (incident=173321):
 ORA-00240: 控制文件入队被持有的时间超过了 120 秒
 Incident details in: /u01/app/11.1.0/diag/rdbms/roadshow/roadshow1/incident/incdir_173321/roadshow1_arc3_13131_i173321.trc
 Sat Aug 25 02:02:07 2012
 Trace dumping is performing id=[cdmp_20120825020207]
 Sat Aug 25 02:02:08 2012
 Sweep Incident[173321]: completed
 
2、/u01/app/11.1.0/diag/rdbms/roadshow/roadshow1/trace/roadshow1_arc3_13131.trc文件信息
 *** 2012-08-25 02:02:05.940
 ORA-00240: 控制文件入队被持有的时间超过了 120 秒
 
 
 *** 2012-08-25 02:02:41.532
 *** 2012-08-25 02:02:41.532 3333 kcrr.c
 kcrroda: calling ksfdrcres to create AL or RL
 *** 2012-08-25 02:02:41.601 3353 kcrr.c
 kcrroda: completed call to ksfdrcres
 *** 2012-08-25 03:00:13.299 3333 kcrr.c
 
 *** 2012-08-25 03:00:13.299
 kcrroda: calling ksfdrcres to create AL or RL
 *** 2012-08-25 03:00:13.311 3353 kcrr.c
 kcrroda: completed call to ksfdrcres
 *** 2012-08-25 05:00:01.103 3333 kcrr.c
 
 *** 2012-08-25 05:00:01.103
 kcrroda: calling ksfdrcres to create AL or RL
 *** 2012-08-25 05:00:01.120 3353 kcrr.c
 kcrroda: completed call to ksfdrcres
 *** 2012-08-25 06:00:14.574 3333 kcrr.c
 
3、/u01/app/11.1.0/diag/rdbms/roadshow/roadshow1/incident/incdir_173321/roadshow1_arc3_13131_i173321.trc文件信息
 *** 2012-08-25 02:02:05.941
 *** SESSION ID:(299.1) 2012-08-25 02:02:05.941
 *** CLIENT ID:() 2012-08-25 02:02:05.941
 *** SERVICE NAME:(SYS$BACKGROUND) 2012-08-25 02:02:05.941
 *** MODULE NAME:() 2012-08-25 02:02:05.941
 *** ACTION NAME:() 2012-08-25 02:02:05.941
 
 Dump continued from file: /u01/app/11.1.0/diag/rdbms/roadshow/roadshow1/trace/roadshow1_arc3_13131.trc
 ORA-00240: 控制文件入队被持有的时间超过了 120 秒
 
 ========= Dump for incident 173321 (ORA 240) ========
 ----- Beginning of Customized Incident Dump(s) -----
 -------------------------------------------------------------------------------
 CONTROL FILE ENQUEUE HELD FOR TOO LONG
 
       holding mode : S
     enqueue holder : 'inst 1, osid 13131'
  enqueue held time : 120 seconds
 
 The current process 'inst 1, osid 13131' holds the control file enqueue
 for more than 120 seconds.
 
 Oracle Support Services triaging information: to find the root-cause, look
 at the call stack of this process 'inst 1, osid 13131' below and ask
 the developer that owns the first NON-service layer in the stack above
 ksu_dispatch_tac to investigate. Common service layers are enqueues (ksq),
 latches (ksl) library cache pins and locks (kgl), and row cache locks (kqr).
 
 Internal debug info:
         type : 0
  acquired at : FILE krsa.c, LINE 792
 
 Dump of the process state:
 
 
 ----- Call Stack Trace -----
 calling              call     entry                argument values in hex     
 location             type     point                (? means dubious value)    
 -------------------- -------- -------------------- ----------------------------
 skdstdst()+28        call     kgdsdst()            000000000 ? 000000000 ?
                                                    7FFF5BDE79F0 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 ksedst1()+95         call     skdstdst()           000000000 ? 000000000 ?
                                                    7FFF5BDE79F0 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 kcc_tac_callback()+  call     ksedst1()            000000000 ? 000000000 ?
 1635                                               7FFF5BDE79F0 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 ksu_dispatch_tac()+  call     kcc_tac_callback()   2B6850F50678 ? 7FFF5BE0DB58 ?
 927                                                7FFF5BDE79F0 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 ksvcheckwait()+946   call     ksu_dispatch_tac()   2B6850F50678 ? 7FFF5BE0DB58 ?
                                                    7FFF5BDE79F0 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 ksvworkwait()+1725   call     ksvcheckwait()       2B6850F50678 ? 7FFF5BE0DB58 ?
                                                    7FFF5BDE79F0 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 ksvwait()+902        call     ksvworkwait()        05037C19A ? 000000000 ?
                                                    000000000 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 ksvsubmit()+4315     call     ksvwait()            0BE5C5880 ? 07FFFFFFF ?
                                                    000000000 ? 7FFF5BDE7AB8 ?
                                                    7FFF5BE07A10 ? 000000000 ?
 kfncSlaveSubmit()+4  call     ksvsubmit()          0800B0001 ? 000000000 ?
 79                                                 0BE5C5880 ? 07FFFFFFF ?
                                                    D00000000 ? 100000001 ?
 kfncFileIdentify()+  call     kfncSlaveSubmit()    7FFF5BE08FD8 ? 000000000 ?
 1106                                               007908E4C ? 07FFFFFFF ?
                                                    00000039D ? 000000011 ?
 kfioIdentify()+1457  call     kfncFileIdentify()   0BE5C5910 ? 0BE5C5880 ?
                                                    000000031 ? 000DA1951 ?
                                                    0BE5C58F8 ? 0BACE66B8 ?
 ksfd_osmopn()+969    call     kfioIdentify()       7FFF5BE09672 ? 000000031 ?
                                                    000DA1951 ? 000000200 ?
                                                    000000003 ? 0BACE6698 ?
 ksfdopn()+3637       call     ksfd_osmopn()        7FFF5BE09672 ? 000000031 ?
                                                    000000200 ? 000000003 ?
                                                    000000000 ? 0BF586700 ?
 kcropn()+661         call     ksfdopn()            7FFF5BE09672 ? 000000031 ?
                                                    000000200 ? 000000003 ?
                                                    000000000 ? 0BF586700 ?
 kcroio()+9           call     kcropn()             000000000 ? 7FFF5BE09BD8 ?
                                                    000000000 ? 000000000 ?
                                                    000000000 ? 100000000 ?
 kcrrgfi()+396        call     kcroio()             000000000 ? 7FFF5BE09BD8 ?
                                                    000000000 ? 000000000 ?
                                                    000000000 ? 100000000 ?
 kcrrprep()+193       call     kcrrgfi()            000000000 ? 7FFF5BE0DB58 ?
                                                    7FFF5BE0DAD8 ? 000000007 ?
                                                    2B6800000200 ? 2B68508DD84C ?
 kcrrdmx()+1049       call     kcrrprep()           000000000 ? 7FFF5BE0DB58 ?
                                                    2B68508DD780 ? 000000007 ?
                                                    2B6800000200 ? 2B68508DD84C ?
 kcrrdim()+257        call     kcrrdmx()            000000000 ? 000000007 ?
                                                    2B68508DD780 ? 000000000 ?
                                                    2B6800000200 ? 7FFF5BE0A6D0 ?
 kcrrwkx()+3240       call     kcrrdim()            7FFF5BE0DB58 ? 000000007 ?
                                                    7FFF5BE0DAD8 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 kcrrwk()+219         call     kcrrwkx()            7FFF5BE0E200 ? 000000028 ?
                                                    7FFF5BE0DAD8 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 ksbabs()+762         call     kcrrwk()             7FFF5BE0E200 ? 000000028 ?
                                                    7FFF5BE0DAD8 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 ksbrdp()+1487        call     ksbabs()             7FFF5BE0E200 ? 000000028 ?
                                                    7FFF5BE0DAD8 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 opirip()+609         call     ksbrdp()             7FFF5BE0E200 ? 000000028 ?
                                                    7FFF5BE0DAD8 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 opidrv()+554         call     opirip()             000000032 ? 000000004 ?
                                                    7FFF5BE0F348 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 sou2o()+90           call     opidrv()             000000032 ? 000000004 ?
                                                    7FFF5BE0F348 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 opimai_real()+275    call     sou2o()              7FFF5BE0F320 ? 000000032 ?
                                                    000000004 ? 7FFF5BE0F348 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 ssthrdmain()+177     call     opimai_real()        000000000 ? 7FFF5BE0F4C0 ?
                                                    000000004 ? 7FFF5BE0F348 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 main()+215           call     ssthrdmain()         000000003 ? 7FFF5BE0F4C0 ?
                                                    000000004 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 __libc_start_main()  call     main()               000000003 ? 7FFF5BE0F628 ?
 +244                                               000000004 ? 000000000 ?
                                                    000000000 ? 7FFF5BE0DC2C ?
 _start()+41          call     __libc_start_main()  000937DB8 ? 000000001 ?
                                                    7FFF5BE0F628 ? 000000000 ?
                                                    000000000 ? 000000003 ?
 ----- End of Call Stack Trace -----
 Current Wait Stack:
  1: waiting for 'KSV master wait'
     =0, =0, =0
     wait_id=3647 seq_num=3833 snap_id=1
     wait times: snap=2 min 3 sec, exc=2 min 3 sec, total=2 min 3 sec
     wait times: max=infinite
     wait counts: calls=41 s=41
     in_wait=1 iflags=0x15a0
  0: waiting for 'ASM file metadata operation'
     msgop=11, locn=0, =0
     wait_id=3644 seq_num=3832 snap_id=2
     wait times: snap=0.000000 sec, exc=0.000006 sec, total=2 min 3 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     in_wait=1 iflags=0x1520
 There is at least one session blocked by this session.
 Dumping one waiter:
   inst: 2, sid: 300, ser: 1
   wait event: 'enq: CF - contention'
     p1: 'name|mode'=0x43460005
     p2: '0'=0x0
     p3: 'operation'=0x0
   row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
   min_blocked_time: 111 secs, waiter_cache_ver: 5091
 Wait State:
   auto_close=0 flags=0x22 boundary=(nil)/-1
 Session Wait History:
  0: waited for 'ASM file metadata operation'
     msgop=11, locn=0, =0
     wait_id=3644 seq_num=3832 snap_id=2
     wait times: snap=0.000003 sec, exc=0.000006 sec, total=0.094823 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000000 sec of elapsed time
  1: waited for 'KSV master wait'
     =0, =0, =0
     wait_id=3645 seq_num=3831 snap_id=2
     wait times: snap=0.000053 sec, exc=0.000155 sec, total=0.094817 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000000 sec of elapsed time
  2: waited for 'os thread startup'
     =0, =0, =0
     wait_id=3646 seq_num=3830 snap_id=1
     wait times: snap=0.094662 sec, exc=0.094662 sec, total=0.094662 sec
     wait times: max=2 min 0 sec
     wait counts: calls=1 s=1
     occurred after 0.000000 sec of elapsed time
  3: waited for 'KSV master wait'
     =0, =0, =0
     wait_id=3645 seq_num=3829 snap_id=1
     wait times: snap=0.000102 sec, exc=0.000102 sec, total=0.000102 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000000 sec of elapsed time
  4: waited for 'ASM file metadata operation'
     msgop=11, locn=0, =0
     wait_id=3644 seq_num=3828 snap_id=1
     wait times: snap=0.000003 sec, exc=0.000003 sec, total=0.000003 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000056 sec of elapsed time
  5: waited for 'control file sequential read'
     file#=0, block#=71, blocks=1
     wait_id=3643 seq_num=3827 snap_id=1
     wait times: snap=0.000266 sec, exc=0.000266 sec, total=0.000266 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000011 sec of elapsed time
  6: waited for 'control file sequential read'
     file#=0, block#=2d, blocks=1
     wait_id=3642 seq_num=3826 snap_id=1
     wait times: snap=0.000197 sec, exc=0.000197 sec, total=0.000197 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000008 sec of elapsed time
  7: waited for 'control file sequential read'
     file#=0, block#=2b, blocks=1
     wait_id=3641 seq_num=3825 snap_id=1
     wait times: snap=0.000254 sec, exc=0.000254 sec, total=0.000254 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000010 sec of elapsed time
  8: waited for 'control file sequential read'
     file#=0, block#=29, blocks=1
     wait_id=3640 seq_num=3824 snap_id=1
     wait times: snap=0.000200 sec, exc=0.000200 sec, total=0.000200 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000005 sec of elapsed time
  9: waited for 'control file sequential read'
     file#=0, block#=27, blocks=1
     wait_id=3639 seq_num=3823 snap_id=1
     wait times: snap=0.000206 sec, exc=0.000206 sec, total=0.000206 sec
     wait times: max=infinite
     wait counts: calls=0 s=0
     occurred after 0.000006 sec of elapsed time
 Sampled Session History
 ---------------------------------------------------
 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
 ---------------------------------------------------
 Enqueue blocker waiting on 'KSV master wait'
 Dumping global systemstates of the ASM instances, check DIAG traces under the ASM instances.
 ----- End of Customized Incident Dump(s) -----

问题分析：
 从MOS上查询得知，上面两个问题是两个数据库BUG，并给出如下具体的解决办法
 a.对于上面第二点MOS给出的解释和问题解决办法[BUG ID 754289.1]：
 Cause
 As per Bug 6910132 some diagnostic code was left in by mistake causing these unnecessary trace files to be generated.
 
 Solution
 This bug is fixed in Oracle 11.2.
 
 Alternatively, you can apply a one off for Bug 6910132 (if available for your platform)  
 OR 
 You can ignore the trace files and/or implement some means to remove them from your system.  For example:
 
 1.  Use the ADR Command Interpreter (ADRCI) to set a lower retention policy to clean up this diagnostic data more often. 
 2.  Code a shell script. and use cron to run and remove ARC files periodically.
 
 b.对于上面第三点MOS给出的解释和问题解决办法[BUG ID 1308282.1]：
 Cause
 Event 'KSV master wait' indicates the process on the RDBMS side is waiting for a reply from a process on the ASM side.   In 11g, the parameter cell_offload_processing is set to TRUE.  Although that is a parameter is not applicable for non-Exadata databases, it caused ASM to try to deliver smart-scan results.   The issue was reported in Bug 11800170 - ASM IN KSV WAIT AFTER APPLICATION OF 11.2.0.2 GRID PSU.

 Solution
 The following solutions are available for non-Exadata databases:
 
 1.For the quickest solution, use the workaround.  The workaround does not negatively impact non-Exadata databases.
  alter system set cell_offload_processing = false;
 2.Upgrade to 12.1, when available.
 3.Apply the 11.2.0.3 patch set
 4.Apply one-off Patch 11800170, if available for your RDBMS and Grid Homes

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/27471208/viewspace-742010/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/27471208/viewspace-742010/