Background & Overview
This real life example looks the messages written to the alert log during startup after an Oracle crash or a shutdown abort.
In this instance a large transaction was started and then after some time the database was shutdown using the shutdown abort command. The alert log excerpt below shows the messages written to the log during the startup phase highlighting key phases.
Alert Log Excerpt
ALTER DATABASE MOUNT < - - - - - DATABASE MOUNT ISSUED
Mon Sep 17 1938:28 2012
ALTER SYSTEM SET local_listener='(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=xx.xxx.xx.xx)(PORT=1521))))' SCOPE=MEMORY SID='MYDB01';
NOTE: Loaded library: System
SUCCESS: diskgroup REDO01 was mounted
SUCCESS: diskgroup REDO02 was mounted
NOTE: dependency between database MYDB01 and diskgroup resource ora.REDO01.dg is established
NOTE: dependency between database MYDB01 and diskgroup resource ora.REDO02.dg is established
Successful mount of redo thread 1, with mount id 3881113124
Allocated 31874880 bytes in shared pool for flashback generation buffer
Starting background process RVWR
Mon Sep 17 1938:36 2012
RVWR started with pid=25, OS id=9348
SUCCESS: diskgroup FRA01 was mounted
NOTE: dependency between database MYDB01 and diskgroup resource ora.FRA01.dg is established
Database mounted in Exclusive Mode
Lost write protection mode set to "typical"
SUCCESS: diskgroup DATA01 was mounted
NOTE: dependency between database MYDB01 and diskgroup resource ora.DATA01.dg is established
Completed: ALTER DATABASE MOUNT < - - - - - DATABASE MOUNT COMPLETED
Mon Sep 17 1938:37 2012
ALTER DATABASE OPEN < - - - - - - DATABASE OPEN ISSUED
Beginning crash recovery of 1 threads < - - - - - - CRASH RECOVERY STARTED
parallel recovery started with 23 processes
Started redo scan
Completed redo scan
read 723536 KB redo, 90154 data blocks need recovery
Started redo application at
Thread 1: logseq 10419, block 330182
Recovery of Online Redo Log: Thread 1 Group 1 Seq 10419 Reading mem 0
Mem# 0: +REDO01/MYDB01/onlinelog/group_1.264.777909551
Mem# 1: +REDO02/MYDB01/onlinelog/group_1.264.777909553
Recovery of Online Redo Log: Thread 1 Group 2 Seq 10420 Reading mem 0
Mem# 0: +REDO01/MYDB01/onlinelog/group_2.265.777909553
Mem# 1: +REDO02/MYDB01/onlinelog/group_2.265.777909553
Mon Sep 17 1938:49 2012
Recovery of Online Redo Log: Thread 1 Group 4 Seq 10421 Reading mem 0
Mem# 0: +REDO01/MYDB01/onlinelog/group_4.267.777910283
Mem# 1: +REDO02/MYDB01/onlinelog/group_4.267.777910283
Recovery of Online Redo Log: Thread 1 Group 3 Seq 10422 Reading mem 0
Mem# 0: +REDO01/MYDB01/onlinelog/group_3.266.777910283
Mem# 1: +REDO02/MYDB01/onlinelog/group_3.266.777910283
Recovery of Online Redo Log: Thread 1 Group 5 Seq 10423 Reading mem 0
Mem# 0: +REDO01/MYDB01/onlinelog/group_5.268.777910285
Mem# 1: +REDO02/MYDB01/onlinelog/group_5.268.777910291
Mon Sep 17 1939:00 2012
Recovery of Online Redo Log: Thread 1 Group 6 Seq 10424 Reading mem 0
Mem# 0: +REDO01/MYDB01/onlinelog/group_6.269.777910295
Mem# 1: +REDO02/MYDB01/onlinelog/group_6.269.777910301
Completed redo application of 499.22MB
Completed crash recovery at < - - - - - - - CRASH RECOVERY COMPLETE
Thread 1: logseq 10424, block 76805, scn 285247755
90154 data blocks read, 90154 data blocks written, 723536 redo k-bytes read
Mon Sep 17 1939:02 2012
/OPEN
Mon Sep 17 1939:03 2012
ARC3 started with pid=67, OS id=12013
ARC1: Archival started
ARC2: Archival started
ARC1: Becoming the 'no FAL' ARCH
ARC1: Becoming the 'no SRL' ARCH
ARC2: Becoming the heartbeat ARCH
Thread 1 advanced to log sequence 10425 (thread open)
Thread 1 opened at log sequence 10425
Current log# 1 seq# 10425 mem# 0: +REDO01/MYDB01/onlinelog/group_1.264.777909551
Current log# 1 seq# 10425 mem# 1: +REDO02/MYDB01/onlinelog/group_1.264.777909553
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Mon Sep 17 1939:03 2012
SMON: enabling cache recovery
Archived Log entry 10421 added for thread 1 sequence 10424 ID 0xe65c0bac dest 1:
ARC3: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
[9366] Successfully onlined Undo Tablespace 2.
Undo initialization finished serial:0 start:3603672234 end:3603672744 diff:510 (5 seconds)
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery < - - - - - - - TRANSACTION ROLLBACK STARTING
Database Characterset is AL32UTF8
No Resource Manager plan active
replication_dependency_tracking turned off (no async multimaster replication found)
Starting background process QMNC
Mon Sep 17 1939:07 2012
QMNC started with pid=93, OS id=12209
Completed: ALTER DATABASE OPEN < - - - - - - DATABASE OPEN COMPLETED
Mon Sep 17 1941:04 2012
Thread 1 advanced to log sequence 10426 (LGWR switch)
Current log# 2 seq# 10426 mem# 0: +REDO01/MYDB01/onlinelog/group_2.265.777909553 < - REDO GENERATED AS PART OF ROLLBACK
Current log# 2 seq# 10426 mem# 1: +REDO02/MYDB01/onlinelog/group_2.265.777909553
..
..
..
..
<removed for brevity>
..
..
..
..
Mon Sep 17 13:51:30 2012
Archived Log entry 10576 added for thread 1 sequence 10579 ID 0xe65c0bac dest 1:
Mon Sep 17 13:54:12 2012
Thread 1 advanced to log sequence 10581 (LGWR switch)
Current log# 1 seq# 10581 mem# 0: +REDO01/MYDB01/onlinelog/group_1.264.777909551 < - REDO GENERATED AS PART OF ROLLBACK
Current log# 1 seq# 10581 mem# 1: +REDO02/MYDB01/onlinelog/group_1.264.777909553
Mon Sep 17 13:54:13 2012
Archived Log entry 10577 added for thread 1 sequence 10580 ID 0xe65c0bac dest 1:
Mon Sep 17 13:54:58 2012
SMON: Parallel transaction recovery tried < - - - - - - - TRANSACTION ROLLBACK COMPLETE
