Know Your Oracle Database

While working with standby databases on a daily basis, every now and then you run into one of these error messages:

SQL> alter database open read only;
alter database open read only
*
ERROR at line 1:
ORA-10458: standby database requires recovery
ORA-01152: file 1 was not restored from a sufficiently old backup
ORA-01110: data file 1: '+DG/DEV/DATAFILE/system.267.896216857'

Or maybe you have seen this one:

SQL> recover standby database;
ORA-00279: change 2565642 generated at 12/01/2015 20:24:54 needed for thread 1
ORA-00289: suggestion : +DG
ORA-15173: entry 'ARCHIVELOG' does not exist in directory 'DEV'
ORA-00280: change 2565642 for thread 1 is in sequence #60
Specify log: {=suggested | filename | AUTO | CANCEL}
cancel
ORA-01547: warning: RECOVER succeeded but OPEN RESETLOGS would get error below
ORA-01152: file 1 was not restored from a sufficiently old backup
ORA-01110: data file 1: '+DG/DEV/DATAFILE/system.268.897337791'

So how do we go about investigating these? What is the reason for this? Maybe the quick and easy answer to this is that you need to apply more archive logs to the database to get it to a consistent state where you can open it.

But the big question is, to what point do we perform this recovery? What is the specific time or SCN (System Change Number) to which recovery needs to be performed? Over the next few weeks we will create a series of blog posts that will go into these errors in a little more detail. But before doing that, there are a few areas that are important to understand or at least know about - even if just a little. The first part is around the differences between v$datafile and v$datafile_header. Where does the information come from? You might find this surprising but there are a number of DBA’s that are not familiar with these two and where they come from, and some even may think they are the same. Maybe v$datafile_header is a bit easier as the name highlights where the information comes from – the actual datafile header.

v$datafile_header

Now v$datafile_header in summary is showing information from the datafile headers. If you are interested v$datafile_header maps to x$kcvfh. There is a lot of information stored here and we will get to some of this in the next post, but for now as a starting point, let’s just take note that v$datafile_header is showing information from the actual datafiles.

But before we get more into v$datafile_header (we will cover this more in the follow on posts), let’s first spend a little bit of time on v$datafile.

v$datafile

In summary, v$datafile is displaying information from the controlfile. If you look a little closer v$datafile maps to x$kcvdf.

This brings me to an interesting part – the controlfile. The definition of the controlfile is that “it is a small binary file that records the physical structure of the database”. This includes the database name, information about the datafiles, and redo logs as well as information about the current log sequence number and one other crucial part, checkpoint information – which we will get to later. In short, the controlfile is an excellent source of information. Not just for the above, but you will also be able to get information about archive logs and if you look a bit further you might also find a bit more about your RMAN backups, including your default RMAN configuration.

There are two ways to get to information in the controlfile. The first option is to use SQL Queries on the v$ views or the x$ structures (or x$ tables as they are known). The second option is to dump controlfile contents to a trace file – and this is where things can get really interesting for some, but maybe not for all. A detailed understanding of the dump and trace files will not necessarily provide much benefit to most – but can still be good fun to play with.

TIP: One tip I can give is to play a little with hexadecimal - also known as “base 16” or just “hex”. A lot of information in trace files are kind of hidden in hex and by just being able to convert the most basic numbers can already be a big advantage in understanding the information presented in these files. There is a lot of good sources out there to help you understand hex – such as this easy to use tables session here which can be a fun way to learn hex.

Now to show you that the controlfile contains a lot of information about the datafiles, lets use the “oradebug” option from within a SQL*Plus session to dump the controlfile to a trace so we can have a peak at what is inside.

The commands used to do this are:

SQL> oradebug setmypid
Statement processed.

SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/qa1/QA1/trace/QA1_ora_3697.trc

SQL> oradebug dump controlf 3;
Statement processed.

The tracefile_name option is really useful to identify the trace file that will be used.

The oradebug dump option is used with the argument “controlf” indicating we want to dump the controlfile and the number 3 is used to indicate the level of the dump which includes the file header, database information, checkpoint progress records, as well as reuse record information. For more information on oradebug, please see the following - here

Note that a level 3 dump will show the earliest and the last record of the reuse record sections.

The higher the dump level (above 3) the more information will be provided with regards to records from the reuse record section in the control file. Let’s have a look at a controlfile dump at level 3. Please note that some information has been removed (where … is used) for ease of reading and, as there are a number of record sections in the controlfile, we are only showing a few of the key ones to give you an idea on the information available:

