真理是需要不断摸索才能发现的。
所以，在网友的质疑下，我发现上一篇的文章的认识是有
问题的，经过进一步的研究，终于找到了问题的原因所在。
关键原因在于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 <2))
3 /
SPID
------------
27146
SQL> 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<%\0\0\246\353\0\0 \t\0\0 \tx\227\347"..., 512, 512) = 512
gettimeofday({1181288425, 425041}, NULL) = 0
gettimeofday({1181288425, 425189}, NULL) = 0
write(5, "WAIT #1: nam=\'log file sequentia"..., 63) = 63
write(5, "\n", 1) = 1
gettimeofday({1181288425, 425674}, NULL) = 0
stat64("/opt/oracle/product/9.2.0/dbs/", {st_mode=S_IFDIR|0755, st_size=118784, ...}) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch", 0xbfff83b4) = -1 ENOENT (No such file or directory)
stat64("/opt/oracle/product/9.2.0/dbs/", {st_mode=S_IFDIR|0755, st_size=118784, ...}) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch", 0xbfff838c) = -1 ENOENT (No such file or directory)
stat64("/opt/oracle/product/9.2.0/dbs/", {st_mode=S_IFDIR|0755, st_size=118784, ...}) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch", 0xbfff8230) = -1 ENOENT (No such file or directory)
gettimeofday({1181288425, 427220}, NULL) = 0
gettimeofday({1181288425, 427387}, NULL) = 0
close(6) = 0
open("/opt/oracle/admin/eygle/bdump/alert_eygle.log", O_WRONLY|O_APPEND|O_CREAT, 0664) = 6
writev(6, [{"ARCH: Beginning to archive log 4"..., 54}, {"\n", 1}], 2) = 55
gettimeofday({1181288425, 428040}, NULL) = 0
gettimeofday({1181288425, 428142}, NULL) = 0
gettimeofday({1181288425, 428201}, NULL) = 0
close(6) = 0
open("/opt/oracle/admin/eygle/bdump/alert_eygle.log", O_WRONLY|O_APPEND|O_CREAT, 0664) = 6
writev(6, [{"Creating archive destination LOG"..., 94}, {"\n", 1}], 2) = 95
gettimeofday({1181288425, 428415}, NULL) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", 0xbfff81a4) = -1 ENOENT (No such file or directory)
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", 0xbfff7e14) = -1 ENOENT (No such file or directory)
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", 0xbfff8200) = -1 ENOENT (No such file or directory)
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDWR|O_CREAT|O_EXCL|O_SYNC|O_LARGEFILE, 0660) = 14
fstat64(14, {st_mode=S_IFREG|0640, st_size=0, ...}) = 0
fstatfs(14, {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399121, f_bavail=294298, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
lseek(14, 0, SEEK_SET) = 0
write(14, "\0\2\0\0\0\2\0\0\4\0\0\0]\\[Z\240\201\0\0\242\207\0\0\0"..., 512) = 512
ftruncate64(14, 2560) = 0
close(14) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {st_mode=S_IFREG|0640, st_size=2560, ...}) = 0
statfs("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399120, f_bavail=294297, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDONLY|O_LARGEFILE) = 14
close(14) = 0
statfs("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399120, f_bavail=294297, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDWR|O_LARGEFILE) = 14
fcntl64(14, F_SETFD, FD_CLOEXEC) = 0
fcntl64(14, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
fcntl64(14, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
gettimeofday({1181288425, 438810}, NULL) = 0
gettimeofday({1181288425, 438976}, NULL) = 0
pread(13, "F\1\0\0\1\0\0\0i\231<%\0\0\246\353\0\0 \t\0\0 \tx\227\347"..., 2048, 512) = 2048
gettimeofday({1181288425, 439369}, NULL) = 0
gettimeofday({1181288425, 439644}, NULL) = 0
write(5, "WAIT #1: nam=\'log file sequentia"..., 63) = 63
write(5, "\n", 1) = 1
gettimeofday({1181288425, 444474}, NULL) = 0
gettimeofday({1181288425, 444713}, NULL) = 0
pwrite(14, "F\1\0\0\1\0\0\0i\231<%\0\0\207\353\0\0 \t\0\0 \tx\227\347"..., 2048, 512) = 2048
gettimeofday({1181288425, 445135}, NULL) = 0
gettimeofday({1181288425, 445288}, NULL) = 0
gettimeofday({1181288425, 445434}, NULL) = 0
gettimeofday({1181288425, 445583}, NULL) = 0
write(5, "WAIT #1: nam=\'async disk IO\' ela"..., 63) = 63
write(5, "\n", 1) = 1
gettimeofday({1181288425, 446202}, NULL) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {st_mode=S_IFREG|0640, st_size=2560, ...}) = 0
statfs("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399120, f_bavail=294297, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDWR|O_LARGEFILE) = 15
lseek(15, 0, SEEK_SET) = 0
write(15, "\0\2\0\0\0\2\0\0\4\0\0\0]\\[Z\0\0\0\0\2\6\0\0\0\0\0\0\0"..., 512) = 512
ftruncate64(15, 2560) = 0
close(15) = 0
fcntl64(14, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
fcntl64(14, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
fcntl64(14, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
gettimeofday({1181288425, 448328}, NULL) = 0
fcntl64(14, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
fsync(14) = 0
close(14) = 0
close(13) = 0
gettimeofday({1181288425, 451512}, 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, 451936}, NULL) = 0
gettimeofday({1181288425, 452094}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 452826}, NULL) = 0
gettimeofday({1181288425, 452994}, 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, 453370}, NULL) = 0
gettimeofday({1181288425, 453517}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 69) = 69
write(5, "\n", 1) = 1
gettimeofday({1181288425, 453996}, NULL) = 0
gettimeofday({1181288425, 454207}, 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, 454606}, NULL) = 0
gettimeofday({1181288425, 454753}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 455234}, NULL) = 0
gettimeofday({1181288425, 455490}, NULL) = 0
gettimeofday({1181288425, 455687}, NULL) = 0
pread(12, "\25\2\0\0k\0\0\0\234\335\23\0\377\377\1\4\334\34\0\0\0"..., 8192, 876544) = 8192
gettimeofday({1181288425, 456052}, NULL) = 0
gettimeofday({1181288425, 456201}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 69) = 69
write(5, "\n", 1) = 1
gettimeofday({1181288425, 456676}, NULL) = 0
gettimeofday({1181288425, 456861}, NULL) = 0
gettimeofday({1181288425, 457009}, NULL) = 0
pwrite(12, "\25\2\0\0l\0\0\0\241\335\23\0\377\377\1\4\331\0\0\0\0\0"..., 8192, 884736) = 8192
gettimeofday({1181288425, 458166}, NULL) = 0
gettimeofday({1181288425, 458324}, NULL) = 0
gettimeofday({1181288425, 458472}, NULL) = 0
write(5, "WAIT #1: nam=\'control file paral"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 459101}, NULL) = 0
gettimeofday({1181288425, 459258}, 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, 459610}, NULL) = 0
gettimeofday({1181288425, 459757}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 460268}, NULL) = 0
gettimeofday({1181288425, 460509}, NULL) = 0
gettimeofday({1181288425, 460672}, NULL) = 0
pwrite(12, "\25\2\0\0r\1\0\0\241\335\23\0\377\377\1\4J\354\0\0\0\0"..., 8192, 3031040) = 8192
gettimeofday({1181288425, 462014}, NULL) = 0
gettimeofday({1181288425, 462170}, NULL) = 0
gettimeofday({1181288425, 462321}, NULL) = 0
write(5, "WAIT #1: nam=\'control file paral"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 462815}, NULL) = 0
gettimeofday({1181288425, 462983}, NULL) = 0
gettimeofday({1181288425, 463126}, NULL) = 0
pwrite(12, "\25\2\0\0\n\0\0\0\241\335\23\0\377\377\1\4\330\265\0\0"..., 8192, 81920) = 8192
gettimeofday({1181288425, 464504}, NULL) = 0
gettimeofday({1181288425, 464660}, NULL) = 0
gettimeofday({1181288425, 464811}, NULL) = 0
write(5, "WAIT #1: nam=\'control file paral"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 465313}, NULL) = 0
gettimeofday({1181288425, 465513}, NULL) = 0
gettimeofday({1181288425, 465797}, NULL) = 0
pwrite(12, "\25\2\0\0\1\0\0\0\242\335\23\0\377\377\1\4\316C\0\0\0\0"..., 8192, 8192) = 8192
gettimeofday({1181288425, 466874}, NULL) = 0
gettimeofday({1181288425, 467025}, NULL) = 0
gettimeofday({1181288425, 467179}, NULL) = 0
write(5, "WAIT #1: nam=\'control file paral"..., 67) = 67
write(5, "\n", 1) = 1
gettimeofday({1181288425, 467664}, NULL) = 0
gettimeofday({1181288425, 467834}, NULL) = 0
gettimeofday({1181288425, 468007}, NULL) = 0
close(6) = 0
open("/opt/oracle/admin/eygle/bdump/alert_eygle.log", O_WRONLY|O_APPEND|O_CREAT, 0664) = 6
writev(6, [{"ARCH: Completed archiving log 4"..., 54}, {"\n", 1}], 2) = 55
gettimeofday({1181288425, 468804}, NULL) = 0
gettimeofday({1181288425, 468956}, NULL) = 0
pread(12, "\25\2\0\0\n\0\0\0\241\335\23\0\377\377\1\4\330\265\0\0"..., 8192, 81920) = 8192
gettimeofday({1181288425, 469342}, NULL) = 0
gettimeofday({1181288425, 469493}, NULL) = 0
write(5, "WAIT #1: nam=\'control file seque"..., 68) = 68
write(5, "\n", 1) = 1
gettimeofday({1181288425, 470212}, NULL) = 0
gettimeofday({1181288425, 470446}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 60000}, ru_stime={0, 70000}, ...}) = 0
gettimeofday({1181288425, 470763}, NULL) = 0
write(5, "EXEC #1:c=20000,e=74649,p=0,cr=0"..., 79) = 79
write(5, "\n", 1) = 1
gettimeofday({1181288425, 471236}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 60000}, ru_stime={0, 70000}, ...}) = 0
gettimeofday({1181288425, 471698}, NULL) = 0
gettimeofday({1181288425, 471834}, NULL) = 0
gettimeofday({1181288425, 472043}, NULL) = 0
write(5, "WAIT #1: nam=\'SQL*Net message to"..., 73) = 73
write(5, "\n", 1) = 1
gettimeofday({1181288425, 472554}, NULL) = 0
gettimeofday({1181288425, 472735}, NULL) = 0
write(10, "\0\203\0\0\6\0\0\0\0\0\10\5\0d1cl\4\0\0\0\1\0\0\0\0\0\0"..., 131) = 131
read(7,
以上是完整的输出，其中最重要的输入是如下一段：
gettimeofday({1181288425, 428415}, NULL) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", 0xbfff81a4) = -1 ENOENT (No such file or directory)
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", 0xbfff7e14) = -1 ENOENT (No such file or directory)
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", 0xbfff8200) = -1 ENOENT (No such file or directory)
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDWR|O_CREAT|O_EXCL|O_SYNC|O_LARGEFILE, 0660) = 14
fstat64(14, {st_mode=S_IFREG|0640, st_size=0, ...}) = 0
fstatfs(14, {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399121, f_bavail=294298, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
lseek(14, 0, SEEK_SET) = 0
write(14, "\0\2\0\0\0\2\0\0\4\0\0\0]\\[Z\240\201\0\0\242\207\0\0\0"..., 512) = 512
ftruncate64(14, 2560) = 0
close(14) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {st_mode=S_IFREG|0640, st_size=2560, ...}) = 0
statfs("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399120, f_bavail=294297, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDONLY|O_LARGEFILE) = 14
close(14) = 0
statfs("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399120, f_bavail=294297, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDWR|O_LARGEFILE) = 14
fcntl64(14, F_SETFD, FD_CLOEXEC) = 0
fcntl64(14, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
fcntl64(14, F_SETLK, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
gettimeofday({1181288425, 438810}, NULL) = 0
gettimeofday({1181288425, 438976}, NULL) = 0
pread(13, "F\1\0\0\1\0\0\0i\231<%\0\0\246\353\0\0 \t\0\0 \tx\227\347"..., 2048, 512) = 2048
gettimeofday({1181288425, 439369}, NULL) = 0
gettimeofday({1181288425, 439644}, NULL) = 0
write(5, "WAIT #1: nam=\'log file sequentia"..., 63) = 63
write(5, "\n", 1) = 1
gettimeofday({1181288425, 444474}, NULL) = 0
gettimeofday({1181288425, 444713}, NULL) = 0
pwrite(14, "F\1\0\0\1\0\0\0i\231<%\0\0\207\353\0\0 \t\0\0 \tx\227\347"..., 2048, 512) = 2048
gettimeofday({1181288425, 445135}, NULL) = 0
gettimeofday({1181288425, 445288}, NULL) = 0
gettimeofday({1181288425, 445434}, NULL) = 0
gettimeofday({1181288425, 445583}, NULL) = 0
write(5, "WAIT #1: nam=\'async disk IO\' ela"..., 63) = 63
write(5, "\n", 1) = 1
gettimeofday({1181288425, 446202}, NULL) = 0
stat64("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {st_mode=S_IFREG|0640, st_size=2560, ...}) = 0
statfs("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=2063560, f_bfree=399120, f_bavail=294297, f_files=1048576, f_ffree=1027926, f_fsid={0, 0}, f_namelen=255, f_frsize=0}) = 0
open("/opt/oracle/product/9.2.0/dbs/arch1_326.dbf", O_RDWR|O_LARGEFILE) = 15
也就是说，正是执行alter system archive log current的进程完成了归档工作。
那们现在也就清楚了，如果系统中还存在归档进程，哪怕只是一个，也会出现竞争。
说白了，其实还是一个锁定的问题。
