admin – 第67页 – Database SOS

CURSOR_SHARING=SIMILAR引起的悲剧

一个客户反馈说有一系统经常性负载比较高,让我帮忙分析原因
系统负载情况

[oracle@zwq-kfdialdb ~]$ top -c
top - 17:11:06 up 78 days,  1:12,  5 users,  load average: 124.83, 125.90, 112.13
Tasks: 836 total, 152 running, 684 sleeping,   0 stopped,   0 zombie
Cpu(s): 98.1%us,  0.1%sy,  0.0%ni,  1.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  132070908k total, 90494280k used, 41576628k free,  1147384k buffers
Swap: 67108856k total,        0k used, 67108856k free, 79109904k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
12179 oracle    15   0 32.5g 142m 139m R 39.0  0.1   6:09.20 oracleahdial (LOCAL=NO)
11530 oracle    16   0 32.5g 469m 466m R 36.1  0.4  11:14.23 oracleahdial (LOCAL=NO)
11816 oracle    15   0 32.5g 467m 463m R 36.1  0.4   6:33.86 oracleahdial (LOCAL=NO)
11577 oracle    15   0 32.5g 480m 477m R 34.7  0.4   7:15.98 oracleahdial (LOCAL=NO)
12136 oracle    16   0 32.5g 455m 452m R 31.9  0.4   9:07.88 oracleahdial (LOCAL=NO)
11237 oracle    16   0 32.5g 997m 992m R 31.2  0.8  20:53.50 oracleahdial (LOCAL=NO)
11427 oracle    16   0 32.5g 137m 135m R 31.2  0.1  11:50.16 oracleahdial (LOCAL=NO)
12051 oracle    16   0 32.5g 459m 456m R 31.2  0.4   6:12.67 oracleahdial (LOCAL=NO)
[oracle@zwq-kfdialdb ~]$ vmstat 3 10
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
137  0      0 41566600 1147384 79109888    0    0     0     3    0    0  0  0 99  0  0
146  0      0 41567548 1147384 79109888    0    0     0    47 1058 32190 98  0  2  0  0
150  0      0 41568056 1147384 79109888    0    0     0    39 1081 31543 98  0  2  0  0
12  0      0 41568464 1147384 79109888    0    0     0    23 1056 32111 98  0  2  0  0
62  0      0 41568776 1147384 79109888    0    0     0    11 1067 31474 98  0  2  0  0
108  0      0 41568304 1147384 79109888    0    0     0    39 1059 31193 98  0  2  0  0
140  0      0 41569280 1147384 79109888    0    0     0    48 1063 31171 98  0  2  0  0
140  0      0 41569444 1147384 79109888    0    0     0    40 1075 30508 98  0  2  0  0

通过top和vmstat看出系统现在负载很高,主要都是用户进程导致.

查询等待事件

SQL> select event from v$session where wait_class#<>6;
EVENT
----------------------------------------------------------------
cursor: mutex S
SQL> /
EVENT
----------------------------------------------------------------
cursor: mutex S
SQL> /
EVENT
----------------------------------------------------------------
cursor: mutex S
SQL> /
EVENT
----------------------------------------------------------------
cursor: mutex S
SQL> SELECT a.*, s.sql_text
  2    FROM v$sql s,
  3         (SELECT sid,
  4                 event,
  5                 wait_class,
  6                 p1 cursor_hash_value,
  7                 p2raw Mutex_value,
  8                 TO_NUMBER (SUBSTR (p2raw, 1, 8), 'xxxxxxxx') hold_mutex_x_sid
  9            FROM v$session_wait
 10           WHERE event LIKE 'cursor%') a
 11   WHERE s.HASH_VALUE = a.cursor_hash_value
 12  /
no rows selected
SQL>  select event from v$session where wait_class#<>6;
EVENT
----------------------------------------------------------------
SQL*Net message to client

数据库开始的等待事件只有cursor: mutex S,等该等待事件消失后系统负载也恢复正常

再次查看系统负载

[oracle@zwq-kfdialdb ~]$ top -c -i10
top - 17:13:51 up 78 days,  1:15,  6 users,  load average: 12.57, 78.21, 96.45
Tasks: 702 total,   2 running, 700 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.5%us,  0.2%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  132070908k total, 86477808k used, 45593100k free,  1147500k buffers
Swap: 67108856k total,        0k used, 67108856k free, 79116036k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
15045 oracle    16   0 13136 1476  724 R 10.6  0.0   0:00.12 top -c -i10
10010 root      10  -5     0    0    0 D  0.0  0.0   0:00.68 [kondemand/4]
10019 root      10  -5     0    0    0 D  0.0  0.0   1:41.58 [kondemand/13]
10020 root      10  -5     0    0    0 D  0.0  0.0   1:52.28 [kondemand/14]
10021 root      10  -5     0    0    0 R  0.0  0.0   2:01.54 [kondemand/15]
12166 root      24   0 10084  300  216 D  0.0  0.0   0:00.00 /opt/VRTSgab/gablogd
[oracle@zwq-kfdialdb ~]$  vmstat 3 10
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 45484264 1147528 79117360    0    0     0     3    0    0  0  0 99  0  0
 2  0      0 45468452 1147528 79117456    0    0     4   161 1372 5369  2  2 97  0  0
 3  0      0 45463712 1147528 79117584    0    0     4   187 1602 7253  6  0 93  0  0
 1  0      0 45458220 1147528 79117648    0    0     1    99 1358 5821  2  0 98  0  0
 0  0      0 45475168 1147528 79117712    0    0     0    41 1321 5321  2  0 98  0  0
 0  0      0 45473624 1147528 79117744    0    0     3   104 1378 5455  2  0 98  0  0
 2  0      0 45474656 1147528 79117776    0    0     0    55 1196 4872  1  0 99  0  0
 0  0      0 45474376 1147532 79117824    0    0     8   113 1170 4990  2  0 98  0  0
 1  0      0 45475440 1147532 79117872    0    0     1    56 1187 5301  3  0 97  0  0
 1  0      0 45475824 1147532 79117888    0    0     3    99 1083 4643  3  0 97  0  0

结合上面的等待事件查询,我们可以大概评估出来,当cursor: mutex S等待消失后,系统负载也恢复正常,现在已经不存在环境,如果要找出问题只能够是借助AWR和ASH

分析ASH
Top User Events

Top SQL with Top Events

Activity Over Time

通过对ASH分析,可以大概确定,在这段时间内,引起系统负载高主要是cursor: mutex S导致

分析AWR
awr整体信息(从这里看数据库是相当的繁忙)

Load Profile(从这里看数据库业务比较小)

Top 5 Timed Foreground Events(主要等待事件cursor: mutex S,和前面分析相符)

OS LOAD(虽然和系统看到有一定出入,但是整体还是展示系统负载较高)

SQL ordered by Version Count(出现cursor: mutex S,因为load profile中解析不多,所以想到高版本问题,这里确实非常高)

通过这里的一些列分析,我们已经基本上可以确定,该数据库因为高版本问题导致cursor: mutex S以及library cache 相关等待严重,从而出现系统负载过高.

找出高版本原因
高版本相关信息和查询请见:关于High Versions Count总结

SQL> select * from table(version_rpt('f8b9tba7sfsb5'));
COLUMN_VALUE
--------------------------------------------------------------------------------
Version Count Report Version 3.2.1 -- Today's Date 19-jul-12 18:13
RDBMS Version :11.2.0.1.0 Host: zwq-kfdialdb Instance 1 : ahdial
==================================================================
Addr: 000000080FA4CEA0  Hash_Value: 2408014181  SQL_ID f8b9tba7sfsb5
Sharable_Mem: 206315729 bytes   Parses: 48689
Stmt:
0 select count(*) as col_0_0_ from TBL_SP_SALES_RECORDS tblspsales
1 0_ where tblspsales0_.SALES_RECORDS_STATUS=:"SYS_B_0" and tblsps
2 ales0_.MOBILE_TELE_NO=:"SYS_B_1"
3
COLUMN_VALUE
--------------------------------------------------------------------------------
Versions Summary
----------------
AUTH_CHECK_MISMATCH :4
TRANSLATION_MISMATCH :4
ROLL_INVALID_MISMATCH :10219
PURGED_CURSOR :9
Total Versions:10219
Plan Hash Value Summary
-----------------------
COLUMN_VALUE
--------------------------------------------------------------------------------
Plan Hash Value Count
=============== =====
      791727930 920
     2820478500 9300
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for AUTH_CHECK_MISMATCH :
  # of Ver PARSING_USER_ID PARSING_SCHEMA_ID PARSING_SCHEMA_NAME
========== =============== ================= ===================
     10218               75                75 HOLLYSP
COLUMN_VALUE
--------------------------------------------------------------------------------
         2              107               107 HOLLYSP_TEST
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for TRANSLATION_MISMATCH :
Summary of objects probably causing TRANSLATION_MISMATCH
  Object# Owner.Object_Name
========= =================
    76737 HOLLYSP.TBL_SP_SALES_RECORDS
 HOLLYSP.TBL_SP_SALES_RECORDS
 HOLLYSP_TEST.TBL_SP_SALES_RECORDS
COLUMN_VALUE
--------------------------------------------------------------------------------
   107043 HOLLYSP_TEST.TBL_SP_SALES_RECORDS
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for ROLL_INVALID_MISMATCH :
No details available
~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for PURGED_CURSOR :
No details available
####
To further debug Ask Oracle Support for the appropiate level LLL.
COLUMN_VALUE
--------------------------------------------------------------------------------
alter session set events
 'immediate trace name cursortrace address 2408014181, level LLL';