...
***************************************************************************
DATABASE ENTRY
***************************************************************************
...
 11/19/2015 21:18:15
 DB Name "QA1"
...
 Controlfile Creation Timestamp  11/19/2015 21:18:16
...
 Resetlogs scn: 0x0000.00197ffb Resetlogs Timestamp  12/02/2015 16:20:50
 Prior resetlogs scn: 0x0000.00105dd5 Prior resetlogs Timestamp  11/24/2015 23:27:25
 Redo Version: compatible=0xc100200
 #Data files = 5, #Online files = 5
 Database checkpoint: Thread=1 scn: 0x0000.001b948a
 Threads: #Enabled=1, #Open=1, Head=1, Tail=1
 enabled  threads:  01000000 00000000 00000000 00000000 00000000 00000000
...
 Controlfile Checkpointed at scn:  0x0000.001b9750 12/16/2015 10:05:51
...
...

***************************************************************************
LOG FILE RECORDS
***************************************************************************
...
LOG FILE #1:
  name #1: +DATA/QA1/ONLINELOG/group_1.286.896217497
 Thread 1 redo log links: forward: 2 backward: 0
 siz: 0x5000 seq: 0x00000034 hws: 0x2 bsz: 512 nab: 0x3a29 flg: 0x1 dup: 1
 Archive links: fwrd: 0 back: 0 Prev scn: 0x0000.001b8a2d
 Low scn: 0x0000.001b8a47 12/16/2015 09:20:51
 Next scn: 0x0000.001b948a 12/16/2015 10:00:49
 
LOG FILE #2:
  name #2: +DATA/QA1/ONLINELOG/group_2.287.896217497
 Thread 1 redo log links: forward: 3 backward: 1
 siz: 0x5000 seq: 0x00000035 hws: 0x1 bsz: 512 nab: 0xffffffff flg: 0x8 dup: 1
 Archive links: fwrd: 0 back: 0 Prev scn: 0x0000.001b8a47
 Low scn: 0x0000.001b948a 12/16/2015 10:00:49
 Next scn: 0xffff.ffffffff 01/01/1988 00:00:00
 
LOG FILE #3:
  name #3: +DATA/QA1/ONLINELOG/group_3.288.896217497
 Thread 1 redo log links: forward: 0 backward: 2
 siz: 0x5000 seq: 0x00000033 hws: 0x2 bsz: 512 nab: 0x3a29 flg: 0x1 dup: 1
 Archive links: fwrd: 0 back: 0 Prev scn: 0x0000.001b8a0f
 Low scn: 0x0000.001b8a2d 12/16/2015 09:20:46
 Next scn: 0x0000.001b8a47 12/16/2015 09:20:51


***************************************************************************
DATA FILE RECORDS
***************************************************************************
...
 
DATA FILE #1:
  name #4: +DATA/QA1/DATAFILE/system.289.896217497
creation size=25600 block size=8192 status=0xe flg=0x1 head=4 tail=4 dup=1
 pdb_id 0, tablespace 0, index=1 krfil=1 prev_file_in_ts=0 prev_file_in_pdb=0
 unrecoverable scn: 0x0000.00000000 01/01/1988 00:00:00
 Checkpoint cnt:548 scn: 0x0000.001b948a 12/16/2015 10:00:49
 Stop scn: 0xffff.ffffffff 12/03/2015 00:06:07
 Creation Checkpointed at scn:  0x0000.00000009 11/19/2015 21:18:24
...
 Offline scn: 0x0000.00197ffa prev_range: 0
 Online Checkpointed at scn:  0x0000.00197ffb 12/02/2015 16:20:50
...
 Hot Backup end marker scn: 0x0000.00000000
 aux_file is NOT DEFINED
 Plugged readony: NO
...
 Online move state: 0

DATA FILE #2:
  name #5: +DATA/QA1/DATAFILE/sysaux.290.896217507
creation size=6400 block size=8192 status=0xe flg=0x1 head=5 tail=5 dup=1
 pdb_id 0, tablespace 1, index=2 krfil=2 prev_file_in_ts=0 prev_file_in_pdb=0
 unrecoverable scn: 0x0000.00000000 01/01/1988 00:00:00
 Checkpoint cnt:546 scn: 0x0000.001b948a 12/16/2015 10:00:49
 Stop scn: 0xffff.ffffffff 12/03/2015 00:06:07
 Creation Checkpointed at scn:  0x0000.0000093f 11/19/2015 21:18:27
