oracle中zero divide,Oracle内部错误:ORA-07445[kcflfi()+466] [INT_DIVIDE_BY_ZERO]一例

一套Windows上的11.2.0.1单实例数据库在database open阶段出现了ORA-07445:core dump [kcflfi()+466] [INT_DIVIDE_BY_ZERO] [] [PC:0x500282E] [] []内部错误，具体的出错日志如下:

LOG CONTENT

=======================ALERT.LOG============================

Starting ORACLE instance (normal)

LICENSE_MAX_SESSION = 0

LICENSE_SESSIONS_WARNING = 0

Picked latch-free SCN scheme 2

Using LOG_ARCHIVE_DEST_1 parameter default value as USE_DB_RECOVERY_FILE_DEST

ARCH: Warning; less destinations available than specified

by LOG_ARCHIVE_MIN_SUCCEED_DEST init.ora parameter

Autotune of undo retention is turned on.

IMODE=BR

ILAT =84

2011-08-01 13:13:47.068000 +08:00

LICENSE_MAX_USERS = 0

SYS auditing is disabled

Starting up:

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options.

Using parameter settings in server-side spfile C:\APP\PRODUCT\11.2.0\DBHOME_1\DATABASE\SPFILEG11R2.ORA

System parameters with non-default values:

_spin_count = 2000

processes = 500

event = "10500 trace name context forever,level 8:10013 trace name context forever,level 10:

10015 trace name context forever,level 10"

sga_max_size = 600M

shared_pool_size = 152M

large_pool_size = 32M

java_pool_size = 4M

streams_pool_size = 0

_db_file_direct_io_count = 12

sga_target = 0

memory_target = 0

control_files = "C:\APP\ORADATA\G11R2\CONTROLFILE\O1_MF_6VWCSH9J_.CTL"

control_files = "C:\APP\FLASH_RECOVERY_AREA\G11R2\CONTROLFILE\O1_MF_6VWCSHNF_.CTL"

db_block_checksum = "TRUE"

db_block_size = 8192

db_cache_size = 196M

_shared_io_pool_size = 0

compatible = "11.2.0.0.0"

log_archive_dest_2 = "service=stdby optional lgwr sync affirm valid_for=(online_logfiles,all_roles)"

log_buffer = 10485760

db_create_file_dest = "C:\app\oradata"

db_recovery_file_dest = "C:\app\flash_recovery_area"

db_recovery_file_dest_size= 500000M

undo_tablespace = "UNDOTBS1"

_kgl_bucket_count = 2

remote_login_passwordfile= "EXCLUSIVE"

db_domain = ""

session_cached_cursors = 300

audit_file_dest = "C:\APP\ADMIN\G11R2\ADUMP"

optimizer_features_enable= "10.2.0.4"

audit_trail = "DB"

cell_offload_plan_display= "ALWAYS"

db_name = "G11R2"

open_cursors = 3000

_optimizer_extended_cursor_sharing_rel= "NONE"

pga_aggregate_target = 300M

diagnostic_dest = "C:\APP"

2011-08-01 13:13:48.164000 +08:00

PMON started with pid=2, OS id=984

VKTM started with pid=3, OS id=3656 at elevated priority

VKTM running at (10)millisec precision with DBRM quantum (100)ms

GEN0 started with pid=4, OS id=5824

DIAG started with pid=5, OS id=5832

DBRM started with pid=6, OS id=2784

PSP0 started with pid=7, OS id=2500

DIA0 started with pid=8, OS id=5320

MMAN started with pid=9, OS id=4128

DBW0 started with pid=10, OS id=5852

LGWR started with pid=11, OS id=3960

CKPT started with pid=12, OS id=4472

SMON started with pid=13, OS id=5788

RECO started with pid=14, OS id=6036

MMON started with pid=15, OS id=5740

MMNL started with pid=16, OS id=2112

ORACLE_BASE from environment = C:\app

