lgwr

Only ARCH Bgprocess may create archivelog?

2011/05/30 by admin 2 Comments

我们在学习Oracle入门知识时都会介绍到ARCH归档进程，归档进程ARCH负责将在线重做日志归档，注意ARCH只会将日志文件中存在的重做内容复制到归档日志文件中，举例来说重做日志文件的大小是512MB，但当前写入的redo entry只占用10MB空间，此时由某些条件触发了日志切换，那么产生的归档文件的大小仍是10MB。

一直以来存在着这样一种误解：归档操作只会由ARCH进程负责完成。

实际上归档操作可能由多种进程完成，举例来说前台进程Fore ground process就可以完成归档操作，当在前台进程中执行alter system archive log current命令时实际执行归档操作的是前台进程(server process)，而非ARCH，这可能是大多数人料想之外的，口说无凭，我们具体验证一下:

[oracle@rh2 ~]$ ps -ef|grep LOCAL=YES|grep G10R2
oracle   20790 20789  0 19:17 ?        00:00:00 oracleG10R2 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

SQL> set linesize 200 pagesize 1400;
SQL> select le.leseq "Current log sequence No",
  2         100 * cp.cpodr_bno / le.lesiz "Percent Full",
  3         (cpodr_bno - 1) * 512  "bytes used exclude header",
  4         le.lesiz * 512 - cpodr_bno * 512 "Left space",
  5         le.lesiz  *512       "logfile size"
  6    from x$kcccp cp, x$kccle le
  7   where LE.leseq = CP.cpodr_seq
  8     and bitand(le.leflg, 24) = 8;

Current log sequence No Percent Full bytes used exclude header Left space logfile size
----------------------- ------------ ------------------------- ---------- ------------
                    720   62.0244141                  32518144   19910144     52428800

/* 通过以上脚本可以了解当前日志文件(current logfile)的使用情况，
    这里可以看到日志文件大小为50MB，已使用32MB                    */

[oracle@rh2 ~]$ strace -p 20972 -o archive.log
Process 20972 attached - interrupt to quit

SQL> alter system archive log current;
System altered.