...
 Offline scn: 0x0000.00197ffa prev_range: 0
 Online Checkpointed at scn:  0x0000.00197ffb 12/02/2015 16:20:50
...
 Hot Backup end marker scn: 0x0000.00000000
 aux_file is NOT DEFINED
 Plugged readony: NO
 Plugin scnscn: 0x0000.00000000
 Plugin resetlogs scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
 Foreign creation scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
 Foreign checkpoint scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
 Online move state: 0
....
....

***************************************************************************
RMAN CONFIGURATION RECORDS
***************************************************************************
...
CONTROLFILE AUTOBACKUP:ON recno=1
DEVICE TYPE:DISK BACKUP TYPE TO COMPRESSED BACKUPSET PARALLELISM 1 recno=2
CHANNEL:DEVICE TYPE DISK FORMAT   '/u01/backup/QA1/%U' recno=3
CONTROLFILE AUTOBACKUP FORMAT FOR DEVICE TYPE:DISK TO '/u01/backup/QA1/c-%F' recno=4
....
....

***************************************************************************
ARCHIVED LOG RECORDS
***************************************************************************
…
Earliest record:
 RECID #7 Recno 355 Record timestamp  12/02/15 15:30:00 Thread=1 Seq#=142
  Flags:  
  Resetlogs scn and time scn: 0x0000.00105dd5 11/24/15 23:27:25
  filename +DATA/QA1/ARCHIVELOG/2015_12_02/thread_1_seq_142.505.897406199
  Low scn: 0x0000.0017d089 12/02/15 12:58:43 Next scn: 0x0000.0017d180 12/02/15 13:05:24
  Block count=32  Blocksize=512
  
Latest record:
 RECID #389 Recno 41 Record timestamp  12/16/15 10:00:49 Thread=1 Seq#=52
  Flags:  
  Resetlogs scn and time scn: 0x0000.00197ffb 12/02/15 16:20:50
  filename +DATA/QA1/ARCHIVELOG/2015_12_16/thread_1_seq_52.696.898596049
  Low scn: 0x0000.001b8a47 12/16/15 09:20:51 Next scn: 0x0000.001b948a 12/16/15 10:00:49
  Block count=14888  Blocksize=512
....
....

*** END OF DUMP ***

*** 2015-12-16 10:05:51.800
Oradebug command 'dump controlf 3' console output: 

As you can see, there is a lot of information stored in the controlfile and there are only portions of it shown above.

Database Entry Section

First, let’s have a quick look at the database entry section:

***************************************************************************
DATABASE ENTRY
***************************************************************************
...
 11/19/2015 21:18:15
 DB Name "QA1"
...
 Controlfile Creation Timestamp  11/19/2015 21:18:16
...
 Resetlogs scn: 0x0000.00197ffb Resetlogs Timestamp  12/02/2015 16:20:50
 Prior resetlogs scn: 0x0000.00105dd5 Prior resetlogs Timestamp  11/24/2015 23:27:25
 Redo Version: compatible=0xc100200
 #Data files = 5, #Online files = 5
 Database checkpoint: Thread=1 scn: 0x0000.001b948a
 Threads: #Enabled=1, #Open=1, Head=1, Tail=1
 enabled  threads:  01000000 00000000 00000000 00000000 00000000 00000000
...
 Controlfile Checkpointed at scn:  0x0000.001b9750 12/16/2015 10:05:51
...
...

In this section we can see a number of details about this database QA1, for example how many datafiles there are, as well as what the last controlfile checkpoint SCN and checkpoint time were. This is all information that can be useful in recovery scenarios.

Log File Records Section

Next on the list to highlight is the log file records section. Here, you will find a lot of information regarding your online redo logs. If you look a little closer, you can see what the First and Next SCN numbers of the redo logs are, and in this case, log file group 2 is the current log. We will get back to this section in a later post.

***************************************************************************
LOG FILE RECORDS
***************************************************************************
...
LOG FILE #1:
  name #1: +DATA/QA1/ONLINELOG/group_1.286.896217497
 Thread 1 redo log links: forward: 2 backward: 0
 siz: 0x5000 seq: 0x00000034 hws: 0x2 bsz: 512 nab: 0x3a29 flg: 0x1 dup: 1
 Archive links: fwrd: 0 back: 0 Prev scn: 0x0000.001b8a2d
 Low scn: 0x0000.001b8a47 12/16/2015 09:20:51
 Next scn: 0x0000.001b948a 12/16/2015 10:00:49
 