alter database mount exclusive

2011-08-01 13:13:52.390000 +08:00

Sweep [inc][135908]: completed

NSS2 started with pid=19, OS id=2728

Sweep [inc][135901]: completed

Successful mount of redo thread 1, with mount id 2704081164

Database mounted in Exclusive Mode

2011-08-01 13:13:53.413000 +08:00

Lost write protection disabled

2011-08-01 13:13:54.578000 +08:00

Sweep [inc][135897]: completed

Sweep [inc2][135908]: completed

Sweep [inc2][135901]: completed

Sweep [inc2][135897]: completed

2011-08-01 13:13:55.788000 +08:00

Completed: alter database mount exclusive

alter database open

Beginning crash recovery of 1 threads

parallel recovery started with 3 processes

2011-08-01 13:13:56.959000 +08:00

Started redo scan

Completed redo scan

read 0 KB redo, 0 data blocks need recovery

Started redo application at

Thread 1: logseq 867, block 88140, scn 9122496

Recovery of Online Redo Log: Thread 1 Group 3 Seq 867 Reading mem 0

Mem# 0: C:\APP\ORADATA\G11R2\ONLINELOG\O1_MF_3_6VWCSMPO_.LOG

Mem# 1: C:\APP\FLASH_RECOVERY_AREA\G11R2\ONLINELOG\O1_MF_3_6VWCSNGX_.LOG

Completed redo application of 0.00MB

Completed crash recovery at

Thread 1: logseq 867, block 88140, scn 9142497

0 data blocks read, 0 data blocks written, 0 redo k-bytes read

2011-08-01 13:13:58.738000 +08:00

LGWR: STARTING ARCH PROCESSES

ARC0 started with pid=22, OS id=4784

2011-08-01 13:13:59.765000 +08:00

ARC0: Archival started

LGWR: STARTING ARCH PROCESSES COMPLETE

ARC0: STARTING ARCH PROCESSES

ARC1 started with pid=24, OS id=2780

ARC2 started with pid=25, OS id=1288

ARC1: Archival started

LGWR: Primary database is in MAXIMUM AVAILABILITY mode

ARC2: Archival started

ARC1: Becoming the 'no FAL' ARCH

ARC1: Becoming the 'no SRL' ARCH

ARC2: Becoming the heartbeat ARCH

LGWR: Destination LOG_ARCHIVE_DEST_1 is not serviced by LGWR

ARC3 started with pid=26, OS id=3876

2011-08-01 13:14:00.828000 +08:00

ARC3: Archival started

ARC0: STARTING ARCH PROCESSES COMPLETE

NSS2 started with pid=19, OS id=5156

2011-08-01 13:14:29.008000 +08:00

ORA-16198: LGWR received timedout error from KSR

2011-08-01 13:14:35.980000 +08:00

Errors in file c:\app\diag\rdbms\g11r2\g11r2\trace\g11r2_lgwr_3960.trc:

ORA-16198: Timeout incurred on internal channel during remote archival

LGWR: Error 16198 verifying archivelog destination LOG_ARCHIVE_DEST_2

Destination LOG_ARCHIVE_DEST_2 is UNSYNCHRONIZED

LGWR: Continuing...

ARCH: LGWR is scheduled to archive destination LOG_ARCHIVE_DEST_2 after log switch

2011-08-01 13:14:38.629000 +08:00

Trying to expand controlfile section 11 for Oracle Managed Files

Exception [type: INT_DIVIDE_BY_ZERO, ] [] [PC:0x500282E, __VInfreq__kcflfi()+466]

Errors in file c:\app\diag\rdbms\g11r2\g11r2\trace\g11r2_arc0_4784.trc (incident=136091):

ORA-07445: exception encountered: core dump [kcflfi()+466] [INT_DIVIDE_BY_ZERO] [] [PC:0x500282E] [] []

