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

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/

--//連結裡面提到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.

--從這個連結也可以看出使用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

相關文章