To turn it off do use address 1, level 2147483648
================================================================
59 rows selected.
SQL> select * from table(version_rpt('6zhjf3qh8gyp9'));
COLUMN_VALUE
--------------------------------------------------------------------------------
Version Count Report Version 3.2.1 -- Today's Date 19-jul-12 18:15
RDBMS Version :11.2.0.1.0 Host: zwq-kfdialdb Instance 1 : ahdial
==================================================================
Addr: 00000007FD46D2A8  Hash_Value: 2693266089  SQL_ID 6zhjf3qh8gyp9
Sharable_Mem: 111904227 bytes   Parses: 4880
Stmt:
0 select count(*) as col_0_0_ from TBL_SP_SALES_RECORDS tblspsales
1 0_ where tblspsales0_.SALES_RECORDS_STATUS=:"SYS_B_0" and tblsps
2 ales0_.CAMPAIGN_ID=:"SYS_B_1" and tblspsales0_.IS_CONN=:"SYS_B_2
3 " and tblspsales0_.SALES_TIME>=:"SYS_B_3" and tblspsales0_.SALES
4 _PERSON=:"SYS_B_4"
COLUMN_VALUE
--------------------------------------------------------------------------------
5
Versions Summary
----------------
BIND_MISMATCH :4804
INCOMP_LTRL_MISMATCH :372
HASH_MATCH_FAILED :4936
Total Versions:4935
Plan Hash Value Summary
COLUMN_VALUE
--------------------------------------------------------------------------------
-----------------------
Plan Hash Value Count
=============== =====
     1645985080 3
     2040125427 4933
~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for BIND_MISMATCH :
Consolidated details for :
BIND_MISMATCH,USER_BIND_PEEK_MISMATCH,BIND_UACS_DIFF and
COLUMN_VALUE
--------------------------------------------------------------------------------
BIND_EQUIV_FAILURE (Mislabled as ROW_LEVEL_SEC_MISMATCH BY bug 6964441 in 11gR1)
from v$sql_bind_capture
COUNT(*) POSITION MIN(MAX_LENGTH) MAX(MAX_LENGTH) DATATYPE (PRECISION,SCALE)
======== ======== =============== =============== ======== ================
    4936        1              32              32        1 (,)
    4936        2              32              32        1 (,)
    4936        3              32              32        1 (,)
    4936        4              32              32        1 (,)
    4936        5              32              32        1 (,)
