[20181217]ogg抽取日志分析.txt

来源：这里教程网时间：2026-03-03 12:45:29 作者：

[20181217]ogg抽取日志分析.txt --//上个星期遇到ogg存在大量读取日志的情况,而且因为open使用O_DIRECT,导致直接从磁盘读取.如果抽取进程越大, --//读取量越大,而且我发现读取量并不与日志产生量相符,也就是读取存在大量"垃圾"信息.从读取的大小也可以判断, --//每次都是固定的1024000(1000K),今天再做一些细节分析,继续上个星期的分析: 1.环境: SYS@XXXXdg2> @ &r/ver1 PORT_STRING VERSION BANNER ------------------------------ -------------- -------------------------------------------------------------------------------- x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production 2.分析: # ps -eLfc | egrep "^UID|70[3]" UID PID PPID LWP NLWP CLS PRI STIME TTY TIME CMD oracle 703 2649 703 12 TS 24 Sep26 ? 00:07:13 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 704 12 TS 24 Sep26 ? 00:02:58 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 705 12 TS 24 Sep26 ? 00:04:09 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 706 12 TS 24 Sep26 ? 00:00:03 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 707 12 TS 23 Sep26 ? 00:00:00 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 712 12 TS 24 Sep26 ? 00:00:00 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 715 12 TS 24 Sep26 ? 00:00:10 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 716 12 TS 23 Sep26 ? 03:37:22 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 717 12 TS 23 Sep26 ? 01:35:50 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 718 12 TS 24 Sep26 ? 00:00:01 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 719 12 TS 24 Sep26 ? 00:05:18 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS oracle 703 2649 720 12 TS 24 Sep26 ? 00:04:44 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS # strace -t -p 703 -f -e read Process 703 attached with 12 threads - interrupt to quit [pid 717] 08:40:02 read(22, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 720] 08:40:02 read(26, "\1\"\0\0y\241\10\0\337\20\0\0\20\200\"_`\0\0\0\4\30\6\0\16\235L/\1\0\0\0"..., 1024000) = 1024000 [pid 717] 08:40:02 read(22, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 717] 08:40:02 read(22, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 720] 08:40:02 read(26, "\1\"\0\0I\251\10\0\335\20\0\0d\200\250\177</div></div>\r\n<d"..., 1024000) = 1024000 [pid 716] 08:40:02 read(18, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 719] 08:40:02 read(24, "\1\"\0\0\362\20\31\0\361\25\0\0 \200\366\37\1\n\t\0\0\0\6\0\211\235L/\6\0\0\0"..., 1024000) = 1024000 [pid 716] 08:40:02 read(18, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 716] 08:40:02 read(18, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 719] 08:40:02 read(24, "\1\"\0\0\31\27\31\0\361\25\0\0\310\200\310\371\f\0\0\0o\0\10\0~>\3\0C_\200\21"..., 1024000) = 1024000 [pid 716] 08:40:02 read(18, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 716] 08:40:02 read(18, "\0\350\0\0\6\0\0\0\0\0\6\1\"R\1\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0"..., 32784) = 232 [pid 719] 08:40:02 read(24, "\1\"\0\0\351\36\31\0\357\25\0\0\330\201\211\212\3\0\r\v\0\0\0\0\0\0//\2\0\3\0"..., 1024000) = 1024000 Process 703 detached Process 704 detached Process 705 detached Process 706 detached Process 707 detached Process 712 detached Process 715 detached Process 716 detached Process 717 detached Process 718 detached Process 719 detached Process 720 detached # ls -l /proc/719/fd/24 /proc/720/fd/26 lr-x------ 1 oracle oinstall 64 2018-12-17 08:41:19 /proc/719/fd/24 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_10.327.862659471 lr-x------ 1 oracle oinstall 64 2018-12-17 08:44:02 /proc/720/fd/26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 SYS@XXXXdg2> set numw 12 SYS@XXXXdg2> select * from v$standby_log; GROUP# DBID THREAD# SEQUENCE# BYTES BLOCKSIZE USED ARC STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME LAST_CHANGE# LAST_TIME ------ ---------- ------- --------- ---------- --------- --------- --- ---------- ------------- ------------------- ------------ --------- ------------ ------------------- 9 UNASSIGNED 1 0 4294967296 512 0 NO UNASSIGNED 10 2417323702 1 5617 4294967296 512 879460352 YES ACTIVE 26562122884 2018-12-17 02:27:24 26563418035 2018-12-17 08:42:33 11 UNASSIGNED 1 0 4294967296 512 0 NO UNASSIGNED 12 UNASSIGNED 1 0 4294967296 512 0 NO UNASSIGNED 13 UNASSIGNED 1 0 4294967296 512 0 NO UNASSIGNED 14 UNASSIGNED 2 0 4294967296 512 0 NO UNASSIGNED 15 2417323702 2 4319 4294967296 512 306921472 YES ACTIVE 26562122789 2018-12-17 02:27:23 26563418050 2018-12-17 08:42:33 16 UNASSIGNED 2 0 4294967296 512 0 NO UNASSIGNED 17 UNASSIGNED 2 0 4294967296 512 0 NO UNASSIGNED 18 UNASSIGNED 2 0 4294967296 512 0 NO UNASSIGNED 10 rows selected. --//单独监测/u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525使用情况,因为实例2我们产生的日志量较少. # ps -eLo tid,pid,cmd | grep "extrac[t]" | grep " 70[3] " | cut -c1-5 | xargs -I{} ls -l /proc/{}/fd/ | grep group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 09:05 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 08:41 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 lr-x------ 1 oracle oinstall 64 Dec 17 08:44 26 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 --//巧合还是使用线程的原因.每个tid打开的 /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525对应的文件句柄都是26. # strace -t -p 703 -f -e trace=desc -o /tmp/703.txt Process 703 attached with 12 threads - interrupt to quit Process 703 detached Process 704 detached Process 705 detached Process 706 detached Process 707 detached Process 712 detached Process 715 detached Process 716 detached Process 717 detached Process 718 detached Process 719 detached Process 720 detached # egrep "read\(26|write\(26|lseek\(26" /tmp/703.txt 720 09:36:00 read(26, "\1\"\0\0002\236\23\0\337\20\0\0\204\200\227ttable></div>\r\n<d"..., 1024000) = 1024000 720 09:36:00 read(26, "\1\"\0\0\2\246\23\0\337\20\0\0\20\200\226S-stretch:normal;"..., 1024000) = 1024000 720 09:36:00 read(26, "\1\"\0\0\322\255\23\0\335\20\0\0\20\200LV\" template=\"fals"..., 1024000) = 1024000 717 09:36:00 lseek(26, 659570688, SEEK_SET) = 659570688 720 09:36:00 read(26, "\1\"\0\0 \250\23\0\337\20\0\0\20\200\351\4`\0\0\0\4\32\6\0\327\217^/\1\0\7Z"..., 1024000) = 1024000 720 09:36:00 read(26, "\1\"\0\0\360\257\23\0\335\20\0\0\20\200/\35\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1024000) = 1024000 717 09:36:03 lseek(26, 659582464, SEEK_SET) = 659582464 720 09:36:03 read(26, "\1\"\0\0007\250\23\0\337\20\0\0\20\200gi`\0\0\0\4\0\6\0\t\220^/\1\0\25/"..., 1024000) = 1024000 720 09:36:03 read(26, "\1\"\0\0\7\260\23\0\335\20\0\0\20\200h\227\327\265\264\251\264\314\312\365\301\313\275\342\304\324\274\271"..., 1024000) = 1024000 717 09:36:06 lseek(26, 659796992, SEEK_SET) = 659796992 720 09:36:06 read(26, "\1\"\0\0\332\251\23\0\337\20\0\0\20\200\26\1`\0\0\0\4\0\6\0\274\223^/\1\0\20\0"..., 1024000) = 1024000 720 09:36:06 read(26, "\1\"\0\0\252\261\23\0\335\20\0\0\20\200Yi CHECKED VALUE=\312"..., 1024000) = 1024000 717 09:36:09 lseek(26, 659919360, SEEK_SET) = 659919360 720 09:36:09 read(26, "\1\"\0\0\311\252\23\0\337\20\0\0\20\200\344\362`\0\0\0\4\26\6\0\226\227^/\1\0\2\0"..., 1024000) = 1024000 720 09:36:09 read(26, "\1\"\0\0\231\262\23\0\335\20\0\0\20\200N~177px; top:54px;"..., 1024000) = 1024000 717 09:36:12 lseek(26, 660056064, SEEK_SET) = 660056064 720 09:36:12 read(26, "\1\"\0\0\324\253\23\0\337\20\0\0\20\200Y\\`\0\0\0\0047\6\0z\233^/\1\0n="..., 1024000) = 1024000 720 09:36:12 read(26, "\1\"\0\0\244\263\23\0\335\20\0\0\20\200S\rdth:42px; height"..., 1024000) = 1024000 717 09:36:15 lseek(26, 660185088, SEEK_SET) = 660185088 720 09:36:15 read(26, "\1\"\0\0\320\254\23\0\337\20\0\0\20\200\257\245`\0\0\0\4\0\6\0\242\236^/\1\0=\0"..., 1024000) = 1024000 720 09:36:15 read(26, "\1\"\0\0\240\264\23\0\335\20\0\0\20\200cxnormal;font-styl"..., 1024000) = 1024000 717 09:36:18 lseek(26, 660417536, SEEK_SET) = 660417536 720 09:36:18 read(26, "\1\"\0\0\226\256\23\0\337\20\0\0\20\200G\217\244\0\0\0\1\0\6\0002\243^/\1\0=\0"..., 1024000) = 1024000 720 09:36:18 read(26, "\1\"\0\0f\266\23\0\335\20\0\0$\200\360\341\4\0\20\0\4\0\0\0\1\0\0\0\2\0\0\0"..., 1024000) = 1024000 717 09:36:21 lseek(26, 660678656, SEEK_SET) = 660678656 720 09:36:21 read(26, "\1\"\0\0\224\260\23\0\337\20\0\0\20\200\225\354`\0\0\0\0047\6\0<\250^/\1\0\22\327"..., 1024000) = 1024000 720 09:36:21 read(26, "\1\"\0\0d\270\23\0\335\20\0\0(\200f\03460\" props=\"text-"..., 1024000) = 1024000 717 09:36:24 lseek(26, 660878848, SEEK_SET) = 660878848 720 09:36:24 read(26, "\1\"\0\0\33\262\23\0\337\20\0\0\20\200X\362`\0\0\0\4\0\6\0B\253^/\1\0\0\0"..., 1024000) = 1024000 720 09:36:24 read(26, "\1\"\0\0\353\271\23\0\335\20\0\0H\200\365/\304\25.MY\6\22fZ\200\0$\0\0\5\304"..., 1024000) = 1024000 717 09:36:27 lseek(26, 661559808, SEEK_SET) = 661559808 720 09:36:27 read(26, "\1\"\0\0M\267\23\0\337\20\0\0\20\200\207\302`\0\0\0\0040\6\0\206\261^/\1\0tr"..., 1024000) = 1024000 720 09:36:27 read(26, "\1\"\0\0\35\277\23\0\337\20\0\0\24\200\r\320\352\177\0Q\354\0\0\0\1,\6\0\331\265^/"..., 1024000) = 1024000 720 09:36:27 read(26, "\1\"\0\0\355\306\23\0\337\20\0\0\364\200\300>:11pt;font-weigh"..., 1024000) = 1024000 720 09:36:27 read(26, <unfinished ...> 720 09:36:27 read(26, <unfinished ...> 717 09:36:30 lseek(26, 663702016, SEEK_SET) = 663702016 720 09:36:30 read(26, "\1\"\0\0\245\307\23\0\337\20\0\0,\200\237[\0\0\0\0\0\0\0\0\16=]\34\16\334\225\220"..., 1024000) = 1024000 720 09:36:30 read(26, "\1\"\0\0u\317\23\0\335\20\0\0(\200\316\316\270\351\227\267\343\200\201\345\222\263\345\227\275\343\200\201"..., 1024000) = 1024000 717 09:36:33 lseek(26, 663939584, SEEK_SET) = 663939584 720 09:36:33 read(26, "\1\"\0\0u\311\23\0\337\20\0\0\20\200\17\177`\0\0\0\4V\6\0\376\272^/\1\0\302\266"..., 1024000) = 1024000 720 09:36:33 read(26, "\1\"\0\0E\321\23\0\335\20\0\0\10\201U\273\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1024000) = 1024000 717 09:36:36 lseek(26, 664193024, SEEK_SET) = 664193024 720 09:36:36 read(26, "\1\"\0\0d\313\23\0\337\20\0\0\20\200u\216`\0\0\0\4\0\6\0\v\277^/\1\0\377\377"..., 1024000) = 1024000 720 09:36:36 read(26, "\1\"\0\0004\323\23\0\335\20\0\0H\200\2118-style:1;bot-sty"..., 1024000) = 1024000 717 09:36:39 lseek(26, 664287744, SEEK_SET) = 664287744 720 09:36:39 read(26, "\1\"\0\0\35\314\23\0\337\20\0\0\20\200u\205`\0\0\0\4\0\6\0\326\302^/\1\0\343\316"..., 1024000) = 1024000 720 09:36:40 read(26, "\1\"\0\0\355\323\23\0\335\20\0\0\24\200\234\252MR\0\0\10\1\0\0\1*\6\0\312\263\7/"..., 1024000) = 1024000 717 09:36:42 lseek(26, 664322560, SEEK_SET) = 664322560 720 09:36:42 read(26, "\1\"\0\0a\314\23\0\337\20\0\0\20\200\366\215`\0\0\0\0046\6\0\253\305^/\1\0\267\0"..., 1024000) = 1024000 720 09:36:43 read(26, "\1\"\0\0001\324\23\0\335\20\0\0L\200\200\223\10\0\0\0\0\0\0\0\t\0\0\0\2\0\0\0"..., 1024000) = 1024000 --//没有写操作, # egrep "read\(26|write\(26|lseek\(26" /tmp/703.txt | grep lseek | uniq -c 1 717 09:36:00 lseek(26, 659570688, SEEK_SET) = 659570688 1 717 09:36:03 lseek(26, 659582464, SEEK_SET) = 659582464 1 717 09:36:06 lseek(26, 659796992, SEEK_SET) = 659796992 1 717 09:36:09 lseek(26, 659919360, SEEK_SET) = 659919360 1 717 09:36:12 lseek(26, 660056064, SEEK_SET) = 660056064 1 717 09:36:15 lseek(26, 660185088, SEEK_SET) = 660185088 1 717 09:36:18 lseek(26, 660417536, SEEK_SET) = 660417536 1 717 09:36:21 lseek(26, 660678656, SEEK_SET) = 660678656 1 717 09:36:24 lseek(26, 660878848, SEEK_SET) = 660878848 1 717 09:36:27 lseek(26, 661559808, SEEK_SET) = 661559808 1 717 09:36:30 lseek(26, 663702016, SEEK_SET) = 663702016 1 717 09:36:33 lseek(26, 663939584, SEEK_SET) = 663939584 1 717 09:36:36 lseek(26, 664193024, SEEK_SET) = 664193024 1 717 09:36:39 lseek(26, 664287744, SEEK_SET) = 664287744 1 717 09:36:42 lseek(26, 664322560, SEEK_SET) = 664322560 --//每次读取之前实际上有一个lseek的过程(如果没什么业务估计间隔3秒),并且是线程717完成lseek操作. --//顺便在主库执行如下: SYS@XXXX2> @ checkpoint 检查点队列 on disk rba 检查点队列脏块数量时间戳当前时间 on disk rba scn 检查点心跳 CPDRT low_rba on_disk_rba CPODT SYSDATE DIFF_DATE CPODS CPHBT CURRENT_SCN DIFF_SCN INDX ------------ -------------------- -------------------- ------------------- ------------------- ----------- ---------------- ------------ ------------ ------------ ------------ 18286 5617.3377963.0 5617.3578348.0 2018-12-17 09:35:59 2018-12-17 09:35:59 .00 26564529964 992194276 26564530069 105 0 10017 4319.1210801.0 4319.1288022.0 2018-12-17 09:35:58 2018-12-17 09:35:59 1.00 26564529568 992256782 26564530069 501 1 SYS@XXXX2> / 检查点队列检查点队列 on disk rba 检查点队列脏块数量时间戳当前时间 on disk rba scn 检查点心跳 CPDRT low_rba on_disk_rba CPODT SYSDATE DIFF_DATE CPODS CPHBT CURRENT_SCN DIFF_SCN INDX ------------ -------------------- -------------------- ------------------- ------------------- ----------- ---------------- ------------ ------------ ------------ ------------ 18305 5617.3379464.0 5617.3579839.0 2018-12-17 09:36:01 2018-12-17 09:36:01 .00 26564530620 992194278 26564530747 127 0 9378 4319.1211042.0 4319.1288430.0 2018-12-17 09:36:01 2018-12-17 09:36:01 .00 26564530742 992256785 26564530747 5 1 SYS@XXXX2> / 检查点队列检查点队列 on disk rba 检查点队列脏块数量时间戳当前时间 on disk rba scn 检查点心跳 CPDRT low_rba on_disk_rba CPODT SYSDATE DIFF_DATE CPODS CPHBT CURRENT_SCN DIFF_SCN INDX ------------ -------------------- -------------------- ------------------- ------------------- ----------- ---------------- ------------ ------------ ------------ ------------ 18308 5617.3381643.0 5617.3581950.0 2018-12-17 09:36:05 2018-12-17 09:36:06 1.00 26564531852 992194282 26564532143 291 0 9094 4319.1215356.0 4319.1288722.0 2018-12-17 09:36:05 2018-12-17 09:36:06 1.00 26564531967 992256789 26564532143 176 1 --// 1 717 09:36:06 lseek(26, 659796992, SEEK_SET) = 659796992 --//659796992/512=1288666,与on_disk_rba中间数值很接近.对应的就是x$kcccp.cpodr_bno字段. --//分析其中1段: 717 09:36:06 lseek(26, 659796992, SEEK_SET) = 659796992 720 09:36:06 read(26, "\1\"\0\0\332\251\23\0\337\20\0\0\20\200\26\1`\0\0\0\4\0\6\0\274\223^/\1\0\20\0"..., 1024000) = 1024000 720 09:36:06 read(26, "\1\"\0\0\252\261\23\0\335\20\0\0\20\200Yi CHECKED VALUE=\312"..., 1024000) = 1024000 --//720 09:36:06 read(26, "\1\"\0\0\332\251\23\0\337\20\0\0\20\200\26\1`\0\0\0\4\0\6\0\274\223^/\1\0\20\0"..., 1024000) = 1024000 # od -j 659796992 -N 32 -t o1 /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 4724732000 001 042 000 000 332 251 023 000 337 020 000 000 020 200 026 001 4724732020 140 000 000 000 004 000 006 000 274 223 136 057 001 000 020 000 4724732040 --//里面的字符 "`^/ 对应8进制是42,140,136,57,都可以对上.查看不方便,使用bvi看看. SYS@XXXXdg2> select dump('"`^/',8) from dual ; DUMP('"`^/',8) --------------------------- Typ=96 Len=4: 42,140,136,57 --//659796992+1024000 = 660820992 --//720 09:36:06 read(26, "\1\"\0\0\252\261\23\0\335\20\0\0\20\200Yi CHECKED VALUE=\312"..., 1024000) = 1024000 # bvi -b 660820992 -s 32 /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525 27635400 01 22 00 00 AA B1 13 00 DF 10 00 00 10 80 F4 13 .".............. 27635410 73 3D 22 74 65 78 74 2D 64 65 63 6F 72 61 74 69 s="text-decorati 27635420 --//明显与当前日志里面的信息对不上,里面有"text-de..."信息,明显读取的是无用的"垃圾"日志. --//看看归档的日志就明白了: # bvi -b 660820992 -s 32 /u01/app/oracle/oradata/XXXXdg2/archivelog/2_4317_862160568.dbf 27635400 01 22 00 00 AA B1 13 00 DD 10 00 00 10 80 59 69 ."............Yi 27635410 20 43 48 45 43 4B 45 44 20 56 41 4C 55 45 3D CA CHECKED VALUE=. 27635420 --//当前已经是seq=4319. SYS@XXXX2> archive log list; Database log mode Archive Mode Automatic archival Enabled Archive destination +RECOC1 Oldest online log sequence 4316 Next log sequence to archive 4319 Current log sequence 4319 --//为什么不查看seq=4318,thread=2的归档文件,因为 # ls -l /u01/app/oracle/oradata/XXXXdg2/archivelog/2_431[789]_862160568.dbf -rw-r----- 1 oracle oinstall 1561763328 2018-12-17 02:27:10 /u01/app/oracle/oradata/XXXXdg2/archivelog/2_4317_862160568.dbf -rw-r----- 1 oracle oinstall 26112 2018-12-17 02:27:23 /u01/app/oracle/oradata/XXXXdg2/archivelog/2_4318_862160568.dbf --//因为2_4318_862160568.dbf文件太小. 总结: --//可以看出ogg大致的抽取过程,不断推进读取日志文件,还原里面的信息. --//而且每次抽取都是1024000字节,这样必然读到大量"无用"信息,而且你可以看到抽取进程会不时调用nanosleep. # strace -ttt -p 720 Process 720 attached - interrupt to quit 1545014325.106690 restart_syscall(<... resuming interrupted call ...>) = 0 1545014325.173353 futex(0x2b2c1919fcd4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x2b2c1919fcd0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1545014325.173445 futex(0x2b2c1919fca8, FUTEX_WAKE_PRIVATE, 1) = 1 1545014325.173513 read(26, "\1\"\0\0fe \0\337\20\0\0\20\200/q`\0\0\0\4l\6\0\255\240s/\1\0;m"..., 1024000) = 1024000 1545014325.174096 futex(0x2b2c1919fcd4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x2b2c1919fcd0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1545014325.174158 nanosleep({0, 100000000}, NULL) = 0 1545014325.275372 read(26, "\1\"\0\0006m \0\335\20\0\0\224\201R\324\1\0\377\377\4\0 \0\27\0\0\0^|=\0"..., 1024000) = 1024000 1545014325.275972 nanosleep({0, 100000000}, NULL) = 0 1545014325.377350 nanosleep({0, 100000000}, NULL) = 0 1545014325.478344 nanosleep({0, 100000000}, NULL) = 0 1545014325.579337 nanosleep({0, 100000000}, NULL) = 0 1545014325.680372 nanosleep({0, 100000000}, NULL) = 0 1545014325.781344 nanosleep({0, 100000000}, NULL) = 0 1545014325.882349 nanosleep({0, 100000000}, NULL) = 0 1545014325.983350 nanosleep({0, 100000000}, NULL) = 0 1545014326.084352 nanosleep({0, 100000000}, NULL) = 0 1545014326.185364 nanosleep({0, 100000000}, NULL) = 0 1545014326.286361 nanosleep({0, 100000000}, NULL) = 0 1545014326.387366 nanosleep({0, 100000000}, NULL) = 0 1545014326.488362 nanosleep({0, 100000000}, NULL) = 0 1545014326.589647 nanosleep({0, 100000000}, NULL) = 0 1545014326.691385 nanosleep({0, 100000000}, NULL) = 0 1545014326.792364 nanosleep({0, 100000000}, NULL) = 0 1545014326.893371 nanosleep({0, 100000000}, NULL) = 0 1545014326.994373 nanosleep({0, 100000000}, NULL) = 0 1545014327.095383 nanosleep({0, 100000000}, NULL) = 0 1545014327.196388 nanosleep({0, 100000000}, NULL) = 0 1545014327.297365 nanosleep({0, 100000000}, NULL) = 0 1545014327.398378 nanosleep({0, 100000000}, NULL) = 0 1545014327.499370 nanosleep({0, 100000000}, NULL) = 0 1545014327.600386 nanosleep({0, 100000000}, NULL) = 0 1545014327.701386 nanosleep({0, 100000000}, NULL) = 0 1545014327.802379 nanosleep({0, 100000000}, NULL) = 0 1545014327.903388 nanosleep({0, 100000000}, NULL) = 0 1545014328.004399 nanosleep({0, 100000000}, NULL) = 0 1545014328.105386 nanosleep({0, 100000000}, NULL) = 0 1545014328.206407 futex(0x2b2c1919fcd4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x2b2c1919fcd0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1545014328.206478 futex(0x2b2c1919fca8, FUTEX_WAKE_PRIVATE, 1) = 1 1545014328.206536 read(26, "\1\"\0\0/l \0\337\20\0\0\20\200\4\n`\0\0\0\4t\6\0\304\243s/\1\0:n"..., 1024000) = 1024000 1545014328.207194 futex(0x2b2c1919fcd4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x2b2c1919fcd0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1 1545014328.207250 nanosleep({0, 100000000}, NULL) = 0 1545014328.308407 read(26, "\1\"\0\0\377s \0\335\20\0\0\20\200\30b`\0\0\0\4l\6\0000\330 /\1\00000"..., 1024000) = 1024000 1545014328.316103 nanosleep({0, 100000000}, NULL) = 0 1545014328.417393 nanosleep({0, 100000000}, NULL) = 0 1545014328.518387 nanosleep({0, 100000000}, NULL) = 0 1545014328.619399 nanosleep({0, 100000000}, NULL) = 0 # man nanosleep NANOSLEEP(2) Linux Programmer's Manual NANOSLEEP(2) NAME nanosleep - pause execution for a specified time SYNOPSIS #define _POSIX_C_SOURCE 199309 #include <time.h> int nanosleep(const struct timespec *req, struct timespec *rem); DESCRIPTION nanosleep() delays the execution of the program for at least the time specified in *req. The function can return earlier if a signal has been delivered to the process. In this case, it returns -1, sets errno to EINTR, and writes the remaining time into the structure pointed to by rem unless rem is NULL. The value of *rem can then be used to call nanosleep() again and complete the specified pause. The structure timespec is used to specify intervals of time with nanosecond precision. It is specified in <time.h> and has the form struct timespec { time_t tv_sec; /* seconds */ long tv_nsec; /* nanoseconds */ }; The value of the nanoseconds field must be in the range 0 to 999999999. --//100000000 nanoseconds(纳秒),1纳秒=0.000000001秒=10^(-9)秒 ,100000000 nanoseconds(纳秒)就是0.1秒. --//也就是pause 0~0.1秒.strace的前面时间也可以看出来. --//附上checkpoint.sql脚本: $ cat checkpoint.sql column low_rba format a20 column low_rba16 format a20 column on_disk_rba format a20 column on_disk_rba16 format a20 column rtckp_rba format a20 column diff_date format 9999999.99 column CPOSD_ono_disk_rba_scn format 99999999999999999999999999999999 column cpdrt heading "检查点队列|脏块数量|CPDRT" column cpodt_on_disk_rba heading "检查点队列|on disk rba|时间戳|CPODT" column cpods heading "检查点队列|on disk rba scn|CPODS" column cphbt heading "检查点心跳|CPHBT" column current_sysdate heading "当前时间|SYSDATE" set num 12 PROMPT PROMPT REDO: PROMPT SELECT cpdrt , cplrba_seq || '.' || cplrba_bno || '.' || cplrba_bof "low_rba", cpodr_seq || '.' || cpodr_bno || '.' || cpodr_bof "on_disk_rba", TO_DATE (CPODT, 'MM-DD-YYYY HH24:MI:SS') cpodt_on_disk_rba, SYSDATE current_sysdate, ROUND ( (SYSDATE - TO_DATE (CPODT, 'MM-DD-YYYY HH24:MI:SS')) * 86400, 2) diff_date, CPODS , CPHBT, current_scn, current_scn - cpods diff_scn, indx FROM x$kcccp, v$database --//在我完成以上分析后我发现如下链接: https://blog.pythian.com/oracle-goldengate-extract-internals-part-i/ https://blog.pythian.com/oracle-goldengate-extract-internals-part-ii/ https://blog.pythian.com/oracle-goldengate-extract-internals-part-iii/ http://www.cnxdug.org/?p=1879 --//链接里面提到rac+asm的情况读取调用dbms_diskgroup.read,我没有环境无法测试. https://blog.pythian.com/oracle-goldengate-extract-internals-part-ii/ What else can we say? First of all, the read size is significantly smaller, just 28672 bytes, compared to 1000K read size when the log has been located on a cooked file system. If you get such a small read size and the fact that the data needs to go through the network and SQL*Net stacks… I would say that I expect this to be much less efficient compared to how online redo logs are being read from a file system. One of the immediate things to realize is that, in case you're running the Extract process on the same machine as your ASM instance, it probably makes total sense to configure the connection string to ASM instance (the one which is being specified in the Extract process parameters) using bequeath protocol so the traffic can go through a pipe instead of a socket which should provide better performance. --从这个链接http://www.cnxdug.org/?p=1879也可以看出使用rac+asm,ogg读取接近日志大小.而使用文件系统的数据库情况就不同了. --//从链接看https://blog.pythian.com/oracle-goldengate-extract-internals-part-i/ nanosleep({1, 0}, NULL) = 0 --//pause时间在0-1秒之间. --//里面提到一些sql语句执行,我给继续分析看看.

编辑推荐：

返回列表

[20181217]ogg抽取日志分析.txt

编辑推荐：

相关推荐

excel表格怎样在数字前输入0

excel表格里怎么替换数据

excel表格里面如何插入圆形

excel表格里怎么添加表格数据透视表

excel表格中怎么添加线边框

excel表格里怎样设置条件自动排序

excel表格例怎样导入数据库

Excel表格如何设置数据排序

excel表格里怎么选择性粘贴快捷键

excel表格怎么插入分隔符号

excel表格怎么设置多行多列数据内容排序

Excel表格如何设置行和列相互转换

excel表格连接公式怎么使用

excel表格怎样链接到cad中

雷神推出 MIX PRO II 迷你主机：基于 Ultra 200H，玻璃上盖 + ARGB 灯效

制造商 Musnap 推出彩色墨水屏电纸书 Ocean C：支持手写笔、第三方安卓应用

最新软件资讯

热文推荐

天极热推