[oracle@rh2 ~]$ cat archive.log |egrep "open|read|write"
read(8, "\1\2\0\0\6\0\0\0\0\0\3^\10!\200\0\0\0\0\0\0\30\352\341\0\0\0\0\0`\0\0"..., 2064) = 258
open("/s01/admin/G10R2/bdump/alert_G10R2.log", O_WRONLY|O_CREAT|O_APPEND, 0660) = 6
writev(6, [{"Mon May 30 19:31:23 2011\n", 25}, {"ALTER SYSTEM ARCHIVE LOG", 24}, {"\n", 1}], 3) = 50
open("/flashcard/oradata/G10R2/controlfile/1.ctl", O_RDWR|O_SYNC|O_DIRECT) = 12
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\361\374\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\17\0\0\0\2324\0\0\377\377\1\4?^\0\0\0\6\0\0\0\0\0\0\0\0\0\2"..., 16384, 245760) = 16384
pread(12, "\25\302\0\0\21\0\0\0\2324\0\0\377\377\1\4\377\37\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 278528) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2234\0\0\377\377\1\4\327\312\0\0\0\220\1\0\316\2\0\0\2\0\0\0"..., 16384, 360448) = 16384
pread(12, "\25\302\0\0\23\0\0\0\2174\0\0\377\377\1\4\372\202\0\0\17\0\0\0\265!\315\0\0\0/\234"..., 16384, 311296) = 16384
pwrite(12, "\25\302\0\0\22\0\0\0\2334\0\0\377\377\1\4B\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pwrite(12, "\25\302\0\0\20\0\0\0\2334\0\0\377\377\1\4\240^\0\0\200\6\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pwrite(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\t\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\t\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\20\0\0\0\2354\0\0\377\377\1\4\241\177\0\0\200'\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pread(12, "\25\302\0\0\22\0\0\0\2354\0\0\377\377\1\4X\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2354\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 360448) = 16384
pread(12, "\25\302\0\0\36\0\0\0\2354\0\0\377\377\1\4\367\5\0\0\3\0\3\0\2\0\0\0\0\0/f"..., 16384, 491520) = 16384
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDONLY|O_DIRECT) = 13
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDWR|O_SYNC|O_DIRECT) = 13
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDONLY|O_DIRECT) = 14
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDWR|O_SYNC|O_DIRECT) = 14
pread(13, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
pread(14, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDONLY|O_DIRECT) = 13
open("/flashcard/oradata/G10R2/onlinelog/o1_mf_3_6v34jpmp_.log", O_RDWR|O_SYNC|O_DIRECT) = 13
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDONLY|O_DIRECT) = 14
open("/s01/flash_recovery_area/G10R2/onlinelog/o1_mf_3_6v34jpyn_.log", O_RDWR|O_SYNC|O_DIRECT) = 14
pread(13, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
pread(14, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 512, 512) = 512
pread(12, "\25\302\0\0\24\0\0\0\2354\0\0\377\377\1\4\341\202\0\0\17\0\0\0\265!\315\0\0\0/\234"..., 16384, 327680) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\20\0\0\0\2354\0\0\377\377\1\4\241\177\0\0\200'\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pread(12, "\25\302\0\0\22\0\0\0\2354\0\0\377\377\1\4X\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pread(12, "\25\302\0\0D\1\0\0\2234\0\0\377\377\1\4L\250\0\0\0\0\0\0\0\0\0\0008\251\332,"..., 16384, 5308416) = 16384
pread(12, "\25\302\0\0A\1\0\0\2234\0\0\377\377\1\4\3715\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5259264) = 16384
pwrite(12, "\25\302\0\0C\1\0\0\2364\0\0\377\377\1\4\210\232\0\0\0000\360\1\0\0\0\0\v\252\332,"..., 16384, 5292032) = 16384
pwrite(12, "\25\302\0\0\21\0\0\0\2364\0\0\377\377\1\4[\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 278528) = 16384
pwrite(12, "\25\302\0\0\17\0\0\0\2364\0\0\377\377\1\4?\177\0\0\0'\0\0\0\0\0\0\0\0\0\2"..., 16384, 245760) = 16384
pwrite(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_CREAT|O_EXCL|O_SYNC, 0660) = 15
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_SYNC|O_DIRECT) = 15
write(15, "\0\"\0\0\0\0\300\377\0\0\0\0\0\0\0\0~\240\0\0\0\2\0\0\30\370\0\0}|{z"..., 512) = 512
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDONLY|O_DIRECT) = 15
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_DIRECT) = 15
pread(13, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200Um\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 1048576, 512) = 1048576
pwrite(15, "\1\"\0\0\1\0\0\0\320\2\0\0\0\200tm\0\0\0\0\0\3 \n\22\235\205\254G10R"..., 1048576, 512) = 1048576
pread(13, "\1\"\0\0\1\10\0\0\320\2\0\0\0\200\271\242:22:48:01\5VALID\1"..., 1048576, 1049088) = 1048576
pwrite(15, "\1\"\0\0\1\10\0\0\320\2\0\0\0\200\271\242:22:48:01\5VALID\1"..., 1048576, 1049088) = 1048576
pread(13, "\1\"\0\0\1\20\0\0\320\2\0\0\0\200\220\271\n\0232011-05-12:22:"..., 1048576, 2097664) = 1048576
pwrite(15, "\1\"\0\0\1\20\0\0\320\2\0\0\0\200\220\271\n\0232011-05-12:22:"..., 1048576, 2097664) = 1048576
pread(13, "\1\"\0\0\1\30\0\0\320\2\0\0\364\201\261/\21\0232011-05-12:22:"..., 1048576, 3146240) = 1048576
pwrite(15, "\1\"\0\0\1\30\0\0\320\2\0\0\364\201\261/\21\0232011-05-12:22:"..., 1048576, 3146240) = 1048576
pread(13, "\1\"\0\0\1 \0\0\320\2\0\0\0\200\31~:22:54:21\5VALID\1"..., 1048576, 4194816) = 1048576
pwrite(15, "\1\"\0\0\1 \0\0\320\2\0\0\0\200\31~:22:54:21\5VALID\1"..., 1048576, 4194816) = 1048576
pread(13, "\1\"\0\0\1(\0\0\320\2\0\0\0\200\320\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 5243392) = 1048576
pwrite(15, "\1\"\0\0\1(\0\0\320\2\0\0\0\200\320\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 5243392) = 1048576
pread(13, "\1\"\0\0\0010\0\0\320\2\0\0\374\200\265$\5\f\27<\10\7xo\5\f\27<\10\02320"..., 1048576, 6291968) = 1048576
pwrite(15, "\1\"\0\0\0010\0\0\320\2\0\0\374\200\265$\5\f\27<\10\7xo\5\f\27<\10\02320"..., 1048576, 6291968) = 1048576
pread(13, "\1\"\0\0\0018\0\0\320\2\0\0\0\200W&796508\377\5\304\2\6\2\t\377\tP"..., 1048576, 7340544) = 1048576
pwrite(15, "\1\"\0\0\0018\0\0\320\2\0\0\0\200W&796508\377\5\304\2\6\2\t\377\tP"..., 1048576, 7340544) = 1048576
pread(13, "\1\"\0\0\1@\0\0\320\2\0\0\0\200*2SYS\7D807355\377\5\304\2\7"..., 1048576, 8389120) = 1048576
pwrite(15, "\1\"\0\0\1@\0\0\320\2\0\0\0\200*2SYS\7D807355\377\5\304\2\7"..., 1048576, 8389120) = 1048576
pread(13, "\1\"\0\0\1H\0\0\320\2\0\0\0\200~\5\tPROCEDURE\7xo\5\f\30"..., 1048576, 9437696) = 1048576
pwrite(15, "\1\"\0\0\1H\0\0\320\2\0\0\0\200~\5\tPROCEDURE\7xo\5\f\30"..., 1048576, 9437696) = 1048576
pread(13, "\1\"\0\0\1P\0\0\320\2\0\0\0\200ll\5\f\30\10'\0232011-05-12"..., 1048576, 10486272) = 1048576
pwrite(15, "\1\"\0\0\1P\0\0\320\2\0\0\0\200ll\5\f\30\10'\0232011-05-12"..., 1048576, 10486272) = 1048576
pread(13, "\1\"\0\0\1X\0\0\320\2\0\0\0\200\320\370\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 11534848) = 1048576
pwrite(15, "\1\"\0\0\1X\0\0\320\2\0\0\0\200\320\370\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 11534848) = 1048576
pread(13, "\1\"\0\0\1`\0\0\320\2\0\0\0\200\27\216 \377\tPROCEDURE\7xo\5"..., 1048576, 12583424) = 1048576
pwrite(15, "\1\"\0\0\1`\0\0\320\2\0\0\0\200\27\216 \377\tPROCEDURE\7xo\5"..., 1048576, 12583424) = 1048576
pread(13, "\1\"\0\0\1h\0\0\320\2\0\0008\201fj\1N\1N,\0\r\3SYS\7D860"..., 1048576, 13632000) = 1048576
pwrite(15, "\1\"\0\0\1h\0\0\320\2\0\0008\201fj\1N\1N,\0\r\3SYS\7D860"..., 1048576, 13632000) = 1048576
pread(13, "\1\"\0\0\1p\0\0\320\2\0\0\0\200\25%\7xo\5\f\30\20:\0232011-05"..., 1048576, 14680576) = 1048576
pwrite(15, "\1\"\0\0\1p\0\0\320\2\0\0\0\200\25%\7xo\5\f\30\20:\0232011-05"..., 1048576, 14680576) = 1048576
pread(13, "\1\"\0\0\1x\0\0\320\2\0\0\0\200G\36\7xo\5\f\30\23\6\7xo\5\f\30\23\6"..., 1048576, 15729152) = 1048576
pwrite(15, "\1\"\0\0\1x\0\0\320\2\0\0\0\200G\36\7xo\5\f\30\23\6\7xo\5\f\30\23\6"..., 1048576, 15729152) = 1048576
pread(13, "\1\"\0\0\1\200\0\0\320\2\0\0004\200\"\34311-05-12:23:20:1"..., 1048576, 16777728) = 1048576
pwrite(15, "\1\"\0\0\1\200\0\0\320\2\0\0004\200\"\34311-05-12:23:20:1"..., 1048576, 16777728) = 1048576
pread(13, "\1\"\0\0\1\210\0\0\320\2\0\0\0\200\320(\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 17826304) = 1048576
pwrite(15, "\1\"\0\0\1\210\0\0\320\2\0\0\0\200\320(\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 17826304) = 1048576
pread(13, "\1\"\0\0\1\220\0\0\320\2\0\0\0\200\343\367\377\tPROCEDURE\7xo\5\f"..., 1048576, 18874880) = 1048576
pwrite(15, "\1\"\0\0\1\220\0\0\320\2\0\0\0\200\343\367\377\tPROCEDURE\7xo\5\f"..., 1048576, 18874880) = 1048576
pread(13, "\1\"\0\0\1\230\0\0\320\2\0\0\350\201\200\263\33\32\0232011-05-12:23"..., 1048576, 19923456) = 1048576
pwrite(15, "\1\"\0\0\1\230\0\0\320\2\0\0\350\201\200\263\33\32\0232011-05-12:23"..., 1048576, 19923456) = 1048576
pread(13, "\1\"\0\0\1\240\0\0\320\2\0\0\34\201\36\326-12:23:28:30\5VAL"..., 1048576, 20972032) = 1048576
pwrite(15, "\1\"\0\0\1\240\0\0\320\2\0\0\34\201\36\326-12:23:28:30\5VAL"..., 1048576, 20972032) = 1048576
pread(13, "\1\"\0\0\1\250\0\0\320\2\0\0\0\200P\331VALID\1N\1N\1N,\0\r\3S"..., 1048576, 22020608) = 1048576
pwrite(15, "\1\"\0\0\1\250\0\0\320\2\0\0\0\200P\331VALID\1N\1N\1N,\0\r\3S"..., 1048576, 22020608) = 1048576
pread(13, "\1\"\0\0\1\260\0\0\320\2\0\0\0\200\342X\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 23069184) = 1048576
pwrite(15, "\1\"\0\0\1\260\0\0\320\2\0\0\0\200\342X\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 23069184) = 1048576
pread(13, "\1\"\0\0\1\270\0\0\320\2\0\0\0\200k\251,\0\r\3SYS\7D968280\377"..., 1048576, 24117760) = 1048576
pwrite(15, "\1\"\0\0\1\270\0\0\320\2\0\0\0\200k\251,\0\r\3SYS\7D968280\377"..., 1048576, 24117760) = 1048576
pread(13, "\1\"\0\0\1\300\0\0\320\2\0\0\310\200Ix:37:19\5VALID\1N\1N"..., 1048576, 25166336) = 1048576
pwrite(15, "\1\"\0\0\1\300\0\0\320\2\0\0\310\200Ix:37:19\5VALID\1N\1N"..., 1048576, 25166336) = 1048576
pread(13, "\1\"\0\0\1\310\0\0\320\2\0\0\0\200\34*#\7\377\tPROCEDURE\7xo"..., 1048576, 26214912) = 1048576
pwrite(15, "\1\"\0\0\1\310\0\0\320\2\0\0\0\200\34*#\7\377\tPROCEDURE\7xo"..., 1048576, 26214912) = 1048576
pread(13, "\1\"\0\0\1\320\0\0\320\2\0\0\0\200\343\336A\377\tPROCEDURE\7xo\5"..., 1048576, 27263488) = 1048576
pwrite(15, "\1\"\0\0\1\320\0\0\320\2\0\0\0\200\343\336A\377\tPROCEDURE\7xo\5"..., 1048576, 27263488) = 1048576
pread(13, "\1\"\0\0\1\330\0\0\320\2\0\0P\200\367{/\377\tPROCEDURE\7xo\5"..., 1048576, 28312064) = 1048576
pwrite(15, "\1\"\0\0\1\330\0\0\320\2\0\0P\200\367{/\377\tPROCEDURE\7xo\5"..., 1048576, 28312064) = 1048576
pread(13, "\1\"\0\0\1\340\0\0\320\2\0\0\0\200\315_-05-12:23:46:08\5"..., 1048576, 29360640) = 1048576
pwrite(15, "\1\"\0\0\1\340\0\0\320\2\0\0\0\200\315_-05-12:23:46:08\5"..., 1048576, 29360640) = 1048576
pread(13, "\1\"\0\0\1\350\0\0\320\2\0\0\0\200\263Xo\5\f\0302\31\7xo\5\f\0302\31\0232"..., 1048576, 30409216) = 1048576
pwrite(15, "\1\"\0\0\1\350\0\0\320\2\0\0\0\200\263Xo\5\f\0302\31\7xo\5\f\0302\31\0232"..., 1048576, 30409216) = 1048576
pread(13, "\1\"\0\0\1\360\0\0\320\2\0\0\0\200\213K\5VALID\1N\1N\1N,\0\r\3"..., 1048576, 31457792) = 1048576
pwrite(15, "\1\"\0\0\1\360\0\0\320\2\0\0\0\200\213K\5VALID\1N\1N\1N,\0\r\3"..., 1048576, 31457792) = 1048576
pread(13, "\1\"\0\0\1\370\0\0\320\2\0\0\300\200\333N\24\0\t\0T\0\210\22\"\0\0\0\t\0\t\0"..., 12288, 32506368) = 12288
pwrite(15, "\1\"\0\0\1\370\0\0\320\2\0\0\300\200\333N\24\0\t\0T\0\210\22\"\0\0\0\t\0\t\0"..., 12288, 32506368) = 12288
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_DIRECT) = 16
write(16, "\0\"\0\0\0\0\300\377\0\0\0\0\0\0\0\0~\240\0\0\0\2\0\0\30\370\0\0}|{z"..., 512) = 512
open("/s01/flash_recovery_area/G10R2/archivelog/2011_05_30/o1_mf_1_720_6y700ch9_.arc", O_RDWR|O_DIRECT) = 16
write(16, "\0\"\0\0\0\0\300\377\0\0\0\0\0\0\0\0~\240\0\0\0\2\0\0\30\370\0\0}|{z"..., 512) = 512
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\r\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\17\0\0\0\2364\0\0\377\377\1\4?\177\0\0\0'\0\0\0\0\0\0\0\0\0\2"..., 16384, 245760) = 16384
pread(12, "\25\302\0\0\21\0\0\0\2364\0\0\377\377\1\4[\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 278528) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2354\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 360448) = 16384
pread(12, "\25\302\0\0\313\0\0\0\2234\0\0\377\377\1\4\2\245\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3325952) = 16384
pread(12, "\25\302\0\0(\1\0\0d4\0\0\377\377\1\4\6*\0\0\33\0\4\0\333\7\0\0\0\0\0\0"..., 16384, 4849664) = 16384
pread(12, "\25\302\0\0A\1\0\0\2234\0\0\377\377\1\4\3715\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5259264) = 16384
pread(12, "\25\302\0\0\313\0\0\0\2234\0\0\377\377\1\4\2\245\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3325952) = 16384
pwrite(12, "\25\302\0\0B\1\0\0\2374\0\0\377\377\1\4\3725\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5275648) = 16384
pread(12, "\25\302\0\0C\1\0\0\2364\0\0\377\377\1\4\210\232\0\0\0000\360\1\0\0\0\0\v\252\332,"..., 16384, 5292032) = 16384
pread(12, "\25\302\0\0B\1\0\0\2374\0\0\377\377\1\4\3725\0\0\0\236<\216\5\0\0\0\0\300[\310"..., 16384, 5275648) = 16384
pwrite(12, "\25\302\0\0D\1\0\0\2374\0\0\377\377\1\4\177\253\0\0\0\0\0\0\0\0\0\0\v\252\332,"..., 16384, 5308416) = 16384
pread(12, "\25\302\0\0\313\0\0\0\2234\0\0\377\377\1\4\2\245\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3325952) = 16384
pwrite(12, "\25\302\0\0B\1\0\0\2374\0\0\377\377\1\4\353{\0\0\0\316,\220\5\0\0\0\0\300[\310"..., 16384, 5275648) = 16384
pread(12, "\25\302\0\0\26\0\0\0\2354\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 360448) = 16384
pwrite(12, "\25\302\0\0\25\0\0\0\2374\0\0\377\377\1\4\236W\0\0\0\220\1\0\321\2\0\0\1\0\0\0"..., 16384, 344064) = 16384
pwrite(12, "\25\302\0\0\314\0\0\0\2374\0\0\377\377\1\4\231@\0\0005\251\332,D\"\315\0\0\0\0\0"..., 16384, 3342336) = 16384
pwrite(12, "\25\302\0\0\22\0\0\0\2374\0\0\377\377\1\4\323\35\0\0\0\0\0\0\0\0\0\0Q\350\255,"..., 16384, 294912) = 16384
pwrite(12, "\25\302\0\0\20\0\0\0\2374\0\0\377\377\1\4\261\375\0\0\200%\0\0\0\0\0\0\0\0\0\2"..., 16384, 262144) = 16384
pwrite(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\0043\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
pread(12, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\0043\377\0\0\0\0\0\0\0\3 \n\22\235\205\254"..., 16384, 16384) = 16384
write(11, "\0\313\0\0\6\0\0\0\0\0\10\6\0\315\"\315\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0"..., 203) = 203

在以上system call trace中可以看到前台进程首先读取并更新了控制文件(controlfile/1.ctl)，之后读取了在线日志文件的头部(read o1_mf_3_6v34jpmp_.log=512bytes),接着以相关属性创建了归档日志文件(o1_mf_1_720_6y700ch9_.arc，注意这里使用了O_CREAT、O_EXCL、O_SYNC、0660属性)并得到该打开文件描述符15，接着以每次buffer为1048576字节来读取在线日志并写入归档日志pread(onlinelog)->pwrite(archivelog)，直到在线日志中的redo记录被写完。这里的buffer大小1048576实际上受到隐藏参数_log_archive_buffer_size(Size of each archival buffer in log file blocks)的影响，该参数指定了归档缓冲的大小，其单位为日志文件块(log file block)，日志文件块大小在不同平台上各有差异，具体可以参考这里。目前主流的UNIX平台上日志文件标准块大小为512 bytes，而_log_archive_buffer_size的默认值一般为2048，所以得出了这里的(2048*512)=1048576=1MB buffer大小。需要注意的是与”alter system archive log current”命令不同，”switch logfile”不会引起前台进程去执行归档操作，归档操作仍将由ARCH进程完成。

我们可以很方便的通过查询v$archived_log视图来了解具体完成某个日志文件归档操作的是何种进程，这得益于其creator列:


SQL> select distinct creator  from v$archived_log;

CREATOR
-------
RMAN
FGRD
ARCH


CREATOR 	VARCHAR2(7) 	Creator of the archivelog:

    ARCH - Archiver process
    FGRD - Foreground process
    RMAN - Recovery Manager
    SRMN - RMAN at standby
    LGWR - Logwriter process

以上可以看到可能创建归档日志的进程不仅仅局限于FGRD与ARCH，RMAN(注意实际上并非直接由rman进程完成)在执行热备操作时也可能掺合进来归档一把，此外在DataGuard环境中LGWR也会参与归档操作。

V$archived_log视图中另外一个有趣的字段是REGISTRAR，一般来说在非DataGuard环境中CREATOR总是等于REGISTRAR，而在DataGuard环境中REGISTRAR常是RFS(remote file server process (RFS) on the standby system where the RFS process writes the redo data to either archived redo log files or standby redo log files)后台进程，而实际的CREATOR则往往仍是ARCH或LGWR。

REGISTRAR 	VARCHAR2(7) 	Registrar of the entry:

    RFS - Remote File Server process
    ARCH - Archiver process
    FGRD - Foreground process
    RMAN - Recovery manager
    SRMN - RMAN at standby
    LGWR - Logwriter process

Filed Under: Oracle, Oracle Internal Research内部原理研究 Tagged With: arch, archivelog, lgwr, Oracle Data Guard Standby, redo

Does LGWR use synchronous IO even AIO enabled?

2011/05/21 by admin 4 Comments

在Oracle中开启AIO异步IO后可以一定程度上提升数据库IO性能，但同时也引入了丢失commit数据的风险。具体可以参见小荷同学的文章，但是这里存在一个疑问就是redo重做记录是同步写出还是在启用AIO后同样使用异步IO的API，我们可以通过跟踪lgwr后台进程的system call系统调用来说明该问题:


SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi
PL/SQL Release 10.2.0.4.0 - Production
CORE    10.2.0.4.0      Production
TNS for Linux: Version 10.2.0.4.0 - Production
NLSRTL Version 10.2.0.4.0 - Production


SQL> show parameter disk_asynch_io

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
disk_asynch_io                       boolean     TRUE

SQL> show parameter filesystem

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
filesystemio_options                 string      SETALL

[oracle@rh2 ~]$ ps -ef|grep dbw0_G10R2|grep -v grep
oracle   29168     1  0 19:02 ?        00:00:01 ora_dbw0_G10R2

[oracle@rh2 ~]$ strace -p 29168

.............................
io_submit(140140183375872, 34, {{0x7f74ee284e10, 0, 1, 0, 16},
{0x7f74ee290920, 0, 1, 0, 16}, {0x7f74ee286970, 0, 1, 0, 16}, {0x7f74ee290db0, 0, 1, 0, 16}  = 34

io_getevents(140140183375872, 1, 1024, {{0x7f74ee284e10, 0x7f74ee284e10, 8192, 0},
0x7f74ee289710, 8192, 0}}, {600, 0}) = 12

times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
times(NULL)                             = 480509951
getrusage(RUSAGE_SELF, {ru_utime={0, 417936}, ru_stime={0, 823874}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 417936}, ru_stime={0, 823874}, ...}) = 0
io_getevents(140140183375872, 1, 1024, {{0x7f74ee28c4b0, 0x7f74ee28c4b0, 8192, 0},
{0x7f74ee287290, 0x7f74ee287290, 8192, 0}, {0x7f74ee283988, 0x7f74ee283988, 8192, 0},
{0x7f74ee27fbf0, 0x7f74ee27fbf0, 8192, 0}, {0x7f74ee28a030, 0x7f74ee28a030, 8192, 0}, {0x7f74ee28fdb8, = 22

/* 此处dbwr使用io_submit函数将I/O请求入列，
    io_submit是典型的asynchronous I/O system calls，
    可见Oracle针对数据文件写出已在使用异步IO */

[oracle@rh2 ~]$ ps -ef|grep lgwr_G10R2|grep -v grep
oracle   29170     1  0 19:02 ?        00:00:01 ora_lgwr_G10R2

[oracle@rh2 ~]$ strace -p 29170
.............................
io_submit(139932588023808, 2, {{0x7f4497f423c8, 0, 1, 0, 20}, {0x7f4497f42590, 0, 1, 0, 21}}) = 2

io_getevents(139932588023808, 1, 1024, {{0x7f4497f423c8, 0x7f4497f423c8, 3584, 0}}, {600, 0}) = 1
times(NULL)                             = 480533371
io_getevents(139932588023808, 1, 1023, {{0x7f4497f42590, 0x7f4497f42590, 3584, 0}}, {600, 0}) = 1

以上io_submit system call说明当数据库启用AIO后lgwr同样使用异步IO写出重做记录到online logfile，换而言之当存储crash时的确可能出现redo记录丢失而造成的记录丢失情况。

实际控制lgwr是否使用异步IO的是一个隐藏参数_lgwr_async_io，该参数一般默认为false:

SQL> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
  2   FROM SYS.x$ksppi x, SYS.x$ksppcv y
  3   WHERE x.inst_id = USERENV ('Instance')
  4   AND y.inst_id = USERENV ('Instance')
  5   AND x.indx = y.indx
  6  AND x.ksppinm='_lgwr_async_io';

NAME
--------------------------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
DESCRIB
--------------------------------------------------------------------------------
_lgwr_async_io
FALSE
LGWR Asynchronous IO enabling boolean flag

你可能要这样问:”既然该_lgwr_async_io参数默认为false，那么lgwr就应当使用同步IO而非async，这岂不矛盾?”

是的，理论上来说默认_lgwr_async_io参数为false，lgwr应当使用sync。但是在版本10.1.0.2到11.1.0.6存在一个“Bug:8357698 LGWR USES ASYNC IO INSPITE OF SETTING _LGWR_ASYNC_IO=FALSE”：

Abstract: LGWR USES ASYNC IO INSPITE OF SETTING _LGWR_ASYNC_IO=FALSE

PROBLEM:
——–
+ Lgwr uses asynch IO irrespective of the setting _lgwr_async_io=false
and consumes high CPU performing IO poll operations.
+ short stack and truss output show that the lgwr is waiting for asynch IO
completion notification.

This particular problem was dormant for a long time and highly affects the
database performance.

DIAGNOSTIC ANALYSIS:
——————–
LGWR Shortstack
~~~~~~~~~~~~~~~

aiowait()+540<-skgfospo()+216<-skgfrwat()+80<-ksfdwtio()+476<-ksfdwat1()+84<-k
sfdrwat

0()+520<-kcrfw_post()+500<-kcrfw_redo_write()+2964<-ksbabs()+764<-ksbrdp()

aiowait()+540<-skgfospo()+216<-skgfrwat()+80<-ksfdwtio()+476<-ksfdwat1()+84<-k
sfdrwat

0()+520<-kcrfw_post()+500<-kcrfw_redo_write()+2964<-ksbabs()+764<-ksbrdp()

aiowait()+540<-skgfospo()+216<-skgfrwat()+80<-ksfdwtio()+476<-ksfdwat1()+84<-k
sfdrwat

0()+520<-kcrfw_post()+500<-kcrfw_redo_write()+2964<-ksbabs()+764<-ksbrdp()

Truss output
~~~~~~~~~~~~~
= 1048576
67072
27640/38: kaio(AIONOTIFY, 0) = 0
27640/40: kaio(AIONOTIFY, 0) = 0
27640/43: kaio(AIONOTIFY, 0) = 0
27640/45: kaio(AIONOTIFY, 0) = 0
27640/1: kaio(AIOWAIT, 0xFFFFFFFF7FFFD480) = 1
27640/1: kaio(AIOWAIT, 0xFFFFFFFF7FFFD480) = 1
27640/1: kaio(AIOWAIT, 0xFFFFFFFF7FFFD480) = 1
27640/1: kaio(AIOWAIT, 0xFFFFFFFF7FFFD480) = 1
= 1048576
27640/42: kaio(AIONOTIFY, 0) = 0
27640/1: kaio(AIOWAIT, 0xFFFFFFFF7FFFD480) = 1

Note : The TRUSS output was taken with the filesystemio_options=setall.

1. Performed the test on solaris Box with the below settings :

filesystemio_options=none
disk_asynch_io=false
_lgwr_async_io=TRUE

2. Performed another test on Linux with the following settings and it looks
like the behaviour matches with Solaris and hence it looks like it may not be
port specific .

filesystemio_options=SETALL
disk_asynch_io=TRUE
_lgwr_async_io=TRUE/FALSE

Linux_lgwr_true.out ) .

Request you to review the uploaded files and update with the results of your
analysis .

As per Bug:8357698 LGWR USES ASYNC IO INSPITE OF SETTING _LGWR_ASYNC_IO=FALSE , the filesystemio_options & disk_asynch_io are overwriting _lgwr_async_io settings .

Solution
Most often high CPU consumption by lgwr is related to Async IO.

You can try setting filesystemio_options=none & disk_asynch_io=false with obvious performance impact , but this may not be acceptable to you .

As per Bug:8357698 LGWR USES ASYNC IO INSPITE OF SETTING _LGWR_ASYNC_IO=FALSE , the filesystemio_options & disk_asynch_io are overwriting _lgwr_async_io settings .

1] Move the Redologs to the filesystem where the async IO is not permitted . This will cause the lgwr process not to use async calls.

OR

2] Use direct I/O, which is best done by mounting the corresponding filesystems unbuffered ( (using the”sync” option in Linux ext3, or the “forcedirectio” option in Solaris ufs, for example).

For example :
=========
On solaris:
—————
# mount_ufs -o forcedirectio /dev/rdsk/c2t3d0s0 /d17

If forcedirectio is specified and supported by the file system, then for the duration of the mount forced direct I/O will be used. If the filesystem is mounted using forcedirectio, then data is transferred directly between user address space and the disk. If the filesystem is mounted using noforcedirectio, then data is buffered in kernel address space when data is transferred between user address space and the disk. forcedirectio is a performance option that benefits only from large sequential data transfers. The default behavior is noforcedirectio.

On linux :
————–
# mount -o sync /dev/rdsk/c2t3d0s0 /d17

The sync option has effect only for ext2, ext3, fat, vfat and ufs . The default is async .

PS: We recommend you to involve your system administrator in chainging the moutn options of the OS file system .

由于Bug:8357698的存在，导致filesystemio_options和disk_asynch_io 2个参数可以覆盖_lgwr_async_io的设置，这个问题一直到11.1.0.6以后才得到修复，而在11.2中_lgwr_async_io参数干脆被取消了:

SQL> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
PL/SQL Release 11.2.0.2.0 - Production
CORE    11.2.0.2.0      Production
TNS for Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production

SQL> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
  2   FROM SYS.x$ksppi x, SYS.x$ksppcv y
  3   WHERE x.inst_id = USERENV ('Instance')
  4   AND y.inst_id = USERENV ('Instance')
  5   AND x.indx = y.indx
  6  AND x.ksppinm='_lgwr_async_io';

no rows selected

SQL> show parameter filesystem

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
filesystemio_options                 string      setall
SQL> show parameter async

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
disk_asynch_io                       boolean     TRUE
tape_asynch_io                       boolean     TRUE

io_submit(139755827974144, 2, {{0x7f1b6e992450, 0, 1, 0, 256}, {0x7f1b6e9921f8, 0, 1, 0, 259}}) = 2
io_getevents(139755827974144, 2, 128, {{0x7f1b6e992450, 0x7f1b6e992450, 1024, 0}, {0x7f1b6e9921f8, 0x7f1b6e9921f8, 1024, 0}}, {600, 0}) = 2
times({tms_utime=3, tms_stime=4, tms_cutime=0, tms_cstime=0}) = 480863691
semtimedop(2654212, 0x7fffadc3db80, 1, {3, 0}) = 0
times({tms_utime=3, tms_stime=4, tms_cutime=0, tms_cstime=0}) = 480863808
times({tms_utime=3, tms_stime=4, tms_cutime=0, tms_cstime=0}) = 480863808
io_submit(139755827974144, 2, {{0x7f1b6e9921f8, 0, 1, 0, 256}, {0x7f1b6e992450, 0, 1, 0, 259}}) = 2
io_getevents(139755827974144, 2, 128, {{0x7f1b6e9921f8, 0x7f1b6e9921f8, 512, 0}, {0x7f1b6e992450, 0x7f1b6e992450, 512, 0}}, {600, 0}) = 2

/* 在11.2中若启用了AIO，那么lgwr仍会沿用async IO */

总结:
lgwr是否启用async IO取决于_lgwr_async_io隐藏参数，该参数默认为false，也就是说lgwr默认情况下应当使用sync同步IO。但是因为10.1.0.2到11.1.0.6间存在bug会导致_lgwr_async_io被disk_asynch_io和filesystemio_options参数覆盖而不起作用；在以上版本中若启用了AIO那么lgwr无疑会使用AIO，如果既想要启用AIO又不想因为lgwr使用async而造成隐患，那么可以将日志文件所在移动到不允许async IO的位置，或者使用direct/sync/forcedirectio选项来mount文件系统。在版本11.2以后_lgwr_async_io参数被废弃，lgwr是否启用async io完全取决于disk_asynch_io及filesystemio_options。

Filed Under: Oracle Tagged With: async IO, lgwr, redo

Latches and Tuning:Redo Log Buffer and Latches

2010/12/26 by admin Leave a Comment

1. The size of the redo log buffer is determined by the LOG_BUFFER parameter.

a. Determine the size of the LOG_BUFFER by executing the following query:> select * from v$sga;

b. View the LOG_BUFFER setting in the init.ora file.

2. There are three latches associated with the redo log buffer.

a. Execute the following query to view the latches:> select name from v$latchname where name like ‘redo%’;

There will be more discussion about these latches later in the module.

3. A number of parameters that effect latch performance have been made obsolete in Oracle8i.
a. Execute the following query to view the obsolete redo buffer parameters:

> select ksppinm from x$ksppi where ksppinm like ‘_log%’;

Of the parameters listed, _LOG_SIMULTANEOUS_COPIES and _LOG_IO_SIZE are now obsolete. LOG_SMALL_ENTRY_MAX_SIZE and LOG_ENTRY_PREBUILD_THRESHOLD are no longer available in Oracle8i.

_LOG_SIMULTANEOUS_COPIES effects the redo copy latch, but since the redo copy is always acquired there is no need to set this parameter.
_LOG_IO_SIZE effects the redo writing latch.

b. Execute the following query to view the redo related parameters that are still available in Oracle8i:

> select name from v$system_parameter where name like ‘log%’;

You should see the parameters log_buffer, log_checkpoint_interval, and log_checkpoint_timeout.

4. There are 10 wait events associated with the redo log buffer and latches.

a. View the wait events by executing the following query:> select name from v$event_name where name like ‘log%’;

Of the events that are listed, three are of primary importance:

Log buffer space: a process is waiting for space in the log buffer
Log file sync: the time it takes for LGWR to complete the write then post the requester.
Log file parallel write: the main event waited while writing the redo records to the current log file.

b. You can also gather event information from the V$SYSTEM_EVENT view by executing the following query:

> select event,total_waits,total_timeouts,time_waited from v$system_event where
event in (‘log buffer space’,’log file sync’,’log file parallel write’);

In a well tuned system redo-related waits should be none or minimal. If one of the events is not listed in the output that means no event has occurred.

5. There are 14 statistics associated with the redo log buffer and latches.

a. Execute the following query to view the statistics:> select name from v$sysstat where name like ‘redo%’;

The most important statistics are:

Redo Writes: number of times the log buffer is written.
Redo Blocks Written: total number of blocks written.
Redo Log Space Requests: number of times requested to allocate space in the log file.
Redo Size, Redo Entries: how much redo is generated since instance statrup
Redo Buffer Allocation Retries: total number of retries necessary to allocate space in the redo buffer.

6. Contention for redo log buffers does not generally cause major performance problems on the database. Waits for
the event log buffer space could indicate contention for the redo log buffers. However, it may be more useful to find
out the proportion of redo entries which had to wait for space to become available.
a. Execute the following query to determine the ratio:

> select r.value, s.value, r.value/s.value
from v$sysstat r, v$sysstat s
where r.name = ‘redo buffer allocation retries’ and
s.name = ‘redo entries’;;

The ratio should be near zero.

7. Remember from the first practice that there are three latches associated with the redo log buffer; redo allocation,
redo copy, and redo writing. The tuning goal is to minimize contention and waits for these latches.

a. To tune the latches, look at the latch statistics and the ratio of MISSES to GETS by executing the following query:> select n.name, gets, misses, immediate_gets, immediate_misses
from v$latch l, v$latchname n
where n.name in (‘redo allocation’,’redo copy’,’redo writing’)
and n.latch#= l.latch#;

If the ratio of MISSES to GETS exceeds 1%, or the ratio of IMMEDIATE_MISSES to (IMMEDIATE_MISSES+IMMEDIATE_GETS) exceeds 1%, there is latch contention.

To return the ratios you can execute the following query. However, you may receive a division by zero error.

> select n.name, gets, misses, immediate_gets, immediate_misses, (misses/gets),
(immediate_misses/(immediate_misses+immediate_gets))
from v$latch l, v$latchname n
where n.name in (‘redo allocation’,’redo copy’,’redo writing’)
and n.latch#= l.latch#;

8. You can increase the number of redo copy latches by setting the parameter LOG_SIMULTANEOUS_COPIES.
This parameter is a hidden parameter and must be set in the init.ora and the database must be restarted for it
to take effect.

a. One method for determing the number of redo copy latches is to query the V$LATCH_CHILDREN view. There will be one latch for the value of _LOG_SIMULTANEOUS_COPIES. If there is only one latch, you will have to query V$LATCH_PARENT as there will be no children.> select name from v$latch_children where name = ‘redo copy’;

b. If you want to increase or decrease the number of redo copy latches, modify the parameter _LOG_SIMULTANEOUS_COPIES in the init.ora file. Once you have done this, you can bounce the
database and execute the query in step a.

9. You can increase the number of redo writing latches by modifying the parameter _LOG_IO_SIZE. This
parameter is a hidden parameter and must be set in the init.ora and the database must be restarted for it to take
effect.
a. One method for determing the number of redo copy latches is to query the V$LATCH_CHILDREN view. There will be one latch for the value of _LOG_IO_SIZE. If there is only one latch, you will have to query V$LATCH_PARENT as there will be no children.

> select name from v$latch_children where name = ‘redo writing’;

b. If you want to increase or decrease the number of redo copy latches, modify the parameter
_LOG_IO_SIZE in the init.ora file. Once you have done this, you can bounce the database and execute the
query in step a.

Filed Under: Oracle, Oracle Internal Research内部原理研究 Tagged With: latch, lgwr, log, redo