Operating mechanism of Oracle archiving process

Keywords: Oracle rman Database SQL

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)

Posted by Timma on Sun, 21 Apr 2019 14:30:34 -0700