[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语句执行,我给继续分析看看.
来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/267265/viewspace-2285416/，如需转载，请注明出处，否则将追究法律责任。
转载于:http://blog.itpub.net/267265/viewspace-2285416/
扫一扫
1800
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
