ORA-27041 unable to open file

xteitxu

windows 2008 平台  
11.1.0.6.0
数据库 有两个归档路径，下面提示找不到归档的路径中的归档，会每隔一个小时备份并清空到备份机。但是alter偶尔会报以下的错误。为什么oracle会去
scan这些这引起归档呢？

Exception [type: ACCESS_VIOLATION, UNABLE_TO_READ] [ADDR:0x137C0000] [PC:0x6023CFA, {empty}]
Errors in file c:\app\administrator\diag\rdbms\newpro\newpro\trace\newpro_ora_3668.trc  (incident=69485):
ORA-07445: exception encountered: core dump [PC:0x6023CFA] [ACCESS_VIOLATION] [ADDR:0x137C0000] [PC:0x6023CFA] [UNABLE_TO_READ] []
Incident details in: c:\app\administrator\diag\rdbms\newpro\newpro\incident\incdir_69485\newpro_ora_3668_i69485.trc
Tue Feb 28 09:18:54 2012
Errors in file c:\app\administrator\diag\rdbms\newpro\newpro\incident\incdir_69485\newpro_ora_3668_i69485.trc:
OSD-04002: 无法打开文件
O/S-Error: (OS 2) 系统找不到指定的文件。
ORA-00308: cannot open archived log 'D:\ARCH\newpro\newpro_ARC22640_0714939739.001'
ORA-27041: unable to open file
OSD-04002: 无法打开文件
O/S-Error: (OS 2) 系统找不到指定的文件。
ORA-00308: cannot open archived log 'D:\ARCH\newpro\newpro_ARC22639_0714939739.001'
ORA-27041: unable to open file
OSD-04002: 无法打开文件
O/S-Error: (OS 2) 系统找不到指定的文件。
ORA-00308: cannot open archived log 'D:\ARCH\newpro\newpro_ARC22638_0714939739.001'
ORA-27041: unable to open file
OSD-04002: 无法打开文件
O/S-Error: (OS 2) 系统找不到指定的文件。
ORA-00308: cannot open archived log 'D:\ARCH\newpro\newpro_ARC22637_0714939739.001'
ORA-27041: unable to open file
OSD-04002: 无法打开文件
O/S-Error: (OS 2) 系统找不到指定的文件。
ORA-00308: cannot open archived log 'D:\ARCH\newpro\newpro_ARC22636_0714939739.001'
ORA-27041: unable to open file
OSD-04002: 无法打开文件
O/S-Error: (OS 2) 系统找不到指定的文件。
ORA-00308: cannot open archived log '


newpro_ora_3668_i69485_trc.zip (825.28 KB, 下载次数: 1306)

2012-2-29 16:35 上传

点击文件名下载附件

Maclean Liu(刘相兵

请打包后上传 alert.log 和 \newpro_ora_3668.trc

xteitxu

其实，这个错误我是可以避免的，不去清空那个归档目录就可以了。但现在就是不清楚为什么oracle会去find之前已经生成的归档，如果找到，会做什么操作吗？

Maclean Liu(刘相兵

ODM Finding:

1. [Kgghash()+428] [Access_violation] REPORTED IN ALERT LOG [ID 732550.1]
   
2. 
   
3. Applies to:
   
4. Oracle Server - Enterprise Edition - Version: 11.1.0.6 to 11.1.0.7 - Release: 11.1 to 11.1
   
5. Information in this document applies to any platform.
   
6. Oracle Server Enterprise Edition - Version: 11.1.0.6 to 11.1.0.7
   
7. Symptoms
   
8. This article is written specifically for 7445[kgghash()] when seen in conjunction with the following
   
9. symptoms :-
   
10. 
    
11. a) Message in alert log will be similar to :-
    
12. 
    
13. ORA-07445: exception encountered: core dump [kgghash()+428]
    
14. [ACCESS_VIOLATION] [ADDR:0xE180000][PC:0x5CA3D60]
    
15. [UNABLE_TO_READ] []
    
16. 
    
17. b) Stack will be similar to :-
    
