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

copyking

真理是需要不断摸索才能发现的。
所以，在网友的质疑下，我发现上一篇的文章的认识是有问题的，经过进一步的研究，终于找到了问题的原因所在。
关键原因在于alter system archive log current是怎样执行的？这是核心所在。
首先排除归档进程，当log_archive_max_processes参数设置为1时，archive log current同样会出现之前讨论的问题:
SQL> alter system set log_archive_max_processes=1 scope=both;
System altered.
SQL> archive log stop;
Statement processed.
SQL> archive log start;
Statement processed.
SQL> alter system archive log current;
System altered.
此时观察警告日志:
Fri Jun 8 15:33:56 2007
Archive Log Stop
Archive Log Start
Using log_archive_dest parameter default value
Archiving is enabled
ARCH: STARTING ARCH PROCESSES
ARCH: STARTING ARCH PROCESSES COMPLETE
ARC0 started with pid=12
ARC0: Archival started
Fri Jun 8 15:34:12 2007
ARCH: Evaluating archive log 5 thread 1 sequence 324
ARCH: Beginning to archive log 5 thread 1 sequence 324
Creating archive destination LOG_ARCHIVE_DEST_1: '/opt/oracle/product/9.2.0/dbs/arch1_324.dbf'
Fri Jun 8 15:34:12 2007
Beginning log switch checkpoint up to RBA [0x145.2.10], SCN: 0x0004.6c6330e3
Fri Jun 8 15:34:12 2007
ARC0: Evaluating archive log 5 thread 1 sequence 324
ARC0: Unable to archive log 5 thread 1 sequence 324
Log actively being archived by another process
只有一个归档进程了，那么为什么还存在"Log actively being archived by another process"的提示呢?
那么一定还存在另外一个进程在执行归档。
我们索性将所有归档进程停止，再来研究:
SQL> archive log stop;
Statement processed.
SQL> alter system archive log current;
System altered.
在日志中记录了如下信息：
Fri Jun 8 15:34:12 2007
Thread 1 advanced to log sequence 325
Current log# 3 seq# 325 mem# 0: /opt/oracle/oradata/eygle/redo03.log
Fri Jun 8 15:34:12 2007
ARCH: Completed archiving log 5 thread 1 sequence 324
Archive Log Stop
Using log_archive_dest parameter default value
Archiving is disabled
Shutting down archive processes
Archiving is disabled
Fri Jun 8 15:35:52 2007
ARCH shutting down
ARC0: Archival stopped
Fri Jun 8 15:35:55 2007
Beginning log switch checkpoint up to RBA [0x146.2.10], SCN: 0x0004.6c633108
Thread 1 advanced to log sequence 326
Current log# 4 seq# 326 mem# 0: /opt/oracle/oradata/eygle/redo04.dbf
Fri Jun 8 15:35:55 2007
ARCH: Evaluating archive log 3 thread 1 sequence 325
ARCH: Beginning to archive log 3 thread 1 sequence 325
Creating archive destination LOG_ARCHIVE_DEST_1: '/opt/oracle/product/9.2.0/dbs/arch1_325.dbf'
ARCH: Completed archiving log 3 thread 1 sequence 325
Fri Jun 8 15:35:55 2007
Completed checkpoint up to RBA [0x146.2.10], SCN: 0x0004.6c633108
Completed checkpoint up to RBA [0x145.2.10], SCN: 0x0004.6c6330e3
我们注意到归档仍然成功的完成了。
那么到底是哪个进程在进行归档工作呢?
只剩下执行执行命令的进程了:
SQL> select spid from v$process where addr = (
2 select paddr from v$session where sid = (select sid from v$mystat where rownum  alter system archive log current;
System altered.
执行这个命令的同时我们可以跟踪一下这个进程的后台动作：
[oracle@jumper bdump]$ strace -p 27146
Process 27146 attached - interrupt to quit
read(7, "\0\275\0\0\6\0\0\0\0\0\21i\25\4\351\22\10\1\0\0\0\1\0\0"..., 2064) = 189
gettimeofday({1181288425, 367461}, NULL) = 0
gettimeofday({1181288425, 367659}, NULL) = 0
gettimeofday({1181288425, 367804}, NULL) = 0
gettimeofday({1181288425, 367940}, NULL) = 0
gettimeofday({1181288425, 368105}, NULL) = 0
write(5, "*** 2007-06-08 15:40:25.367", 27) = 27
write(5, "\n", 1) = 1
gettimeofday({1181288425, 368638}, NULL) = 0
write(5, "WAIT #1: nam=\'SQL*Net message fr"..., 80) = 80
write(5, "\n", 1) = 1
gettimeofday({1181288425, 369090}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
gettimeofday({1181288425, 369728}, NULL) = 0
gettimeofday({1181288425, 369872}, NULL) = 0
gettimeofday({1181288425, 370007}, NULL) = 0
gettimeofday({1181288425, 370176}, NULL) = 0
gettimeofday({1181288425, 370312}, NULL) = 0
gettimeofday({1181288425, 370442}, NULL) = 0
gettimeofday({1181288425, 370723}, NULL) = 0
gettimeofday({1181288425, 370883}, NULL) = 0
gettimeofday({1181288425, 371024}, NULL) = 0
gettimeofday({1181288425, 371159}, NULL) = 0
gettimeofday({1181288425, 371293}, NULL) = 0
write(5, "STAT #1 id=1 cnt=1 pid=0 pos=1 o"..., 76) = 76
write(5, "\n", 1) = 1
gettimeofday({1181288425, 371787}, NULL) = 0
gettimeofday({1181288425, 371957}, NULL) = 0
gettimeofday({1181288425, 372090}, NULL) = 0
gettimeofday({1181288425, 372226}, NULL) = 0
gettimeofday({1181288425, 372406}, NULL) = 0
gettimeofday({1181288425, 372561}, NULL) = 0
gettimeofday({1181288425, 372698}, NULL) = 0
gettimeofday({1181288425, 372831}, NULL) = 0
gettimeofday({1181288425, 372963}, NULL) = 0
gettimeofday({1181288425, 373096}, NULL) = 0
gettimeofday({1181288425, 373229}, NULL) = 0
gettimeofday({1181288425, 373366}, NULL) = 0
gettimeofday({1181288425, 373497}, NULL) = 0
gettimeofday({1181288425, 373719}, NULL) = 0
write(5, "STAT #1 id=2 cnt=11 pid=1 pos=1 "..., 95) = 95
write(5, "\n", 1) = 1
gettimeofday({1181288425, 374213}, NULL) = 0
gettimeofday({1181288425, 374374}, NULL) = 0
gettimeofday({1181288425, 374510}, NULL) = 0
gettimeofday({1181288425, 374645}, NULL) = 0
gettimeofday({1181288425, 374776}, NULL) = 0
gettimeofday({1181288425, 374911}, NULL) = 0
gettimeofday({1181288425, 375043}, NULL) = 0
gettimeofday({1181288425, 375179}, NULL) = 0
gettimeofday({1181288425, 375351}, NULL) = 0
gettimeofday({1181288425, 375510}, NULL) = 0
gettimeofday({1181288425, 375647}, NULL) = 0
gettimeofday({1181288425, 375781}, NULL) = 0
write(5, "STAT #1 id=3 cnt=1 pid=1 pos=2 o"..., 76) = 76
write(5, "\n", 1) = 1
gettimeofday({1181288425, 376245}, NULL) = 0
gettimeofday({1181288425, 376405}, NULL) = 0
gettimeofday({1181288425, 376635}, NULL) = 0
gettimeofday({1181288425, 376793}, NULL) = 0
gettimeofday({1181288425, 376928}, NULL) = 0
gettimeofday({1181288425, 377061}, NULL) = 0
gettimeofday({1181288425, 377193}, NULL) = 0
gettimeofday({1181288425, 377326}, NULL) = 0
gettimeofday({1181288425, 377457}, NULL) = 0
gettimeofday({1181288425, 377589}, NULL) = 0
gettimeofday({1181288425, 377719}, NULL) = 0
gettimeofday({1181288425, 377855}, NULL) = 0
gettimeofday({1181288425, 377987}, NULL) = 0
gettimeofday({1181288425, 378119}, NULL) = 0
write(5, "STAT #1 id=4 cnt=10 pid=3 pos=1 "..., 95) = 95
write(5, "\n", 1) = 1
gettimeofday({1181288425, 378644}, NULL) = 0
gettimeofday({1181288425, 378803}, NULL) = 0
gettimeofday({1181288425, 378933}, NULL) = 0
gettimeofday({1181288425, 379066}, NULL) = 0
gettimeofday({1181288425, 379197}, NULL) = 0
gettimeofday({1181288425, 379328}, NULL) = 0
gettimeofday({1181288425, 379552}, NULL) = 0
gettimeofday({1181288425, 379703}, NULL) = 0
gettimeofday({1181288425, 379836}, NULL) = 0
gettimeofday({1181288425, 379973}, NULL) = 0
gettimeofday({1181288425, 380105}, NULL) = 0
gettimeofday({1181288425, 380566}, NULL) = 0
write(5, "STAT #1 id=5 cnt=1 pid=3 pos=2 o"..., 81) = 81
write(5, "\n", 1) = 1
gettimeofday({1181288425, 381063}, NULL) = 0
gettimeofday({1181288425, 381228}, NULL) = 0
gettimeofday({1181288425, 381359}, NULL) = 0
gettimeofday({1181288425, 381565}, NULL) = 0
gettimeofday({1181288425, 381708}, NULL) = 0
gettimeofday({1181288425, 381841}, NULL) = 0
gettimeofday({1181288425, 381973}, NULL) = 0
gettimeofday({1181288425, 382106}, NULL) = 0
gettimeofday({1181288425, 382236}, NULL) = 0
gettimeofday({1181288425, 382372}, NULL) = 0
gettimeofday({1181288425, 382502}, NULL) = 0
gettimeofday({1181288425, 382707}, NULL) = 0
write(5, "STAT #1 id=6 cnt=1 pid=5 pos=1 o"..., 75) = 75
write(5, "\n", 1) = 1
gettimeofday({1181288425, 383212}, NULL) = 0
gettimeofday({1181288425, 383378}, NULL) = 0
gettimeofday({1181288425, 383511}, NULL) = 0
gettimeofday({1181288425, 383644}, NULL) = 0
gettimeofday({1181288425, 383774}, NULL) = 0
gettimeofday({1181288425, 383906}, NULL) = 0
gettimeofday({1181288425, 384036}, NULL) = 0
gettimeofday({1181288425, 384168}, NULL) = 0
gettimeofday({1181288425, 384326}, NULL) = 0
gettimeofday({1181288425, 384468}, NULL) = 0
gettimeofday({1181288425, 384616}, NULL) = 0
gettimeofday({1181288425, 384754}, NULL) = 0
gettimeofday({1181288425, 384885}, NULL) = 0
gettimeofday({1181288425, 385017}, NULL) = 0
write(5, "STAT #1 id=7 cnt=1 pid=6 pos=1 o"..., 96) = 96
write(5, "\n", 1) = 1
gettimeofday({1181288425, 385563}, NULL) = 0
gettimeofday({1181288425, 385761}, NULL) = 0
gettimeofday({1181288425, 385897}, NULL) = 0
gettimeofday({1181288425, 386031}, NULL) = 0
gettimeofday({1181288425, 386165}, NULL) = 0
gettimeofday({1181288425, 386298}, NULL) = 0
gettimeofday({1181288425, 386431}, NULL) = 0
gettimeofday({1181288425, 386565}, NULL) = 0
gettimeofday({1181288425, 386697}, NULL) = 0
gettimeofday({1181288425, 386829}, NULL) = 0
gettimeofday({1181288425, 386962}, NULL) = 0
gettimeofday({1181288425, 387098}, NULL) = 0
gettimeofday({1181288425, 387260}, NULL) = 0
gettimeofday({1181288425, 387396}, NULL) = 0
write(5, "STAT #1 id=8 cnt=1 pid=6 pos=2 o"..., 94) = 94
write(5, "\n", 1) = 1
gettimeofday({1181288425, 387874}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
gettimeofday({1181288425, 388966}, NULL) = 0
gettimeofday({1181288425, 389097}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
gettimeofday({1181288425, 389789}, NULL) = 0
gettimeofday({1181288425, 389927}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
gettimeofday({1181288425, 390261}, NULL) = 0
gettimeofday({1181288425, 390444}, NULL) = 0
write(5, "=====================", 21) = 21
write(5, "\n", 1) = 1
gettimeofday({1181288425, 390987}, NULL) = 0
gettimeofday({1181288425, 391136}, NULL) = 0
write(5, "

ARSING IN CURSOR #1 len=32 dep="..., 101) = 101
write(5, "\n", 1) = 1
gettimeofday({1181288425, 391586}, NULL) = 0
gettimeofday({1181288425, 391831}, NULL) = 0
write(5, "alter system archive log current", 32) = 32
write(5, "\n", 1) = 1
gettimeofday({1181288425, 392318}, NULL) = 0
gettimeofday({1181288425, 392456}, NULL) = 0
write(5, "END OF STMT", 11) = 11
write(5, "\n", 1) = 1
gettimeofday({1181288425, 392897}, NULL) = 0
gettimeofday({1181288425, 393043}, NULL) = 0
write(5, "

ARSE #1:c=0,e=938,p=0,cr=0,cu=0"..., 74) = 74
write(5, "\n", 1) = 1
gettimeofday({1181288425, 393657}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 50000}, ru_stime={0, 60000}, ...}) = 0
gettimeofday({1181288425, 394006}, NULL) = 0
gettimeofday({1181288425, 394236}, NULL) = 0
write(5, "BINDS #1:", 9) = 9
write(5, "\n", 1) = 1
gettimeofday({1181288425, 394446}, NULL) = 0
gettimeofday({1181288425, 394598}, NULL) = 0
pread(12, "\25\2\0\0\1\0\0\0\236\335\23\0\377\377\1\4\233F\0\0\0\0"..., 8192, 8192) = 8192
gettimeofday({1181288425, 394963}, NULL) = 0
gettimeofday({1181288425, 395014}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 395181}, NULL) = 0
gettimeofday({1181288425, 395240}, NULL) = 0
pread(12, "\25\2\0\0r\1\0\0\235\335\23\0\377\377\1\4J\354\0\0\0\0"..., 8192, 3031040) = 8192
gettimeofday({1181288425, 395382}, NULL) = 0
gettimeofday({1181288425, 395423}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 69) = 69
write(5, "\n", 1) = 1
gettimeofday({1181288425, 395554}, NULL) = 0
gettimeofday({1181288425, 395610}, NULL) = 0
pread(12, "\25\2\0\0\t\0\0\0\234\335\23\0\377\377\1\4\220\263\0\0"..., 8192, 73728) = 8192
gettimeofday({1181288425, 395747}, NULL) = 0
gettimeofday({1181288425, 395786}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 395918}, NULL) = 0
gettimeofday({1181288425, 395965}, NULL) = 0
pread(12, "\25\2\0\0\10\0\0\0\235\335\23\0\377\377\1\4\240`\0\0\17"..., 8192, 65536) = 8192
gettimeofday({1181288425, 396105}, NULL) = 0
gettimeofday({1181288425, 396145}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 396277}, NULL) = 0
gettimeofday({1181288425, 396327}, NULL) = 0
pread(12, "\25\2\0\0\t\0\0\0\234\335\23\0\377\377\1\4\220\263\0\0"..., 8192, 73728) = 8192
gettimeofday({1181288425, 397245}, NULL) = 0
gettimeofday({1181288425, 397394}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 397887}, NULL) = 0
gettimeofday({1181288425, 398262}, NULL) = 0
pread(12, "\25\2\0\0\10\0\0\0\235\335\23\0\377\377\1\4\240`\0\0\17"..., 8192, 65536) = 8192
gettimeofday({1181288425, 398629}, NULL) = 0
gettimeofday({1181288425, 398773}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 399397}, NULL) = 0
gettimeofday({1181288425, 399574}, NULL) = 0
gettimeofday({1181288425, 399820}, NULL) = 0
pwrite(12, "\25\2\0\0q\1\0\0\236\335\23\0\377\377\1\4I\354\0\0\0\0"..., 8192, 3022848) = 8192
gettimeofday({1181288425, 401723}, NULL) = 0
gettimeofday({1181288425, 401897}, NULL) = 0
gettimeofday({1181288425, 402059}, NULL) = 0
write(5, "WAIT #1: nam=\'control file paral"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 402588}, NULL) = 0
gettimeofday({1181288425, 402754}, NULL) = 0
gettimeofday({1181288425, 402936}, NULL) = 0
gettimeofday({1181288425, 403082}, NULL) = 0
pwrite(12, "\25\2\0\0\1\0\0\0\237\335\23\0\377\377\1\4\247F\0\0\0\0"..., 8192, 8192) = 8192
gettimeofday({1181288425, 404288}, NULL) = 0
gettimeofday({1181288425, 404514}, NULL) = 0
gettimeofday({1181288425, 404693}, NULL) = 0
write(5, "WAIT #1: nam=\'control file paral"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 405201}, NULL) = 0
semctl(12582912, 8, IPC_64|SETVAL, 0xbfff8bac) = 0
gettimeofday({1181288425, 409255}, NULL) = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], NULL, 8) = 0
gettimeofday({1181288425, 412590}, NULL) = 0
setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={5, 120000}}, NULL) = 0
rt_sigprocmask(SIG_UNBLOCK, [ALRM], NULL, 8) = 0
semop(12582912, 0xbfff8ae4, 1) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], NULL, 8) = 0
setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
rt_sigprocmask(SIG_UNBLOCK, [ALRM], NULL, 8) = 0
gettimeofday({1181288425, 415273}, NULL) = 0
gettimeofday({1181288425, 415522}, NULL) = 0
write(5, "WAIT #1: nam=\'switch logfile com"..., 62) = 62
write(5, "\n", 1) = 1
gettimeofday({1181288425, 416049}, NULL) = 0
gettimeofday({1181288425, 416317}, NULL) = 0
pread(12, "\25\2\0\0\1\0\0\0\241\335\23\0\377\377\1\4\227B\0\0\0\0"..., 8192, 8192) = 8192
gettimeofday({1181288425, 416894}, NULL) = 0
gettimeofday({1181288425, 417064}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 417560}, NULL) = 0
gettimeofday({1181288425, 417721}, NULL) = 0
pread(12, "\25\2\0\0q\1\0\0\240\335\23\0\377\377\1\4I\354\0\0\0\0"..., 8192, 3022848) = 8192
gettimeofday({1181288425, 418081}, NULL) = 0
gettimeofday({1181288425, 418225}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 69) = 69
write(5, "\n", 1) = 1
gettimeofday({1181288425, 418766}, NULL) = 0
gettimeofday({1181288425, 418935}, NULL) = 0
pread(12, "\25\2\0\0\t\0\0\0\240\335\23\0\377\377\1\4\333\265\0\0"..., 8192, 73728) = 8192
gettimeofday({1181288425, 419307}, NULL) = 0
gettimeofday({1181288425, 419452}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 420078}, NULL) = 0
gettimeofday({1181288425, 420475}, NULL) = 0
gettimeofday({1181288425, 420654}, NULL) = 0
close(6) = 0
open("/opt/oracle/admin/eygle/bdump/alert_eygle.log", O_WRONLY|O_APPEND|O_CREAT, 0664) = 6
time([1181288425]) = 1181288425
writev(6, [{"Fri Jun 8 15:40:25 2007\n", 25}, {"ARCH: Evaluating archive log 4"..., 54}, {"\n", 1}], 3) = 80
gettimeofday({1181288425, 421608}, NULL) = 0
gettimeofday({1181288425, 421816}, NULL) = 0
pread(12, "\25\2\0\0\22\0\0\0G\334\23\0\377\377\1\4\234\241\0\0\3"..., 8192, 147456) = 8192
gettimeofday({1181288425, 422313}, NULL) = 0
gettimeofday({1181288425, 422465}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 68) = 68
write(5, "\n", 1) = 1
gettimeofday({1181288425, 422951}, NULL) = 0
stat64("/opt/oracle/oradata/eygle/redo04.dbf", {st_mode=S_IFREG|0640, st_size=1049088, ...}) = 0
statfs("/opt/oracle/oradata/eygle/redo04.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399121, f_bavail=294298, f_files=1048576, f_ffree=1027927, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/oradata/eygle/redo04.dbf", O_RDONLY|O_LARGEFILE) = 13
close(13) = 0
statfs("/opt/oracle/oradata/eygle/redo04.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399121, f_bavail=294298, f_files=1048576, f_ffree=1027927, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/oradata/eygle/redo04.dbf", O_RDWR|O_SYNC|O_LARGEFILE) = 13
fcntl64(13, F_SETFD, FD_CLOEXEC) = 0
gettimeofday({1181288425, 424627}, NULL) = 0
pread(13, "F\1\0\0\1\0\0\0i\231

本文来自ChinaUnix博客，如果查看原文请点：http://blog.chinaunix.net/u2/66684/showart_1083524.html