eygle.com   eygle.com
eygle.com eygle
eygle.com  
 

« Canon 400D的梦魇 | Blog首页 | Canon 400D更换记 »

关于Oracle归档进程的运行机制
modb.pro

前几天有位朋友在留言板上提了这样一个问题:

Fri May 25 20:46:06 2007  //自动备份controlfile
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   //发生日志切换
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   //同时启动归档
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   //一秒后另一进程启动,失败
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   //3秒后成功归档
ARCH: Completed archiving log 6 thread 1 sequence 534
Fri May 25 20:46:18 2007   //3秒后日志切换
Thread 1 advanced to log sequence 536
Current log# 2 seq# 536 mem# 0: /dev/udpay/lv_redo21_256m

以上日志是备份过程中产生的,备份脚本如下:

$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;
}
!!

这位朋友提出的问题是,为什么会有:
Log actively being archived by another process

如果一个归档进程已经开始归档日志,为什么另外一个进程又来归档日志?

研究了一下,有了一点新的发现。

首先,归档进程的数量是受初始化参数log_archive_max_processes控制,初始的,这个参数设置为2,Oracle启动两个归档进程:

[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

其中主归档进程会持续访问控制文件:

*** 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

另外一个归档进程以'rdbms ipc message' 事件处于等待:

*** 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

当我们执行alter system archive log current命令时,Oracle Post归档进程时,主归档进程首先执行归档,而次归档进程则需要去读取控制文件,以获得当前及下一归档日志信息:

*** 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

这就导致次归档进程始终会落后于主归档进程,会在警告日志中看到如下信息:

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

这在正常情况下是不会出现的,如果一个归档进程能够满足系统需要,第二个进程就无需启动,而手动switch log则会Post所有归档进程。

在Oracle10g中,情况同样如此:

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)

-The End-


历史上的今天...

By eygle on 2007-06-06 20:38 | Comments (8) | Internal | 1454 |

8 Comments

这个也困惑了我好久,谢谢

我也遇到过这个问题,也很郁闷,不过看到只要有一个归档成功,我就没管它,今天跟着大师再学习一下

只要多花一点心思和时间,往往就能找到更多的事实真相:)

只要多花一点心思和时间,往往就能找到更多的事实真相:)

(1)呃,主进程一定是arch0吗?副进程是arch1、2、3……

(2)还有这些信息是怎么看到的?
*** 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

(3)之前在一个IO有问题、log高active的数据库上也看到过这样的报错,当时没考虑到是有多个进程,只是想到了是因为归档做的慢,一个redolog还没arch完,又再次轮到它做arch了。今天看了eygle的话明白多了~~谢谢~

(4)如果只有一个arch进程,在io有问题的时候还会包这个错吗?应该不会了吧?

谢谢您的指导!!!
不过还是有个疑问
即便是将
log_archive_max_processes
设成1
仍然会报
这个就不是主进程与副进程的关系了吧
我觉得是不是当发出
alter system switch current log
时oracle启动了另外一个归档进程去归档日志呢
也就是不是用已经启动的arch0 arch1
oracle的自动归档与手工归档不是用一个进程?
关于alter system switch current log 究竟做了什么?

这是我的看法,不知道对否
http://www.itpub.net/783079.html

谢谢你的问题,我已经找到根本原因了。

上面说的有问题,等下有空我写出来。


CopyRight © 2004~2020 云和恩墨,成就未来!, All rights reserved.
数据恢复·紧急救援·性能优化 云和恩墨 24x7 热线电话:400-600-8755 业务咨询:010-59007017-7040 or 7037 业务合作: marketing@enmotech.com