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

  • lfree

    2018-12-17 11:09:30
  • Oracle
  • 原创

[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

\r\n

[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>

\r\n

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,  

720   09:36:27 read(26,  

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


       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

  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语句执行,我给继续分析看看.