Incident details in: c:\app\diag\rdbms\g11r2\g11r2\incident\incdir_136091\g11r2_arc0_4784_i136091.trc

2011-08-01 13:14:40.283000 +08:00

Trace dumping is performing id=[cdmp_20110801131440]

2011-08-01 13:14:52.417000 +08:00

Sweep [inc][136091]: completed

Sweep [inc2][136091]: completed

2011-08-01 13:14:59.805000 +08:00

ARC2: Detected ARCH process failure

ARC2: STARTING ARCH PROCESSES

ARC0 started with pid=19, OS id=5016

2011-08-01 13:15:00.836000 +08:00

ARC0: Archival started

ARC2: STARTING ARCH PROCESSES COMPLETE

2011-08-01 13:15:36.689000 +08:00

Deleted Oracle managed file C:\APP\FLASH_RECOVERY_AREA\G11R2\ARCHIVELOG\2011_08_01\O1_MF_1_866_73DFKWRK_.ARC

2011-08-01 13:15:38.013000 +08:00

Error 12154 received logging on to the standby

Errors in file c:\app\diag\rdbms\g11r2\g11r2\trace\g11r2_ora_4852.trc:

ORA-12154: TNS:could not resolve the connect identifier specified

ARCH: Error 12154 Creating archive log file to 'stdby'

Trying to expand controlfile section 11 for Oracle Managed Files

Exception [type: INT_DIVIDE_BY_ZERO, ] [] [PC:0x500282E, __VInfreq__kcflfi()+466]

Errors in file c:\app\diag\rdbms\g11r2\g11r2\trace\g11r2_ora_4852.trc (incident=136051):

ORA-07445: exception encountered: core dump [kcflfi()+466] [INT_DIVIDE_BY_ZERO] [] [PC:0x500282E] [] []

Incident details in: c:\app\diag\rdbms\g11r2\g11r2\incident\incdir_136051\g11r2_ora_4852_i136051.trc

2011-08-01 13:15:39.680000 +08:00

Trace dumping is performing id=[cdmp_20110801131539]

2011-08-01 13:15:42.782000 +08:00

PMON (ospid: 984): terminating the instance due to error 397

2011-08-01 13:15:50.520000 +08:00

Instance terminated by PMON, pid = 984

=============================g11r2_ora_4852_i136051.trc=============================

Dump file c:\app\diag\rdbms\g11r2\g11r2\incident\incdir_136051\g11r2_ora_4852_i136051.trc

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

Windows NT Version V6.1 Service Pack 1

CPU : 4 - type 586, 2 Physical Cores

Process Affinity : 0x0x00000000

Memory (Avail/Total): Ph:2122M/3566M, Ph+PgF:5413M/7130M, VA:1084M/2047M

Instance name: g11r2

Redo thread mounted by this instance: 1

Oracle process number: 17

Windows thread id: 4852, image: ORACLE.EXE (SHAD)

*** 2011-08-01 13:15:38.527

*** SESSION ID:(197.1) 2011-08-01 13:15:38.527

*** CLIENT ID:() 2011-08-01 13:15:38.527

*** SERVICE NAME:() 2011-08-01 13:15:38.527

*** MODULE NAME:(oradim.exe) 2011-08-01 13:15:38.527

*** ACTION NAME:() 2011-08-01 13:15:38.527

Dump continued from file: c:\app\diag\rdbms\g11r2\g11r2\trace\g11r2_ora_4852.trc

ORA-07445: exception encountered: core dump [kcflfi()+466] [INT_DIVIDE_BY_ZERO] [] [PC:0x500282E] [] []

========= Dump for incident 136051 (ORA 7445 [kcflfi()+466]) ========

----- Beginning of Customized Incident Dump(s) -----

Exception [type: INT_DIVIDE_BY_ZERO, ] [] [PC:0x500282E, __VInfreq__kcflfi()+466]

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

