13 April, 2012

When is an ArchiveLog created ?

Here's something about the V$ARCHIVED_LOG view.

I start with a few archivelogs today :

21:01:01 SQL> get Latest_ArchiveLogs
  1  select sequence#, substr(name,1,96),creator, to_char(first_time,'DD-MON HH24:MI'), to_char(completion_time,'DD-MON HH24:MI')
  2  from v$archived_log
  3  where first_time > sysdate-1
  4* order by 1
21:01:07 SQL> /

 SEQUENCE#
----------
SUBSTR(NAME,1,96)
--------------------------------------------------------------------------------------------------------------------------------
CREATOR TO_CHAR(FIRST_TIME,'D TO_CHAR(COMPLETION_TI
------- --------------------- ---------------------
         6
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_6_7rh975jt_.arc
ARCH    12-APR 20:51          12-APR 21:00

         7
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_7_7rh97rjs_.arc
ARCH    12-APR 21:00          12-APR 21:00

         8
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_8_7rh97vv7_.arc
ARCH    12-APR 21:00          12-APR 21:00

         9
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_9_7rh97vwp_.arc
ARCH    12-APR 21:00          12-APR 21:00


21:01:09 SQL> 
Next, I move and re-register them :

[oracle@localhost 2012_04_12]$ pwd
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12
[oracle@localhost 2012_04_12]$ ls -ltr
total 11072
-rw-rw---- 1 oracle oracle 8797696 Apr 12 20:51 o1_mf_1_5_7rh8orgp_.arc
-rw-rw---- 1 oracle oracle 2498560 Apr 12 21:00 o1_mf_1_6_7rh975jt_.arc
-rw-rw---- 1 oracle oracle   11264 Apr 12 21:00 o1_mf_1_7_7rh97rjs_.arc
-rw-rw---- 1 oracle oracle    1024 Apr 12 21:00 o1_mf_1_9_7rh97vwp_.arc
-rw-rw---- 1 oracle oracle    4096 Apr 12 21:00 o1_mf_1_8_7rh97vv7_.arc
[oracle@localhost 2012_04_12]$ rm *1_5_*
[oracle@localhost 2012_04_12]$ pwd
/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12
[oracle@localhost 2012_04_12]$ ls -l
total 2464
-rw-rw---- 1 oracle oracle 2498560 Apr 12 21:00 o1_mf_1_6_7rh975jt_.arc
-rw-rw---- 1 oracle oracle   11264 Apr 12 21:00 o1_mf_1_7_7rh97rjs_.arc
-rw-rw---- 1 oracle oracle    4096 Apr 12 21:00 o1_mf_1_8_7rh97vv7_.arc
-rw-rw---- 1 oracle oracle    1024 Apr 12 21:00 o1_mf_1_9_7rh97vwp_.arc
[oracle@localhost 2012_04_12]$ mkdir /tmp/ARCHLOGS
[oracle@localhost 2012_04_12]$ mv *arc /tmp/ARCHLOGS/
[oracle@localhost 2012_04_12]$ rman target /

Recovery Manager: Release 11.2.0.1.0 - Production on Thu Apr 12 21:03:15 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: ORCL (DBID=1229390655)

RMAN> crosscheck archivelog all;

using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=43 device type=DISK
validation failed for archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_5_7rh8orgp_.arc RECID=15 STAMP=780439880
validation failed for archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_6_7rh975jt_.arc RECID=16 STAMP=780440437
validation failed for archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_7_7rh97rjs_.arc RECID=17 STAMP=780440456
validation failed for archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_8_7rh97vv7_.arc RECID=19 STAMP=780440459
validation failed for archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_9_7rh97vwp_.arc RECID=18 STAMP=780440459
Crosschecked 5 objects


RMAN> delete expired archivelog all;

released channel: ORA_DISK_1
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=43 device type=DISK
List of Archived Log Copies for database with db_unique_name ORCL
=====================================================================

Key     Thrd Seq     S Low Time 
------- ---- ------- - ---------
15      1    5       X 04-APR-12
        Name: /home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_5_7rh8orgp_.arc

16      1    6       X 12-APR-12
        Name: /home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_6_7rh975jt_.arc

17      1    7       X 12-APR-12
        Name: /home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_7_7rh97rjs_.arc

19      1    8       X 12-APR-12
        Name: /home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_8_7rh97vv7_.arc

18      1    9       X 12-APR-12
        Name: /home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_9_7rh97vwp_.arc


Do you really want to delete the above objects (enter YES or NO)? YES
deleted archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_5_7rh8orgp_.arc RECID=15 STAMP=780439880
deleted archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_6_7rh975jt_.arc RECID=16 STAMP=780440437
deleted archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_7_7rh97rjs_.arc RECID=17 STAMP=780440456
deleted archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_8_7rh97vv7_.arc RECID=19 STAMP=780440459
deleted archived log
archived log file name=/home/oracle/app/oracle/flash_recovery_area/ORCL/archivelog/2012_04_12/o1_mf_1_9_7rh97vwp_.arc RECID=18 STAMP=780440459
Deleted 5 EXPIRED objects


RMAN> 
RMAN> exit


Recovery Manager complete.
[oracle@localhost 2012_04_12]$ sleep 120
[oracle@localhost 2012_04_12]$ 
[oracle@localhost 2012_04_12]$ rman target /

Recovery Manager: Release 11.2.0.1.0 - Production on Thu Apr 12 21:06:18 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: ORCL (DBID=1229390655)

RMAN> catalog start with '/tmp/ARCHLOGS';

using target database control file instead of recovery catalog
searching for all files that match the pattern /tmp/ARCHLOGS

List of Files Unknown to the Database
=====================================
File Name: /tmp/ARCHLOGS/o1_mf_1_9_7rh97vwp_.arc
File Name: /tmp/ARCHLOGS/o1_mf_1_6_7rh975jt_.arc
File Name: /tmp/ARCHLOGS/o1_mf_1_7_7rh97rjs_.arc
File Name: /tmp/ARCHLOGS/o1_mf_1_8_7rh97vv7_.arc

Do you really want to catalog the above files (enter YES or NO)? YES
cataloging files...
cataloging done

List of Cataloged Files
=======================
File Name: /tmp/ARCHLOGS/o1_mf_1_9_7rh97vwp_.arc
File Name: /tmp/ARCHLOGS/o1_mf_1_6_7rh975jt_.arc
File Name: /tmp/ARCHLOGS/o1_mf_1_7_7rh97rjs_.arc
File Name: /tmp/ARCHLOGS/o1_mf_1_8_7rh97vv7_.arc

RMAN> 
I have relocated and re-cataloged the files. Now, I query them again in V$ARCHIVED_LOG :
21:08:32 SQL> l
  1  select sequence#, substr(name,1,96),creator, to_char(first_time,'DD-MON HH24:MI'), to_char(completion_time,'DD-MON HH24:MI')
  2  from v$archived_log
  3  where first_time > sysdate-1
  4  and name is not null
  5* order by 1
21:08:33 SQL> /

 SEQUENCE#
----------
SUBSTR(NAME,1,96)
--------------------------------------------------------------------------------------------------------------------------------
CREATOR TO_CHAR(FIRST_TIME,'D TO_CHAR(COMPLETION_TI
------- --------------------- ---------------------
         6
/tmp/ARCHLOGS/o1_mf_1_6_7rh975jt_.arc
RMAN    12-APR 20:51          12-APR 21:06

         7
/tmp/ARCHLOGS/o1_mf_1_7_7rh97rjs_.arc
RMAN    12-APR 21:00          12-APR 21:06

         8
/tmp/ARCHLOGS/o1_mf_1_8_7rh97vv7_.arc
RMAN    12-APR 21:00          12-APR 21:06

         9
/tmp/ARCHLOGS/o1_mf_1_9_7rh97vwp_.arc
RMAN    12-APR 21:00          12-APR 21:06


21:08:33 SQL> 
21:09:23 SQL> !ls -l /tmp/ARCHLOGS
total 2464
-rw-rw---- 1 oracle oracle 2498560 Apr 12 21:00 o1_mf_1_6_7rh975jt_.arc
-rw-rw---- 1 oracle oracle   11264 Apr 12 21:00 o1_mf_1_7_7rh97rjs_.arc
-rw-rw---- 1 oracle oracle    4096 Apr 12 21:00 o1_mf_1_8_7rh97vv7_.arc
-rw-rw---- 1 oracle oracle    1024 Apr 12 21:00 o1_mf_1_9_7rh97vwp_.arc

21:09:26 SQL> 
What has changed ? The COMPLETION_TIME has changed from 21:00 to 21:06. Apparently, this is NOT read from the ArchiveLog file. It is not read from the OS timestamp either.
 Today's question :  How does Oracle set the COMPLETION_TIME that we see in V$ARCHIVED_LOG ?  What are the implications of the change we see here ?  (Think about Standby Databases and Cloning).

.
.
.

7 comments:

Vaibhav said...

Hi Hemant,

Regarding your questions

Question 1]

What has changed? The COMPLETION_TIME has changed from 21:00 to 21:06. Apparently, this is NOT read from the ArchiveLog file. It is not read from the OS timestamp either.
How does Oracle set the COMPLETION_TIME that we see in V$ARCHIVED_LOG?


--> It is the time at which the archived log at new destination was registered with the controlfile.

In the RMAN output (cataloging the archived logs) posted by you, I find the following timestamp

Recovery Manager: Release 11.2.0.1.0 - Production on Thu Apr 12 "21:06:18 2012"

The completion time from the V$ARCHIVED_LOG accordingly shows 12-APR 21:06


Question 2]

