ORACLE startup報錯之ORA-01154&&ORA-01155&&ORA-01033&&ORA-03113

清風艾艾發表於2017-08-02
    今天,一實施同事求助,說一地市oracle資料庫無法透過遠端連線,連線報錯如圖:
作業系統:windows server2008 R2 
資料庫版本:oracle 11.2.0.1

初看報錯貌似資料庫正處在開啟或關閉的過程中。檢視告警日誌,最近的一次資料庫啟動發生在上午10:50,部分告警日誌如下:
Wed Aug 02 10:51:48 2017
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 3
Wed Aug 02 10:52:01 2017
Autotune of undo retention is turned on. 
IMODE=BR
ILAT =86
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Starting up:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options.
然後,實施同事說,他中午那會startup了一下資料庫,但是資料庫停在了:“資料庫裝載完畢。”好長一段時間,如圖:

然後,啟動就報了ORA-03113,如果所示:

然後,他又說,資料庫啟動失敗後,他接著重啟了資料庫伺服器主機,然後但是問題依舊。
接下來是我的處理過程:
登入資料庫伺服器,
檢視主機狀態,CPU、磁碟IO、記憶體等資源很空閒
檢視資料庫服務和監聽服務均已啟動
登入資料庫sqlplus檢視資料庫例項當前狀態是mounted
Microsoft Windows [版本 6.1.7601]
版權所有 (c) 2009 Microsoft Corporation。保留所有權利。
C:\Users\Administrator>sqlplus / as sysdba
SQL*Plus: Release 11.2.0.1.0 Production on 星期三 8月 2 13:48:40 2017
Copyright (c) 1982, 2010, Oracle.  All rights reserved.
連線到:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> select status from v$instance;
STATUS
------------
MOUNTED
--嘗試open資料庫報ORA-01154,日誌如下:
SQL> alter database open;
alter database open
*
第 1 行出現錯誤:
ORA-01154: 資料庫忙。現在不允許開啟, 關閉, 裝載和卸裝
接下來,重啟了作業系統的Oracle例項服務,然後重新啟動,啟動依然停留在“資料庫裝載完畢”,日誌如下:
從 Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options(情況複雜) 斷開
C:\Users\Administrator>sqlplus / as sysdba
SQL*Plus: Release 11.2.0.1.0 Production on 星期三 8月 2 13:58:58 2017
Copyright (c) 1982, 2010, Oracle.  All rights reserved.
已連線到空閒例程。
SQL> startup
ORACLE 例程已經啟動。
Total System Global Area 2.0577E+10 bytes
Fixed Size                  2184672 bytes
Variable Size            8589937184 bytes
Database Buffers         1.1945E+10 bytes
Redo Buffers               39743488 bytes
資料庫裝載完畢。
--觀察資料庫告警日誌,12:59分資料庫有ORA-00949,有例項程式超時等待
Wed Aug 02 12:59:29 2017
Errors in file d:\oraclehome\oracle\diag\rdbms\bmi\bmi\trace\bmi_arc1_3604.trc  (incident=164377):
ORA-00494: 持有入隊 [CF] 的時間過長 (超過 900 秒) (由 'inst 1, osid 3084')
Incident details in: d:\oraclehome\oracle\diag\rdbms\bmi\bmi\incident\incdir_164377\bmi_arc1_3604_i164377.trc
Killing enqueue blocker (pid=3084) on resource CF-00000000-00000000 by (pid=3604)
 by killing session 638.1
Killing enqueue blocker (pid=3084) on resource CF-00000000-00000000 by (pid=3604)
 by terminating the process