Process Id: 0x000010bc Thread Id : 0x000012f4 Time : Mon Aug 01 13:15:38

Excp. Code: 0xc0000094 Excp. Type: INT_DIVIDE Flags: 0x00000000

------------------- Registers ----------------------------

eip = 0500282e esp = 0d9f525c ebp = 0d9f577c edi = 37eefe00 esi = 00000265

eax = 00000265 ebx = 00000000 ecx = 089ee234 edx = 00000000

ecs = 0000001b eds = 00000023 ees = 00000023 ess = 00000023

egs = 00000000 efs = 0000003b

eflags = 00010246

------------------- End of Registers ---------------------

*** 2011-08-01 13:15:38.536

dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x3, level=3, mask=0x0)

----- Current SQL Statement for this session (sql_id=a01hp0psv0rrh) -----

alter database open

----------- messages from pre-loading .sym files:

Symbol file C:\app\product\11.2.0\dbhome_1\RDBMS\ADMIN\oracommon11.SYM does not match binary.

Symbol TimeStamp=4bb5eaac, Module TimeStamp=0 are different

Symbol file C:\app\product\11.2.0\dbhome_1\RDBMS\ADMIN\oraclsra11.SYM does not match binary.

Symbol TimeStamp=4bb4cf99, Module TimeStamp=0 are different

----------- end of messages from pre-loading .sym files

----- Call Stack Trace -----

calling call entry argument values in hex

location type point (? means dubious value)

-------------------- -------- -------------------- ----------------------------

Symbol file C:\app\product\11.2.0\dbhome_1\BIN\oracommon11.SYM does not match binary.

Symbol TimeStamp=4bb5eaac, Module TimeStamp=0 are different

Symbol file C:\app\product\11.2.0\dbhome_1\BIN\oraclsra11.SYM does not match binary.

Symbol TimeStamp=4bb4cf99, Module TimeStamp=0 are different

EnumerateLoadedModules64 failed with error -1073741819

Symbol file oraclsra11.SYM does not match binary.

Symbol TimeStamp=4bb4cf99, Module TimeStamp=0 are different

Symbol file oracommon11.SYM does not match binary.

Symbol TimeStamp=4bb5eaac, Module TimeStamp=0 are different

__VInfreq__kcflfi() 00000000

+466

_kccrszf()+287 CALLrel _kcflfi() 0 318345B8 34 31C0DD40 4000

265 4 7FFFFFFF 1 0 0

_kccrsd_expd()+1418 CALLrel _kccrszf() D9F7CEC 268 264

_kccwnc_reuse_expan CALLrel _kccrsd_expd() D9F7CEC B 38

d()+640

__VInfreq__kccwnc() CALLrel _kccwnc_reuse_expan D9F7CEC B 26

+235 d()

_krse_arc_complete( CALLrel _kccwnc() D9F7CEC D9F6D38 B

)+1615

_krse_arc_driver_co CALLrel _krse_arc_complete( D9F78AC

re()+1307 )

_krse_arc_driver()+ CALLrel _krse_arc_driver_co D9F7CEC 1 D9F7C6C 0 0 D9F7CC8

274 re() 0 0 0 0 0 0 0

_krsq_arch_to_force CALLrel _krse_arc_driver() D9F7CEC 1 D9F7C6C 0 0 D9F7CC8

_switch()+196 0 0 0 0 0 0 0

__VInfreq__kcttsc() CALLrel _krsq_arch_to_force D9F7CEC 1

+129 _switch()

_kcfopd()+1504 CALLrel _kcttsc() 2

_adbdrv()+16700 CALLrel _kcfopd() 0 0 0 0 D9FBBF8

_opiexe()+13594 CALLrel _adbdrv() 4A C0000094 33644518 D9FBD38

6D60697 2F3FC5F0

_opiosq0()+6248 CALLrel _opiexe() 4 0 D9FC704