What are the implications of the change we see here? (Think about Standby Databases and Cloning).

I tried to simulate the scenario as below.

-- checked for the latest archived log i.e. sequence# 115

SCOTT @ ora11prd> select * from ( select name,creator,thread#,sequence#,first_time ,next_time,completion_time,deleted from v$archived_log order by first_time desc ) where rownum <2;

NAME CREATOR THREAD# SEQUENCE# FIRST_TIME NEXT_TIME COMPLETION_TIME DEL
------- ---------- ---------- -------------------- -------------------- --------
C:\APP\XYZ\FAST_RECOVERY_AREA\ORA11PRD\ARCHIVELOG\2012_04_13\O1_MF_1_115_7RJX7R2Z_.ARC
FGRD 1 115 13-APR-2012 13:33:16 13-APR-2012 13:48:23 13-APR-2012 13:48:24 NO


-- Copied the archived log O1_MF_1_115_7RJX7R2Z_.ARC to the new location C:\TEMP and deleted it from the original location. Followed the steps as demonstrated by you


C:\>rman target sys/abc123

Recovery Manager: Release 11.2.0.2.0 - Production on Fri Apr 13 13:49:27 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.

connected to target database: ORA11PRD (DBID=2917379073)

RMAN> crosscheck archivelog from logseq 115;

RMAN> delete expired archivelog all;

RMAN> catalog start with 'C:\TEMP';

RMAN>

-- Now we find that there are two records for the archived log with sequence# 115. The first record is marked as DELETED. For the second record. the COMPLETION_TIME has changed but the FIRST_TIME and NEXT_TIME ( of course first_change#,next_change# also) have remained same. So there are no implications for either database cloning or for the standby database.

SCOTT @ ora11prd> select name,creator,thread#,sequence#,first_time ,next_time,completion_time,deleted from v$archived_log where sequence#=115;

NAME CREATOR THREAD# SEQUENCE# FIRST_TIME NEXT_TIME COMPLETION_TIME DEL
------- ---------- ---------- -------------------- -------------------- -------------------- ---

FGRD 1 115 13-APR-2012 13:33:16 13-APR-2012 13:48:23 13-APR-2012 13:48:24 YES

C:\TEMP\O1_MF_1_115_7RJX7R2Z_.ARC
RMAN 1 115 13-APR-2012 13:33:16 13-APR-2012 13:48:23 13-APR-2012 13:52:47 NO

Hemant K Chitale said...

Your answer to the first question is correct.
In terms of implications for database cloning or standby databases, Oracle can handle the archivelogs correctly. The issue is when DBAs write monitoring / alert scripts that monitor archivelogs based on COMPLETION_TIME.
Consider what happens when there is a network outage and ArchiveLogs are registered much later in the Standby.
Or in the case of database cloning if the archivelog has been deleted and reregistered at the source.

Vaibhav said...

Hi Hemant,

Scenario 1 : in the case of database cloning if the archivelog has been deleted and reregistered at the source

On the source database let's delete and re-register the archived log with sequence# 136.

SQL> select name,creator,thread#,sequence#,first_time ,next_time,completion_time,deleted from v$archived_log where sequence#= 136;
NAME CREATOR THREAD# SEQUENCE# FIRST_TIME NEXT_TIME COMPLETION_TIME DEL
------- ---------- ---------- -------------------- -------------------- -------------------- ---
C:\APP\XYZ\FAST_RECOVERY_AREA\ORA11PRD\ARCHIVELOG\2012_04_16\O1_MF_1_136_7RRRQT3V_.ARC
ARCH 1 136 16-APR-2012 13:20:24 16-APR-2012 13:20:41 16-APR-2012 13:20:44 NO


C:\>rman target sys/abc123

Recovery Manager: Release 11.2.0.2.0 - Production on Mon Apr 16 13:23:55 2012
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
connected to target database: ORA11PRD (DBID=2917379073)

RMAN>crosscheck archivelog from logseq 136;

RMAN>delete expired archivelog all;

RMAN>catalog start with 'C:\TEMP';

SCOTT @ ora11prd> select name,creator,thread#,sequence#,first_time ,next_time,completion_time,deleted from v$archived_log where sequence#= 136;
NAME CREATOR THREAD# SEQUENCE# FIRST_TIME NEXT_TIME COMPLETION_TIME DEL
------- ---------- ---------- -------------------- -------------------- -------------------- ---

ARCH 1 136 16-APR-2012 13:20:24 16-APR-2012 13:20:41 16-APR-2012 13:20:44 YES
C:\TEMP\O1_MF_1_136_7RRRQT3V_.ARC
RMAN 1 136 16-APR-2012 13:20:24 16-APR-2012 13:20:41 16-APR-2012 13:24:50 NO <== new completion time

-- rman clone script

run{
set until sequence 138 thread 1 ;
allocate auxiliary channel d1 type disk;
allocate auxiliary channel d2 type disk;
duplicate target database to oraclone;
}


-----------------------------------------------rman clone log -----------------------------------------

contents of Memory Script:
{
set until scn 2014851 ; to_char(scn_to_timestamp(2014851),'DD-MON-YYYY HH24:MI:SS') == 16-APR-2012 13:23:29
recover
clone database
delete archivelog
;
}

--the clone database target is 16-APR-2012 13:23:29 which is less than the COMPLETION_TIME i.e. 16-APR-2012 13:24:50 of archived log with sequence 136

archived log file name=C:\APP\XYZ\FAST_RECOVERY_AREA\ORA11PRD\ARCHIVELOG\2012_04_16\O1_MF_1_134_7RRROBW9_.ARC thread=1 sequence=134
archived log file name=C:\APP\XYZ\FAST_RECOVERY_AREA\ORA11PRD\ARCHIVELOG\2012_04_16\O1_MF_1_135_7RRRQ8RD_.ARC thread=1 sequence=135
archived log file name=C:\TEMP\O1_MF_1_136_7RRRQT3V_.ARC thread=1 sequence=136 <== re-registered archived log
archived log file name=C:\APP\XYZ\FAST_RECOVERY_AREA\ORA11PRD\ARCHIVELOG\2012_04_16\O1_MF_1_137_7RRRX3WP_.ARC thread=1 sequence=137
media recovery complete, elapsed time: 00:00:09
Finished recover at 16-APR-12
Oracle instance started

contents of Memory Script:
{
Alter clone database open resetlogs;
}
executing Memory Script

database opened
Finished Duplicate Db at 16-APR-12
released channel: d1
released channel: d2

Recovery Manager complete.

-----------------------------------------------rman clone log -----------------------------------------


The archived (sequence# 136) log which was deleted and re-registered on the source database got applied successfully.

Vaibhav said...

Hi Hemant,

Scenario : there is a network outage and ArchiveLogs are registered much later in the Standby database configuration

-- delete and re-register the archived log generated during the outage i.e. archived log with sequence# 143

Standby database
=================

SYS @ oraclone> select name,open_mode,database_role from v$database;
NAME OPEN_MODE DATABASE_ROLE
--------- -------------------- ----------------
ORA11PRD MOUNTED PHYSICAL STANDBY

SYS @ oraclone> select CLIENT_PROCESS,thread#,sequence#,status from v$managed_standby;
CLIENT_P THREAD# SEQUENCE# STATUS
-------- ---------- ---------- ------------
......
ARCH 0 0 CONNECTED
LGWR 1 142 IDLE
N/A 1 142 WAIT_FOR_LOG
...

-- simulate the outage e.g. shutdown the standby database manually

SYS @ oraclone> shutdown immediate;

Primary database
=========================

SCOTT @ ora11prd> select * from v$log;
GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME
---------- ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- -------------------- ------------ --------------------
1 1 145 52428800 512 1 NO CURRENT 2017882 16-APR-2012 14:24:54 2.8147E+14
2 1 143 52428800 512 1 YES INACTIVE 2017644 16-APR-2012 14:24:12 2017824 16-APR-2012 14:24:42
3 1 144 52428800 512 1 YES INACTIVE 2017824 16-APR-2012 14:24:42 2017882 16-APR-2012 14:24:54

SQL> select name,creator,thread#,sequence#,first_time ,next_time,completion_time,deleted from v$archived_log where sequence#=143;

NAME CREATOR THREAD# SEQUENCE# FIRST_TIME NEXT_TIME COMPLETION_TIME DEL
------- ---------- ---------- -------------------- -------------------- -------------------- ---
C:\APP\XYZ\FAST_RECOVERY_AREA\ORA11PRD\ARCHIVELOG\2012_04_16\O1_MF_1_143_7RRWHV1V_.ARC
ARCH 1 143 16-APR-2012 14:24:12 16-APR-2012 14:24:42 16-APR-2012 14:24:47 NO


C:\>rman target sys/abc123

RMAN> crosscheck archivelog from logseq 143;

RMAN> delete expired archivelog all;

RMAN> catalog start with 'C:\TEMP';

RMAN>


Standby database
==========================

SYS @ oraclone> startup mount;

SYS @ oraclone> recover managed standby database disconnect;
Media recovery complete.

SYS @ oraclone> select client_process,thread#,sequence#,status from v$managed_standby;

CLIENT_P THREAD# SEQUENCE# STATUS
-------- ---------- ---------- ------------
......
ARCH 0 0 CONNECTED
N/A 1 147 WAIT_FOR_LOG
LGWR 1 147 IDLE

Primary database
=========================

SCOTT @ ora11prd> select name,creator,thread#,sequence#,first_time ,next_time,completion_time,deleted from v$archived_log where sequence#=143;
NAME CREATOR THREAD# SEQUENCE# FIRST_TIME NEXT_TIME COMPLETION_TIME DEL
------- ---------- ---------- -------------------- -------------------- -------------------- ---
ARCH 1 143 16-APR-2012 14:24:12 16-APR-2012 14:24:42 16-APR-2012 14:24:47 YES

C:\TEMP\O1_MF_1_143_7RRWHV1V_.ARC
RMAN 1 143 16-APR-2012 14:24:12 16-APR-2012 14:24:42 16-APR-2012 14:28:47 NO

oraclone
ARCH 1 143 16-APR-2012 14:24:12 16-APR-2012 14:24:42 16-APR-2012 14:31:27 NO


The archived (sequence# 143) log which was deleted and re-registered on the primary database was transported and applied on the physical standby database successfully.

Hemant K Chitale said...

Vaibhav,
Good. You have demonstrated that Oracle does use SEQUENCE# and SCN information correctly, irrespective of [registered] COMPLETION_TIME.

My point is : "The issue is when DBAs write monitoring / alert scripts that monitor archivelogs based on COMPLETION_TIME."
So any monitoring / alert scripts should not use COMPLETION_TIME but SEQUENCE# and SCN information.

SurranĂ³ said...

Sorry for bringing up an old thread but this was the latest I could find in google.


BRIEF:

Does completion_time refer to the end of successful operation, i.e. write to disk (local) or transfer to standby dest (if standby_dest='YES')?



DETAILS:

I'm about to write a script that lists archivelog files that are

* still in dest 1 (i.e. on filesystem),

* have been backed up (i.e. BACKUP_COUNT>0 for the local destination),

* have been successfully transferred (not necessarily applied) to physical standby


I have problems with this last point. Granted, I can check registrar and applied on standby site, but how do I do it on primary site? Is it a safe assumption that if standby_dest='YES' and completion_timeThanks in advance,
G.

Hemant K Chitale said...

Gabor,

The COMPLETION_TIME at the primary is generally the time the write completed because it is local to where it was created -- Oracle registers the archivelog when it is completed. At the Standby, COMPLETION_TIME is when it actually got registered, which may be later.

As for your second question, I would recommend that you include a query to V$ARCHIVED_LOG on the Standby to see that it got registered at the Standby.

Hemant K Chitale