30 January, 2012

Understanding RESETLOGS

Whenever we do an Incomplete Recovery (recovery until CANCEL or until a specific SCN/CHANGE#, SEQUENCE# or TIME), we have to OPEN the database with a RESETLOGS.

RESETLOGS_TIME has to be indicated by Oracle if we were to query the database later. This is the time when the RESETLOGS was issued. RESETLOGS_CHANGE# is the SCN for the database at the issuance of the command. Oracle also provides information of the RESETLOGS_ID for each "incarnation". A RESETLOGS creates a new "incarnation" of the database.

Thus, my database has this information :
SQL> select sysdate from dual;

SYSDATE
---------
29-JAN-12

SQL> select resetlogs_time from v$database;

RESETLOGS
---------
01-JAN-12

SQL> select incarnation#, resetlogs_change#, resetlogs_time, resetlogs_id                            
  2  from v$database_incarnation
  3  order by 1;

INCARNATION# RESETLOGS_CHANGE# RESETLOGS RESETLOGS_ID
------------ ----------------- --------- ------------
           1                 1 13-AUG-09    694825248
           2            754488 30-OCT-09    701609923
           3           4955792 01-JAN-12    771419578
           4           4957614 01-JAN-12    771421939

SQL> 
As of today, 29-Jan, we can see that the database has undergone 4 RESETLOGS, the latest having been on 01-JAN-12 (in fact, there were two RESETLOGS that date). Why does this query report duplicate entries for the same SEQUENCE# ?
SQL> l
  1  select sequence#, trunc(first_time)
  2  from v$archived_log
  3  where first_time > to_date('31-DEC-11','DD-MON-RR')
  4* order by 1
SQL> /

 SEQUENCE# TRUNC(FIR
---------- ---------
         1 01-JAN-12
         1 01-JAN-12
         1 01-JAN-12
         1 01-JAN-12
         1 01-JAN-12
         2 01-JAN-12
         2 01-JAN-12
         2 14-JAN-12
         2 01-JAN-12
         2 01-JAN-12
         3 01-JAN-12
         3 01-JAN-12
         3 15-JAN-12
         3 01-JAN-12
         4 15-JAN-12
         5 15-JAN-12
       180 01-JAN-12
       180 01-JAN-12
       180 01-JAN-12
       181 01-JAN-12
       181 01-JAN-12
       181 01-JAN-12
       182 01-JAN-12
       182 01-JAN-12

24 rows selected.

SQL> 
It does seem very confusing to have SEQUENCE#1 to SEQUENCE#3 report 5 entries each. And why is there a gap between SEQUENCE#5 and SEQUENCE#180 ?   Can we dig deeper ?
I can collect more information thus :
SQL> select resetlogs_id, sequence#, trunc(first_time)
  2  from v$archived_log
  3  order by 1,2
  4  /

RESETLOGS_ID  SEQUENCE# TRUNC(FIR
------------ ---------- ---------
   701609923        179 26-DEC-11
   701609923        180 01-JAN-12
   701609923        180 01-JAN-12
   701609923        180 01-JAN-12
   701609923        181 01-JAN-12
   701609923        181 01-JAN-12
   701609923        181 01-JAN-12
   701609923        182 01-JAN-12
   701609923        182 01-JAN-12
   771419578          1 01-JAN-12
   771419578          1 01-JAN-12
   771419578          1 01-JAN-12
   771419578          1 01-JAN-12
   771419578          2 01-JAN-12
   771419578          2 01-JAN-12
   771419578          2 01-JAN-12
   771419578          2 01-JAN-12
   771419578          3 01-JAN-12
   771419578          3 01-JAN-12
   771419578          3 01-JAN-12
   771421939          1 01-JAN-12
   771421939          2 14-JAN-12
   771421939          3 15-JAN-12
   771421939          4 15-JAN-12
   771421939          5 15-JAN-12

25 rows selected.

SQL> 
Now, I can see that the SEQUENCE# 179 to 182 are for 26-DEC-11 to 01-JAN-12 for INCARNATION#2 which existed from 30-OCT-09 to 01-JAN-12 (this information is retrieved from V$DATABASE_INCARNATION from the earlier query). Yet, there are repeated entries from the same SEQUENCE# (180 and 181 have three entries each while 182 has two entries) !   Was each log file archived more than once ?  Similarly, in INCARNATION#3 I have three entries for each of SEQUENCE# 1 to 3.  Then, the latest INCARNATION#4  (for RESETLOGS_ID 771421939) has only 1 entry each for SEQUENCE# 1 to 5.

Were there really multiple archivelogs created from SEQUENCE# 180 to 182 and again for 1 to 3 on 01-JAN-12 ?

Here's a listing of archivelog files :

[oracle@linux64 2012_01_01]$ pwd
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01
[oracle@linux64 2012_01_01]$ ls -ltr
total 10200
-rw-rw---- 1 oracle oracle 5261824 Jan  1 10:59 o1_mf_1_179_7hzlzvcg_.arc
-rw-rw---- 1 oracle oracle   90112 Jan  1 11:00 o1_mf_1_180_7hzm1ogl_.arc
-rw-rw---- 1 oracle oracle  483840 Jan  1 11:02 o1_mf_1_181_7hzm5frg_.arc
-rw-rw---- 1 oracle oracle  377856 Jan  1 11:12 o1_mf_1_182_7hzmst65_.arc
-rw-rw---- 1 oracle oracle  483840 Jan  1 11:12 o1_mf_1_181_7hzmst4n_.arc
-rw-rw---- 1 oracle oracle   90112 Jan  1 11:12 o1_mf_1_180_7hzmst70_.arc
-rw-rw---- 1 oracle oracle 1486336 Jan  1 11:25 o1_mf_1_1_7hznjsy3_.arc
-rw-rw---- 1 oracle oracle   15872 Jan  1 11:26 o1_mf_1_2_7hznmzh7_.arc
-rw-rw---- 1 oracle oracle  590848 Jan  1 11:52 o1_mf_1_3_7hzp3my5_.arc
-rw-rw---- 1 oracle oracle   15872 Jan  1 11:52 o1_mf_1_2_7hzp3mxw_.arc
-rw-rw---- 1 oracle oracle 1486336 Jan  1 11:52 o1_mf_1_1_7hzp3mvq_.arc
[oracle@linux64 2012_01_01]$ 
That's curious ! I dont' see three archivelog files, but I do see two archivelogs for SEQUENCE# 180 and 181 and 1 and 2!!

Can anyone explain this ?
Hint : I did an OPEN RESETLOGS.

.
.
UPDATE 06-Feb :
Since there hasn't been a response ....
some more information ...

SQL> l
  1  select sequence#, resetlogs_id,
  2  to_char(first_time,'DD-MON HH24:MI:SS'), to_char(completion_time,'DD-MON HH24:MI:SS'),
  3  nvl(name,'Name is a NULL')
  4  from v$archived_log
  5  where sequence# in (1,2,3,180,181,182)
  6* order by sequence#, resetlogs_id, completion_time
SQL> /

 SEQUENCE# RESETLOGS_ID TO_CHAR(FIRST_TIME,'DD-M TO_CHAR(COMPLETION_TIME,
---------- ------------ ------------------------ ------------------------
NVL(NAME,'NAMEISANULL')
--------------------------------------------------------------------------------
         1    771419578 01-JAN 11:12:58          01-JAN 11:25:14
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_1
_7hznjsy3_.arc

         1    771419578 01-JAN 11:12:58          01-JAN 11:48:44
Name is a NULL

         1    771419578 01-JAN 11:12:58          01-JAN 11:50:00
/home/oracle/app/oracle/oradata/orcl/redo01.log

         1    771419578 01-JAN 11:12:58          01-JAN 11:52:19
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_1
_7hzp3mvq_.arc

         1    771421939 01-JAN 11:52:19          14-JAN 23:48:56
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_14/o1_mf_1_1
_7k38z82o_.arc

         2    771419578 01-JAN 11:25:13          01-JAN 11:26:55
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_2
_7hznmzh7_.arc

         2    771419578 01-JAN 11:25:13          01-JAN 11:48:44
Name is a NULL

         2    771419578 01-JAN 11:25:13          01-JAN 11:50:00
/home/oracle/app/oracle/oradata/orcl/redo02.log

         2    771419578 01-JAN 11:25:13          01-JAN 11:52:19
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_2
_7hzp3mxw_.arc

         2    771421939 14-JAN 23:48:55          15-JAN 22:47:38
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_15/o1_mf_1_2
_7k5srb64_.arc

         3    771419578 01-JAN 11:26:55          01-JAN 11:48:44
Name is a NULL

         3    771419578 01-JAN 11:26:55          01-JAN 11:50:00
/home/oracle/app/oracle/oradata/orcl/redo03.log

         3    771419578 01-JAN 11:26:55          01-JAN 11:52:19
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_3
_7hzp3my5_.arc

         3    771421939 15-JAN 22:47:38          15-JAN 23:14:40
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_15/o1_mf_1_3
_7k5vc0nf_.arc

       180    701609923 01-JAN 10:59:07          01-JAN 11:00:05
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_1
80_7hzm1ogl_.arc

       180    701609923 01-JAN 10:59:07          01-JAN 11:11:00
Name is a NULL

       180    701609923 01-JAN 10:59:07          01-JAN 11:12:58
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_1
80_7hzmst70_.arc

       181    701609923 01-JAN 11:00:05          01-JAN 11:08:38
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_1
81_7hzm5frg_.arc

       181    701609923 01-JAN 11:00:05          01-JAN 11:11:00
Name is a NULL

       181    701609923 01-JAN 11:00:05          01-JAN 11:12:58
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_1
81_7hzmst4n_.arc

       182    701609923 01-JAN 11:02:05          01-JAN 11:11:00
Name is a NULL

       182    701609923 01-JAN 11:02:05          01-JAN 11:12:58
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_1
82_7hzmst65_.arc


22 rows selected.

SQL> 
Look at the number of occurrences of SEQUENCE#1. Check the COMPLETION TIME for these entries. Why is the NAME a NULL value for some occurrences ?

.....  OK .... since it is unlikely that anyone will yet reply to the latest question .....
Here's more information from the alert.log :
Sun Jan 01 11:25:13 2012
ALTER SYSTEM ARCHIVE LOG
Sun Jan 01 11:25:13 2012
Thread 1 advanced to log sequence 2 (LGWR switch)
  Current log# 2 seq# 2 mem# 0: /home/oracle/app/oracle/oradata/orcl/redo02.log
Sun Jan 01 11:25:14 2012
Archived Log entry 10 added for thread 1 sequence 1 ID 0x4d6fd925 dest 1:


Sun Jan 01 11:33:24 2012
alter database mount
Sun Jan 01 11:33:28 2012
Successful mount of redo thread 1, with mount id 1299165956
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: alter database mount
Sun Jan 01 11:35:19 2012
Errors in file /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_4414.trc:
ORA-27037: unable to obtain file status
Linux Error: 13: Permission denied
Additional information: 3
ORA-01122: database file 14 failed verification check
ORA-01110: data file 14: '/oradata/add_tbs.dbf'
ORA-01565: error in identifying file '/oradata/add_tbs.dbf'
ORA-27037: unable to obtain file status
Linux Error: 13: Permission denied
Additional information: 3
Checker run found 1 new persistent data failures
Sun Jan 01 11:36:21 2012
Errors in file /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_4427.trc:
ORA-27037: unable to obtain file status
Linux Error: 13: Permission denied
Additional information: 3
ORA-01122: database file 14 failed verification check
ORA-01110: data file 14: '/oradata/add_tbs.dbf'
ORA-01565: error in identifying file '/oradata/add_tbs.dbf'
ORA-27037: unable to obtain file status
Linux Error: 13: Permission denied
Additional information: 3
Sun Jan 01 11:36:23 2012
Full restore complete of datafile 7 /home/oracle/app/oracle/oradata/orcl/FLOW_1146416395631714.dbf.  Elapsed time: 0:00:00
  checkpoint is 4956847
  last deallocation scn is 960623
Full restore complete of datafile 4 /home/oracle/app/oracle/oradata/orcl/users01.dbf.  Elapsed time: 0:00:08
  checkpoint is 4956847
  last deallocation scn is 4932522
Sun Jan 01 11:36:38 2012
Full restore complete of datafile 6 /home/oracle/app/oracle/oradata/orcl/FLOW_1046101119510758.dbf.  Elapsed time: 0:00:00
  checkpoint is 4956853
  last deallocation scn is 833081
Full restore complete of datafile 8 /home/oracle/app/oracle/oradata/orcl/FLOW_1170420963682633.dbf.  Elapsed time: 0:00:01
  checkpoint is 4956853
  last deallocation scn is 969921
Full restore complete of datafile 5 /home/oracle/app/oracle/oradata/orcl/example01.dbf.  Elapsed time: 0:00:03
  checkpoint is 4956853
  last deallocation scn is 985357
Full restore complete of datafile 9 /home/oracle/app/oracle/oradata/orcl/FLOW_1194425963955800.dbf.  Elapsed time: 0:00:01
  checkpoint is 4956856
  last deallocation scn is 976123
Full restore complete of datafile 10 /home/oracle/app/oracle/oradata/orcl/FLOW_1218408858999342.dbf.  Elapsed time: 0:00:01
  checkpoint is 4956856
  last deallocation scn is 981657
Full restore complete of datafile 11 /home/oracle/app/oracle/oradata/orcl/FLOW_1242310449730067.dbf.  Elapsed time: 0:00:01
  checkpoint is 4956856
  last deallocation scn is 1367698
Full restore complete of datafile 12 /home/oracle/app/oracle/oradata/orcl/FLOW_1266412439758696.dbf.  Elapsed time: 0:00:01
  checkpoint is 4956856
  last deallocation scn is 2558126
Full restore complete of datafile 13 /home/oracle/app/oracle/oradata/orcl/APEX_1295922881855015.dbf.  Elapsed time: 0:00:01
  checkpoint is 4956856
Sun Jan 01 11:37:41 2012
Signalling error 1152 for datafile 4!
Signalling error 1152 for datafile 5!
Signalling error 1152 for datafile 6!
Signalling error 1152 for datafile 7!
Signalling error 1152 for datafile 8!
Signalling error 1152 for datafile 9!
Signalling error 1152 for datafile 10!
Signalling error 1152 for datafile 11!
Signalling error 1152 for datafile 12!
Signalling error 1152 for datafile 13!
Errors in file /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_4436.trc:
ORA-27037: unable to obtain file status
Linux Error: 13: Permission denied
Additional information: 3
ORA-01122: database file 14 failed verification check
ORA-01110: data file 14: '/oradata/add_tbs.dbf'
ORA-01565: error in identifying file '/oradata/add_tbs.dbf'
ORA-27037: unable to obtain file status
Linux Error: 13: Permission denied
Additional information: 3
Checker run found 12 new persistent data failures
Sun Jan 01 11:41:53 2012
Signalling error 1152 for datafile 4!
Signalling error 1152 for datafile 5!
Signalling error 1152 for datafile 6!
Signalling error 1152 for datafile 7!
Signalling error 1152 for datafile 8!
Signalling error 1152 for datafile 9!
Signalling error 1152 for datafile 10!
Signalling error 1152 for datafile 11!

Sun Jan 01 11:44:09 2012
Full restore complete of datafile 1 /home/oracle/app/oracle/oradata/orcl/system01.dbf.  Elapsed time: 0:01:09
  checkpoint is 4956816 
  last deallocation scn is 2681676
  Undo Optimization current scn is 4717725

Sun Jan 01 11:45:38 2012
Full restore complete of datafile 2 /home/oracle/app/oracle/oradata/orcl/sysaux01.dbf.  Elapsed time: 0:01:13
  checkpoint is 4956816
  last deallocation scn is 4862545

Sun Jan 01 11:45:57 2012
Full restore complete of datafile 3 /home/oracle/app/oracle/oradata/orcl/undotbs01.dbf.  Elapsed time: 0:00:10
  checkpoint is 4956816
  last deallocation scn is 4718440
  Undo Optimization current scn is 4717725

Sun Jan 01 11:48:02 2012
Full restore complete of datafile 14 to datafile copy /home/oracle/app/oracle/oradata/orcl/add_tbs.dbf.  Elapsed time: 0:00:00 
  checkpoint is 4956816

Switch of datafile 14 complete to datafile copy
  checkpoint is 4956816

alter database recover datafile list clear
Completed: alter database recover datafile list clear
alter database recover datafile list
 1 , 2 , 3 , 4 , 5 , 6 , 7 , 8 , 9 , 10 , 11 , 12 , 13 , 14
Completed: alter database recover datafile list
 1 , 2 , 3 , 4 , 5 , 6 , 7 , 8 , 9 , 10 , 11 , 12 , 13 , 14
alter database recover if needed
 start until cancel using backup controlfile
Media Recovery Start
 started logmerger process
Parallel Media Recovery started with 4 slaves
ORA-279 signalled during: alter database recover if needed
 start until cancel using backup controlfile
...
alter database recover logfile '/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_2_7hznmzh7_.arc'
Media Recovery Log /home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_2_7hznmzh7_.arc
Sun Jan 01 11:50:01 2012
ORA-279 signalled during: alter database recover logfile '/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_01_01/o1_mf_1_2_7hznmzh7_.arc'...
alter database recover logfile '/home/oracle/app/oracle/oradata/orcl/redo03.log'
Media Recovery Log /home/oracle/app/oracle/oradata/orcl/redo03.log
Sun Jan 01 11:50:01 2012
Incomplete recovery applied all redo ever generated.
Recovery completed through change 4957613 time 01/01/2012 11:30:06
Media Recovery Complete (orcl)
Completed: alter database recover logfile '/home/oracle/app/oracle/oradata/orcl/redo03.log'
Sun Jan 01 11:52:19 2012
alter database open resetlogs
Archived Log entry 18 added for thread 1 sequence 1 ID 0x4d6fd925 dest 1:
Archived Log entry 19 added for thread 1 sequence 2 ID 0x4d6fd925 dest 1:
Archived Log entry 20 added for thread 1 sequence 3 ID 0x4d6fd925 dest 1:
RESETLOGS after complete recovery through change 4957613
Resetting resetlogs activation ID 1299175717 (0x4d6fd925)
Sun Jan 01 11:52:23 2012
Setting recovery target incarnation to 4
Sun Jan 01 11:52:23 2012
Assigning activation ID 1299165956 (0x4d6fb304)

Sun Jan 01 11:52:24 2012
ARC2 started with pid=20, OS id=4534
Thread 1 opened at log sequence 1
  Current log# 1 seq# 1 mem# 0: /home/oracle/app/oracle/oradata/orcl/redo01.log
Successful open of redo thread 1

Do you notice how SEQUENCE#1 was Archive Log Entry 10 and again entry 18 after an OPEN RESETLOGS. The actual Online Redo Log files were *still present* and yet, I did an Incomplete Recovery and OPEN RESETLOGS. The Onlne Redo Log file that was present on disk was *again* archived out by Oracle (and a new activiation ID and target incarnation assigned). Thus, this was an OPEN RESETLOGS with Online Redo Logs present. Oracle automatically detected that the files were present and archived them out ! . .

.
.
.

6 comments:

PANKAJ ZONE said...

Hi Hemant,
One of column of table contains zeros, if we use null instead of zeros, what will be the impact on space,performance,data loading.
Table size is 2 GB and rows are2,500,000.
Please help me as this table going to double in size in next month.

My email id is pankaj.bandelwar115@gmail.com

Thanks in advance

Hemant K Chitale said...

Pankaj,
A NULL would still take one byte for storage.

Anonymous said...

Hemant

can i have a detail steps how to recreate the standby database ?

1.what are the files should be cleaned on the standby side.
2.whether the archived files are to be deleted on the standby side.
3.what are the file should be copied from the primary side i.e standby control fiel,datafiles
whether we need redologs to be copied?

Hemant K Chitale said...

Pavan,
You need to recopy the standby controlfile and backups of the datafiles.
Archivelogs older than the datafile backups are not required at the standby site.

Hemant

Vijay said...

Hi Hemant,

I have a peculiar situation ….
We had a Database on RAC with ASM. The RAC cluster nodes FC card is faulty & and the H/W engg. says the OS has to be reinstalled completely which will formatting everything what we have.
I have a RMAN backup of the RAC DB which needs to be restored in single non-ADM node. The RMAN source server version is Windows 2003 64bit with Oracle 10.2.0.3.0 whereas the server in which we are trying to restore this database is Windows 2003 32bit, Oracle 10.2.0.4. The RMAN backup is Level 0 online backup without “ARCHIVE LOGS”(yes Archive logs are not backed up), we have a Level 1 backup also without archive logs.
Kindly suggest.

Hemant K Chitale said...

Vijay,
Without ArchiveLogs any Online Backup is unusable.
RMAN backup and restore can be done to different wordsizes, however utlirp.sql needs to be run.
There are a few Oracle Support notes on word size conversion.

You must log an SR with Oracle Support for the action plan for your specific case.