18. 
    
19. Function List (to Full stack) (to Summary stack)
    
20. kgghash <- kkocsCreateBindSet <- kkocsStoreBindAwareStats <- kkocsCheckBindAware
    
21. <- kksumc <- opiexe <- opipls <- opiodr <- rpidrus <- rpidru <- rpiswu2
    
22. <- rpidrv <- psddr0 <- psdnal
    
23. <- pevm_EXECC <- pfrinstr_EXECC <- pfrrun_no_tool <- pfrrun <- plsql_run
    
24. <- peicnt <- kkxexe <- opiexe <- opiall0 <- opial7
    
25. <- opiodr <- ttcpip <- opitsk <- opiino <- opiodr
    
26. <- VInfreq__opirip <- opidrv <- sou2o <- opimai_real <- opimai
    
27. <- BackgroundThreadStart
    
28. 
    
29. c) In the trace we see :-
    
30. 
    
31. _kkocsCreateBindSet CALLrel _kgghash()+0 xxxxxx 1F40 xxxxxx
    
32. 
    
33. 1F40 is a key value here
    
34. Cause
    
35. 
    
36. If the above symptoms are seen unpublished Bug 7352414 is the likely cause but to make
    
37. this conclusion other bugs need to be referred to.
    
38. Solution
    
39. 
    
40. 
    
41. Bug 6650766 reports :-
    
42. 
    
43. It appears that we are passing in 8000 (1F40) when the buffer length is less (4000).
    
44. bnd.kxsbplen is 8000 and is avl.
    
45. 
    
46. A trace file can be searched for the 'current cursor' and then the bind values for that
    
47. cursor can be reviewed :-
    
48. 
    
49. Bind#2
    
50. oacdty=01 mxl=4001(4672) mxlc=00 mal=00 scl=00 pre=00
    
51. oacflg=13 fl2=206001 frm=01 csi=31 siz=4000 off=0
    
52. kxsbbbfp=0e17ed10 bln=4000 avl=8000 flg=09
    
53. value="<User><EmployeeSysID>660</EmployeeSysID><FirstName>PRO</FirstName&
    
54. gt;<LastName>052P_01</LastName><LastLogin>08/11/2008
    
55. 09:02A</LastLogin><SessionID>000006779E66EC91DC43EBB06DC2F6FA17AA75</SessionID><
    
56. ;/User><NavigationPanelOn></NavigationPanelOn><SystemName>Ce"...
    
57. 
    
58. So in summary if we see ORA-7445[KGGHASH] where 1F40 is seen in the call from kkocsCreateBindSet and we see a bind showing bln=4000 avl=8000
    
59. we are likely to be facing this bug.
    
60. 
    
61. It should be noted that analysis on Bug 6650766 comes to a halt but similar symptoms
    
62. were filed under Bug 7343776  which was confirmed to be a duplicate of
    
63. unpublished Bug 7352414.
    
64. 
    
65. It was initially mentioned under Bug 6650766  that some diagnostics patch would
    
66. need to be written but this position has changed.
    
67. 
    
68. unpublished Bug 7352414
    
69. 
    
70. This issue is fixed in 11.2.0.1 (Base Release)
    
71. 11.1.0.7.1 (Patch Set Update)
    
72. 11.1.0.7 Patch 2 on Windows Platforms
    
73. 11.1.0.7 Generic Recommended Patch Bundle
    
74. 
    
75. Note that this fix has been superseded by the fix in unpublished Bug 8763922
    
76. 
    
77. 
    
78. unpublished Bug 8763922
    
79. 
    
80. This issue is fixed in 12.1 (Future Release)
    
81. 11.2.0.2 (Server Patch Set)
    
82. 11.2.0.1 Bundle Patch 9 for Exadata Database
    
83. 11.1.0.7.5 (Patch Set Update)
    
