Archivelog Completed Before VS UNTIL TIME

有网友在T.ASKMACLEAN.COM上 提问关于”DELETE ARCHIVELOG ALL COMPLETED BEFORE” 与 “DELETE ARCHIVELOG UNTIL TIME “的区别。为了了解这2个命令细微的差别,我们先来温习一些 ARCHIVED LOG的知识。

 

V$ARCHIVED_LOG:

FIRST_TIME             DATE     Timestamp of the first change
NEXT_TIME              DATE     Timestamp of the next change
COMPLETION_TIME        DATE     Time when the archiving completed

 

 

FIRST_TIME代表该归档日志中LOW SCN对应的时间戳, 而NEXT_TIME代表HIGH SCN对应的时间戳; COMPLETION_TIME指该日志实际归档成功的时间,当归档可以快速完成时 NEXT_TIME往往等于COMPLETION_TIME,但是也存在因为LOGFILE SIZE尺寸较大导致archive归档操作持续较长时间,导致 NEXT_TIME << COMPLETION_TIME的情况存在。

 

 

我们来看一个例子:

 

首先通过修改log_archive_max_processes=1,保证实例只拥有一个ARC0归档进程:

 

 

SQL> select * from V$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bi
PL/SQL Release 10.2.0.5.0 - Production
CORE    10.2.0.5.0      Production
TNS for Linux: Version 10.2.0.5.0 - Production
NLSRTL Version 10.2.0.5.0 - Production

SQL>
SQL> select * from global_name;

GLOBAL_NAME
--------------------------------------------------------------------------------
www.askmaclean.com

SQL> alter system set log_archive_max_processes=1;
System altered.

[oracle@vrh8 udump]$ ps -ef|grep arc|grep -v grep
oracle   21777     1  0 07:22 ?        00:00:00 ora_arc0_G10R25

SQL> alter session set nls_date_format='YYYY-MM-DD hh24:mi:ss';
Session altered.

SQL> select  SEQUENCE#, FIRST_CHANGE# from v$log where status='CURRENT';

 SEQUENCE# FIRST_CHANGE#
---------- -------------
       232       2476748

 

 

CURRENT LOGFILE当前在线日志的SEQUENCE#=232, FIRST_CHANGE#=2476748。

我们利用oradebug suspend 命令将ARC0归档后台进程强制挂起,这将导致归档长时间无法完成; 注意不要在生产环境做这样的操作!!

 

 

SQL> oradebug setospid 21777;
Oracle pid: 20, Unix process pid: 21777, image: oracle@vrh8.oracle.com (ARC0)

SQL> oradebug suspend;
Statement processed.

SQL> alter system switch logfile;

System altered.

SQL> alter system switch logfile;

System altered.

WAIT A MOMENT;

SQL> select sequence#,name,first_time,next_time,COMPLETION_TIME from v$archived_log where sequence# =( select max(sequence#) from v$archived_log);

 SEQUENCE#
----------
NAME
--------------------------------------------------------------------------------
FIRST_TIME          COMPLETION_TIME
------------------- -------------------
       231
/s01/flash_recovery_area/G10R25/archivelog/2012_05_17/o1_mf_1_231_7v9rh2rg_.arc
2012-05-17 07:32:44 2012-05-17 07:32:50

 

 

可以看到手动suspend ARC0后switch logfile,归档没有照常发生,V$ARCHIVED_LOG中最大的SEQUENCE#仍是 231。 之后我们resume ARC0:

 

SQL> exec dbms_lock.sleep(60);

SQL> oradebug resume;
Statement processed.

SQL>  set linesize 80  pagesize 1400;
SQL>  select sequence#,name,first_time,next_time,COMPLETION_TIME from v$archived_log where sequence# =( select max(sequence#) from v$archived_log);

 SEQUENCE#
----------
NAME
--------------------------------------------------------------------------------
FIRST_TIME          NEXT_TIME           COMPLETION_TIME
------------------- ------------------- -------------------
       232
/s01/flash_recovery_area/G10R25/archivelog/2012_05_17/o1_mf_1_232_7v9s3dcf_.arc
2012-05-17 07:32:50 2012-05-17 07:41:32 2012-05-17 07:43:40

 

 

NEXT_TIME=07:41:32 而 COMPLETION_TIME= 07:43:40,相差了2分钟左右。

 

DUMP LOGFILE可以了解更多信息:

 

 

SQL> alter system dump logfile '/s01/flash_recovery_area/G10R25/archivelog/2012_05_17/o1_mf_1_232_7v9s3dcf_.arc';

System altered.

SQL> oradebug setmypid;
Statement processed.

SQL> oradebug tracefile_name
/s01/admin/G10R25/udump/g10r25_ora_21848.trc

SQL> !vi /s01/admin/G10R25/udump/g10r25_ora_21848.trc

 Low  scn: 0x0000.0025cacc (2476748) 05/17/2012 07:32:50
 Next scn: 0x0000.0025cb8f (2476943) 05/17/2012 07:41:32
 Enabled scn: 0x0000.0005eca9 (388265) 11/07/2011 03:58:11
 Thread closed scn: 0x0000.0025cacc (2476748) 05/17/2012 07:32:50

 

 

以上我们复习了 关于ARCHIVED LOG 的FIRST_TIME和 COMPLETION_TIME的知识,接下来我们实际来了解”DELETE ARCHIVELOG ALL COMPLETED BEFORE” 与 “DELETE ARCHIVELOG UNTIL TIME “的区别。

 

RMAN会通过$ORACLE_HOME/rdbms/admin/recover.bsq将RMAN命令解析成PL/SQL包的调用,包括:DBMS_RCVMAN和DBMS_BACKUP_RESTORE等内置PACKAGE。

 

当使用BACKUP/DELETE ARCHIVELOG “Completed Before”/”UNTIL TIME”时DBMS_RCVMAN会调用以下一个SQL语句,查询V$ARCHIVED_LOG视图中是否有满足条件的归档日志:

 

