A friend asked such a question:
Fri May 25 20:46:06 2007 //Automatic backup control file
Starting control autobackup
Control autobackup written to DISK device
handle '/ora_rman_backup/crtl_backup/c-4205638757-20070525-00'
Fri May 25 20:46:11 2007 //Log switching occurs
Thread 1 advanced to log sequence 535
Current log# 1 seq# 535 mem# 0: /dev/udpay/lv_redo11_256m
Current log# 1 seq# 535 mem# 1: /dev/udpay/lv_redo12_256m
Fri May 25 20:46:11 2007 //Start archiving at the same time
ARCH: Evaluating archive log 6 thread 1 sequence 534
ARCH: Beginning to archive log 6 thread 1 sequence 534
Creating archive destination LOG_ARCHIVE_DEST_1: '/archivelog/arch/1_534.dbf'
Fri May 25 20:46:12 2007 //A second later another process starts and fails.
ARC0: Evaluating archive log 6 thread 1 sequence 534
ARC0: Unable to archive log 6 thread 1 sequence 534
Log actively being archived by another process
Fri May 25 20:46:15 2007 //Successful filing in 3 seconds
ARCH: Completed archiving log 6 thread 1 sequence 534
Fri May 25 20:46:18 2007 //Log switching after 3 seconds
Thread 1 advanced to log sequence 536
Current log# 2 seq# 536 mem# 0: /dev/udpay/lv_redo21_256m
The above logs are generated during the backup process. The backup scripts are as follows:
$ORACLE_HOME/bin/rman < connect catalog rman/rman @rman;
connect target sys/sys@udpay;
CONFIGURE CONTROLFILE AUTOBACKUP FORMAT FOR DEVICE TYPE DISK TO '/ora_rman_backup/crtl_backup/%F';
CONFIGURE CONTROLFILE AUTOBACKUP ON;
CROSSCHECK ARCHIVELOG ALL;
run{
ALLOCATE CHANNEL ch1 DEVICE TYPE DISK;
backup full database format 'D:/%T_%d' include current controlfile;
sql 'alter system archive log current';
backup filesperset 3 format 'D:/arch%u_%s_%p' archivelog all;
DELETE NOPROMPT ARCHIVELOG UNTIL TIME 'SYSDATE-2';
release channel ch1;
}
!!
The question raised by this friend is why:
Log actively being archived by another process
If an archiving process has started to archive logs, why does another process archive logs?
After a study, there is a new discovery.
First, the number of archiving processes is controlled by the initialization parameter log_archive_max_processes. Initially, this parameter is set to 2. Oracle starts two archiving processes:
[oracle@jumper bdump]$ ps -ef|grep ora_arc oracle 11938 1 0 18:24 ? 00:00:00 ora_arc0_eygle oracle 11940 1 0 18:24 ? 00:00:00 ora_arc1_eygle oracle 16260 11894 0 20:21 pts/5 00:00:00 grep ora_arc
The main archiving process continuously accesses the control files:
*** 2007-06-06 20:23:50.510 WAIT #0: nam='rdbms ipc message' ela= 59999293 p1=6000 p2=0 p3=0 WAIT #0: nam='control file sequential read' ela= 76 p1=0 p2=1 p3=1 WAIT #0: nam='control file sequential read' ela= 36 p1=0 p2=370 p3=1 WAIT #0: nam='control file sequential read' ela= 36 p1=0 p2=8 p3=1 WAIT #0: nam='control file sequential read' ela= 30 p1=0 p2=9 p3=1 *** 2007-06-06 20:24:51.950 WAIT #0: nam='rdbms ipc message' ela= 59999344 p1=6000 p2=0 p3=0 WAIT #0: nam='control file sequential read' ela= 72 p1=0 p2=1 p3=1 WAIT #0: nam='control file sequential read' ela= 35 p1=0 p2=370 p3=1 WAIT #0: nam='control file sequential read' ela= 35 p1=0 p2=8 p3=1 WAIT #0: nam='control file sequential read' ela= 29 p1=0 p2=9 p3=1
Another archiving process is waiting with the'rdbms ipc message'event:
*** 2007-06-06 20:01:15.830 WAIT #0: nam='rdbms ipc message' ela= 148300048 p1=14831 p2=0 p3=0 a*** 2007-06-06 20:06:23.030 WAIT #0: nam='rdbms ipc message' ela= 299999745 p1=30000 p2=0 p3=0 a*** 2007-06-06 20:11:30.230 WAIT #0: nam='rdbms ipc message' ela= 299999735 p1=30000 p2=0 p3=0 a*** 2007-06-06 20:16:37.430 WAIT #0: nam='rdbms ipc message' ela= 299999779 p1=30000 p2=0 p3=0 a*** 2007-06-06 20:21:44.630
When we execute the alter system archive log current command, the Oracle Post archive process first executes the archive, while the sub-archive process needs to read the control file to obtain the current and next archive log information:
*** 2007-06-06 19:58:43.970 WAIT #0: nam='rdbms ipc message' ela= 148134746 p1=30000 p2=0 p3=0 WAIT #0: nam='control file sequential read' ela= 36 p1=0 p2=1 p3=1 WAIT #0: nam='control file sequential read' ela= 29 p1=0 p2=369 p3=1 WAIT #0: nam='control file sequential read' ela= 32 p1=0 p2=8 p3=1 WAIT #0: nam='control file sequential read' ela= 29 p1=0 p2=10 p3=1
This will cause the sub-archiving process to always lag behind the main archiving process. The following information will be seen in the warning log:
Wed Jun 6 19:58:43 2007 ARCH: Evaluating archive log 4 thread 1 sequence 305 ARCH: Beginning to archive log 4 thread 1 sequence 305 Creating archive destination LOG_ARCHIVE_DEST_1: '/opt/oracle/product/9.2.0/dbs/arch1_305.dbf' Wed Jun 6 19:58:43 2007 ARC1: Evaluating archive log 4 thread 1 sequence 305 ARC1: Unable to archive log 4 thread 1 sequence 305 Log actively being archived by another process
Normally, this does not happen. If an archiving process meets the needs of the system, the second process does not need to start, and manual switch log will Post all archiving processes.
In Oracle 10g, the same is true:
Wed Jun 6 20:32:57 2007 ARCH: Evaluating archive log 4 thread 1 sequence 75268 Wed Jun 6 20:32:57 2007 ARC0: Evaluating archive log 4 thread 1 sequence 75268 ARC0: Unable to archive log 4 thread 1 sequence 75268 Log actively being archived by another process Wed Jun 6 20:32:57 2007 ARCH: Beginning to archive log 4 thread 1 sequence 75268 (2074.-1351690850:2074.-1351608674) (mmsdb)