ARC1 (ospid: 3604): terminating the instance due to error 2103
--13:20資料庫被重啟,日誌如下(猜想是主機重啟後的自動重啟)
Wed Aug 02 13:19:29 2017
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 3
Autotune of undo retention is turned on. 
IMODE=BR
ILAT =86
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Starting up:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options.
--觀察到TNS連線報錯:ORA-01155
Wed Aug 02 13:34:35 2017
Errors in file d:\oraclehome\oracle\diag\rdbms\bmi\bmi\trace\bmi_m000_4620.trc:
ORA-01155: 正在開啟, 關閉, 裝載或卸裝資料庫
Wed Aug 02 13:48:39 2017
TNS-12535: TNS: 操作超時
    ns secondary err code: 12606
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=fe80::94b2:4372:a24c:4b6e%11)(PORT=49179))
WARNING: inbound connection timed out (ORA-3136)
Wed Aug 02 13:49:38 2017
Errors in file d:\oraclehome\oracle\diag\rdbms\bmi\bmi\trace\bmi_m000_5596.trc:
ORA-01155: 正在開啟, 關閉, 裝載或卸裝資料庫
再看自己重啟後的告警日誌
Wed Aug 02 13:59:07 2017
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 3
Autotune of undo retention is turned on. 
IMODE=BR
ILAT =86
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Starting up:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options.
......
Wed Aug 02 13:59:12 2017
ALTER DATABASE   MOUNT
Wed Aug 02 13:59:12 2017
MMNL started with pid=17, OS id=2012 
Successful mount of redo thread 1, with mount id 271372528
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: ALTER DATABASE   MOUNT
Wed Aug 02 13:59:17 2017
ALTER DATABASE OPEN
Beginning crash recovery of 1 threads
 parallel recovery started with 15 processes
Wed Aug 02 13:59:41 2017
Started redo scan
Wed Aug 02 14:01:55 2017
Completed redo scan
 read 8951211 KB redo, 764700 data blocks need recovery
Wed Aug 02 14:03:22 2017
Started redo application at
 Thread 1: logseq 364892, block 508132
Recovery of Online Redo Log: Thread 1 Group 7 Seq 364892 Reading mem 0
  Mem# 0: D:\ORACLEHOME\ORACLE\ORADATA\BMI\REDO07_01.LOG
  Mem# 1: D:\ORACLEHOME\ORACLE\ORADATA\BMI\REDO07_02.LOG
Recovery of Online Redo Log: Thread 1 Group 21 Seq 364893 Reading mem 0
  Mem# 0: D:\ORACLEHOME\ORACLE\ORADATA\BMI\REDO21_01.LOG
  Mem# 1: D:\ORACLEHOME\ORACLE\ORADATA\BMI\REDO21_02.LOG
從啟動告警日誌可以看到,資料庫肯定被異常終止過,當前資料庫增在從redo日誌恢復,此時需要耐心等待;再次詢問實施同事並讓其關閉遠端的所有oracle客戶端程式。
然後等待20分鐘,資料庫完成了open操作
Wed Aug 02 14:19:19 2017
Completed crash recovery at
 Thread 1: logseq 364905, block 820661, scn 14976863197959
 764700 data blocks read, 474332 data blocks written, 8951211 redo k-bytes read
Wed Aug 02 14:19:37 2017
LGWR: STARTING ARCH PROCESSES
Wed Aug 02 14:19:37 2017
ARC0 started with pid=37, OS id=1072 
ARC0: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Wed Aug 02 14:19:38 2017
ARC1 started with pid=38, OS id=5408 
Wed Aug 02 14:19:38 2017
ARC2 started with pid=39, OS id=4412 
ARC1: Archival started
ARC2: Archival started
ARC2: Becoming the 'no FAL' ARCH
ARC2: Becoming the 'no SRL' ARCH
ARC1: Becoming the heartbeat ARCH
Wed Aug 02 14:19:38 2017
ARC3 started with pid=40, OS id=5536 
ARC3: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
Thread 1 advanced to log sequence 364906 (thread open)
Thread 1 opened at log sequence 364906
  Current log# 6 seq# 364906 mem# 0: D:\ORACLEHOME\ORACLE\ORADATA\BMI\REDO06_01.LOG
  Current log# 6 seq# 364906 mem# 1: D:\ORACLEHOME\ORACLE\ORADATA\BMI\REDO06_02.LOG