COLUMN_VALUE
--------------------------------------------------------------------------------
SUM(DECODE(column,Y, 1, 0) FROM V$SQL
IS_OBSOLETE IS_BIND_SENSITIVE IS_BIND_AWARE IS_SHAREABLE
=========== ================= ============= ============
          0              4309             0         4309
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for INCOMP_LTRL_MISMATCH :
No details available
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Details for HASH_MATCH_FAILED :
COLUMN_VALUE
--------------------------------------------------------------------------------
No details available
####
To further debug Ask Oracle Support for the appropiate level LLL.
alter session set events
 'immediate trace name cursortrace address 2693266089, level LLL';
To turn it off do use address 1, level 2147483648
================================================================
62 rows selected.

根据经验,出现这么多的高版本情况,很可能是cursor_sharing参数设置问题

--对应sql语句
select count(*) as col_0_0_ from TBL_SP_SALES_RECORDS tblspsales0_
where tblspsales0_.SALES_RECORDS_STATUS=:"SYS_B_0" and
tblspsales0_.CAMPAIGN_ID=:"SYS_B_1" and tblspsales0_.IS_CONN=:"SYS_B_2"
and tblspsales0_.SALES_TIME>=:"SYS_B_3" and tblspsales0_.SALES_PERSON=:"SYS_B_4"
--cursor_sharing参数
SQL> show parameter cursor_sharing;
NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ----------------
cursor_sharing                       string                           SIMILAR

根据oracle官方建议在11g中不推荐使用cursor_sharing=SIMILAR,其实在所有版本中都不推荐,设置为该值很容易导致高版本问题.而且该值会出现莫名其妙的,无法解释的高版本问题.而且根据oracle相关文档,在即将发布的12c版本中,将除掉SIMILAR值.对于客户库的该问题,因为很多sql未绑定参数,为了减少硬解析,建议在业务低谷时设置cursor_sharing=FORCE,并刷新shared pool.

ALERT_QUE表重建方法

最近关注了下网络上,出现了很多AQ$_ALERT_QT_N的index SYS_IOT_TOP_NNNN坏块引起的数据库异常(主要是SYSAUX表空间),因为他们是IOT表和主键的关系,不能简单的rebuild.查询了一些资料,得到一些信息

ALERT_QUE表用途
The ALERT_QUE is used by the Grid Control and DB Control Management Agents to monitor server-generated alerts

ALERT_QUE表重建方法

--方法1
SQL> connect / as sysdba
SQL>alter system enable restricted session;
To drop server alert schema.
SQL>@$ORACLE_HOME/rdbms/admin/catnoalr.sql
To re-create tables, sequence, type and queue for server alert
SQL>@$ORACLE_HOME/rdbms/admin/dbmsslrt.sql
SQL>@$ORACLE_HOME/rdbms/admin/catalrt.sql
To recompile the invalid objects
SQL>@$ORACLE_HOME/rdbms/admin/utlrp.sql
SQL> alter system disable restricted session;
--方法2
SQL> connect / as sysdba
SQL>alter system enable restricted session;
To drop server alert schema.
SQL>@$ORACLE_HOME/rdbms/admin/catnoalr.sql
Rerun catproc.sql
SQL>@$ORACLE_HOME/rdbms/admin/catproc.sql
SQL> alter system disable restricted session;

补充说明

By running the script up, the queue tables will be recreated and the messages
in the queue will be lost.
For 11g you can use catmwin.sql which has the steps to recreate the ALERT_QT.
Alternatively, for 11g you can use the catproc.sql to recreate.
If this option may leave DBSNMP.MGMT_BSLN_INTERNAL invalid.
To validate the same run catsnmp.sql [NOTE:603289.1]

客户端版本导致ORA-00600[kssadd_stage: null parent]

有客户一台应用不能正常工作,报ORA-00600[kssadd_stage: null parent]错误，重启中间件后工作正常.
alert日志

ORA-00600: internal error code, arguments: [kssadd_stage: null parent], [], [], [], [], [], [], []
Tue Jul 17 14:57:37 2012
Trace dumping is performing id=[cdmp_20120717145742]
Tue Jul 17 14:57:39 2012
Errors in file /oracle/10g/admin/fdjdb/udump/fdjdb2_ora_307720.trc:
ORA-00600: internal error code, arguments: [kssadd_stage: null parent], [], [], [], [], [], [], []
Tue Jul 17 14:57:45 2012
Errors in file /oracle/10g/admin/fdjdb/udump/fdjdb2_ora_357344.trc:
ORA-00600: internal error code, arguments: [kssadd_stage: null parent], [], [], [], [], [], [], []

trace文件

Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /oracle/10g/db
System name:    AIX
Node name:      ora2
Release:        1
Version:        6
Machine:        00CCFD354C00
Instance name: fdjdb2
Redo thread mounted by this instance: 2
Oracle process number: 89
Unix process pid: 111068, image: oracle@ora2
*** ACTION NAME:() 2012-07-17 15:08:42.043
*** MODULE NAME:(gsrvr.exe) 2012-07-17 15:08:42.043
*** SERVICE NAME:(fdjdb) 2012-07-17 15:08:42.043
*** SESSION ID:(991.44140) 2012-07-17 15:08:42.043
*** 2012-07-17 15:08:42.043
ksedmp: internal or fatal error
ORA-00600: internal error code, arguments: [kssadd_stage: null parent], [], [], [], [], [], [], []
No current SQL statement being executed.
----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst+001c          bl       ksedst1              40D1A9663F9E7ABB ?
                                                   6ED89E14D59386B5 ?
ksedmp+0290          bl       ksedst               104A2CDB0 ?
ksfdmp+0018          bl       03F2735C
kgerinv+00dc         bl       _ptrgl
kgeasnmierr+004c     bl       kgerinv              11041D938 ? 700000220FFBFC8 ?
                                                   110000770 ? 7000004FDF0C700 ?
                                                   FFFFFFFFFFF89C0 ?
kssadd_stage+0080    bl       kgeasnmierr          110195490 ? 110450040 ?
                                                   104AC46B8 ? 000000000 ?
                                                   000000000 ? 000000000 ?
                                                   000000000 ? 7000004F0FA9208 ?
kqreqa+0058          bl       kssadd_stage         105670038 ? 104CF7BA0 ?
                                                   000000000 ? 000000000 ?
kqrpre1+0850         bl       kqreqa               100203514 ? 1101A2B20 ?
kqrpre+001c          bl       kqrpre1              710000770 ? 000000009 ?
                                                   FFFFFFFFFFF9088 ?
                                                   28A4202200000000 ?
                                                   10012AEE4 ? FFFFFFFFFFF9080 ?
                                                   000000000 ? 11022A3E0 ?
opiosq0+009c         bl       kqrpre               000000000 ? 000000000 ?
                                                   000000000 ? 1101A2B20 ?
                                                   FFFFFFFFFFF9198 ? 1104B7C60 ?
                                                   FFFFFFFFFFF9458 ?
kpooprx+0168         bl       opiosq0              4A00000001 ? 000000001 ?
                                                   000000000 ? A40000000000FF ?
kpoal8+0400          bl       kpooprx              FFFFFFFFFFFB964 ?
                                                   FFFFFFFFFFFB680 ?
                                                   5000000050 ? 100000001 ?
                                                   000000000 ? A40000000000A4 ?
                                                   000000000 ? 1103A1AD8 ?
opiodr+0ae0          bl       _ptrgl
ttcpip+1020          bl       _ptrgl
opitsk+1124          bl       01F971E8
opiino+0990          bl       opitsk               000000000 ? 000000000 ?
opiodr+0ae0          bl       _ptrgl
opidrv+0484          bl       01F96034
sou2o+0090           bl       opidrv               3C02D9A29C ? 4A006E298 ?
                                                   FFFFFFFFFFFF8A0 ?
opimai_real+01bc     bl       01F939B4
main+0098            bl       opimai_real          000000000 ? 000000000 ?
__start+0070         bl       main                 000000000 ? 000000000 ?
--------------------- Binary Stack Dump ---------------------

咨询客户得知访问该数据库的是通过中间件(OCI)+10g Release 1 (10.1) for Windows访问数据库,然后查询MOS[ID 752149.1]发现stack trace
kssadd_stage <- kqreqa <- kqrpre1 <- kqrpre <- opiosq0 <- kpooprx <- kpoal8 <- opiodr <- ttcpip <- opitsk <- opiino <- opiodr <- opidrv <- sou2o <- opimai_real <- main <- start 和客户端版本和访问环境都和unpublished Bug 4937225相似
处理建议
客户端升级到10.2.0.3或者更高版本

8i升级到9i出现ORA-07445[pevm_MOVC_i()+18]

一个朋友数据库从8i升级到9i后,出现ORA-07445[pevm_MOVC_i()+18]错误
alert日志ORA-07445[pevm_MOVC_i()+18]

Mon Jul 16 12:21:54 2012
Errors in file /oracle/admin/ora8/udump/ora8_ora_8938.trc:
ORA-07445: exception encountered: core dump [pevm_MOVC_i()+18] [SIGSEGV] [Address not mapped to object] [0x7] [] []

trace文件

--版本平台信息
Oracle9i Enterprise Edition Release 9.2.0.4.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.4.0 - Production
ORACLE_HOME = /oracle/product/9.2.0
System name:	Linux
Node name:	localhost.localdomain
Release:	2.6.18-194.el5PAE
Version:	#1 SMP Tue Mar 16 22:00:21 EDT 2010
Machine:	i686
Instance name: ora8
Redo thread mounted by this instance: 1
Oracle process number: 15
Unix process pid: 8938, image: oracle@localhost.localdomain (TNS V1-V3)
--trace信息
*** 2012-07-16 12:21:54.399
*** SESSION ID:(12.6) 2012-07-16 12:21:54.399
Exception signal: 11 (SIGSEGV), code: 1 (Address not mapped to object), addr: 0x7, PC: [0x9bfac06, pevm_MOVC_i()+18]
Registers:
%eax: 0x00000000 %ebx: 0x00000025 %ecx: 0x00000000
%edx: 0xbf93bf50 %edi: 0x00000000 %esi: 0x002ff1d8
%esp: 0xbf93bc28 %ebp: 0xbf93bc60 %eip: 0x09bfac06
%efl: 0x00010296
  pevm_MOVC_i()+6 (0x9bfabfa) mov %edi,0xffffffcc(%ebp)
  pevm_MOVC_i()+9 (0x9bfabfd) mov %esi,0xffffffd0(%ebp)
  pevm_MOVC_i()+12 (0x9bfac00) mov %ebx,0xffffffc8(%ebp)
  pevm_MOVC_i()+15 (0x9bfac03) mov 0x14(%ebp),%eax
> pevm_MOVC_i()+18 (0x9bfac06) movb 0x7(%eax),%dl
  pevm_MOVC_i()+21 (0x9bfac09) mov $0x0,0xfffffff0(%ebp)
  pevm_MOVC_i()+28 (0x9bfac10) movb %dl,0xffffffe0(%ebp)
  pevm_MOVC_i()+31 (0x9bfac13) movb %dl,0xffffffe0(%ebp)
  pevm_MOVC_i()+34 (0x9bfac16) cmpb $0x1,%dl
*** 2012-07-16 12:21:54.407
ksedmp: internal or fatal error
ORA-07445: exception encountered: core dump [pevm_MOVC_i()+18] [SIGSEGV] [Address not mapped to object] [0x7] [] []
----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedmp()+269         call     ksedst()+0           1 ? 0 ? 0 ? 1 ? 64252C31 ?
                                                   6666006C ?
ssexhd()+1108        call     ksedmp()+0           3 ? 0 ? 0 ? 0 ? 0 ? 0 ?
pevm_MOVC_i()+18     signal   ssexhd()+0           B ? BF93B8BC ? BF93B93C ?
pfrrun()+8458        call     pevm_MOVC_i()+0      2FF19C ? 16 ? BE14650 ? 0 ?
pricar()+1277        call     pfrrun()+0           2FF19C ? 1 ? BF93CCFC ?
                                                   AD638A0 ? 2DFBAC ? 0 ?
pricbr()+427         call     pricar()+0           BF93DA88 ? BF93D084 ?
                                                   9BEAE0C ? 1 ? 0 ? 98C93728 ?
prient2()+598        call     pricbr()+0           BF93DA88 ? BF93D084 ? 0 ?
prient()+1438        call     prient2()+0          BF93DA88 ? BF93D084 ? 1 ?
                                                   BF93E4E0 ? 0 ?
kkxrpc()+347         call     prient()+0           BF93DA88 ? AD638A0 ?
                                                   BF93E534 ? 38 ? 1C8C997 ? 0 ?
kporpc()+138         call     kkxrpc()+0           4C ? F ? BF93E63C ?
opiodr()+5238        call     kjushutdown()+2671   4C ? F ? BF93E63C ?
ttcpip()+2124        call     opiodr()+0           4C ? F ? BF93E63C ? 0 ?
Cannot find symbol in /lib/libc.so.6.
opitsk()+1635        call     ttcpip()+0           AD638A0 ? 4C ? BF93E63C ? 0 ?
                                                   BF93EF14 ? BF93EF10 ?
opiino()+602         call     opitsk()+0           0 ? 0 ? AD638A0 ? BE01DE0 ?
                                                   103 ? 0 ?
opiodr()+5238        call     kjushutdown()+2671   3C ? 4 ? BF9402E0 ?
opidrv()+517         call     opiodr()+0           3C ? 4 ? BF9402E0 ? 0 ?
sou2o()+25           call     opidrv()+0           3C ? 4 ? BF9402E0 ?
main()+182           call     sou2o()+0            BF9402C4 ? 3C ? 4 ?
                                                   BF9402E0 ? 0 ? 0 ?
00125E9C             call     main()+0             2 ? BF940384 ? BF940390 ?
                                                   88A810 ? 0 ? 1 ?
---------------------Binary Stack Dump ---------------------
--进程信息
Process global information:
     process: 0x962ba0b8, call: 0x96342cd8, xact: (nil), curses: 0x962e4070, usrses: 0x962e4070
  ----------------------------------------
  SO: 0x962ba0b8, type: 2, owner: (nil), flag: INIT/-/-/0x00
  (process) Oracle pid=15, calls cur/top: 0x96342cd8/0x96342cd8, flag: (0) -
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 196 0 4
              last post received-location: kslpsr
              last process to post me: 962b7828 1 6
              last post sent: 0 0 15
              last post sent-location: ksasnd
              last process posted by me: 962b7828 1 6
    (latch info) wait_event=0 bits=0
    Process Group: DEFAULT, pseudo proc: 0x962d9444
    O/S info: user: oracle, term: UNKNOWN, ospid: 8938
    OSD pid info: Unix process pid: 8938, image: oracle@localhost.localdomain (TNS V1-V3)
    ----------------------------------------
    SO: 0x962e4070, type: 4, owner: 0x962ba0b8, flag: INIT/-/-/0x00
    (session) trans: (nil), creator: 0x962ba0b8, flag: (8000041) USR/- BSY/-/-/-/-/-
              DID: 0001-000F-00000004, short-term DID: 0000-0000-00000000
              txn branch: (nil)
              oct: 0, prv: 0, sql: (nil), psql: 0x98c3b858, user: 95/DDDD
    O/S info: user: mis, term: LANDERSVR3, ospid: 7904:3012, machine: XANDER\LANDERSVR3
              program: c:\orant\bin\f50run32.exe c:\forms\bas9010.fmx
    application name: c:\orant\bin\f50run32.exe c:\forms\bas9010.fmx, hash value=0
    last wait for 'db file sequential read' blocking sess=0x0 seq=1277 wait_time=11
                file#=1, block#=21b, blocks=1

1.该用户程序是从8i升级到9i之后产生该错误
2.报错的访问程序是FORM 5

解决方案
查询MOS[ID 273411.1]发现是因为FORM 5和9i不兼容导致该错误,ORACLE未给出解决方案,言外之意,如果FORM不能升级,那就只能把ORACLE重新降级到8i.

温馨提示
在做oracle数据库升级前,需要实现进行评估,测试,如果是oracle相关软件和oracle数据库结合紧密,升级前最好需要和ORACLE技术人员确认是否兼容.

using backup controlfile 两种使用情况区别

使用备份控制文件和重建控制文件恢复,都需要使用到using backup controlfile命令,但是两种情况下却有着本质的区别
试验准备条件

SQL> select * from v$version;
BANNER
-------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
PL/SQL Release 11.2.0.3.0 - Production
CORE    11.2.0.3.0      Production
TNS for Linux: Version 11.2.0.3.0 - Production
NLSRTL Version 11.2.0.3.0 - Production
SQL> select to_char(sysdate,'yyyy-mm-dd')"www.xifenfei.com" from dual;
www.xifenfei.com
--------------------
2012-07-13
SQL> alter database open resetlogs;
Database altered.
SQL> select name from v$controlfile;
NAME
----------------------------------------------------
/u01/oracle/oradata/ora11g/control01.ctl
SQL> !cp /u01/oracle/oradata/ora11g/control01.ctl /tmp/xff.ctl
SQL> alter system checkpoint;
System altered.
SQL> /
System altered.
SQL> /
System altered.
SQL> alter system switch logfile;
System altered.
SQL> /
System altered.
SQL> /
System altered.
SQL> /
System altered.
SQL> alter system checkpoint;
System altered.
SQL> shutdown abort;
ORACLE instance shut down.
SQL> !rm /u01/oracle/oradata/ora11g/control01.ctl
SQL> ! cp /tmp/xff.ctl /u01/oracle/oradata/ora11g/control01.ctl
SQL> startup
ORACLE instance started.
Total System Global Area  523108352 bytes
Fixed Size                  1346052 bytes
Variable Size             432014844 bytes
Database Buffers           83886080 bytes
Redo Buffers                5861376 bytes
Database mounted.
ORA-01122: database file 1 failed verification check
ORA-01110: data file 1: '/u01/oracle/oradata/ora11g/system01.dbf'
ORA-01207: file is more recent than control file - old control file

相关说明：
1.通过resetlogs使得试验更加清晰
2.通过多次的checkpoint实现增加scn,switch logfile实现日志组切换
3.通过模拟备份控制文件恢复

查询相关SCN

SQL> set linesize 150
SQL> select file#,to_char(checkpoint_change#,'9999999999999999') "SCN",
  2  to_char(RESETLOGS_CHANGE#,'9999999999999999') "RESETLOGS SCN",FUZZY
  3  from v$datafile_header;
     FILE# SCN                                RESETLOGS SCN                      FUZZY
---------- ---------------------------------- ---------------------------------- ------
         1           2118981                            2118577                  YES
         2           2118981                            2118577                  YES
         3           2118981                            2118577                  YES
         4           2118981                            2118577                  YES
         6           2118981                            2118577                  YES
SQL> select file#,to_char(checkpoint_change#,'999999999999999') "SCN",
  2  to_char(last_change#,'999999999999999')"STOP_SCN" from v$datafile;
     FILE# SCN                              STOP_SCN
---------- -------------------------------- --------------------------------
         1          2118580
         2          2118580
         3          2118580
         4          2118580
         6          2118580
SQL> select CONTROLFILE_CHANGE#   from v$database;
CONTROLFILE_CHANGE#
-------------------
            2118713

做关于控制文件和数据文件dump

SQL> oradebug setmypid;
Statement processed.
SQL> oradebug dump file_hdrs 3;
Statement processed.
SQL> oradebug tracefile_name;
/u01/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_593.trc
SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@xifenfei ~]$ sqlplus / as sysdba
SQL*Plus: Release 11.2.0.3.0 Production on Fri Jul 13 03:05:48 2012
Copyright (c) 1982, 2011, Oracle.  All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> oradebug setmypid;
Statement processed.
SQL>  oradebug dump controlf 3;
Statement processed.
SQL> oradebug tracefile_name;
/u01/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_775.trc

分析file_hdrs 3 dump文件

--datafile 1的datafile header信息
Tablespace #0 - SYSTEM  rel_fn:1
Creation   at   scn: 0x0000.00000007 09/18/2011 17:33:47
Backup taken at scn: 0x0000.00000000 01/01/1988 00:00:00 thread:0
 reset logs count:0x2eff82e3 scn: 0x0000.002053b1
 prev reset logs count:0x2e9e8451 scn: 0x0000.0016eaab
 recovered at 07/13/2012 02:56:18
 status:0x2004 root dba:0x00400208 chkpt cnt: 760 ctl cnt:759
begin-hot-backup file size: 0
Checkpointed at scn:  0x0000.00205545 07/13/2012 03:01:42
--datafile 1的控制文件中信息
DATA FILE #1:
  name #7: /u01/oracle/oradata/ora11g/system01.dbf
creation size=0 block size=8192 status=0xe head=7 tail=7 dup=1
 tablespace 0, index=1 krfil=1 prev_file=0
 unrecoverable scn: 0x0000.00000000 01/01/1988 00:00:00
 Checkpoint cnt:752 scn: 0x0000.002053b4 07/13/2012 02:59:18
 Stop scn: 0xffff.ffffffff 07/13/2012 02:58:43
 Creation Checkpointed at scn:  0x0000.00000007 09/18/2011 17:33:47

通过这里可以看出来:
datafile header的Checkpointed scn(00205545)>controfile datafile的Checkpoint scn(002053b4)
datafile header的checkpiont count(760)>controfile datafile的checkpiont count(752)
所以在数据库open的时候会报ORA-01207错误

尝试恢复数据库

SQL> recover database using backup controlfile;
ORA-00279: change 2118713 generated at 07/13/2012 02:58:43 needed for thread 1
ORA-00289: suggestion : /u01/oracle/oradata/archivelog/ora11g/1_1_788497123.dbf
ORA-00280: change 2118713 for thread 1 is in sequence #1
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
ORA-00308: cannot open archived log
'/u01/oracle/oradata/archivelog/ora11g/1_1_788497123.dbf'
ORA-27037: unable to obtain file status
Linux Error: 2: No such file or directory
Additional information: 3
SQL>
SQL> select to_char(2118713,'xxxxxxx') from dual;
TO_CHAR(2118713,
----------------
  205439

分析controlf 3 dump文件

***************************************************************************
DATABASE ENTRY
***************************************************************************
 (size = 316, compat size = 316, section max = 1, section in-use = 1,
  last-recid= 0, old-recno = 0, last-recno = 0)
 (extent = 1, blkno = 1, numrecs = 1)
 03/12/2012 22:17:06
 DB Name "ORA11G"
 Database flags = 0x00404000 0x00001000
 Controlfile Creation Timestamp  03/12/2012 22:17:07
 Incmplt recovery scn: 0x0000.00000000
 Resetlogs scn: 0x0000.002053b1 Resetlogs Timestamp  07/13/2012 02:58:43
 Prior resetlogs scn: 0x0000.0016eaab Prior resetlogs Timestamp  05/01/2012 13:14:57
 Redo Version: compatible=0xb200000
 #Data files = 5, #Online files = 5
 Database checkpoint: Thread=1 scn: 0x0000.002053b4
 Threads: #Enabled=1, #Open=1, Head=1, Tail=1
 Max log members = 3, Max data members = 1
 Arch list: Head=0, Tail=0, Force scn: 0x0000.00000000scn: 0x0000.00000000
 Activation ID: 4184707968
 Controlfile Checkpointed at scn:  0x0000.00205439 07/13/2012 02:59:25 <==控制文件checkpiont,控制文件每3秒的一次checkpiont
 thread:0 rba:(0x0.0.0)

通过recover的提示和对于controlf 3 dump文件的分析,可以确定数据库使用备份控制文件恢复,需要改控制文件备份之时开始的所有归档日志

查询数据库当前redo情况

SQL> select member from v$logfile;
MEMBER
-------------------------------------------------------------
/u01/oracle/oradata/ora11g/redo03.log
/u01/oracle/oradata/ora11g/redo02.log
/u01/oracle/oradata/ora11g/redo01.log
SQL> select SEQUENCE#,STATUS,FIRST_CHANGE# ,NEXT_CHANGE# from v$log;
 SEQUENCE# STATUS                           FIRST_CHANGE# NEXT_CHANGE#
---------- -------------------------------- ------------- ------------
         1 CURRENT                                2118577   2.8147E+14
         0 UNUSED                                       0            0
         0 UNUSED                                       0            0
SQL> archive log list;
Database log mode              No Archive Mode
Automatic archival             Disabled
Archive destination            /u01/oracle/oradata/archivelog/ora11g
Oldest online log sequence     1
Current log sequence           1
SQL> alter system dump logfile '/u01/oracle/oradata/ora11g/redo03.log';
System altered.
SQL> alter system dump logfile '/u01/oracle/oradata/ora11g/redo02.log';
System altered.
SQL> alter system dump logfile '/u01/oracle/oradata/ora11g/redo01.log';
System altered.

因为数据库处于非归档模式,而得到的redo信息主要都是来自控制文件,所以只能通过dump redo来分析当前redo的情况

分析redo log dump

DUMP OF REDO FROM FILE '/u01/oracle/oradata/ora11g/redo03.log'
 Opcodes *.*
 RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff
 SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
 Times: creation thru eternity
 FILE HEADER:
	Compatibility Vsn = 186646528=0xb200000
	Db ID=4173966754=0xf8c9ada2, Db Name='ORA11G'
	Activation ID=4184707968=0xf96d9380
	Control Seq=7660=0x1dec, File size=30720=0x7800
	File Number=3, Blksiz=512, File Type=2 LOG
 descrip:"Thread 0001, Seq# 0000000003, SCN 0x00000020553d-0x000000205540"
 thread: 1 nab: 0x2 seq: 0x00000003 hws: 0x2 eot: 0 dis: 0
 resetlogs count: 0x2eff82e3 scn: 0x0000.002053b1 (2118577)
 prev resetlogs count: 0x2e9e8451 scn: 0x0000.0016eaab (1501867)
 Low  scn: 0x0000.0020553d (2118973) 07/13/2012 03:01:34
 Next scn: 0x0000.00205540 (2118976) 07/13/2012 03:01:35
 Enabled scn: 0x0000.002053b1 (2118577) 07/13/2012 02:58:43
 Thread closed scn: 0x0000.0020553d (2118973) 07/13/2012 03:01:34
 Disk cksum: 0xa716 Calc cksum: 0xa716
DUMP OF REDO FROM FILE '/u01/oracle/oradata/ora11g/redo02.log'
 Opcodes *.*
 RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff
 SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
 Times: creation thru eternity
 FILE HEADER:
	Compatibility Vsn = 186646528=0xb200000
	Db ID=4173966754=0xf8c9ada2, Db Name='ORA11G'
	Activation ID=4184707968=0xf96d9380
	Control Seq=7663=0x1def, File size=30720=0x7800
	File Number=2, Blksiz=512, File Type=2 LOG
 descrip:"Thread 0001, Seq# 0000000005, SCN 0x000000205543-0xffffffffffff"
 thread: 1 nab: 0xffffffff seq: 0x00000005 hws: 0x1 eot: 1 dis: 0
 resetlogs count: 0x2eff82e3 scn: 0x0000.002053b1 (2118577)
 prev resetlogs count: 0x2e9e8451 scn: 0x0000.0016eaab (1501867)
 Low  scn: 0x0000.00205543 (2118979) 07/13/2012 03:01:36
 Next scn: 0xffff.ffffffff 01/01/1988 00:00:00
 Enabled scn: 0x0000.002053b1 (2118577) 07/13/2012 02:58:43
 Thread closed scn: 0x0000.00205543 (2118979) 07/13/2012 03:01:36
 Disk cksum: 0xc3f9 Calc cksum: 0xc3f9
 Terminal recovery stop scn: 0x0000.00000000
 Terminal recovery  01/01/1988 00:00:00
 Most recent redo scn: 0x0000.00000000
DUMP OF REDO FROM FILE '/u01/oracle/oradata/ora11g/redo01.log'
 Opcodes *.*
 RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff
 SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
 Times: creation thru eternity
 FILE HEADER:
	Compatibility Vsn = 186646528=0xb200000
	Db ID=4173966754=0xf8c9ada2, Db Name='ORA11G'
	Activation ID=4184707968=0xf96d9380
	Control Seq=7663=0x1def, File size=30720=0x7800
	File Number=1, Blksiz=512, File Type=2 LOG
 descrip:"Thread 0001, Seq# 0000000004, SCN 0x000000205540-0x000000205543"
 thread: 1 nab: 0x2 seq: 0x00000004 hws: 0x2 eot: 0 dis: 0
 resetlogs count: 0x2eff82e3 scn: 0x0000.002053b1 (2118577)
 prev resetlogs count: 0x2e9e8451 scn: 0x0000.0016eaab (1501867)
 Low  scn: 0x0000.00205540 (2118976) 07/13/2012 03:01:35
 Next scn: 0x0000.00205543 (2118979) 07/13/2012 03:01:36
 Enabled scn: 0x0000.002053b1 (2118577) 07/13/2012 02:58:43
 Thread closed scn: 0x0000.00205540 (2118976) 07/13/2012 03:01:35
 Disk cksum: 0xaa26 Calc cksum: 0xaa26
 Terminal recovery stop scn: 0x0000.00000000
 Terminal recovery  01/01/1988 00:00:00
 Most recent redo scn: 0x0000.00000000

通过对redo dump的分析可以得到：
1.最小的sequence#=3是redo03.log
2.current redo为redo02.log

继续尝试恢复

SQL> recover database using backup controlfile;
ORA-00279: change 2118713 generated at 07/13/2012 02:58:43 needed for thread 1
ORA-00289: suggestion : /u01/oracle/oradata/archivelog/ora11g/1_1_788497123.dbf
ORA-00280: change 2118713 for thread 1 is in sequence #1
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
/u01/oracle/oradata/ora11g/redo02.log
ORA-00326: log begins at change 2118979, need earlier change 2118713
ORA-00334: archived log: '/u01/oracle/oradata/ora11g/redo02.log'

关于备份控制文件使用using backup controlfile总结:恢复的启动控制文件备份的scn,需要该控制文件备份后的所有归档日志.对于当前这个非归档,而且redo被覆盖的库,该方法无法正常恢复

重建控制文件并做controlf 3 dump

SQL> alter database backup controlfile to trace as '/tmp/ctl.trace';
Database altered.
SQL> shutdown immediate
ORA-01109: database not open
Database dismounted.
ORACLE instance shut down.
SQL> STARTUP NOMOUNT
CREATE CONTROLFILE REUSE DATABASE "ORA11G" NORESETLOGS  NOARCHIVELOG
    MAXLOGFILES 16
    MAXLOGMEMBERS 3
    MAXDATAFILES 100
    MAXINSTANCES 8
    MAXLOGHISTORY 292
LOGFILE
  GROUP 1 '/u01/oracle/oradata/ora11g/redo01.log'  SIZE 15M BLOCKSIZE 512,
  GROUP 2 '/u01/oracle/oradata/ora11g/redo02.log'  SIZE 15M BLOCKSIZE 512,
  GROUP 3 '/u01/oracle/oradata/ora11g/redo03.log'  SIZE 15M BLOCKSIZE 512
DATAFILE
  '/u01/oracle/oradata/ora11g/system01.dbf',
  '/u01/oracle/oradata/ora11g/sysaux01.dbf',
  '/u01/oracle/oradata/ora11g/undotbs01.dbf',
  '/u01/oracle/oradata/ora11g/users01.dbf',
  '/u01/oracle/oradata/ora11g/xifenfei02.dbf'
CHARACTER SET AL32UTF8
;
ORACLE instance started.
Total System Global Area  523108352 bytes
Fixed Size                  1346052 bytes
Variable Size             432014844 bytes
Database Buffers           83886080 bytes
Redo Buffers                5861376 bytes
SQL>   2    3    4    5    6    7    8    9   10   11   12   13   14   15   16   17   18
Control file created.
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug dump controlf 3;
Statement processed.
SQL> oradebug tracefile_name;
/u01/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_1867.trc

尝试数据库恢复

SQL>  recover database using backup controlfile;
ORA-00279: change 2118981 generated at 07/13/2012 03:01:42 needed for thread 1
ORA-00289: suggestion : /u01/oracle/oradata/archivelog/ora11g/1_5_788497123.dbf
ORA-00280: change 2118981 for thread 1 is in sequence #5
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
ORA-00308: cannot open archived log
'/u01/oracle/oradata/archivelog/ora11g/1_5_788497123.dbf'
ORA-27037: unable to obtain file status
Linux Error: 2: No such file or directory
Additional information: 3
SQL>
SQL> select to_char(2118981,'xxxxxxx') from dual;
TO_CHAR(2118981,
----------------
  205545
SQL> set linesize 150
SQL> select file#,to_char(checkpoint_change#,'9999999999999999') "SCN",
  2  to_char(RESETLOGS_CHANGE#,'9999999999999999') "RESETLOGS SCN",FUZZY
  3  from v$datafile_header;
     FILE# SCN                                RESETLOGS SCN                      FUZZY
---------- ---------------------------------- ---------------------------------- ------
         1           2118981                            2118577                  YES
         2           2118981                            2118577                  YES
         3           2118981                            2118577                  YES
         4           2118981                            2118577                  YES
         6           2118981                            2118577                  YES
SQL> select file#,to_char(checkpoint_change#,'999999999999999') "SCN",
  2  to_char(last_change#,'999999999999999')"STOP_SCN" from v$datafile;
     FILE# SCN                              STOP_SCN
---------- -------------------------------- --------------------------------
         1          2118981
         2          2118981
         3          2118981
         4          2118981
         6          2118981

分析 controlf 3 dump文件

***************************************************************************
DATABASE ENTRY
***************************************************************************
 (size = 316, compat size = 316, section max = 1, section in-use = 1,
  last-recid= 0, old-recno = 0, last-recno = 0)
 (extent = 1, blkno = 1, numrecs = 1)
 07/13/2012 03:24:51
 DB Name "ORA11G"
 Database flags = 0x00400102 0x00001000
 Controlfile Creation Timestamp  07/13/2012 03:24:51
 Incmplt recovery scn: 0x0000.00000000
 Resetlogs scn: 0x0000.002053b1 Resetlogs Timestamp  07/13/2012 02:58:43
 Prior resetlogs scn: 0x0000.0016eaab Prior resetlogs Timestamp  05/01/2012 13:14:57
 Redo Version: compatible=0xb200000
 #Data files = 5, #Online files = 5
 Database checkpoint: Thread=1 scn: 0x0000.00205543
***************************************************************************
DATA FILE RECORDS
***************************************************************************
 (size = 520, compat size = 520, section max = 100, section in-use = 6,
  last-recid= 0, old-recno = 0, last-recno = 0)
 (extent = 1, blkno = 11, numrecs = 100)
DATA FILE #1:
  name #8: /u01/oracle/oradata/ora11g/system01.dbf
creation size=0 block size=8192 status=0x12 head=8 tail=8 dup=1
 tablespace 0, index=1 krfil=1 prev_file=0
 unrecoverable scn: 0x0000.00000000 01/01/1988 00:00:00
 Checkpoint cnt:760 scn: 0x0000.00205545 07/13/2012 03:01:42
 Stop scn: 0xffff.ffffffff 07/13/2012 03:24:51
 Creation Checkpointed at scn:  0x0000.00000007 09/18/2011 17:33:47

完成恢复

SQL> recover database using backup controlfile;
ORA-00279: change 2118981 generated at 07/13/2012 03:01:42 needed for thread 1
ORA-00289: suggestion : /u01/oracle/oradata/archivelog/ora11g/1_5_788497123.dbf
ORA-00280: change 2118981 for thread 1 is in sequence #5
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
/u01/oracle/oradata/ora11g/redo02.log
Log applied.
Media recovery complete.

关于重建控制文件后使用using backup总结:重建控制文件后,恢复的起点是datafile header scn 最小值,需要改scn之后的所有日志

未收集统计信息对象—执行sql动态采样

在一次ORA-7445导致oracle数据库down掉故障分析中,发现一条类似的sql非常大(通过复制到文档确定该sql大小是5M左右)

SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB)
opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE
*/ NVL(SUM(C1),0), NVL(SUM(C2),0) FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("DCREDITMSG_00")
 FULL("DCREDITMSG_00") NO_PARALLEL_INDEX("DCREDITMSG_00") */ 1 AS C1, CASE WHEN
 "DCREDITMSG_00"."PHONE_NO"='具体电话号码' OR "DCREDITMSG_00"."PHONE_NO"='具体电话号码' OR
……………………N多OR "DCREDITMSG_00"."PHONE_NO"='具体电话号码'
"DCREDITMSG_00"."PHONE_NO"='具体电话号码' THEN 1 ELSE 0 END AS C2 FROM
"BSSADMIN"."DCREDITMSG_00" SAMPLE BLOCK (0.032410 , 1) SEED (1) "DCREDITMSG_00") SAMPLESUB

当时该sql因某种原因导致大量的sql area中很多内存泄露,最终导致数据库down掉.通过实验找出类此奇怪SQL.

创建模拟表

SQL> create table t_xifenfei
  2  as
  3  select  * from dba_objects;
Table created.
SQL> select count(*) from t_xifenfei;
  COUNT(*)
----------
     74605
SQL> select NUM_ROWS,LAST_ANALYZED from dba_tables
  2  where  table_name='T_XIFENFEI' and owner='CHF';
  NUM_ROWS LAST_ANALYZE
---------- ------------

得出信息:
1.该表一共有记录数74605条
2.该表未收集统计信息

查看执行计划

SQL>  set autotrace trace exp
SQL> select /*+ dynamic_sampling(t 0) */ * from t_xifenfei t;
Execution Plan
----------------------------------------------------------
Plan hash value: 548923532
--------------------------------------------------------------------------------
| Id  | Operation         | Name       | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |            | 88868 |    17M|   299   (2)| 00:00:04 |
|   1 |  TABLE ACCESS FULL| T_XIFENFEI | 88868 |    17M|   299   (2)| 00:00:04 |
--------------------------------------------------------------------------------
--通过hint指定动态采样sql相关对象统计信息,
可以看到我们实际的表记录是74605而数据库采样出来的记录为88868,原则上还是可以接受
SQL> select * from t_xifenfei;
Execution Plan
----------------------------------------------------------
Plan hash value: 548923532
--------------------------------------------------------------------------------
| Id  | Operation         | Name       | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |            | 73449 |    14M|   298   (1)| 00:00:04 |
|   1 |  TABLE ACCESS FULL| T_XIFENFEI | 73449 |    14M|   298   (1)| 00:00:04 |
--------------------------------------------------------------------------------
Note
-----
   - dynamic sampling used for this statement (level=2)
--因为没有统计信息,数据库动态采样sql相关对象统计信息
可以看到我们实际的表记录是74605而数据库采样出来的记录为73449,比手工指定采样准确

对自动采样进行10046跟踪

SQL> conn / as sysdba
Connected.
SQL> oradebug  setmypid
Statement processed.
SQL> oradebug EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12
Statement processed.
SQL> select count(*) from CHF.t_xifenfei;
  COUNT(*)
----------
     74605
SQL>  oradebug TRACEFILE_NAME
/u01/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_27967.trc

分析trace文件

*** 2012-07-12 15:42:34.991
WAIT #0:nam='SQL*Net message from client'ela= 56716427 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1342078954991525
=====================
PARSING IN CURSOR #3063864268 len=404 dep=1 uid=0 oct=3 lid=0 tim=1342078955037387
hv=4184780033 ad='385d3708' sqlid='3gjvvxzwqxb81'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB)
opt_param('parallel_execution_enabled', 'false')
NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),0), NVL(SUM(C2),0) FROM
(SELECT /*+ NO_PARALLEL("T_XIFENFEI") FULL("T_XIFENFEI") NO_PARALLEL_INDEX("T_XIFENFEI") */ 1 AS C1,
1 AS C2 FROM "CHF"."T_XIFENFEI" SAMPLE BLOCK (5.790441 , 1) SEED (1) "T_XIFENFEI") SAMPLESUB
END OF STMT
PARSE #3063864268:c=6000,e=5404,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=205916192,tim=1342078955037303
EXEC #3063864268:c=0,e=206,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=205916192,tim=1342078955037901
FETCH #3063864268:c=4998,e=4759,p=0,cr=65,cu=0,mis=0,r=1,dep=1,og=1,plh=205916192,tim=1342078955042730
STAT #3063864268 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=65 pr=0 pw=0 time=4795 us)'
STAT #3063864268 id=2 cnt=4253 pid=1 pos=1 obj=76370 op='TABLE ACCESS SAMPLE T_XIFENFEI
(cr=65 pr=0 pw=0 time=8247 us cost=19 size=61752 card=5146)'
CLOSE #3063864268:c=0,e=7,dep=1,type=0,tim=1342078955043024
=====================
PARSING IN CURSOR #3063864784 len=35 dep=0 uid=0 oct=3 lid=0 tim=1342078955043465 hv=2174183953 ad='3ed2d700'
sqlid='fadutqq0tfuhj'
select count(*) from CHF.t_xifenfei
END OF STMT
PARSE #3063864784:c=51991,e=51648,p=0,cr=66,cu=0,mis=1,r=0,dep=0,og=1,plh=2715729601,tim=1342078955043464
EXEC #3063864784:c=0,e=75,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2715729601,tim=1342078955043645
WAIT #3063864784: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1342078955043705

通过这个trace的分析,果然发现在执行我们需要的sql前,执行了SELECT /* OPT_DYN_SAMP */组成的一个复杂的采样sql语句.

收集统计信息查看执行计划

SQL> EXEC DBMS_STATS.gather_table_stats('CHF','T_XIFENFEI');
PL/SQL procedure successfully completed.
SQL> select NUM_ROWS,LAST_ANALYZED from dba_tables
  2  where  table_name='T_XIFENFEI' and owner='CHF';
  NUM_ROWS LAST_ANALYZE
---------- ------------
     74605 12-JUL-12
SQL>  set autotrace trace exp
SQL> select * from t_xifenfei;
Execution Plan
----------------------------------------------------------
Plan hash value: 548923532
--------------------------------------------------------------------------------
| Id  | Operation         | Name       | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |            | 74605 |  7139K|   298   (1)| 00:00:04 |
|   1 |  TABLE ACCESS FULL| T_XIFENFEI | 74605 |  7139K|   298   (1)| 00:00:04 |
--------------------------------------------------------------------------------
--执行计划未提示dynamic sampling

继续做10046

SQL> conn / as sysdba
Connected.
SQL> oradebug  setmypid
Statement processed.
SQL> oradebug EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12
Statement processed.
SQL> select count(*) from CHF.t_xifenfei;
  COUNT(*)
----------
     74605
SQL> oradebug TRACEFILE_NAME
/u01/oracle/diag/rdbms/ora11g/ora11g/trace/ora11g_ora_29780.trc

分析trace文件

*** 2012-07-12 16:14:53.914
Oradebug command 'EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12' console output: <none>
WAIT #0: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1342080893914307
*** 2012-07-12 16:14:59.376
WAIT #0: nam='SQL*Net message from client' ela= 5461608 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1342080899376008
=====================
PARSING IN CURSOR #3063709248 len=35 dep=0 uid=0 oct=3 lid=0 tim=1342080899379562 hv=2174183953
ad='3ed2d700' sqlid='fadutqq0tfuhj'
select count(*) from CHF.t_xifenfei
END OF STMT

通过这里可以发现,当有了统计信息后,数据库不能再使用那条N多hint的sql去动态采样统计信息.

总结建议
动态采样（Dynamic Sampling）技术的最初提出是在Oracle 9i R2，在段（表，索引，分区）没有分析的情况下，为了使CBO 优化器得到足够的信息以保证做出正确的执行计划而发明的一种技术，可以把它看做分析手段的一种补充。当段对象没有统计信息时（即没有做分析），动态采样技术可以通过直接从需要分析的对象上收集数据块（采样）来获得CBO需要的统计信息。为了cbo,oracle引进了该功能,原则上说是一个很不错的东西,但是偶尔也是会出现一些意外,所以如果发现数据库中有表未做统计分析,建议手工处理下,ORACLE的自动收集统计信息程序也有不靠谱的时候(发现多次10g的库中有部分表未收集统计信息)

Oracle 11g增加列,并带默认值的新特性

在11g以前,如果要在一个大表中增加一列,并设置默认值,那将是一个非常悲剧的事情.有些时候不得不选择在线重定义功能来实现该需求.而在11g中增加新列并设置默认值,只是简单的修改数据字典来实现该功能,大大提供效率
10g加列(默认值)

SQL> select * from v$version;
BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
PL/SQL Release 10.2.0.1.0 - Production
CORE    10.2.0.1.0      Production
TNS for Linux: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production
SQL> create table t_xifenfei
  2  as select object_id,object_name from dba_objects;
Table created.
SQL> select count(*) from t_xifenfei;
  COUNT(*)
----------
     49827
SQL> desc t_xifenfei
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 OBJECT_ID                                          NUMBER
 OBJECT_NAME                                        VARCHAR2(128)
SQL> set timing on
SQL> alter table t_xifenfei add c_xff varchar2(100) default 'www.xifenfei.com' not null;
Table altered.
Elapsed: 00:00:06.13
--使用了6秒钟
SQL> select   rowid,
  2   dbms_rowid.rowid_relative_fno(rowid)rel_fno,
  3   dbms_rowid.rowid_block_number(rowid)blockno,
  4   dbms_rowid.rowid_row_number(rowid) rowno
  5  from t_xifenfei where object_name='OBJ$';
ROWID                 REL_FNO    BLOCKNO      ROWNO
------------------ ---------- ---------- ----------
AAAMwJAAEAAAAB8AAr          4        124         43
SQL> alter system dump datafile 4 block 124;
System altered.
Elapsed: 00:00:00.08

11g增加列(默认值)

SQL> select * from v$version;
BANNER
-----------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
PL/SQL Release 11.2.0.3.0 - Production
CORE    11.2.0.3.0      Production
TNS for Linux: Version 11.2.0.3.0 - Production
NLSRTL Version 11.2.0.3.0 - Production
SQL> create table t_xifenfei
  2  as select object_id,object_name from dba_objects;
Table created.
SQL> select count(*) from t_xifenfei;
  COUNT(*)
----------
     74605
SQL> select   rowid,
  2   dbms_rowid.rowid_relative_fno(rowid)rel_fno,
  3   dbms_rowid.rowid_block_number(rowid)blockno,
  4   dbms_rowid.rowid_row_number(rowid) rowno
  5  from t_xifenfei where object_name='OBJ$';
ROWID                 REL_FNO    BLOCKNO      ROWNO
------------------ ---------- ---------- ----------
AAASpRAAEAAAACrAAu          4        171         46
SQL> alter system dump datafile 4 block 171;
System altered.
SQL> set timing on
SQL> alter table t_xifenfei add c_xff varchar2(100) default 'www.xifenfei.com' not null;
Table altered.
Elapsed: 00:00:00.19
--只是使用了0.19秒
SQL> select   rowid,
  2   dbms_rowid.rowid_relative_fno(rowid)rel_fno,
  3   dbms_rowid.rowid_block_number(rowid)blockno,
  4   dbms_rowid.rowid_row_number(rowid) rowno
  5  from t_xifenfei where object_name='OBJ$';
ROWID                 REL_FNO    BLOCKNO      ROWNO
------------------ ---------- ---------- ----------
AAASpRAAEAAAACrAAu          4        171         46
Elapsed: 00:00:00.04
SQL> alter system dump datafile 4 block 171;
System altered.

通过10g和11g的增加相同列和默认值的对比可以发现,11g的速度要比10g快很多很多,下面我们通过上面dump出来相关的数据块来分析原因
dump分析
11g增加列之前dump

tab 0, row 0, @0x1f74
tl: 12 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 15
col  1: [ 5]  49 43 4f 4c 24
tab 0, row 1, @0x1f66
tl: 14 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 2f
col  1: [ 7]  49 5f 55 53 45 52 31
tab 0, row 2, @0x1f5b
tl: 11 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 1d
col  1: [ 4]  43 4f 4e 24

11g增加列之后dump

tab 0, row 0, @0x1f74
tl: 12 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 15
col  1: [ 5]  49 43 4f 4c 24
tab 0, row 1, @0x1f66
tl: 14 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 2f
col  1: [ 7]  49 5f 55 53 45 52 31
tab 0, row 2, @0x1f5b
tl: 11 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 1d
col  1: [ 4]  43 4f 4e 24
tab 0, row 3, @0x1f4f
tl: 12 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 10
col  1: [ 5]  55 4e 44 4f 24

10g增加列之后dump
因为10g在没有增加列之前的dump和11g未增加列之前类似,所以未dump出来

tab 0, row 0, @0x1f63
tl: 29 fb: --H-FL-- lb: 0x2  cc: 3
col  0: [ 2]  c1 15
col  1: [ 5]  49 43 4f 4c 24
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d
tab 0, row 1, @0x1f44
tl: 31 fb: --H-FL-- lb: 0x2  cc: 3
col  0: [ 2]  c1 2d
col  1: [ 7]  49 5f 55 53 45 52 31
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d
tab 0, row 2, @0x1f28
tl: 28 fb: --H-FL-- lb: 0x2  cc: 3
col  0: [ 2]  c1 1d
col  1: [ 4]  43 4f 4e 24
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d
tab 0, row 3, @0x1f0b
tl: 29 fb: --H-FL-- lb: 0x2  cc: 3
col  0: [ 2]  c1 10
col  1: [ 5]  55 4e 44 4f 24
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d

对比发现11g在增加列之后,以前的数据dump出来的内容未有任何改变.也就是说:在10g中,我们增加一个列和默认值,会自动的增加到真实的数据中,而在11g中增加列和默认值并未真的加到11g的表中已经存在的数据中.
11g中插入新数据dump测试

SQL>  insert into chf.t_xifenfei(object_id,object_name)
  2  select object_id,object_name FROM DBA_OBJECTS;
74605 rows created.
SQL> commit;
Commit complete.
SQL> ALTER SYSTEM FLUSH BUFFER_CACHE;
System altered.
SQL> /
System altered.
--建议刷新
SQL>
SQL>
SQL> select   rowid,
  2   dbms_rowid.rowid_relative_fno(rowid)rel_fno,
  3   dbms_rowid.rowid_block_number(rowid)blockno,
  4   dbms_rowid.rowid_row_number(rowid) rowno
  5  from chf.t_xifenfei where object_name='OBJ$';
ROWID                 REL_FNO    BLOCKNO      ROWNO
------------------ ---------- ---------- ----------
AAASpRAAEAAAACrAAu          4        171         46
AAASpRAAEAAAB5TAAu          4       7763         46
SQL> ALTER SYSTEM DUMP DATAFILE 4 BLOCK 7763;
System altered.
--dump内容
tab 0, row 0, @0x4e3
tl: 29 fb: --H-FL-- lb: 0x1  cc: 3
col  0: [ 2]  c1 15
col  1: [ 5]  49 43 4f 4c 24
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d
tab 0, row 1, @0x500
tl: 31 fb: --H-FL-- lb: 0x1  cc: 3
col  0: [ 2]  c1 2f
col  1: [ 7]  49 5f 55 53 45 52 31
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d
tab 0, row 2, @0x51f
tl: 28 fb: --H-FL-- lb: 0x1  cc: 3
col  0: [ 2]  c1 1d
col  1: [ 4]  43 4f 4e 24
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d
tab 0, row 3, @0x53b
tl: 29 fb: --H-FL-- lb: 0x1  cc: 3
col  0: [ 2]  c1 10
col  1: [ 5]  55 4e 44 4f 24
col  2: [16]  77 77 77 2e 78 69 66 65 6e 66 65 69 2e 63 6f 6d

通过这里看看出:在11g中后续插入的数据,默认值也插入到数据文件中

Oracle 11G的DDL_LOCK_TIMEOUT参数

今天kaums给客户做培训11g新特性,发现还真的有不少挺好的新东西,但是以前没有怎么去关注的他们,在后续的几篇中,陆续整理处理.
DDL_LOCK_TIMEOUT specifies a time limit for how long DDL statements will wait in a DML lock queue. The default value of zero indicates a status of NOWAIT. The maximum value of 1,000,000 seconds will result in the DDL statement waiting forever to acquire a DML lock.
If a lock is not acquired before the timeout period expires, then an error is returned.
数据库ddl_lock_timeout参数

SQL> select * from v$version;
BANNER
---------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - Production
PL/SQL Release 11.2.0.3.0 - Production
CORE    11.2.0.3.0      Production
TNS for Linux: Version 11.2.0.3.0 - Production
NLSRTL Version 11.2.0.3.0 - Production
SQL> show parameter ddl_lock_timeout;
NAME                                 TYPE       VALUE
------------------------------------ ---------- --------------
ddl_lock_timeout                     integer    0

ddl_lock_timeout默认值测试(同以前版本)

--会话1
SQL> set time on
10:27:57 SQL> create table t_xifenfei as
10:28:05   2  select * from dba_users;
Table created.
Elapsed: 00:00:00.08
10:28:17 SQL> delete from t_xifenfei where username='CHF';
1 row deleted.
--会话2
SQL> set timing on
SQL> ALTER TABLE T_XIFENFEI DROP COLUMN AUTHENTICATION_TYPE;
ALTER TABLE T_XIFENFEI DROP COLUMN AUTHENTICATION_TYPE
            *
ERROR at line 1:
ORA-00054: resource busy and acquire with NOWAIT specified or timeout expired
Elapsed: 00:00:00.01

设置ddl_lock_timeout超时测试

--会话1
10:28:17 SQL> delete from t_xifenfei where username='CHF';
1 row deleted.
--会话2
SQL>  ALTER SESSION SET ddl_lock_timeout=10;
Session altered.
Elapsed: 00:00:00.00
SQL> ALTER TABLE T_XIFENFEI DROP COLUMN AUTHENTICATION_TYPE;
ALTER TABLE T_XIFENFEI DROP COLUMN AUTHENTICATION_TYPE
            *
ERROR at line 1:
ORA-00054: resource busy and acquire with NOWAIT specified or timeout expired
Elapsed: 00:00:10.01

设置ddl_lock_timeout未超时测试

--会话2
SQL> ALTER SESSION SET ddl_lock_timeout=30;
Session altered.
Elapsed: 00:00:00.00
--会话1
10:30:00 SQL> COMMIT;
Commit complete.
Elapsed: 00:00:00.00
--会话2
SQL> ALTER TABLE T_XIFENFEI DROP COLUMN AUTHENTICATION_TYPE;
Table altered.
Elapsed: 00:00:07.91

在以前的版本中ddl操作是nowait等待,通过实验可以发现ddl_lock_timeout可以在一定程度上解决因为我们不清楚这个表是否有dml操作而导致ddl操作不能进行的情况,从一定程度上减少了自己去尝试ddl操作,或者查询相关视图然后找出相关会话,然后kill掉对应数据的情况,可以说是在修改表结构的时候一个很不错的新特性.

使用flashback query恢复被删除plsql

今天一个朋友在11g中误删除生产中的一个过程,让他通过对dba_source视图的flashback query找回该过程.
从10g及其以后的版本中,如果被删除的plsql被及时发现(undo 未被覆盖掉)可以使用flashback query功能实现恢复.
创建plsql并删除

SQL> select * from v$version;
BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
PL/SQL Release 10.2.0.1.0 - Production
CORE    10.2.0.1.0      Production
TNS for Linux: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production
SQL> create or replace PROCEDURE  p_test_del(in_put varchar2) as
  2  begin
  3  dbms_output.put_line(in_put);
  4  end;
  5  /
Procedure created.
SQL> set serveroutput on
SQL> exec p_test_del('www.xifenfei.com');
www.xifenfei.com
PL/SQL procedure successfully completed.
SQL> select to_char(sysdate,'yyyy-mm-dd hh24:mi:ss') from dual;
TO_CHAR(SYSDATE,'YY
-------------------
2012-07-02 08:34:45
SQL> drop  PROCEDURE  p_test_del;
Procedure dropped.

恢复plsql

SQL> set pagesize 0
SQL> column text format a4000
SQL> spool /tmp/get_delete_proc.xff
SQL> SELECT text
  2         FROM DBA_source AS OF TIMESTAMP TO_TIMESTAMP('2012-07-02 08:34:45', 'YYYY-MM-DD HH24:MI:SS')
  3        WHERE OWNER = 'CHF' AND NAME = 'P_TEST_DEL' ORDER BY LINE;
PROCEDURE  p_test_del(in_put varchar2) as
begin
dbms_output.put_line(in_put);
end;
SQL> spool off;
SQL> !more /tmp/get_delete_proc.xff
SQL> SELECT text
  2         FROM DBA_source AS OF TIMESTAMP TO_TIMESTAMP('2012-07-02 08:34:45', 'YYYY-MM-DD HH24:MI:SS')
  3        WHERE OWNER = 'CHF' AND NAME = 'P_TEST_DEL' ORDER BY LINE;
create PROCEDURE  p_test_del(in_put varchar2) as
begin
dbms_output.put_line(in_put);
end;
SQL> spool off;

重建plsql

SQL> create PROCEDURE  p_test_del(in_put varchar2) as
  2  begin
  3  dbms_output.put_line(in_put);
  4  end;
  5  /
Procedure created.
SQL> set serveroutput on
SQL> exec p_test_del('惜分飞');
惜分飞
PL/SQL procedure successfully completed.

ORA-00600[kcbshlc_1]导致数据库 down 案例

一台服务器因为ORA-00600[kcbshlc_1]错误引起PMON异常导致数据库down掉

Sun Jul  8 17:20:10 2012
Errors in file /opt/oracle/admin/xff/bdump/xff_pmon_16412.trc:
ORA-00600: internal error code, arguments: [kcbshlc_1], [33], [], [], [], [], [], []
Sun Jul  8 17:20:12 2012
Errors in file /opt/oracle/admin/xff/bdump/xff_pmon_16412.trc:
ORA-00600: internal error code, arguments: [kcbshlc_1], [33], [], [], [], [], [], []
Sun Jul  8 17:20:12 2012
PMON: terminating instance due to error 472

分析trace文件

Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /opt/oracle/product/10.2.0
System name:	Linux
Node name:	localhost.localdomain
Release:	2.6.9-89.ELsmp
Version:	#1 SMP Mon Apr 20 10:33:05 EDT 2009
Machine:	x86_64
Instance name: xff
Redo thread mounted by this instance: 1
Oracle process number: 2
Unix process pid: 16412, image: oracle@localhost.localdomain (PMON)
*** 2012-07-08 03:00:11.351
*** SERVICE NAME:(SYS$BACKGROUND) 2012-07-08 03:00:11.338
*** SESSION ID:(1105.1) 2012-07-08 03:00:11.338
 wsd 0x1f8169a6c8, sbuf (nil), setid 9, op 0
lcuridx 0, lasz (nil)
freeing in-flux r/w latch for process state: 1fc165d248
... in-flux r/w latch  1fc1fcc9b0 Child cache buffers chains level=1 child#=4753
        Location from where latch is held: kcbgtcr: kslbegin excl:
        Context saved from call: 113266196
        state=busy(exclusive) (val=0x2000000000000071) holder orapid = 113
    waiters [orapid (seconds since: put on list, posted, alive check)]:
     139 (2, 1341687611, 2)
     192 (2, 1341687611, 2)
     191 (2, 1341687611, 2)
     173 (2, 1341687611, 2)
     185 (2, 1341687611, 2)
     176 (2, 1341687611, 2)
     174 (2, 1341687611, 2)
     118 (2, 1341687611, 2)
     190 (2, 1341687611, 2)
     179 (2, 1341687611, 2)
     184 (1, 1341687611, 1)
     189 (1, 1341687611, 1)
     177 (1, 1341687611, 1)
     195 (1, 1341687611, 1)
     187 (1, 1341687611, 1)
     194 (1, 1341687611, 1)
     147 (1, 1341687611, 1)
     183 (1, 1341687611, 1)
     143 (1, 1341687611, 1)
     144 (1, 1341687611, 1)
     186 (1, 1341687611, 1)
     188 (1, 1341687611, 1)
     196 (1, 1341687611, 1)
     145 (1, 1341687611, 1)
     193 (1, 1341687611, 1)
     waiter count=25
*** 2012-07-08 03:50:06.228
 wsd 0x1f8169ac20, sbuf 0xac1ffafe8, setid 10, op 3
lcuridx 1, lasz 0x3c1ffc110
*** 2012-07-08 16:30:05.294
freeing in-flux r/w latch for process state: 20406507f0
... in-flux r/w latch  1f81265f28 Child cache buffers chains level=1 child#=14180
        Location from where latch is held: kcbgtcr: kslbegin excl:
        Context saved from call: 71341989
        state=busy(exclusive) (val=0x2000000000000066) holder orapid = 102
    waiters [orapid (seconds since: put on list, posted, alive check)]:
     121 (2, 1341736205, 2)
     116 (2, 1341736205, 2)
     125 (2, 1341736205, 2)
     140 (2, 1341736205, 2)
     145 (2, 1341736205, 2)
     waiter count=5
freeing in-flux r/w latch for process state: 1fc165f9d0
... in-flux r/w latch  1f813aec18 Child cache buffers chains level=1 child#=20914
        Location from where latch is held: kcbrls: kslbegin:
        Context saved from call: 96505705
        state=busy(exclusive) (val=0x200000000000007b) holder orapid = 123
*** 2012-07-08 17:20:10.876
 wsd 0x1f8169a6c8, sbuf (nil), setid 9, op 0
lcuridx 0, lasz (nil)
*** 2012-07-08 17:20:10.876
ksedmp: internal or fatal error
ORA-00600: internal error code, arguments: [kcbshlc_1], [33], [], [], [], [], [], []
----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst()+31          call     ksedst1()            000000000 ? 000000001 ?
                                                   7FBFFFCEB0 ? 7FBFFFCF10 ?
                                                   7FBFFFCE50 ? 000000000 ?
ksedmp()+610         call     ksedst()             000000000 ? 000000001 ?
                                                   7FBFFFCEB0 ? 7FBFFFCF10 ?
                                                   7FBFFFCE50 ? 000000000 ?
ksfdmp()+21          call     ksedmp()             000000003 ? 000000001 ?
                                                   7FBFFFCEB0 ? 7FBFFFCF10 ?
                                                   7FBFFFCE50 ? 000000000 ?
kgerinv()+161        call     ksfdmp()             000000003 ? 000000001 ?
                                                   7FBFFFCEB0 ? 7FBFFFCF10 ?
                                                   7FBFFFCE50 ? 000000000 ?
kgeasnmierr()+163    call     kgerinv()            0066876E0 ? 2A97200260 ?
                                                   7FBFFFCF10 ? 7FBFFFCE50 ?
                                                   000000000 ? 000000000 ?
kcbshlc()+239        call     kgeasnmierr()        0066876E0 ? 2A97200260 ?
                                                   7FBFFFCF10 ? 7FBFFFCE50 ?
                                                   000000000 ? 000000021 ?
kslilcr()+770        call     kcbshlc()            0066876E0 ? 1F801DDB28 ?
                                                   7FBFFFCF10 ? 7FBFFFCE50 ?
                                                   000000000 ? 000000021 ?
ksl_cleanup()+1567   call     kslilcr()            7FBFFFCE50 ? 000000000 ?
                                                   7FBFFFDCE0 ? 1F801DDB28 ?
                                                   0066876E0 ? 000000021 ?
ksuxfl()+492         call     ksl_cleanup()        000000000 ? 000000000 ?
                                                   000000000 ? 1F801DDB28 ?
                                                   0066876E0 ? 000000021 ?
ksuxda()+55          call     ksuxfl()             1FC165B8E0 ? 000000000 ?
                                                   000000000 ? 1F801DDB28 ?
                                                   0066876E0 ? 000000021 ?
ksucln()+1390        call     ksuxda()             1FC165B8E0 ? 000000000 ?
                                                   000000000 ? 1F801DDB28 ?
                                                   0066876E0 ? 000000021 ?
ksbrdp()+794         call     ksucln()             060008100 ? 000000000 ?
                                                   FFFFFFFF9720ED9F ?
                                                   1F801DDB28 ? 0066876E0 ?
                                                   000000021 ?
opirip()+616         call     ksbrdp()             060008100 ? 000000000 ?
                                                   000000001 ? 060008100 ?
                                                   0066876E0 ? 000000021 ?
opidrv()+582         call     opirip()             000000032 ? 000000004 ?
                                                   7FBFFFF698 ? 060008100 ?
                                                   0066876E0 ? 000000021 ?
sou2o()+114          call     opidrv()             000000032 ? 000000004 ?
                                                   7FBFFFF698 ? 060008100 ?
                                                   0066876E0 ? 000000021 ?
opimai_real()+317    call     sou2o()              7FBFFFF670 ? 000000032 ?
                                                   000000004 ? 7FBFFFF698 ?
                                                   0066876E0 ? 000000021 ?
main()+116           call     opimai_real()        000000003 ? 7FBFFFF700 ?
                                                   000000004 ? 7FBFFFF698 ?
                                                   0066876E0 ? 000000021 ?
__libc_start_main()  call     main()               000000003 ? 7FBFFFF700 ?
+219                                               000000004 ? 7FBFFFF698 ?
                                                   0066876E0 ? 000000021 ?
_start()+42          call     __libc_start_main()  000713984 ? 000000001 ?
                                                   7FBFFFF848 ? 005288D00 ?
                                                   000000000 ? 000000003 ?

通过这个trace可以看出数据库运行在LINUX 64操作系统,版本是10.2.0.4。
出现错误的原因:
PMON在清理1fc165d248的时候,因为被orapid = 102持有,导致清理失败.
PMON在清理20406507f0的时候,因为被orapid = 102持有,导致清理失败.
PMON在清理1fc165f9d0的时候,因为被orapid = 123持有,导致清理失败.

查询MOS[443909.1]
发现是unpublished Bug 4723109.处理方法打上Patch 4723109.

作者：admin