Here's something about the V$ARCHIVED_LOG view.
I start with a few archivelogs today :
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>
[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:
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
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.
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.
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.
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.
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.
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
Post a Comment