LOG FILE #2:
  name #2: +DATA/QA1/ONLINELOG/group_2.287.896217497
 Thread 1 redo log links: forward: 3 backward: 1
 siz: 0x5000 seq: 0x00000035 hws: 0x1 bsz: 512 nab: 0xffffffff flg: 0x8 dup: 1
 Archive links: fwrd: 0 back: 0 Prev scn: 0x0000.001b8a47
 Low scn: 0x0000.001b948a 12/16/2015 10:00:49
 Next scn: 0xffff.ffffffff 01/01/1988 00:00:00
 
LOG FILE #3:
  name #3: +DATA/QA1/ONLINELOG/group_3.288.896217497
 Thread 1 redo log links: forward: 0 backward: 2
 siz: 0x5000 seq: 0x00000033 hws: 0x2 bsz: 512 nab: 0x3a29 flg: 0x1 dup: 1
 Archive links: fwrd: 0 back: 0 Prev scn: 0x0000.001b8a0f
 Low scn: 0x0000.001b8a2d 12/16/2015 09:20:46
 Next scn: 0x0000.001b8a47 12/16/2015 09:20:51

Data File Records

The next section that can also be extremely useful, is the data file records. This is where you can get a lot of information about the datafiles - all stored in the controlfile.

***************************************************************************
DATA FILE RECORDS
***************************************************************************
...
DATA FILE #1:
  name #4: +DATA/QA1/DATAFILE/system.289.896217497
creation size=25600 block size=8192 status=0xe flg=0x1 head=4 tail=4 dup=1
 pdb_id 0, tablespace 0, index=1 krfil=1 prev_file_in_ts=0 prev_file_in_pdb=0
 unrecoverable scn: 0x0000.00000000 01/01/1988 00:00:00
 Checkpoint cnt:548 scn: 0x0000.001b948a 12/16/2015 10:00:49
 Stop scn: 0xffff.ffffffff 12/03/2015 00:06:07
 Creation Checkpointed at scn:  0x0000.00000009 11/19/2015 21:18:24
...
 Offline scn: 0x0000.00197ffa prev_range: 0
 Online Checkpointed at scn:  0x0000.00197ffb 12/02/2015 16:20:50
...
 Hot Backup end marker scn: 0x0000.00000000
 aux_file is NOT DEFINED
 Plugged readony: NO
...
 Online move state: 0

DATA FILE #2:
  name #5: +DATA/QA1/DATAFILE/sysaux.290.896217507
creation size=6400 block size=8192 status=0xe flg=0x1 head=5 tail=5 dup=1
 pdb_id 0, tablespace 1, index=2 krfil=2 prev_file_in_ts=0 prev_file_in_pdb=0
 unrecoverable scn: 0x0000.00000000 01/01/1988 00:00:00
 Checkpoint cnt:546 scn: 0x0000.001b948a 12/16/2015 10:00:49
 Stop scn: 0xffff.ffffffff 12/03/2015 00:06:07
 Creation Checkpointed at scn:  0x0000.0000093f 11/19/2015 21:18:27
...
 Offline scn: 0x0000.00197ffa prev_range: 0
 Online Checkpointed at scn:  0x0000.00197ffb 12/02/2015 16:20:50
...
 Hot Backup end marker scn: 0x0000.00000000
 aux_file is NOT DEFINED
 Plugged readony: NO
 Plugin scnscn: 0x0000.00000000
 Plugin resetlogs scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
 Foreign creation scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
 Foreign checkpoint scn/timescn: 0x0000.00000000 01/01/1988 00:00:00
 Online move state: 0
.... 
....

All datafiles will be listed including the file number and file name. But the interesting part that we will get to over the next few posts, are the Checkpoint SCN values. In particular there is one value “Stop scn” which is mapped to the column “last_change#” and “last_time” when looking at v$datafile. This naming is a bit strange as once you understand this value a bit better, “stop scn” actually makes more sense, but others might feel totally different about this. There is a lot of information stored in the controlfile with regards to the datafiles and if you want to view the controlfile details with regards to datafiles, v$datafile (x$kcvdf) is the first place to start.

Another interesting section, or should we say sections, in the controlfile are the sections about backups – specifically RMAN backups. There is a lot of information stored in the controlfile about RMAN configuration and backups. To give you an indication - see the section “rman configuration records” below.