84. 11.1.0.7 Patch 23 on Windows Platforms
    
85. 
    
86. This fix is really just an extension to the fix for  to also cover the same scenario for RAW binds.
    
87. 
    
88. Solution
    
89. 
    
90. Apply the patch 8763922 if available
    
91. 
    
92. OR
    
93. 
    
94. Try the following workaround:
    
95. 
    
96. Disabling bind peeking.
    
97. 
    
98. This would be enabled via setting :-
    
99. 
    
100. _optim_peek_user_binds=false
     
101. References
     
102. BUG:7343776 - INTERMITTENT 7445[KGGHASH] THAT SEEMS TO LINK TO BUG:6650766
     
103. BUG:6650766 - ORA-07445: EXCEPTION ENCOUNTERED: CORE DUMP [KGGHASH()+428] [ACCESS_V

复制代码

Maclean Liu(刘相兵

ODM Data:

正在运行的SQL语句：

*** 2012-02-28 09:18:24.661
----- Current SQL Statement for this session (sql_id=66u8z4rpn0351) -----
UPDATE SYM_USRGRID SET UPDBY=:1, UPDDT=:2, CLIENTLAYOUT=:3, COND1=:4, COND2=:5, FDESC=:6 WHERE USRID=:7 AND OBJID=:8 AND CTLID=:9


相关的stack call

*** 2012-02-28 09:18:24.692
06023CFA                      00000000
_kkocsCreateBindSet  CALLrel  _kgghash()+0         137BF060 FA1 6FB5F800
()+496
_kkocsStoreBindAwar  CALLrel  _kkocsCreateBindSet
eStats()+752                  ()+0
_kkocsCheckBindAwar  CALLrel  _kkocsStoreBindAwar
e()+81                        eStats()+0
_kksumc()+1896       CALLrel  _kkocsCheckBindAwar  AAC9A8FC 11510218
                              e()+0
_opiexe()+7469       CALLrel  _kksumc()+0          11510218 2
_kpoal8()+2299       CALLrel  _opiexe()+0          49 3 168CC7F0
_opiodr()+1224       CALLreg  00000000             5E 1C 168CF1E0


_kkocsCheckBindAware=> _kkocsStoreBindAware = > _kkocsCreateBindSet  

这个几个函数 显然是在做  11g bind aware cursor 即 adaptive cursor sharing 自适应游标，

建议通过 设置 _optim_peek_user_binds=false   禁用绑定窥视来绕过该问题， 也建议 禁用 11g的 adaptive cursor sharing

Maclean Liu(刘相兵

Errors in file c:\app\administrator\diag\rdbms\newpro\newpro\incident\incdir_69485\newpro_ora_3668_i69485.trc:
OSD-04002: 无法打开文件
O/S-Error: (OS 2) 系统找不到指定的文件。
ORA-00308: cannot open archived log 'D:\ARCH\newpro\newpro_ARC22640_0714939739.001'
ORA-27041: unable to open file


"不清楚为什么oracle会去find之前已经生成的归档"


END OF PINNED BUFFER HISTORY
kcbdnbRedoRelevantComponent: short stack dump in question: *** WARNING: Unable to skip initial frames
short stack dump to trace:
*** WARNING: Unable to skip initial frames
end short stack dump to trace
*** timestamp before redo dump: 02/28/2012 09:18:25
***********************************************
* Dump Online Redo for Buffers in Pin History *
***********************************************
$$$$$$$ Dump Online Redo for DBA list (tsn.rdba in hex):


*** 2012-02-28 09:18:30.027
*Error 308 when opening Archive Log -
D:\ARCH\newpro\newpro_ARC22632_0714939739.001 at SCN: scn: 0x0000.7439813a (1949925690)
*Error is non fatal for dump - Dump will continue
descrip:"Thread 0001, Seq# 0000022632, SCN 0x00007439813a-0x0000743984a6"
*Error 308 when opening Archive Log -
D:\ARCH\newpro\newpro_ARC22633_0714939739.001 at SCN: scn: 0x0000.743984a6 (1949926566)
*Error is non fatal for dump - Dump will continue
descrip:"Thread 0001, Seq# 0000022633, SCN 0x0000743984a6-0x0000743984e7"

*** 2012-02-28 09:18:30.885
*Error 308 when opening Archive Log -
D:\ARCH\newpro\newpro_ARC22634_0714939739.001 at SCN: scn: 0x0000.743984e7 (1949926631)
*Error is non fatal for dump - Dump will continue
descrip:"Thread 0001, Seq# 0000022634, SCN 0x0000743984e7-0x00007439a664"

REDO RECORD - Thread:1 RBA: 0x00586f.00012e4d.012c LEN: 0x0048 VLD: 0x01
SCN: 0x0000.7439f2e8 SUBSCN:  1 02/28/2012 00:12:24
CHANGE #1 MEDIA RECOVERY MARKER SCN:0x0000.00000000 SEQ:  0 OP:18.3
Reuse redo entry
Range reuse: tsn=2 base=12588553 nblks=128
*Error 308 when opening Archive Log -
D:\ARCH\newpro\newpro_ARC22640_0714939739.001 at SCN: scn: 0x0000.7439f364 (1949954916)
*Error is non fatal for dump - Dump will continue
descrip:"Thread 0001, Seq# 0000022640, SCN 0x00007439f364-0x00007439f99f"



Reuse redo entry  Range reuse

这是因为该bug 的触发 引起了 服务进程对 Online Redo 的dump ，当 oracle进程意识到内存中可能存在corrupt block时，它会启动对archivelogs的转储，作为诊断工作的一部分。


“DBWR detects a corrupt block in memory. It starts dumping the ARCHIVELOGs as
part of diagnosability framework.

It took almost 40 minutes to dump 34 ARCHIVELOGs. While creating the trace
file, the DB frozen and 'checkpoint not complete' msg was reported in the
alert log.

There were a number of other error in the alert log that we suspect of memory
corruption took place on the same time, since the DB was restarted and
validated and no corruption were found。


REDO RECORD - Thread:1 RBA: 0x04fae1.003ad654.01dc LEN: 0x0048 VLD: 0x01
SCN: 0x0766.fec316e5 SUBSCN: 2 09/03/2009 19:44:01
CHANGE #1 MEDIA RECOVERY MARKER SCN:0x0000.00000000 SEQ: 0 OP:18.3 ENC:0
Reuse redo entry
Range reuse: tsn=226 base=3926004036 nblks=5

REDO RECORD - Thread:1 RBA: 0x04fae1.003b5d91.0108 LEN: 0x0048 VLD: 0x01
SCN: 0x0766.fec40489 SUBSCN: 2 09/03/2009 19:44:16
CHANGE #1 MEDIA RECOVERY MARKER SCN:0x0000.00000000 SEQ: 0 OP:18.3 ENC:0
Reuse redo entry
Range reuse: tsn=1 base=387549449 nblks=512

During the same period, the database reported a 'checkpoint not complete' in
the alert log

”Hdr: 9143376 11.1.0.7.0 RDBMS 11.1.0.7.0 RECOVERY PRODID-5 PORTID-23
Abstract: DBWR FROZEN DB WHILE DUMPING ARCHIVELOGS FOR A CORRUPT BLOCK

xteitxu

非常感谢maclean对我的问题的分析。分析得好透彻，学习了！

xteitxu

maclean,这种bug对系统影响大吗？会把数据库给crash了吗？

Maclean Liu(刘相兵

建议你测试 禁用 绑定变量窥视是否会对 现有SQL造成 执行计划偏差的问题， 如果没有的话 建议设置 _optim_peek_user_binds=false 并 禁用 11g的 adaptive cursor sharing。

该问题造成 oracle process crash，可能伴随 memory corruption 属于 轻微严重的影响。

xteitxu

非常感谢maclean！