_kpooprx()+277 CALLrel _opiosq0() 3 E D9FC970 A4 0

_kpoal8()+632 CALLrel _kpooprx() D9FF074 D9FD3F8 13 1 0 A4

_opiodr()+1248 CALLreg 00000000 5E 1C D9FF070

___dyn_tls_init_cal CALLreg 00000000 5E 1C D9FF070 1

lback()+2935122

_opitsk()+1404 CALL??? 00000000 C9A10E8 5E D9FF070 0 D9FED00

D9FF19C 53E52E 0 D9FF1C8

_opiino()+980 CALLrel _opitsk() 0 0

_opiodr()+1248 CALLreg 00000000 3C 4 D9FFBC4

_opidrv()+1201 CALLrel _opiodr() 3C 4 D9FFBC4 0

_sou2o()+55 CALLrel _opidrv() 3C 4 D9FFBC4

_opimai_real()+124 CALLrel _sou2o() D9FFBD4 3C 4 D9FFBC4

_opimai()+125 CALLrel _opimai_real() 2 D9FFBFC

_OracleThreadStart@ CALLrel _opimai() 2 D9FFF3C 0 70 FFFFFFFF

4()+830 FFFFFFFF

___dyn_tls_init_cal CALLptr 00000000 901FF6C D9FFFD4 776437F5

lback()+366382316 901FF6C 765D34CB 0

___dyn_tls_init_cal CALLreg 00000000 901FF6C 765D34CB 0 0 901FF6C

lback()+367384440 0

___dyn_tls_init_cal CALLrel ___dyn_tls_init_cal 401326 901FF6C 0 0 0 0

lback()+367384392 lback()+367384403

00000000 CALL??? 00000000

--------------------- Binary Stack Dump ---------------------

..................

从以上日志中可以看到在”Trying to expand controlfile section 11 for Oracle Managed Files“扩扎控制文件过程中出现了

_kccwnc_reuse_expan->_kccrsd_expd->_kccrszf->_kcflfi->_VInfreq__kcflfi()

函数的7445错误,kcf意为(manages and coordinates operations on the control file(s),kcf.c)，是在处理日志文件中引发了INT_DIVIDE_BY_ZERO除数为零的代码bug。

通过7445和kcflfi关键词在MOS上搜索没有太大的发现，说明该Bug的处罚几率非常低，正好让我碰到说明是某些特殊参数的设置引起了该问题。

目标锁定启动日志中的非默认隐藏参数"_db_file_direct_io_count"，该参数决定了直接路径读写的IO大小，从9i开始该参数的单位调整为bytes而非原先的blocks，之前因为对该参数进行一些测试所以设置了一个较小值。

Parameter: DB_FILE_DIRECT_IO_COUNT

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Versions:8.0 - 8.1

This parameter is hidden in 9.0 onwards.

Parameter type: integer

Parameter class: dynamic, scope = ALTER SYSTEM DEFERRED

Default value: 64

Range of values: operating system-dependent

Description:

~~~~~~~~~~~~

DB_FILE_DIRECT_IO_COUNT is used to specify the number of blocks to be used

for IO operations done by backup, restore or direct path read and write

functions. The IO buffer size is a product of DB_FILE_DIRECT_IO_COUNT and

DB_BLOCK_SIZE. The IO buffer size cannot exceed max_IO_size for your

platform.

Assigning a high value to this parameter results in greater use of PGA or

SGA memory.

o In Oracle8i, minimize the number of I/O requests by setting the

DB_FILE_DIRECT_IO_COUNT instance parameter so that

DB_BLOCK_SIZE x DB_FILE_DIRECT_IO_COUNT = max_io_size of system

In Oracle8i the default for this is 64 blocks.

(In Oracle9i, it is replaced by _DB_FILE_DIRECT_IO_COUNT which governs

the size of direct I/Os in BYTES (not blocks). The default is 1Mb but

will be sized down if the max_io_size of the system is smaller.)