Successful open of redo thread 1
Wed Aug 02 14:19:45 2017
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Wed Aug 02 14:19:45 2017
SMON: enabling cache recovery
Successfully onlined Undo Tablespace 2.
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery
Database Characterset is ZHS16GBK
No Resource Manager plan active
replication_dependency_tracking turned off (no async multimaster replication found)
Wed Aug 02 14:20:02 2017
Starting background process QMNC
Wed Aug 02 14:20:02 2017
QMNC started with pid=58, OS id=5700 
Completed: ALTER DATABASE OPEN
--在資料庫open的過程中,本地登入sqlplus檢視會話資訊,資料庫確實開啟了並行程式恢復:
SQL>  select sid,process,program from  v$session
  2  where
  3   type = 'USER'
  4  and
  5  SID not in (select DISTINCT SID from v$mystat);


       SID PROCESS                  PROGRAM
---------- ------------------------ ----------------------------------------------------------------
         3 3668                     ORACLE.EXE (P011)
         4 828                      ORACLE.EXE (P022)
        51 6024                     ORACLE.EXE (P012)
        52 5824                     ORACLE.EXE (P023)
       100 5880                     ORACLE.EXE (P013)
       101 4624                     ORACLE.EXE (P024)
       148 6048                     ORACLE.EXE (P014)
       150 2452                     ORACLE.EXE (P025)
       198 6028                     ORACLE.EXE (P000)
       200 3060                     ORACLE.EXE (P026)
       251 4844                     ORACLE.EXE (P027)
       298 4556                     ORACLE.EXE (P001)
       299 4356                     ORACLE.EXE (P028)
       347 4828                     ORACLE.EXE (P002)
       348 5956                     ORACLE.EXE (P029)
       396 5716                     ORACLE.EXE (P003)
       397 4288                     ORACLE.EXE (P030)
       443 5992                     ORACLE.EXE (P004)
       444 2828                     ORACLE.EXE (P015)
       445 4140                     ORACLE.EXE (P031)
       492 4704                     ORACLE.EXE (P005)
       493 5840                     ORACLE.EXE (P016)
       541 6004                     ORACLE.EXE (P006)
       542 2216                     ORACLE.EXE (P017)
       590 5048                     ORACLE.EXE (P018)
       591 1808                     ORACLE.EXE (P007)
       639 5632                     ORACLE.EXE (P019)
       640 4936                     ORACLE.EXE (P008)
       641 4436                     ORACLE.EXE (J000)
       689 5576                     ORACLE.EXE (P020)
       690 5884                     ORACLE.EXE (P009)
       737 6064                     ORACLE.EXE (P021)
       739 6012                     ORACLE.EXE (P010)
已選擇33行。
資料庫完成open後檢視資料庫狀態,資料庫恢復正常:
SQL> startup
ORACLE 例程已經啟動。
Total System Global Area 2.0577E+10 bytes
Fixed Size                  2184672 bytes
Variable Size            8589937184 bytes
Database Buffers         1.1945E+10 bytes
Redo Buffers               39743488 bytes
資料庫裝載完畢。
資料庫已經開啟。
SQL> select instance_name,status from v$instance;
INSTANCE_NAME    STATUS
---------------- ------------
bmi              OPEN
SQL>
SQL> select name,open_mode from v$database;
NAME      OPEN_MODE
--------- --------------------
BMI       READ WRITE
SQL> 

注意:本次故障中,需要實施同事明白Oracle資料庫的啟動和關閉過程;重啟作業系統前,需要先關閉oracle監聽、確定當前資料庫中沒有執行計劃任務或儲存過程、
關閉oracle資料庫例項、關閉oracle資料庫服務、重啟作業系統,如果不是這個順序,就可能導致資料檔案損壞,資料庫啟動需要恢復而開啟過程很慢,需要耐心等待。




來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/29357786/viewspace-2142974/,如需轉載,請註明出處,否則將追究法律責任。

相關文章