博客

故障描述：

一台老物理服务器搬迁，启动操作系统后尝试启动数据库报错

SQL> startup
ORACLE instance started.

Total System Global Area 2.0176E+10 bytes
Fixed Size		    2261928 bytes
Variable Size		 5167385688 bytes
Database Buffers	 1.4965E+10 bytes
Redo Buffers		   41463808 bytes
Database mounted.
ORA-00600: internal error code, arguments: [kcm_headroom_warn_1], [], [], [],
[], [], [], [], [], [], [], []

数据库告警日志如下:

Wed Jan 01 15:14:49 2014
Errors in file /u01/app/oracle/diag/rdbms/ORCL/ORCL/trace/ORCL_p022_8900.trc:
ORA-01578: ORACLE data block corrupted (file # 9, block # 2966543)
ORA-01110: data file 9: '/oracle/oradate/nsfw_date1.dbf'
ORA-10564: tablespace NAFW_DATE
ORA-01110: data file 9: '/oracle/oradate/nsfw_date1.dbf'
ORA-10560: block type 'TRANSACTION MANAGED DATA BLOCK'
ORA-00607: Internal error occurred while making a change to a data block
ORA-00600: internal error code, arguments: [2252], [4606], [2066037001], [4234], [3231154176], [], [], [], [], [], [], []
Wed Jan 01 15:14:49 2014
Completed crash recovery at
 Thread 1: logseq 5813458, block 5729, scn 19784685422394
 269 data blocks read, 269 data blocks written, 2611 redo k-bytes read
************************************************************
Warning: The SCN headroom for this database is only -4511 hours!
************************************************************
Errors in file /u01/app/oracle/diag/rdbms/ORCL/ORCL/trace/ORCL_ora_8839.trc  (incident=1019669):
ORA-00600: internal error code, arguments: [kcm_headroom_warn_1], [], [], [], [], [], [], [], [], [], [], []
Incident details in: /u01/app/oracle/diag/rdbms/ORCL/ORCL/incident/incdir_1019669/ORCL_ora_8839_i1019669.trc
Wed Jan 01 15:14:51 2014
Dumping diagnostic data in directory=[cdmp_20140101151451], requested by (instance=1, osid=8839), summary=[incident=1019669].
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Errors in file /u01/app/oracle/diag/rdbms/ORCL/ORCL/trace/ORCL_ora_8839.trc:
ORA-00600: internal error code, arguments: [kcm_headroom_warn_1], [], [], [], [], [], [], [], [], [], [], []
ORA-600 signalled during: ALTER DATABASE OPEN...
Wed Jan 01 15:14:52 2014
Sweep [inc][1019669]: completed
Sweep [inc2][1019669]: completed
Wed Jan 01 15:17:58 2014

看这个日志我们可以发现日期明显不对，跟当前时间相差九年

问题处理：

查询根据报错信息

ORA-00600: internal error code, arguments: [kcm_headroom_warn_1]

查询MOS，因为时间相差过大导致数据库scn号出了问题，数据库无法启动，需要修改操作系统时间

###查看当前系统时间
# date
2014年 01月 01日 星期三 15:33:55 CST

###修改当前系统日期
# date -s 2023/04/20
2023年 04月 20日 星期四 00:00:00 CST

#修改当前系统时间
# date -s 11:32:00
2023年 04月 20日 星期四 11:32:00 CST

###将当前系统时间写入硬件
# hwclock -w

###再次查看当前操作系统时间
# date
2023年 04月 20日 星期四 11:32:09 CST

修改操作系统时间时，数据库告警日志如下：

Thu Apr 20 00:00:00 2023
Warning: VKTM detected a time drift.
Time drifts can result in an unexpected behavior such as time-outs. Please check trace file for more details.
Thu Apr 20 11:32:00 2023
Warning: VKTM detected a time drift.
Time drifts can result in an unexpected behavior such as time-outs. Please check trace file for more details.

再次尝试启动数据库

SQL> startup
ORACLE instance started.

Total System Global Area 2.0176E+10 bytes
Fixed Size		    2261928 bytes
Variable Size		 5368712280 bytes
Database Buffers	 1.4764E+10 bytes
Redo Buffers		   41463808 bytes
Database mounted.
Database opened.
SQL>

监控数据库告警日志，并无异常，数据库启动成功，启动监听

Thu Apr 20 11:32:29 2023
Shutting down instance (immediate)
Shutting down instance: further logons disabled
Stopping background process MMNL
Stopping background process MMON
Thu Apr 20 11:32:42 2023
License high water mark = 34
All dispatchers and shared servers shutdown
ALTER DATABASE CLOSE NORMAL
ORA-1109 signalled during: ALTER DATABASE CLOSE NORMAL...
ALTER DATABASE DISMOUNT
Shutting down archive processes
Archiving is disabled
Completed: ALTER DATABASE DISMOUNT
ARCH: Archival disabled due to shutdown: 1089
Shutting down archive processes
Archiving is disabled
ARCH: Archival disabled due to shutdown: 1089
Thu Apr 20 11:32:43 2023
Stopping background process VKTM
Shutting down archive processes
Archiving is disabled
Thu Apr 20 11:32:46 2023
Instance shutdown complete
Thu Apr 20 11:33:31 2023
Starting ORACLE instance (normal)
************************ Large Pages Information *******************
Per process system memlock (soft) limit = 64 KB
 
Total Shared Global Region in Large Pages = 0 KB (0%)
 
Large Pages used by this instance: 0 (0 KB)
Large Pages unused system wide = 0 (0 KB)
Large Pages configured system wide = 0 (0 KB)
Large Page size = 2048 KB
 
RECOMMENDATION:
  Total System Global Area size is 19 GB. For optimal performance,
  prior to the next instance restart:
  1. Increase the number of unused large pages by 
 at least 9665 (page size 2048 KB, total size 19 GB) system wide to
  get 100% of the System Global Area allocated with large pages
  2. Large pages are automatically locked into physical memory.
 Increase the per process memlock (soft) limit to at least 19 GB to lock
 100% System Global Area 's large pages into physical memory'
********************************************************************
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Initial number of CPU is 64
Number of processor cores in the system is 32
Number of processor sockets in the system is 4
CELL communication is configured to use 0 interface(s):
CELL IP affinity details:
    NUMA status: NUMA system w/ 4 process groups
    cellaffinity.ora status: cannot find affinity map at '/etc/oracle/cell/network-config/cellaffinity.ora' (see trace file for details)
CELL communication will use 1 IP group(s):
    Grp 0: 
Picked latch-free SCN scheme 3
Autotune of undo retention is turned on. 
IMODE=BR
ILAT =830
LICENSE_MAX_USERS = 0
SYS auditing is disabled
NUMA system with 4 nodes detected
Starting up:
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options.
ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_2
System name:	Linux
Node name:	jkzh.data
Release:	2.6.32-358.el6.x86_64
Version:	#1 SMP Tue Jan 29 11:47:41 EST 2013
Machine:	x86_64
Using parameter settings in server-side spfile /u01/app/oracle/product/11.2.0/dbhome_2/dbs/spfileORCL.ora
System parameters with non-default values:
  processes                = 5000
  sga_target               = 19328M
  control_files            = "/u01/app/oracle/oradata/ORCL/control01.ctl"
  control_files            = "/u01/app/oracle/fast_recovery_area/ORCL/control02.ctl"
  control_file_record_keep_time= 31
  db_block_size            = 8192
  _external_scn_rejection_threshold_hours= 24
  compatible               = "11.2.0.4.0"
  log_archive_dest_1       = "location=/u01/app/oracle/archivelog/"
  db_recovery_file_dest    = "/home/oracle/fast_recovery_area"
  db_recovery_file_dest_size= 450G
  enable_goldengate_replication= TRUE
  undo_tablespace          = "UNDOTBS1"
  remote_login_passwordfile= "EXCLUSIVE"
  db_domain                = ""
  dispatchers              = "(PROTOCOL=TCP) (SERVICE=ORCLXDB)"
  cursor_sharing           = "FORCE"
  audit_file_dest          = "/u01/app/oracle/admin/ORCL/adump"
  open_links               = 50
  open_links_per_instance  = 50
  audit_trail              = "DB"
  db_name                  = "ORCL"
  open_cursors             = 5000
  pga_aggregate_target     = 6437M
  diagnostic_dest          = "/u01/app/oracle"
Thu Apr 20 11:33:33 2023
PMON started with pid=2, OS id=15125 
Thu Apr 20 11:33:33 2023
PSP0 started with pid=3, OS id=15133 
Thu Apr 20 11:33:34 2023
VKTM started with pid=4, OS id=15158 at elevated priority
VKTM running at (1)millisec precision with DBRM quantum (100)ms
Thu Apr 20 11:33:34 2023
GEN0 started with pid=5, OS id=15162 
Thu Apr 20 11:33:34 2023
DIAG started with pid=6, OS id=15164 
Thu Apr 20 11:33:34 2023
DBRM started with pid=7, OS id=15166 
Thu Apr 20 11:33:34 2023
DIA0 started with pid=8, OS id=15168 
Thu Apr 20 11:33:34 2023
MMAN started with pid=9, OS id=15170 
Thu Apr 20 11:33:34 2023
DBW0 started with pid=10, OS id=15172 
Thu Apr 20 11:33:34 2023
DBW1 started with pid=11, OS id=15174 
Thu Apr 20 11:33:34 2023
DBW2 started with pid=12, OS id=15176 
Thu Apr 20 11:33:34 2023
DBW3 started with pid=13, OS id=15178 
Thu Apr 20 11:33:34 2023
DBW4 started with pid=14, OS id=15180 
Thu Apr 20 11:33:34 2023
DBW5 started with pid=15, OS id=15182 
Thu Apr 20 11:33:34 2023
DBW6 started with pid=16, OS id=15184 
Thu Apr 20 11:33:34 2023
DBW7 started with pid=17, OS id=15186 
Thu Apr 20 11:33:34 2023
LGWR started with pid=18, OS id=15188 
Thu Apr 20 11:33:34 2023
CKPT started with pid=19, OS id=15190 
Thu Apr 20 11:33:34 2023
SMON started with pid=20, OS id=15192 
Thu Apr 20 11:33:34 2023
RECO started with pid=21, OS id=15194 
Thu Apr 20 11:33:34 2023
MMON started with pid=22, OS id=15196 
Thu Apr 20 11:33:34 2023
MMNL started with pid=23, OS id=15198 
starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)(PROTOCOL=TCP))'...
starting up 1 shared server(s) ...
ORACLE_BASE from environment = /u01/app/oracle
Thu Apr 20 11:33:34 2023
ALTER DATABASE   MOUNT
Successful mount of redo thread 1, with mount id 1963447886
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: ALTER DATABASE   MOUNT
Thu Apr 20 11:33:39 2023
ALTER DATABASE OPEN
LGWR: STARTING ARCH PROCESSES
Thu Apr 20 11:33:39 2023
ARC0 started with pid=27, OS id=15210 
ARC0: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Thu Apr 20 11:33:40 2023
ARC1 started with pid=28, OS id=15212 
Thu Apr 20 11:33:40 2023
ARC2 started with pid=29, OS id=15214 
Thread 1 advanced to log sequence 5813459 (thread open)
Thu Apr 20 11:33:40 2023
ARC3 started with pid=30, OS id=15216 
ARC1: Archival started
ARC2: Archival started
ARC2: Becoming the 'no FAL' ARCH
ARC2: Becoming the 'no SRL' ARCH
ARC1: Becoming the heartbeat ARCH
Thread 1 opened at log sequence 5813459
  Current log# 2 seq# 5813459 mem# 0: /u01/app/oracle/oradata/ORCL/redo02.log
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
SMON: enabling cache recovery
ARC3: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
[15208] Successfully onlined Undo Tablespace 2.
Undo initialization finished serial:0 start:1356044 end:1356584 diff:540 (5 seconds)
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery
Database Characterset is AL32UTF8
No Resource Manager plan active
Archived Log entry 5809643 added for thread 1 sequence 5813458 ID 0x67ecf084 dest 1:
replication_dependency_tracking turned off (no async multimaster replication found)
Thu Apr 20 11:33:49 2023
Starting background process QMNC
Thu Apr 20 11:33:49 2023
QMNC started with pid=31, OS id=15220 
Thu Apr 20 11:33:51 2023
db_recovery_file_dest_size of 460800 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Completed: ALTER DATABASE OPEN
Thu Apr 20 11:33:54 2023

至此，问题解决，有什么问题欢迎留言

Document ID: 2147012