ORA-19863 during RMAN duplicate

Applies to:

Oracle Server - Enterprise Edition - Version: 10.2.0.3

This problem can occur on any platform.

Symptoms

-- Problem Statement:

Duplicate failed during the datafile restore stage:

Starting restore at 2008-Apr-09 09:28:24

using channel ORA_AUX_DISK_1

channel ORA_AUX_DISK_1: starting datafile backupset restore

channel ORA_AUX_DISK_1: specifying datafile(s) to restore from backup set

restoring datafile 00003 to /u06/oradata/hcmprdc/sysaux01.dbf

...

restoring datafile 00121 to /u06/oradata/hcmprdc/waapp.dbf

channel ORA_AUX_DISK_1: reading from backup piece

/u04/oradata/flash_recovery_area/HCMPRD/mdjd8s5v_1_1

RMAN-00571: ===========================================================

RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============

RMAN-00571: ===========================================================

RMAN-03002: failure of Duplicate Db command at 04/09/2008 09:28:28

RMAN-03015: error occurred in stored script Memory Script

ORA-19870: error reading backup piece /u04/oradata/flash_recovery_area/HCMPRD/mdjd8s5v_1_1

ORA-19863: device block size 1040384 is larger than max allowed: 262144

Cause

The database parameter _db_file_direct_io_count in the target and auxiliary instance does not match.

Solution

-- To implement the solution:

Ensure that parameter _db_file_direct_io_count on the target and auxiliary database the same

_DB_FILE_DIRECT_IO_COUNT need to be set to the same value between the source database

where the backup was taken and the target database where the backup is being restored.

2.0 Size of Input/Output Buffers

================================

a. input buffers

----------------

NOTE : DB_FILE_DIRECT_IO_COUNT is not available in Oracle9i onwards.

In Oracle9i, it is replaced by a hidden _DB_FILE_DIRECT_IO_COUNT which

governs the size of direct I/Os in BYTES (not blocks). The default is

1Mb butwill be sized down if the max_io_size of the system is smaller.

The input buffer size is:

buffersize = db_block_size * db_file_direct_io_count

As there are 4 input buffers, the total input buffer memory use per channel is:

memory(input) = #buffers * #files * buffersize

= 4 * #files * buffersize

For example, if 2 channels are used, and each of these channels backs up 3

files, then for each channel

memory(input) = 4 * 3 * db_block_size * db_file_direct_io_count

b. output buffers

-----------------

For disk channels, the output buffer size is:

buffersize = db_block_size * db_file_direct_io_count

For SBT_TAPE channels, the output buffer size in Oracle8/8i is o/s dependant. (On Solaris,

this defaults to 64k) On 9i/10g it defaults to 256k for all platforms. The BLKSIZE argument to 'allocate channel...' can be

used to override the default value.

As there are 4 output buffers,

memory(output) = #buffers * buffersize

= 4 * buffersize

一般来说使用该隐藏参数的默认值即可，通过重置该参数后修复启动问题:

SQL> select * from v$version;

BANNER

--------------------------------------------------------------------------------

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

PL/SQL Release 11.2.0.1.0 - Production

CORE 11.2.0.1.0 Production

TNS for 32-bit Windows: Version 11.2.0.1.0 - Production

NLSRTL Version 11.2.0.1.0 - Production

SQL> alter system reset "_db_file_direct_io_count" scope=spfile;

System altered.

SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ

FROM SYS.x$ksppi x, SYS.x$ksppcv y

WHERE x.inst_id = USERENV ('Instance')

AND y.inst_id = USERENV ('Instance')

AND x.indx = y.indx

AND x.ksppinm LIKE '%db_file_direct_io_count%'

/

NAME VALUE DESCRIB

------------------------------ -------------------- ------------------------------

_db_file_direct_io_count 1048576 Sequential I/O buf size

windows上的11gr2默认该参数为1MB