HASH_VALUE=  3114867949
SELECT :B20 TYPE_CON,
       RECID KEY_CON,
       RECID RECID_CON,
       STAMP STAMP_CON,
       TO_NUMBER(NULL) SETSTAMP_CON,
       TO_NUMBER(NULL) SETCOUNT_CON,
       TO_NUMBER(NULL) BSRECID_CON,
       TO_NUMBER(NULL) BSSTAMP_CON,
       TO_NUMBER(NULL) BSKEY_CON,
       TO_NUMBER(NULL) BSLEVEL_ CON,
       TO_CHAR(NULL) BSTYPE_CON,
       TO_NUMBER(NULL) ELAPSESECS_CON,
       TO_NUMBER(NULL) P IECECOUNT_CON,
       NAME FILENAME_CON,
       TO_CHAR(NULL) TAG_CON,
       TO_NUMBER(NULL) COPYNUM BER_CON,
       STATUS STATUS_CON,
       BLOCKS BLOCKS_CON,
       BLOCK_SIZE BLOCKSIZE_CON,
       'DISK' DEVICETYPE_CON,
       COMPLETION_TIME COMPTIME_CON,
       TO_DATE(NULL) CFCREATIONTIME_CON,
       TO_NUMBER(NULL) PIECENUMBER_CON,
       TO_DATE(NULL) BPCOMPTIME_CON,
       TO_CHAR(NULL) BPC OMPRESSED_CON,
       :B19 TYPE_ACT,
       TO_NUMBER(NULL) FROMSCN_ACT,
       TO_NUMBER(NULL) TOSCN _ACT,
       TO_DATE(NULL) TOTIME_ACT,
       TO_NUMBER(NULL) RLGSCN_ACT,
       TO_DATE(NULL) RLGTIM E_ACT,
       TO_NUMBER(NULL) DBINCKEY_ACT,
       TO_NUMBER(NULL) LEVEL_ACT,
       TO_NUMBER(NULL) DFNUMBER_OBJ,
       TO_NUMBER(NULL) DFCREATIONSCN_OBJ,
       TO_NUMBER(NULL) CFSEQUENCE_OBJ,
       TO_DATE(NULL) CFDATE_OBJ,
       SEQUENCE# LOGSEQUENCE_OBJ,
       THREAD# LOGTHREAD_OBJ,
       RES ETLOGS_CHANGE# LOGRLGSCN_OBJ,
       RESETLOGS_TIME LOGRLGTIME_OBJ,
       FIRST_CHANGE# LOGLO WSCN_OBJ,
       FIRST_TIME LOGLOWTIME_OBJ,
       NEXT_CHANGE# LOGNEXTSCN_OBJ,
       NEXT_TIME LOGN EXTTIME_OBJ,
       DECODE(END_OF_REDO_TYPE, 'TERMINAL', 'YES', 'NO') LOGTERMINAL_OBJ,
       T O_CHAR(NULL) CFTYPE_OBJ,
       TO_NUMBER(NULL) KEEP_OPTIONS,
       TO_DATE(NULL) KEEP_UNTIL,
       TO_NUMBER(NULL) AFZSCN_ACT,
       TO_DATE(NULL) RFZTIME_ACT,
       TO_NUMBER(NULL) RFZSCN_A CT,
       TO_CHAR(NULL) MEDIA_CON,
       IS_RECOVERY_DEST_FILE ISRDF_CON
  FROM V$ARCHIVED_LOG
 WHERE (:B18 IS NULL OR THREAD# = :B18)
   AND (:B17 IS NULL OR SEQUENCE# = :B17)
   AND (:B16 IS NULL OR FIRST_CHANGE# = :B16)
   AND (:B15 IS NULL OR NAME LIKE :B15)
   AND (:B14 IS NULL OR COMPLETION_TIME >= :B14)
   AND (:B13 IS NULL OR COMPLETION_TIME <= :B13)
   AND DECODE(:B10,
              :B12,
              DECODE(STATUS, 'A', :B9, :B11),
              DBMS _RCVMAN.ISSTATUSMATCH(STATUS, :B10)) = :B9
   AND STANDBY_DEST = 'NO'
   AND (ARCHIVE D = 'YES')
   AND (:B8 IS NULL OR THREAD# = :B8)
   AND (:B7 IS NULL OR SEQUENCE# >= :B7)
   AND (:B6 IS NULL OR SEQUENCE# <= :B6)
   AND (:B5 IS NULL OR NEXT_CHANGE# > :B5)
   AND (:B4 IS NULL OR FIRST_CHANGE# < :B4)
   AND (:B3 IS NULL OR NAME LIKE :B 3)
   AND (:B2 IS NULL OR NEXT_TIME > :B2)
   AND (:B1 IS NULL OR FIRST_TIME <= :B1)
 ORDER BY RESETLOGS_CHANGE#,
          RESETLOGS_TIME,
          THREAD#,
          SEQUENCE#,
          LOGTERMINAL_OB    J DESC,
          STAMP_CON         DESC

 

 

已知该语句的HASH_VALUE=3114867949 ,虽然该语句使用了绑定变量且似乎10046 TRACE capture不到其BIND VALUE,但仍可以通过v$sql_bind_capture视图找到:

 

 

当DELETE ARCHIVELOG UNTIL TIME ‘SYSDATE-7’;执行时:

 

col name for a20
col value_string for a50		  
SQL> select name,value_string from v$sql_bind_capture where hash_value='3114867949';
:B20
:B19
:B18                 NULL
:B18                 NULL
:B17                 NULL
:B17                 NULL
:B16                 NULL
:B16                 NULL
:B15                 NULL
:B15                 NULL
:B14                 NULL
:B14                 NULL
:B13                 NULL
:B13                 NULL
:B10                 27
:B12                 1
:B9                  1
:B11                 0
:B10                 27
:B9                  1
:B8                  NULL
:B8                  NULL
:B7                  NULL
:B7                  NULL
:B6                  NULL
:B6                  NULL
:B5                  NULL
:B5                  NULL
:B4                  NULL
:B4                  NULL
:B3                  NULL
:B3                  NULL
:B2                  NULL
:B2                  NULL
:B1                  05/10/12 07:15:26
:B1                  05/10/12 07:15:26
36 rows selected.

 

其中有意义的绑定值为:

:B1 05/10/12 07:15:26 =》即SYSDATE – 7

可以在上述SQL中找到相关条件:B1 IS NULL OR FIRST_TIME <= :B1,即 FIRST_TIME <= ‘SYSDATE-7’;

即 UNTIL TIME 的TIME指的是 ARCHIVELOG的FIRST_TIME ,即归档日志中LOW SCN对应的时间戳;其意思为找出所有LOW SCN TIMESTAMP小于等于指定的时间变量的归档日志。

 

当DELETE ARCHIVELOG ALL COMPLETED BEFORE ‘SYSDATE-7’;执行时:

 

SQL> select name,value_string from v$sql_bind_capture where hash_value='3114867949';
:B20
:B19
:B18                 NULL
:B18                 NULL
:B17                 NULL
:B17                 NULL
:B16                 NULL
:B16                 NULL
:B15                 NULL
:B15                 NULL
:B14                 NULL
:B14                 NULL
:B13                 05/10/12 07:21:00
:B13                 05/10/12 07:21:00
:B10                 27
:B12                 1
:B9                  1
:B11                 0
:B10                 27
:B9                  1
:B8                  NULL
:B8                  NULL
:B7                  NULL
:B7                  NULL
:B6                  NULL
:B6                  NULL
:B5                  0
:B5                  0
:B4                  281474976710656
:B4                  281474976710656
:B3                  NULL
:B3                  NULL
:B2                  NULL
:B2                  NULL
:B1                  NULL
:B1                  NULL

其中有意义的绑定值为 :B13 05/10/12 07:21:00=> ‘SYSDATE-7′

SQL中的相关条件:B13 IS NULL OR COMPLETION_TIME <= :B13 即   COMPLETION_TIME <=’SYSDATE=7’;

COMPLETED BEFORE指的是ARCHIVELOG的COMPLETION_TIME,即实际归档操作完成的时间;其意思为找出所有归档完成时间小于指定的时间变量的归档日志。

 

 

当DELETE ARCHIVELOG ALL COMPLETED  AFTER    ‘SYSDATE-7’;执行时:

 

SQL> select name,value_string from v$sql_bind_capture where hash_value='3114867949';
:B20
:B19
:B18                 NULL
:B18                 NULL
:B17                 NULL
:B17                 NULL
:B16                 NULL
:B16                 NULL
:B15                 NULL
:B15                 NULL
:B14                 05/10/12 07:23:03
:B14                 05/10/12 07:23:03
:B13                 NULL
:B13                 NULL
:B10                 27
:B12                 1
:B9                  1
:B11                 0
:B10                 27
:B9                  1
:B8                  NULL
:B8                  NULL
:B7                  NULL
:B7                  NULL
:B6                  NULL
:B6                  NULL
:B5                  0
:B5                  0
:B4                  281474976710656
:B4                  281474976710656
:B3                  NULL
:B3                  NULL
:B2                  NULL
:B2                  NULL
:B1                  NULL
:B1                  NULL

 

 

:B14 IS NULL OR COMPLETION_TIME >= :B14,类似的AFTER操作仅仅是从小于等于变成了大于等于。

COMPLETED AFTER指的是ARCHIVELOG的COMPLETION_TIME,即实际归档操作完成的时间;其意思为找出所有归档完成时间大于等于指定的时间变量的归档日志。

 

Summary :

UNTIL TIME的TIME  指的是 ARCHIVELOG的FIRST_TIME ,即归档日志中LOW SCN对应的时间戳;其意思为找出所有LOW SCN TIMESTAMP小于等于指定的时间变量的归档日志。

COMPLETED BEFORE  指的是ARCHIVELOG的COMPLETION_TIME,即实际归档操作完成的时间;其意思为找出所有归档完成时间小于指定的时间变量的归档日志。

COMPLETED AFTER   指的是ARCHIVELOG的COMPLETION_TIME,即实际归档操作完成的时间;其意思为找出所有归档完成时间大于等于指定的时间变量的归档日志。

 

Question:

搞清楚这些细节对实际的工作由什么意义?

 

Answer:

ARCHIVELOG相关过滤条件 UNTIL TIME 和 COMPLETED BEFORE是存在区别的,在平时备份BACKUP时可能感受不到这种区别。

试想这样一个场景,
SEQUENCE A 的ARCHIVELOG 的First TIME为 07:45 、 NEXT TIME为08:10、归档操作耗费了1分钟即COMPLETION_TIME为08:11
SEQUENCE A+1即后续的一个ARCHIVELOG的 FIRST TIME为08:10,NEXT TIME为08:30……..

我们以08:00为时间变量,

若使用DELETE  ARCHIVELOG UNTIL TIME 08:00 ,因为SENQUENCE A的FIRST_TIME <08:00,所以SEQUENCE A将被删除,若没有相应的归档备份或COPY,则意味着08:00~08:10 这段时间将变成unrecoverable;

若使用DELETE ARCHIVELOG ALL  COMPLETED  BEFORE 08:00,因为SENQUENCE A的COMPLETION_TIME>08:00,所以SEQUENCE A将不被删除。

 

来实际体验一下这个结论,SEQUENCE 232的
FIRST_TIME=2012-05-17 07:32:50,
NEXT TIME=2012-05-17 07:41:32,
COMPLETION_TIME=2012-05-17 07:43:40

 

 

RMAN> DELETE ARCHIVELOG  ALL COMPLETED BEFORE "to_timestamp('2012-05-17 07:40:00','YYYY-MM-DD hh24:mi:ss')";
released channel: ORA_DISK_1
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=140 devtype=DISK
RMAN> DELETE ARCHIVELOG  UNTIL TIME "to_timestamp('2012-05-17 07:40:00','YYYY-MM-DD hh24:mi:ss')";
released channel: ORA_DISK_1
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=140 devtype=DISK
List of Archived Log Copies
Key     Thrd Seq     S Low Time  Name
------- ---- ------- - --------- ----
39      1    232     A 17-MAY-12 /s01/flash_recovery_area/G10R25/archivelog/2012_05_17/o1_mf_1_232_7v9s3dcf_.arc
Do you really want to delete the above objects (enter YES or NO)? y
deleted archive log
archive log filename=/s01/flash_recovery_area/G10R25/archivelog/2012_05_17/o1_mf_1_232_7v9s3dcf_.arc recid=39 stamp=783503020
Deleted 1 objects

Oracle为何会发生归档日志archivelog大小远小于联机重做日志online redo log size的情况?

《rac不到redo大小就切换是什么原因?》

 

这个帖子详细讨论了RAC或单机环境中归档日志没到online redolog size 大小就马上切换问题的成因, 主要是由于oracle内部算法所决定的,  一般不会造成实例 性能或可用性问题, 唯一的困扰可能是 生成了较多的小归档日志。

 

Only ARCH Bgprocess may create archivelog?

我们在学习Oracle入门知识时都会介绍到ARCH归档进程,归档进程ARCH负责将在线重做日志归档,注意ARCH只会将日志文件中存在的重做内容复制到归档日志文件中,举例来说重做日志文件的大小是512MB,但当前写入的redo entry只占用10MB空间,此时由某些条件触发了日志切换,那么产生的归档文件的大小仍是10MB。

一直以来存在着这样一种误解:归档操作只会由ARCH进程负责完成。

实际上归档操作可能由多种进程完成,举例来说前台进程Fore ground process就可以完成归档操作,当在前台进程中执行alter system archive log current命令时实际执行归档操作的是前台进程(server process),而非ARCH,这可能是大多数人料想之外的,口说无凭,我们具体验证一下:

[oracle@rh2 ~]$ ps -ef|grep LOCAL=YES|grep G10R2
oracle   20790 20789  0 19:17 ?        00:00:00 oracleG10R2 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
SQL> set linesize 200 pagesize 1400;
SQL> select le.leseq "Current log sequence No",
2         100 * cp.cpodr_bno / le.lesiz "Percent Full",
3         (cpodr_bno - 1) * 512  "bytes used exclude header",
4         le.lesiz * 512 - cpodr_bno * 512 "Left space",
5         le.lesiz  *512       "logfile size"
6    from x$kcccp cp, x$kccle le
7   where LE.leseq = CP.cpodr_seq
8     and bitand(le.leflg, 24) = 8;
Current log sequence No Percent Full bytes used exclude header Left space logfile size
----------------------- ------------ ------------------------- ---------- ------------
720   62.0244141                  32518144   19910144     52428800
/* 通过以上脚本可以了解当前日志文件(current logfile)的使用情况,
这里可以看到日志文件大小为50MB,已使用32MB                    */
[oracle@rh2 ~]$ strace -p 20972 -o archive.log
Process 20972 attached - interrupt to quit
SQL> alter system archive log current;
System altered.
[oracle@rh2 ~]$ cat archive.log |egrep "open|read|write"
read(8, "\1\2\0\0\6\0\0\0\0\0\3^\10!\200\0\0\0\0\0\0\30\352\341\0\0\0\0\0`\0\0"..., 2064) = 258
open("/s01/admin/G10R2/bdump/alert_G10R2.log", O_WRONLY|O_CREAT|O_APPEND, 0660) = 6
writev(6, [{"Mon May 30 19:31:23 2011\n", 25}, {"ALTER SYSTEM ARCHIVE LOG", 24}, {"\n", 1}], 3) = 50
open("/flashcard/oradata/G10R2/controlfile/1.ctl", O_RDWR|O_SYNC|O_DIRECT) = 12
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\361\374\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\17\0\0\0\2324\0\0\377\377\1\4?^\0\0\0\6\0\0\0\0\0\0\0\0\0\2"..., 16384, 245760) = 16384
pread(12, "\25\302\0\0\21\0\0\0\2324\0\0\377\377\1\4\377\37\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 278528) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2234\0\0\377\377\1\4\327\312\0\0\0\220\1\0\316\2\0\0\2\0\0\0"..., 16384, 360448) = 16384
pread(12, "\25\302\0\0\23\0\0\0\2174\0\0\377\377\1\4\372\202\0\0\17\0\0\0\265!\315\0\0\0/\234"..., 16384, 311296) = 16384
pwrite(12, "\25\302\0\0\22\0\0\0\2334\0\0\377\377\1\4B\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pwrite(12, "\25\302\0\0\20\0\0\0\2334\0\0\377\377\1\4\240^\0\0\200\6\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pwrite(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\t\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\t\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\20\0\0\0\2354\0\0\377\377\1\4\241\177\0\0\200'\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pread(12, "\25\302\0\0\22\0\0\0\2354\0\0\377\377\1\4X\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2354\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 360448) = 16384
pread(12, "\25\302\0\0\36\0\0\0\2354\0\0\377\377\1\4\367\5\0\0\3\0\3\0\2\0\0\0\0\0/f"..., 16384, 491520) = 16384
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDONLY|O_DIRECT) = 13
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDWR|O_SYNC|O_DIRECT) = 13
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDONLY|O_DIRECT) = 14
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDWR|O_SYNC|O_DIRECT) = 14
pread(13, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
pread(14, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDONLY|O_DIRECT) = 13
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDWR|O_SYNC|O_DIRECT) = 13
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDONLY|O_DIRECT) = 14
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDWR|O_SYNC|O_DIRECT) = 14
pread(13, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
pread(14, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
pread(12, "\25\302\0\0\24\0\0\0\2354\0\0\377\377\1\4\341\202\0\0\17\0\0\0\265!\315\0\0\0/\234"..., 16384, 327680) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\20\0\0\0\2354\0\0\377\377\1\4\241\177\0\0\200'\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pread(12, "\25\302\0\0\22\0\0\0\2354\0\0\377\377\1\4X\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pread(12, "\25\302\0\0D\1\0\0\2234\0\0\377\377\1\4L\250\0\0\0\0\0\0\0\0\0\0008\251\332,"..., 16384, 5308416) = 16384
pread(12, "\25\302\0\0A\1\0\0\2234\0\0\377\377\1\4\3715\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5259264) = 16384
pwrite(12, "\25\302\0\0C\1\0\0\2364\0\0\377\377\1\4\210\232\0\0\0000\360\1\0\0\0\0\v\252\332,"..., 16384, 5292032) = 16384
pwrite(12, "\25\302\0\0\21\0\0\0\2364\0\0\377\377\1\4[\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 278528) = 16384
pwrite(12, "\25\302\0\0\17\0\0\0\2364\0\0\377\377\1\4?\177\0\0\0'\0\0\0\0\0\0\0\0\0\2"..., 16384, 245760) = 16384
pwrite(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_CREAT|O_EXCL|O_SYNC, 0660) = 15
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_SYNC|O_DIRECT) = 15
write(15, "\0\"\0\0\0\0\300\377\0\0\0\0\0\0\0\0~\240\0\0\0\2\0\0\30\370\0\0}|{z"..., 512) = 512
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDONLY|O_DIRECT) = 15
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_DIRECT) = 15
pread(13, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 1048576, 512) = 1048576
pwrite(15, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200tm\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 1048576, 512) = 1048576
pread(13, "\1\"\0\0\1\10\0\0\320\2\0\0\0\200\271\242:22:48:01\5VALID\1"..., 1048576, 1049088) = 1048576
pwrite(15, "\1\"\0\0\1\10\0\0\320\2\0\0\0\200\271\242:22:48:01\5VALID\1"..., 1048576, 1049088) = 1048576
pread(13, "\1\"\0\0\1\20\0\0\320\2\0\0\0\200\220\271\n\0232011-05-12:22:"..., 1048576, 2097664) = 1048576
pwrite(15, "\1\"\0\0\1\20\0\0\320\2\0\0\0\200\220\271\n\0232011-05-12:22:"..., 1048576, 2097664) = 1048576
pread(13, "\1\"\0\0\1\30\0\0\320\2\0\0\364\201\261/\21\0232011-05-12:22:"..., 1048576, 3146240) = 1048576
pwrite(15, "\1\"\0\0\1\30\0\0\320\2\0\0\364\201\261/\21\0232011-05-12:22:"..., 1048576, 3146240) = 1048576
pread(13, "\1\"\0\0\1 \0\0\320\2\0\0\0\200\31~:22:54:21\5VALID\1"..., 1048576, 4194816) = 1048576
pwrite(15, "\1\"\0\0\1 \0\0\320\2\0\0\0\200\31~:22:54:21\5VALID\1"..., 1048576, 4194816) = 1048576
pread(13, "\1\"\0\0\1(\0\0\320\2\0\0\0\200\320\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 5243392) = 1048576
pwrite(15, "\1\"\0\0\1(\0\0\320\2\0\0\0\200\320\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 5243392) = 1048576
pread(13, "\1\"\0\0\0010\0\0\320\2\0\0\374\200\265$\5\f\27<\10\7xo\5\f\27<\10\02320"..., 1048576, 6291968) = 1048576
pwrite(15, "\1\"\0\0\0010\0\0\320\2\0\0\374\200\265$\5\f\27<\10\7xo\5\f\27<\10\02320"..., 1048576, 6291968) = 1048576
pread(13, "\1\"\0\0\0018\0\0\320\2\0\0\0\200W&796508\377\5\304\2\6\2\t\377\tP"..., 1048576, 7340544) = 1048576
pwrite(15, "\1\"\0\0\0018\0\0\320\2\0\0\0\200W&796508\377\5\304\2\6\2\t\377\tP"..., 1048576, 7340544) = 1048576
pread(13, "\1\"\0\0\1@\0\0\320\2\0\0\0\200*2SYS\7D807355\377\5\304\2\7"..., 1048576, 8389120) = 1048576
pwrite(15, "\1\"\0\0\1@\0\0\320\2\0\0\0\200*2SYS\7D807355\377\5\304\2\7"..., 1048576, 8389120) = 1048576
pread(13, "\1\"\0\0\1H\0\0\320\2\0\0\0\200~\5\tPROCEDURE\7xo\5\f\30"..., 1048576, 9437696) = 1048576
pwrite(15, "\1\"\0\0\1H\0\0\320\2\0\0\0\200~\5\tPROCEDURE\7xo\5\f\30"..., 1048576, 9437696) = 1048576
pread(13, "\1\"\0\0\1P\0\0\320\2\0\0\0\200ll\5\f\30\10'\0232011-05-12"..., 1048576, 10486272) = 1048576
pwrite(15, "\1\"\0\0\1P\0\0\320\2\0\0\0\200ll\5\f\30\10'\0232011-05-12"..., 1048576, 10486272) = 1048576
pread(13, "\1\"\0\0\1X\0\0\320\2\0\0\0\200\320\370\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 11534848) = 1048576
pwrite(15, "\1\"\0\0\1X\0\0\320\2\0\0\0\200\320\370\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 11534848) = 1048576
pread(13, "\1\"\0\0\1`\0\0\320\2\0\0\0\200\27\216 \377\tPROCEDURE\7xo\5"..., 1048576, 12583424) = 1048576
pwrite(15, "\1\"\0\0\1`\0\0\320\2\0\0\0\200\27\216 \377\tPROCEDURE\7xo\5"..., 1048576, 12583424) = 1048576
pread(13, "\1\"\0\0\1h\0\0\320\2\0\0008\201fj\1N\1N,\0\r\3SYS\7D860"..., 1048576, 13632000) = 1048576
pwrite(15, "\1\"\0\0\1h\0\0\320\2\0\0008\201fj\1N\1N,\0\r\3SYS\7D860"..., 1048576, 13632000) = 1048576
pread(13, "\1\"\0\0\1p\0\0\320\2\0\0\0\200\25%\7xo\5\f\30\20:\0232011-05"..., 1048576, 14680576) = 1048576
pwrite(15, "\1\"\0\0\1p\0\0\320\2\0\0\0\200\25%\7xo\5\f\30\20:\0232011-05"..., 1048576, 14680576) = 1048576
pread(13, "\1\"\0\0\1x\0\0\320\2\0\0\0\200G\36\7xo\5\f\30\23\6\7xo\5\f\30\23\6"..., 1048576, 15729152) = 1048576
pwrite(15, "\1\"\0\0\1x\0\0\320\2\0\0\0\200G\36\7xo\5\f\30\23\6\7xo\5\f\30\23\6"..., 1048576, 15729152) = 1048576
pread(13, "\1\"\0\0\1\200\0\0\320\2\0\0004\200\"\34311-05-12:23:20:1"..., 1048576, 16777728) = 1048576
pwrite(15, "\1\"\0\0\1\200\0\0\320\2\0\0004\200\"\34311-05-12:23:20:1"..., 1048576, 16777728) = 1048576
pread(13, "\1\"\0\0\1\210\0\0\320\2\0\0\0\200\320(\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 17826304) = 1048576
pwrite(15, "\1\"\0\0\1\210\0\0\320\2\0\0\0\200\320(\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 17826304) = 1048576
pread(13, "\1\"\0\0\1\220\0\0\320\2\0\0\0\200\343\367\377\tPROCEDURE\7xo\5\f"..., 1048576, 18874880) = 1048576
pwrite(15, "\1\"\0\0\1\220\0\0\320\2\0\0\0\200\343\367\377\tPROCEDURE\7xo\5\f"..., 1048576, 18874880) = 1048576
pread(13, "\1\"\0\0\1\230\0\0\320\2\0\0\350\201\200\263\33\32\0232011-05-12:23"..., 1048576, 19923456) = 1048576
pwrite(15, "\1\"\0\0\1\230\0\0\320\2\0\0\350\201\200\263\33\32\0232011-05-12:23"..., 1048576, 19923456) = 1048576
pread(13, "\1\"\0\0\1\240\0\0\320\2\0\0\34\201\36\326-12:23:28:30\5VAL"..., 1048576, 20972032) = 1048576
pwrite(15, "\1\"\0\0\1\240\0\0\320\2\0\0\34\201\36\326-12:23:28:30\5VAL"..., 1048576, 20972032) = 1048576
pread(13, "\1\"\0\0\1\250\0\0\320\2\0\0\0\200P\331VALID\1N\1N\1N,\0\r\3S"..., 1048576, 22020608) = 1048576
pwrite(15, "\1\"\0\0\1\250\0\0\320\2\0\0\0\200P\331VALID\1N\1N\1N,\0\r\3S"..., 1048576, 22020608) = 1048576
pread(13, "\1\"\0\0\1\260\0\0\320\2\0\0\0\200\342X\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 23069184) = 1048576
pwrite(15, "\1\"\0\0\1\260\0\0\320\2\0\0\0\200\342X\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 23069184) = 1048576
pread(13, "\1\"\0\0\1\270\0\0\320\2\0\0\0\200k\251,\0\r\3SYS\7D968280\377"..., 1048576, 24117760) = 1048576
pwrite(15, "\1\"\0\0\1\270\0\0\320\2\0\0\0\200k\251,\0\r\3SYS\7D968280\377"..., 1048576, 24117760) = 1048576
pread(13, "\1\"\0\0\1\300\0\0\320\2\0\0\310\200Ix:37:19\5VALID\1N\1N"..., 1048576, 25166336) = 1048576
pwrite(15, "\1\"\0\0\1\300\0\0\320\2\0\0\310\200Ix:37:19\5VALID\1N\1N"..., 1048576, 25166336) = 1048576
pread(13, "\1\"\0\0\1\310\0\0\320\2\0\0\0\200\34*#\7\377\tPROCEDURE\7xo"..., 1048576, 26214912) = 1048576
pwrite(15, "\1\"\0\0\1\310\0\0\320\2\0\0\0\200\34*#\7\377\tPROCEDURE\7xo"..., 1048576, 26214912) = 1048576
pread(13, "\1\"\0\0\1\320\0\0\320\2\0\0\0\200\343\336A\377\tPROCEDURE\7xo\5"..., 1048576, 27263488) = 1048576
pwrite(15, "\1\"\0\0\1\320\0\0\320\2\0\0\0\200\343\336A\377\tPROCEDURE\7xo\5"..., 1048576, 27263488) = 1048576
pread(13, "\1\"\0\0\1\330\0\0\320\2\0\0P\200\367{/\377\tPROCEDURE\7xo\5"..., 1048576, 28312064) = 1048576
pwrite(15, "\1\"\0\0\1\330\0\0\320\2\0\0P\200\367{/\377\tPROCEDURE\7xo\5"..., 1048576, 28312064) = 1048576
pread(13, "\1\"\0\0\1\340\0\0\320\2\0\0\0\200\315_-05-12:23:46:08\5"..., 1048576, 29360640) = 1048576
pwrite(15, "\1\"\0\0\1\340\0\0\320\2\0\0\0\200\315_-05-12:23:46:08\5"..., 1048576, 29360640) = 1048576
pread(13, "\1\"\0\0\1\350\0\0\320\2\0\0\0\200\263Xo\5\f\0302\31\7xo\5\f\0302\31\0232"..., 1048576, 30409216) = 1048576
pwrite(15, "\1\"\0\0\1\350\0\0\320\2\0\0\0\200\263Xo\5\f\0302\31\7xo\5\f\0302\31\0232"..., 1048576, 30409216) = 1048576
pread(13, "\1\"\0\0\1\360\0\0\320\2\0\0\0\200\213K\5VALID\1N\1N\1N,\0\r\3"..., 1048576, 31457792) = 1048576
pwrite(15, "\1\"\0\0\1\360\0\0\320\2\0\0\0\200\213K\5VALID\1N\1N\1N,\0\r\3"..., 1048576, 31457792) = 1048576
pread(13, "\1\"\0\0\1\370\0\0\320\2\0\0\300\200\333N\24\0\t\0T\0\210\22\"\0\0\0\t\0\t\0"..., 12288, 32506368) = 12288
pwrite(15, "\1\"\0\0\1\370\0\0\320\2\0\0\300\200\333N\24\0\t\0T\0\210\22\"\0\0\0\t\0\t\0"..., 12288, 32506368) = 12288
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_DIRECT) = 16
write(16, "\0\"\0\0\0\0\300\377\0\0\0\0\0\0\0\0~\240\0\0\0\2\0\0\30\370\0\0}|{z"..., 512) = 512
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_DIRECT) = 16
write(16, "\0\"\0\0\0\0\300\377\0\0\0\0\0\0\0\0~\240\0\0\0\2\0\0\30\370\0\0}|{z"..., 512) = 512
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\17\0\0\0\2364\0\0\377\377\1\4?\177\0\0\0'\0\0\0\0\0\0\0\0\0\2"..., 16384, 245760) = 16384
pread(12, "\25\302\0\0\21\0\0\0\2364\0\0\377\377\1\4[\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 278528) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2354\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 360448) = 16384
pread(12, "\25\302\0\0\313\0\0\0\2234\0\0\377\377\1\4\2\245\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3325952) = 16384
pread(12, "\25\302\0\0(\1\0\0d4\0\0\377\377\1\4\6*\0\0\33\0\4\0\333\7\0\0\0\0\0\0"..., 16384, 4849664) = 16384
pread(12, "\25\302\0\0A\1\0\0\2234\0\0\377\377\1\4\3715\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5259264) = 16384
pread(12, "\25\302\0\0\313\0\0\0\2234\0\0\377\377\1\4\2\245\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3325952) = 16384
pwrite(12, "\25\302\0\0B\1\0\0\2374\0\0\377\377\1\4\3725\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5275648) = 16384
pread(12, "\25\302\0\0C\1\0\0\2364\0\0\377\377\1\4\210\232\0\0\0000\360\1\0\0\0\0\v\252\332,"..., 16384, 5292032) = 16384
pread(12, "\25\302\0\0B\1\0\0\2374\0\0\377\377\1\4\3725\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5275648) = 16384
pwrite(12, "\25\302\0\0D\1\0\0\2374\0\0\377\377\1\4\177\253\0\0\0\0\0\0\0\0\0\0\v\252\332,"..., 16384, 5308416) = 16384
pread(12, "\25\302\0\0\313\0\0\0\2234\0\0\377\377\1\4\2\245\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3325952) = 16384
pwrite(12, "\25\302\0\0B\1\0\0\2374\0\0\377\377\1\4\353{\0\0\0\316,\220\5\0\0\0\0\300[\310"..., 16384, 5275648) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2354\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 360448) = 16384
pwrite(12, "\25\302\0\0\25\0\0\0\2374\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 344064) = 16384
pwrite(12, "\25\302\0\0\314\0\0\0\2374\0\0\377\377\1\4\231@\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3342336) = 16384
pwrite(12, "\25\302\0\0\22\0\0\0\2374\0\0\377\377\1\4\323\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pwrite(12, "\25\302\0\0\20\0\0\0\2374\0\0\377\377\1\4\261\375\0\0\200%\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pwrite(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\0043\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\0043\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
write(11, "\0\313\0\0\6\0\0\0\0\0\10\6\0\315\"\315\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0"..., 203) = 203

在以上system call trace中可以看到前台进程首先读取并更新了控制文件(controlfile/1.ctl),之后读取了在线日志文件的头部(read o1_mf_3_6v34jpmp_.log=512bytes),接着以相关属性创建了归档日志文件(o1_mf_1_720_6y700ch9_.arc,注意这里使用了O_CREAT、O_EXCL、O_SYNC、0660属性)并得到该打开文件描述符15,接着以每次buffer为1048576字节来读取在线日志并写入归档日志pread(onlinelog)->pwrite(archivelog),直到在线日志中的redo记录被写完。这里的buffer大小1048576实际上受到隐藏参数_log_archive_buffer_size(Size of each archival buffer in log file blocks)的影响,该参数指定了归档缓冲的大小,其单位为日志文件块(log file block),日志文件块大小在不同平台上各有差异,具体可以参考这里。目前主流的UNIX平台上日志文件标准块大小为512 bytes,而_log_archive_buffer_size的默认值一般为2048,所以得出了这里的(2048*512)=1048576=1MB buffer大小。需要注意的是与”alter system archive log current”命令不同,”switch logfile”不会引起前台进程去执行归档操作,归档操作仍将由ARCH进程完成。

我们可以很方便的通过查询v$archived_log视图来了解具体完成某个日志文件归档操作的是何种进程,这得益于其creator列:

SQL> select distinct creator  from v$archived_log;
CREATOR
-------
RMAN
FGRD
ARCH
CREATOR 	VARCHAR2(7) 	Creator of the archivelog:
ARCH - Archiver process
FGRD - Foreground process
RMAN - Recovery Manager
SRMN - RMAN at standby
LGWR - Logwriter process

以上可以看到可能创建归档日志的进程不仅仅局限于FGRD与ARCH,RMAN(注意实际上并非直接由rman进程完成)在执行热备操作时也可能掺合进来归档一把,此外在DataGuard环境中LGWR也会参与归档操作。

V$archived_log视图中另外一个有趣的字段是REGISTRAR,一般来说在非DataGuard环境中CREATOR总是等于REGISTRAR,而在DataGuard环境中REGISTRAR常是RFS(remote file server process (RFS) on the standby system where the RFS process writes the redo data to either archived redo log files or standby redo log files)后台进程,而实际的CREATOR则往往仍是ARCH或LGWR。

REGISTRAR 	VARCHAR2(7) 	Registrar of the entry:
RFS - Remote File Server process
ARCH - Archiver process
FGRD - Foreground process
RMAN - Recovery manager
SRMN - RMAN at standby
LGWR - Logwriter process

ARCHIVER ERROR ORA-00354: CORRUPT REDO LOG BLOCK HEADER

Problem Description:
ORA-16038: log 2 sequence# 13831 cannot be archived
ORA-00354: corrupt redo log block header
ORA-00312: online log 2 thread 1: ‘/oradata/3/TOOLS/stdby_redo/srl1.log’

LOG FILE
---------------
Filename = alert_TOOLS5_from_1021.log
See ...
...
Wed Oct 28 11:41:59 2009
Primary database is in MAXIMUM AVAILABILITY mode
Standby controlfile consistent with primary
RFS[1]: Successfully opened standby log 1: '/oradata/3/TOOLS/stdby_redo/srl0.log'
Wed Oct 28 11:42:00 2009
ARC0: Log corruption near block 604525 change 10551037679542 time ?
Wed Oct 28 11:42:00 2009
Errors in file /tools/oracle/admin/TOOLS/bdump/tools_arc0_2143.trc:
ORA-00354: corrupt redo log block header
ORA-00353: log corruption near block 604525 change 10551037679542 time 10/28/2009 11:29:50
ORA-00312: online log 2 thread 1: '/oradata/3/TOOLS/stdby_redo/srl1.log'
ARC0: All Archive destinations made inactive due to error 354
Wed Oct 28 11:42:00 2009
ARC0: Closing local archive destination LOG_ARCHIVE_DEST_2: '/oradata/3/TOOLS/archive/dgarc/1_13831_635534096.arc' (error 354)
(TOOLS)
Committing creation of archivelog '/oradata/3/TOOLS/archive/dgarc/1_13831_635534096.arc' (error 354)
ARCH: Archival stopped, error occurred. Will continue retrying
Wed Oct 28 11:42:05 2009
ORACLE Instance TOOLS - Archival Error
Wed Oct 28 11:42:05 2009
ORA-16038: log 2 sequence# 13831 cannot be archived
ORA-00354: corrupt redo log block header
ORA-00312: online log 2 thread 1: '/oradata/3/TOOLS/stdby_redo/srl1.log'
Wed Oct 28 11:42:05 2009
Errors in file /tools/oracle/admin/TOOLS/bdump/tools_arc0_2143.trc:
ORA-16038: log 2 sequence# 13831 cannot be archived
ORA-00354: corrupt redo log block header
ORA-00312: online log 2 thread 1: '/oradata/3/TOOLS/stdby_redo/srl1.log'
Wed Oct 28 11:43:04 2009
ARCH: Archival stopped, error occurred. Will continue retrying
Wed Oct 28 11:43:04 2009
ORACLE Instance TOOLS - Archival Error
Wed Oct 28 11:43:04 2009
Primary database is in MAXIMUM AVAILABILITY mode
Changing standby controlfile to RESYNCHRONIZATION level
Wed Oct 28 11:43:04 2009
ORA-16014: log 1 sequence# 13832 not archived, no available destinations
ORA-00312: online log 1 thread 1: '/oradata/3/TOOLS/stdby_redo/srl0.log'
Wed Oct 28 11:43:04 2009
Errors in file /tools/oracle/admin/TOOLS/bdump/tools_arc1_2145.trc:
ORA-16014: log 1 sequence# 13832 not archived, no available destinations
ORA-00312: online log 1 thread 1: '/oradata/3/TOOLS/stdby_redo/srl0.log'
RFS[1]: Successfully opened standby log 2: '/oradata/3/TOOLS/stdby_redo/srl1.log'
Wed Oct 28 11:43:13 2009
RFS[3]: Archived Log: '/oradata/3/TOOLS/archive/dgarc/1_13831_635534096.arc'
Wed Oct 28 11:43:14 2009
RFS LogMiner: Registered logfile [/oradata/3/TOOLS/archive/dgarc/1_13831_635534096.arc] to LogMiner session id [4]
Wed Oct 28 11:43:15 2009
LOGMINER: Begin mining logfile for session 4 thread 1 sequence 13831, /oradata/3/TOOLS/archive/dgarc/1_13831_635534096.arc
Wed Oct 28 11:44:03 2009
RFS[3]: Archived Log: '/oradata/3/TOOLS/archive/dgarc/1_13832_635534096.arc'
...
LOG FILE
---------------
Filename = alert_TOOLS6_from_1021.log
See ...
...
Wed Oct 28 11:16:01 2009
Thread 1 advanced to log sequence 13830 (LGWR switch)
Current log# 8 seq# 13830 mem# 0: /oradata/1/redo/TOOLS/redo1a.log
Current log# 8 seq# 13830 mem# 1: /oradata/2/redo/TOOLS/redo1b.log
Current log# 8 seq# 13830 mem# 2: /oradata/3/redo/TOOLS/redo1c.log
Wed Oct 28 11:29:50 2009
LGWR: Standby redo logfile selected to archive thread 1 sequence 13831
LGWR: Standby redo logfile selected for thread 1 sequence 13831 for destination LOG_ARCHIVE_DEST_2
Wed Oct 28 11:29:50 2009
Thread 1 advanced to log sequence 13831 (LGWR switch)
Current log# 9 seq# 13831 mem# 0: /oradata/1/redo/TOOLS/redo2a.log
Current log# 9 seq# 13831 mem# 1: /oradata/2/redo/TOOLS/redo2b.log
Current log# 9 seq# 13831 mem# 2: /oradata/3/redo/TOOLS/redo2c.log
Wed Oct 28 11:41:59 2009
LGWR: Standby redo logfile selected to archive thread 1 sequence 13832
LGWR: Standby redo logfile selected for thread 1 sequence 13832 for destination LOG_ARCHIVE_DEST_2
Wed Oct 28 11:41:59 2009
Thread 1 advanced to log sequence 13832 (LGWR switch)
Current log# 10 seq# 13832 mem# 0: /oradata/1/redo/TOOLS/redo3a.log
Current log# 10 seq# 13832 mem# 1: /oradata/2/redo/TOOLS/redo3b.log
Current log# 10 seq# 13832 mem# 2: /oradata/3/redo/TOOLS/redo3c.log
Wed Oct 28 11:43:04 2009
Destination LOG_ARCHIVE_DEST_2 is UNSYNCHRONIZED
LGWR: Standby redo logfile selected to archive thread 1 sequence 13833
LGWR: Standby redo logfile selected for thread 1 sequence 13833 for destination LOG_ARCHIVE_DEST_2
Wed Oct 28 11:43:04 2009
Thread 1 advanced to log sequence 13833 (LGWR switch)
Current log# 11 seq# 13833 mem# 0: /oradata/1/redo/TOOLS/redo4a.log
Current log# 11 seq# 13833 mem# 1: /oradata/2/redo/TOOLS/redo4b.log
Current log# 11 seq# 13833 mem# 2: /oradata/3/redo/TOOLS/redo4c.log
Wed Oct 28 11:45:04 2009
Destination LOG_ARCHIVE_DEST_2 is SYNCHRONIZED
LGWR: Standby redo logfile selected to archive thread 1 sequence 13834
LGWR: Standby redo logfile selected for thread 1 sequence 13834 for destination LOG_ARCHIVE_DEST_2
Wed Oct 28 11:45:05 2009
Thread 1 advanced to log sequence 13834 (LGWR switch)
Current log# 8 seq# 13834 mem# 0: /oradata/1/redo/TOOLS/redo1a.log
Current log# 8 seq# 13834 mem# 1: /oradata/2/redo/TOOLS/redo1b.log
Current log# 8 seq# 13834 mem# 2: /oradata/3/redo/TOOLS/redo1c.log
Wed Oct 28 11:46:03 2009
Thread 1 cannot allocate new log, sequence 13835
Checkpoint not complete
Current log# 8 seq# 13834 mem# 0: /oradata/1/redo/TOOLS/redo1a.log
Current log# 8 seq# 13834 mem# 1: /oradata/2/redo/TOOLS/redo1b.log
Current log# 8 seq# 13834 mem# 2: /oradata/3/redo/TOOLS/redo1c.log
Wed Oct 28 11:46:10 2009
Destination LOG_ARCHIVE_DEST_2 is UNSYNCHRONIZED
LGWR: Standby redo logfile selected to archive thread 1 sequence 13835
LGWR: Standby redo logfile selected for thread 1 sequence 13835 for destination LOG_ARCHIVE_DEST_2
Wed Oct 28 11:46:11 2009
Thread 1 advanced to log sequence 13835 (LGWR switch)
Current log# 9 seq# 13835 mem# 0: /oradata/1/redo/TOOLS/redo2a.log
Current log# 9 seq# 13835 mem# 1: /oradata/2/redo/TOOLS/redo2b.log
Current log# 9 seq# 13835 mem# 2: /oradata/3/redo/TOOLS/redo2c.log
Wed Oct 28 11:48:03 2009
Thread 1 cannot allocate new log, sequence 13836
Checkpoint not complete
Current log# 9 seq# 13835 mem# 0: /oradata/1/redo/TOOLS/redo2a.log
Current log# 9 seq# 13835 mem# 1: /oradata/2/redo/TOOLS/redo2b.log
Current log# 9 seq# 13835 mem# 2: /oradata/3/redo/TOOLS/redo2c.log
Wed Oct 28 11:48:06 2009
...
From the standby, as at 2009-10-28, 11:42, when the archiver tried to archive the standby
redo logfile. it encountered this error:
ORA-00354: corrupt redo log block header
ORA-00353: log corruption near block 604525 change 10551037679542 time 10/28/2009 11:29:50
ORA-00312: online log 2 thread 1: '/oradata/3/TOOLS/stdby_redo/srl1.log'
Errors in file /tools/oracle/admin/TOOLS/bdump/tools_arc0_2143.trc

The real logfile is retrieved from primary by the standby RFS process, then the log apply continue as usual.
The fact that the standby redo logs are corrupted and identified as corrupt by the ARC process , makes it clear that there could be some sort of I/O errors which has caused.
Reviewing the alert.log file it is clear that the RFS process fetched the new copy of the file which is corrupted and the issue has been resolved.
This is more an issue to be concentrated from the system adminisration end to determine in case there are any issues at the I.O subsystem
.

list some Script to Collect Data Guard Primary Site Diagnostic Information:

Overview
——–
This script is intended to provide an easy method to provide information
necessary to troubleshoot Data Guard issues.

Script Notes
————-
This script is intended to be run via sqlplus as the SYS or Internal user.

Script
——-
– – – – – – – – – – – – – – – – Script begins here – – – – – – – – – – – – – – – –

— NAME: dg_prim_diag.sql (Run on PRIMARY with a LOGICAL or PHYSICAL STANDBY)
— ————————————————————————
— Copyright 2002, Oracle Corporation
— LAST UPDATED: 2/23/04

— Usage: @dg_prim_diag
— ————————————————————————
— PURPOSE:
— This script is to be used to assist in collection information to help
— troubeshoot Data Guard issues with an emphasis on Logical Standby.
— ————————————————————————
— DISCLAIMER:
— This script is provided for educational purposes only. It is NOT
— supported by Oracle World Wide Technical Support.
— The script has been tested and appears to work as intended.
— You should always run new scripts on a test instance initially.
— ————————————————————————
— Script output is as follows:

set echo off
set feedback off
column timecol new_value timestamp
column spool_extension new_value suffix
select to_char(sysdate,’Mondd_hhmi’) timecol,
‘.out’ spool_extension from sys.dual;
column output new_value dbname
select value || ‘_’ output
from v$parameter where name = ‘db_name’;
spool dg_prim_diag_&&dbname&&timestamp&&suffix
set linesize 79
set pagesize 35
set trim on
set trims on
alter session set nls_date_format = ‘MON-DD-YYYY HH24:MI:SS’;
set feedback on
select to_char(sysdate) time from dual;

set echo on

— In the following the database_role should be primary as that is what
— this script is intended to be run on. If protection_level is different
— than protection_mode then for some reason the mode listed in
— protection_mode experienced a need to downgrade. Once the error
— condition has been corrected the protection_level should match the
— protection_mode after the next log switch.

column role format a7 tru
column name format a10 wrap

select name,database_role role,log_mode,
protection_mode,protection_level
from v$database;

— ARCHIVER can be (STOPPED | STARTED | FAILED). FAILED means that the
— archiver failed to archive a log last time, but will try again within 5
— minutes. LOG_SWITCH_WAIT The ARCHIVE LOG/CLEAR LOG/CHECKPOINT event log
— switching is waiting for. Note that if ALTER SYSTEM SWITCH LOGFILE is
— hung, but there is room in the current online redo log, then value is
— NULL

column host_name format a20 tru
column version format a9 tru

select instance_name,host_name,version,archiver,log_switch_wait
from v$instance;

— The following query give us information about catpatch.
— This way we can tell if the procedure doesn’t match the image.

select version, modified, status from dba_registry
where comp_id = ‘CATPROC’;

— Force logging is not mandatory but is recommended. Supplemental
— logging must be enabled if the standby associated with this primary is
— a logical standby. During normal operations it is acceptable for
— SWITCHOVER_STATUS to be SESSIONS ACTIVE or TO STANDBY.

column force_logging format a13 tru
column remote_archive format a14 tru
column dataguard_broker format a16 tru

select force_logging,remote_archive,
supplemental_log_data_pk,supplemental_log_data_ui,
switchover_status,dataguard_broker
from v$database;

— This query produces a list of all archive destinations. It shows if
— they are enabled, what process is servicing that destination, if the
— destination is local or remote, and if remote what the current mount ID
— is.

column destination format a35 wrap
column process format a7
column archiver format a8
column ID format 99
column mid format 99

select dest_id “ID”,destination,status,target,
schedule,process,mountid mid
from v$archive_dest order by dest_id;

— This select will give further detail on the destinations as to what
— options have been set. Register indicates whether or not the archived
— redo log is registered in the remote destination control file.

set numwidth 8
column ID format 99

select dest_id “ID”,archiver,transmit_mode,affirm,async_blocks async,
net_timeout net_time,delay_mins delay,reopen_secs reopen,
register,binding
from v$archive_dest order by dest_id;

— The following select will show any errors that occured the last time
— an attempt to archive to the destination was attempted. If ERROR is
— blank and status is VALID then the archive completed correctly.

column error format a55 wrap

select dest_id,status,error from v$archive_dest;

— The query below will determine if any error conditions have been
— reached by querying the v$dataguard_status view (view only available in
— 9.2.0 and above):

column message format a80

select message, timestamp
from v$dataguard_status
where severity in (‘Error’,’Fatal’)
order by timestamp;

— The following query will determine the current sequence number
— and the last sequence archived. If you are remotely archiving
— using the LGWR process then the archived sequence should be one
— higher than the current sequence. If remotely archiving using the
— ARCH process then the archived sequence should be equal to the
— current sequence. The applied sequence information is updated at
— log switch time.

select ads.dest_id,max(sequence#) “Current Sequence”,
max(log_sequence) “Last Archived”
from v$archived_log al, v$archive_dest ad, v$archive_dest_status ads
where ad.dest_id=al.dest_id
and al.dest_id=ads.dest_id
group by ads.dest_id;

— The following select will attempt to gather as much information as
— possible from the standby. SRLs are not supported with Logical Standby
— until Version 10.1.

set numwidth 8
column ID format 99
column “SRLs” format 99
column Active format 99

select dest_id id,database_mode db_mode,recovery_mode,
protection_mode,standby_logfile_count “SRLs”,
standby_logfile_active ACTIVE,
archived_seq#
from v$archive_dest_status;

— Query v$managed_standby to see the status of processes involved in
— the shipping redo on this system. Does not include processes needed to
— apply redo.

select process,status,client_process,sequence#
from v$managed_standby;

— The following query is run on the primary to see if SRL’s have been
— created in preparation for switchover.

select group#,sequence#,bytes from v$standby_log;

— The above SRL’s should match in number and in size with the ORL’s
— returned below:

select group#,thread#,sequence#,bytes,archived,status from v$log;

— Non-default init parameters.

set numwidth 5
column name format a30 tru
column value format a48 wra
select name, value
from v$parameter
where isdefault = ‘FALSE’;

spool off

– – – – – – – – – – – – – – – – Script ends here – – – – – – – – – – – – – – – –

another one:

Overview
——–

This script is intended to provide an easy method to provide information
necessary to troubleshoot Data Guard issues.

Script Notes
————-

This script is intended to be run via sqlplus as the SYS or Internal user.

Script
——-

– – – – – – – – – – – – – – – – Script begins here – – – – – – – – – – – – – – – –

— NAME: DG_phy_stby_diag.sql
— ————————————————————————
— AUTHOR:
— Michael Smith – Oracle Support Services – DataServer Group
— Copyright 2002, Oracle Corporation
— ————————————————————————
— PURPOSE:
— This script is to be used to assist in collection information to help
— troubeshoot Data Guard issues.
— ————————————————————————
— DISCLAIMER:
— This script is provided for educational purposes only. It is NOT
— supported by Oracle World Wide Technical Support.
— The script has been tested and appears to work as intended.
— You should always run new scripts on a test instance initially.
— ————————————————————————
— Script output is as follows:

set echo off
set feedback off
column timecol new_value timestamp
column spool_extension new_value suffix
select to_char(sysdate,’Mondd_hhmi’) timecol,
‘.out’ spool_extension from sys.dual;
column output new_value dbname
select value || ‘_’ output
from v$parameter where name = ‘db_name’;
spool dgdiag_phystby_&&dbname&&timestamp&&suffix
set lines 200
set pagesize 35
set trim on
set trims on
alter session set nls_date_format = ‘MON-DD-YYYY HH24:MI:SS’;
set feedback on
select to_char(sysdate) time from dual;

set echo on


— ARCHIVER can be (STOPPED | STARTED | FAILED) FAILED means that the archiver failed
— to archive a — log last time, but will try again within 5 minutes. LOG_SWITCH_WAIT
— The ARCHIVE LOG/CLEAR LOG/CHECKPOINT event log switching is waiting for. Note that
— if ALTER SYSTEM SWITCH LOGFILE is hung, but there is room in the current online
— redo log, then value is NULL

column host_name format a20 tru
column version format a9 tru
select instance_name,host_name,version,archiver,log_switch_wait from v$instance;

— The following select will give us the generic information about how this standby is
— setup. The database_role should be standby as that is what this script is intended
— to be ran on. If protection_level is different than protection_mode then for some
— reason the mode listed in protection_mode experienced a need to downgrade. Once the
— error condition has been corrected the protection_level should match the protection_mode
— after the next log switch.

column ROLE format a7 tru
select name,database_role,log_mode,controlfile_type,protection_mode,protection_level
from v$database;

— Force logging is not mandatory but is recommended. Supplemental logging should be enabled
— on the standby if a logical standby is in the configuration. During normal
— operations it is acceptable for SWITCHOVER_STATUS to be SESSIONS ACTIVE or NOT ALLOWED.

column force_logging format a13 tru
column remote_archive format a14 tru
column dataguard_broker format a16 tru
select force_logging,remote_archive,supplemental_log_data_pk,supplemental_log_data_ui,
switchover_status,dataguard_broker from v$database;

— This query produces a list of all archive destinations and shows if they are enabled,
— what process is servicing that destination, if the destination is local or remote,
— and if remote what the current mount ID is. For a physical standby we should have at
— least one remote destination that points the primary set but it should be deferred.

COLUMN destination FORMAT A35 WRAP
column process format a7
column archiver format a8
column ID format 99

select dest_id “ID”,destination,status,target,
archiver,schedule,process,mountid
from v$archive_dest;

— If the protection mode of the standby is set to anything higher than max performance
— then we need to make sure the remote destination that points to the primary is set
— with the correct options else we will have issues during switchover.

select dest_id,process,transmit_mode,async_blocks,
net_timeout,delay_mins,reopen_secs,register,binding
from v$archive_dest;

— The following select will show any errors that occured the last time an attempt to
— archive to the destination was attempted. If ERROR is blank and status is VALID then
— the archive completed correctly.

column error format a55 tru
select dest_id,status,error from v$archive_dest;

— Determine if any error conditions have been reached by querying thev$dataguard_status
— view (view only available in 9.2.0 and above):

column message format a80
select message, timestamp
from v$dataguard_status
where severity in (‘Error’,’Fatal’)
order by timestamp;

— The following query is ran to get the status of the SRL’s on the standby. If the
— primary is archiving with the LGWR process and SRL’s are present (in the correct
— number and size) then we should see a group# active.

select group#,sequence#,bytes,used,archived,status from v$standby_log;

— The above SRL’s should match in number and in size with the ORL’s returned below:

select group#,thread#,sequence#,bytes,archived,status from v$log;

— Query v$managed_standby to see the status of processes involved in the
— configuration.

select process,status,client_process,sequence#,block#,active_agents,known_agents
from v$managed_standby;

— Verify that the last sequence# received and the last sequence# applied to standby
— database.

select al.thrd “Thread”, almax “Last Seq Received”, lhmax “Last Seq Applied”
from (select thread# thrd, max(sequence#) almax
from v$archived_log
where resetlogs_change#=(select resetlogs_change# from v$database)
group by thread#) al,
(select thread# thrd, max(sequence#) lhmax
from v$log_history
where first_time=(select max(first_time) from v$log_history)
group by thread#) lh
where al.thrd = lh.thrd;

— The V$ARCHIVE_GAP fixed view on a physical standby database only returns the next
— gap that is currently blocking redo apply from continuing. After resolving the
— identified gap and starting redo apply, query the V$ARCHIVE_GAP fixed view again
— on the physical standby database to determine the next gap sequence, if there is
— one.

select * from v$archive_gap;

— Non-default init parameters.

set numwidth 5
column name format a30 tru
column value format a50 wra
select name, value
from v$parameter
where isdefault = ‘FALSE’;

spool off

– – – – – – – – – – – – – – – – Script ends here – – – – – – – – – – – – – – – –

沪ICP备14014813号

沪公网安备 31010802001379号