***************************************************************************
RMAN CONFIGURATION RECORDS
***************************************************************************
...
CONTROLFILE AUTOBACKUP:ON recno=1
DEVICE TYPE:DISK BACKUP TYPE TO COMPRESSED BACKUPSET PARALLELISM 1 recno=2
CHANNEL:DEVICE TYPE DISK FORMAT   '/u01/backup/QA1/%U' recno=3
CONTROLFILE AUTOBACKUP FORMAT FOR DEVICE TYPE:DISK TO '/u01/backup/QA1/c-%F' recno=4

This is a listing of the configuration changes I have made in my environment. See Three steps to getting started with RMAN on how you can adjust the default RMAN configuration and how it can make life a lot easier. In this case we have adjusted four of the default configuration options – enabling the auto backup of the controlfile, the location of the auto backup controlfile and then the enabling of the compressed backup set including adjusting my disk based channel to backup to a specific location. This section in the controlfile clearly shows the changes performed. So if you ever wondered where the default RMAN configuration is stored – now you know.

Archived Log Records

The last section (of many more) in the controlfile dump (trace) is that the controlfile also stores a lot of other information, for example, details about the known archive logs. Below is an extract of the section marked “archived log records”:

***************************************************************************
ARCHIVED LOG RECORDS
***************************************************************************
(size = 584, compat size = 584, section max = 696, section in-use = 383,
last-recid= 389, old-recno = 355, last-recno = 41)
(extent = 1, blkno = 200, numrecs = 28)
(extent = 2, blkno = 544, numrecs = 168)
(extent = 3, blkno = 550, numrecs = 168)
(extent = 4, blkno = 558, numrecs = 332)

Earliest record:
RECID #7 Recno 355 Record timestamp 12/02/15 15:30:00 Thread=1 Seq#=142
Flags:
Resetlogs scn and time scn: 0x0000.00105dd5 11/24/15 23:27:25
filename +DATA/QA1/ARCHIVELOG/2015_12_02/thread_1_seq_142.505.897406199
Low scn: 0x0000.0017d089 12/02/15 12:58:43 Next scn: 0x0000.0017d180 12/02/15 13:05:24
Block count=32 Blocksize=512

Latest record:
RECID #389 Recno 41 Record timestamp 12/16/15 10:00:49 Thread=1 Seq#=52
Flags:
Resetlogs scn and time scn: 0x0000.00197ffb 12/02/15 16:20:50
filename +DATA/QA1/ARCHIVELOG/2015_12_16/thread_1_seq_52.696.898596049
Low scn: 0x0000.001b8a47 12/16/15 09:20:51 Next scn: 0x0000.001b948a 12/16/15 10:00:49
Block count=14888 Blocksize=512
....

In the above section, as we have used dump level 3, only the first and last record is shown. If you want to see all the detail, use dump level 11 and then review the trace, and you will get a lot more.

Now in this case we have performed an incomplete recovery and performed an open resetlogs on the database – which is easy to identify by reviewing the “Resetlogs scn and time” and the sequence values (Seq#) between the earliest and latest records.

Out of interest, if you are looking at v$archived_log, you are again listing information stored in the controlfile.

Tip: Have you ever wondered how you can purge data from v$archived_log? Well, it is possible with the help of the dbms_backup_restore package. Be careful when doing this and as always make sure you test this before doing anything like this in production.

SQL> select count(1) from v$archived_log;

  COUNT(1)
----------
       384

SQL> exec sys.dbms_backup_restore.resetCfileSection(11);
PL/SQL procedure successfully completed.

SQL> select count(1) from v$archived_log;

  COUNT(1)
----------
	 0

Now if we re-dump the controlfile using oradebug dump controlf 3 and reviewing the dump file section we can see the following:

***************************************************************************
ARCHIVED LOG RECORDS
***************************************************************************
 (size = 584, compat size = 584, section max = 696, section in-use = 0,
  last-recid= 0, old-recno = 0, last-recno = 0)
 (extent = 1, blkno = 200, numrecs = 28)
 (extent = 2, blkno = 544, numrecs = 168)
 (extent = 3, blkno = 550, numrecs = 168)
 (extent = 4, blkno = 558, numrecs = 332)

The resetCfileSection procedure can be useful, but do take care when using it!

Now that we know a little more about v$datafile and we know that it is showing information obtained from the controlfile, we are now ready to move onto the next part which will start looking at the “Stop SCN” or “last_change#” and what this means from a recovery point of view.