[20181213]ogg大量讀取操作.txt

--//我不知道是否異常,ogg存在大量讀取操作.

--//事情是這樣的,dg磁碟空間爆滿,解決磁碟空間不足的問題後再應用日誌時,發現響應緩慢,基本無法操作伺服器.

--//當時想也許應用日誌量太大,等待結束後也許問題消失.

--//當日志應用結束後,我發現磁碟依舊存在大量讀取操作,感覺很奇怪,這臺機器記憶體充足.

--//作業系統有檔案系統快取,不應該出現這麼頻繁的讀取操作.於是開始著手分析看看.

1.使用iotop觀察:

# free

total used free shared buffers cached

Mem: 132061196 127204348 4856848 0 468756 44091004

-/+ buffers/cache: 82644588 49416608

Swap: 20972848 622000 20350848

--//雖然使用swap,但是看free還有將近5G記憶體呢.cached 將近43G呢.記憶體應該沒有問題.

# iotop -a

Total DISK READ: 8.68 M/s | Total DISK WRITE: 472.90 K/s

TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND

16960 be/4 oracle 64.00 K 1654.34 M 10.70 % 13.49 % ora_dbw2_XXXXdg2

16956 be/4 oracle 36.00 K 1661.74 M 0.00 % 10.70 % ora_dbw0_XXXXdg2

16958 be/4 oracle 68.00 K 1732.70 M 0.00 % 10.24 % ora_dbw1_XXXXdg2

...

719 be/4 oracle 2.67 G 0.00 B 0.00 % 0.49 % extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

943 be/4 oracle 2.66 G 0.00 B 0.00 % 0.48 % extract PARAMFILE /u01/ogg122/dirprm/EXTZY.prm REPORTFILE /u01/ogg122/dirrpt/EXTZY.rpt PROCESSID EXTZY USESUBDIRS

926 be/4 oracle 2.66 G 0.00 B 0.00 % 0.48 % extract PARAMFILE /u01/ogg122/dirprm/EXTYB.prm REPORTFILE /u01/ogg122/dirrpt/EXTYB.rpt PROCESSID EXTYB USESUBDIRS

882 be/4 oracle 2.66 G 0.00 B 0.00 % 0.46 % extract PARAMFILE /u01/ogg122/dirprm/EXTOHS.prm REPORTFILE /u01/ogg122/dirrpt/EXTOHS.rpt PROCESSID EXTOHS USESUBDIRS

783 be/4 oracle 2.66 G 0.00 B 0.00 % 0.46 % extract PARAMFILE /u01/ogg122/dirprm/EXTGY.prm REPORTFILE /u01/ogg122/dirrpt/EXTGY.rpt PROCESSID EXTGY USESUBDIRS

838 be/4 oracle 2.67 G 0.00 B 0.00 % 0.46 % extract PARAMFILE /u01/ogg122/dirprm/EXTMS.prm REPORTFILE /u01/ogg122/dirrpt/EXTMS.rpt PROCESSID EXTMS USESUBDIRS

739 be/4 oracle 2.66 G 0.00 B 0.00 % 0.46 % extract PARAMFILE /u01/ogg122/dirprm/EXTCP.prm REPORTFILE /u01/ogg122/dirrpt/EXTCP.rpt PROCESSID EXTCP USESUBDIRS

805 be/4 oracle 2.66 G 0.00 B 0.00 % 0.46 % extract PARAMFILE /u01/ogg122/dirprm/EXTLIS.prm REPORTFILE /u01/ogg122/dirrpt/EXTLIS.rpt PROCESSID EXTLIS USESUBDIRS

761 be/4 oracle 2.66 G 0.00 B 0.00 % 0.42 % extract PARAMFILE /u01/ogg122/dirprm/EXTEMR.prm REPORTFILE /u01/ogg122/dirrpt/EXTEMR.rpt PROCESSID EXTEMR USESUBDIRS

17051 be/4 oracle 6.84 M 0.00 B 1.66 % 0.22 % ora_pr04_XXXXdg2

17036 be/4 oracle 0.00 B 0.00 B 0.50 % 0.19 % oracleXXXXdg2 (LOCAL=NO)

806 be/4 oracle 2.58 G 0.00 B 0.00 % 0.13 % extract PARAMFILE /u01/ogg122/dirprm/EXTLIS.prm REPORTFILE /u01/ogg122/dirrpt/EXTLIS.rpt PROCESSID EXTLIS USESUBDIRS

17024 be/4 oracle 49.39 M 432.71 M 0.00 % 0.12 % oracleXXXXdg2 (LOCAL=NO)

17169 be/4 oracle 0.00 B 0.00 B 0.72 % 0.12 % oracleXXXXdg2 (LOCAL=NO)

762 be/4 oracle 2.57 G 0.00 B 0.00 % 0.11 % extract PARAMFILE /u01/ogg122/dirprm/EXTEMR.prm REPORTFILE /u01/ogg122/dirrpt/EXTEMR.rpt PROCESSID EXTEMR USESUBDIRS

17094 be/4 oracle 0.00 B 5.00 M 0.65 % 0.09 % oracleXXXXdg2 (LOCAL=NO)

720 be/4 oracle 2.57 G 0.00 B 0.00 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

740 be/4 oracle 2.58 G 0.00 B 0.00 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTCP.prm REPORTFILE /u01/ogg122/dirrpt/EXTCP.rpt PROCESSID EXTCP USESUBDIRS

11068 be/4 root 4.96 M 0.00 B 0.00 % 0.09 % tmux

886 be/4 oracle 2.58 G 0.00 B 0.00 % 0.08 % extract PARAMFILE /u01/ogg122/dirprm/EXTOHS.prm REPORTFILE /u01/ogg122/dirrpt/EXTOHS.rpt PROCESSID EXTOHS USESUBDIRS

933 be/4 oracle 2.58 G 0.00 B 0.00 % 0.08 % extract PARAMFILE /u01/ogg122/dirprm/EXTYB.prm REPORTFILE /u01/ogg122/dirrpt/EXTYB.rpt PROCESSID EXTYB USESUBDIRS

38 rt/3 root 0.00 B 0.00 B 0.00 % 0.08 % [migration/12]

949 be/4 oracle 2.57 G 0.00 B 0.00 % 0.08 % extract PARAMFILE /u01/ogg122/dirprm/EXTZY.prm REPORTFILE /u01/ogg122/dirrpt/EXTZY.rpt PROCESSID EXTZY USESUBDIRS

784 be/4 oracle 2.58 G 0.00 B 0.00 % 0.08 % extract PARAMFILE /u01/ogg122/dirprm/EXTGY.prm REPORTFILE /u01/ogg122/dirrpt/EXTGY.rpt PROCESSID EXTGY USESUBDIRS

840 be/4 oracle 2.57 G 0.00 B 0.00 % 0.08 % extract PARAMFILE /u01/ogg122/dirprm/EXTMS.prm REPORTFILE /u01/ogg122/dirrpt/EXTMS.rpt PROCESSID EXTMS USESUBDIRS

--//發現讀取操作主要集中在extrace操作上.

--//使用iostat觀察:

# dstat -t -d -D total,cciss/c0d0p3,sda,sdb,sdc,sde,sde,sdf,sdg,sdh

-----time----- -dsk/total--dsk/cciss/c---dsk/sda-----dsk/sdb-----dsk/sdc-----dsk/sde-----dsk/sde-----dsk/sdf-----dsk/sdg-----dsk/sdh--

date/time | read writ: read writ: read writ: read writ: read writ: read writ: read writ: read writ: read writ: read writ

13-12 15:57:59| 51M 880k: 25M 440k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:00|8064k 944k:4020k 472k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 :8192B 0 : 0 0

13-12 15:58:01| 12M 6440k:6264k 2004k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 180k: 0 4096B

13-12 15:58:02| 51M 5016k: 25M 1808k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 188k: 0 508k

13-12 15:58:03|8016k 1688k:4008k 816k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 28k: 0 0

13-12 15:58:04| 12M 5400k:6012k 1844k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 :8192B 292k: 0 0

13-12 15:58:05| 51M 5360k: 25M 1312k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 16k 396k: 0 512k

13-12 15:58:06|8040k 1144k:4008k 572k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 :8192B 0 : 0 0

13-12 15:58:07| 12M 4672k:6008k 1572k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 32k 88k: 0 0

13-12 15:58:08| 45M 6336k: 22M 1232k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 512k: 0 512k

13-12 15:58:09| 14M 1568k:7152k 756k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:10| 12M 3904k:6016k 1256k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 256k

13-12 15:58:11| 45M 6960k: 23M 1944k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 512k: 0 256k

13-12 15:58:12| 14M 1448k:7016k 724k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:13| 12M 3440k:6008k 1268k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 184k

13-12 15:58:14| 45M 7440k: 22M 1936k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 512k: 0 328k

13-12 15:58:15| 14M 1408k:7012k 704k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:16| 12M 3752k:6148k 1876k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:17| 37M 9216k: 19M 2628k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 512k: 0 512k

13-12 15:58:18| 22M 1296k: 11M 648k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:19| 12M 1724k:6004k 820k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:20| 37M 9212k: 19M 2496k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 512k: 0 512k

13-12 15:58:21| 22M 2032k: 11M 1016k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:22| 12M 3400k:6312k 1672k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:23| 37M 11M: 19M 2920k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 :8192B 788k: 0 1024k

13-12 15:58:24| 18M 768k:9008k 384k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:25| 16M 1952k:8004k 964k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:26| 37M 6500k: 19M 1452k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 264k: 0 512k

13-12 15:58:27| 18M 652k:9384k 324k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:28| 16M 2136k:8056k 1040k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 16k 28k: 0 0

13-12 15:58:29| 36M 8768k: 18M 2264k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 584k: 0 512k

13-12 15:58:30| 20M 1272k: 9.8M 636k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 :8192B 0 : 0 0

13-12 15:58:31| 16M 3160k:8092k 1568k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:32| 35M 9944k: 18M 2324k: 0 0 : 0 0 : 0 744k: 0 0 : 0 0 : 0 0 : 0 880k: 0 512k

13-12 15:58:33| 20M 1320k: 9.8M 632k: 0 0 : 0 0 : 0 28k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:34| 16M 1920k:8056k 960k: 0 0 : 0 0 : 16k 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:35| 35M 9808k: 18M 2996k: 0 0 : 0 0 : 0 320k: 0 0 : 0 0 : 0 0 : 0 512k: 0 512k

13-12 15:58:36| 16M 1096k:8032k 548k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:37| 20M 2840k: 9.8M 1408k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0

13-12 15:58:38| 34M 6360k: 17M 1276k: 0 0 : 0 0 : 0 436k: 0 0 : 0 0 : 0 0 : 0 444k: 0 512k

13-12 15:58:39| 17M 1552k:8579k 776k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 :8192B 0 : 0 0

13-12 15:58:40| 20M 1984k: 9.8M 944k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 :8192B 48k: 0 0

13-12 15:58:41| 18M 8128k:9004k 2080k: 0 0 : 0 0 : 0 512k: 0 0 : 0 0 : 0 0 : 0 448k: 0 512k

13-12 15:58:42| 33M 1152k: 17M 576k: 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 0 0 : 24k 0 : 0 0

--//注:這個版本的dstat很奇怪,total的數量加倍,也許是bug.

--//找一個程式觀察,注意iotap看到是tid.執行緒號

# ps -eLfc | egrep "UI[D]|71[9]"

UID PID PPID LWP NLWP CLS PRI STIME TTY TIME CMD

oracle 703 2649 719 12 TS 24 Sep26 ? 00:05:04 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

--//真正的程式號703.

# ps -eLfc | egrep "UI[D]|70[3]"

UID PID PPID LWP NLWP CLS PRI STIME TTY TIME CMD

oracle 703 2649 703 12 TS 24 Sep26 ? 00:06:56 /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:47 /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:03:59 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

oracle 703 2649 706 12 TS 21 Sep26 ? 00:00:02 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

oracle 703 2649 707 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 712 12 TS 20 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:09 /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:28:06 /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:32:04 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

oracle 703 2649 718 12 TS 21 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:04 /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:31 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

--//對應12個執行緒.

# strace -t -p 703 -f -e read

Process 703 attached with 12 threads - interrupt to quit --//12執行緒.

[pid 716] 16:04:03 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] 16:04:03 read(24, "\1\"\0\0\316\236.\0\343\25\0\0\200\200\266\244zoA\6\372\22\5\1\4\0 =,\4\0\0"..., 1024000) = 1024000

[pid 716] 16:04:03 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] 16:04:03 read(24, "\1\"\0\0\236\246.\0\337\25\0\0\340\200K9\30\0 \0\24\0\23\0l\0\334\17\"\0\0\0"..., 1024000) = 1024000

[pid 717] 16:04:04 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] 16:04:04 read(25, "\1\"\0\0=S7\0\325\20\0\0\20\200\25\315`\0\0\0\4j\6\0\352Ig-\1\0+O"..., 1024000) = 1024000

[pid 717] 16:04:04 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] 16:04:04 read(25, "\1\"\0\0\r[7\0\307\20\0\0\244\200\4\201top:1878px;font-"..., 1024000) = 1024000

[pid 716] 16:04:06 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] 16:04:06 read(24, "\1\"\0\0\307\242.\0\343\25\0\0\200\2005\6jH\321\10\372\22\5\1\3\0\0\0,\3\0\0"..., 1024000) = 1024000

[pid 716] 16:04:06 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] 16:04:06 read(24, "\1\"\0\0\227\252.\0\337\25\0\0X\200\313\304\6\0\312\v\1\2or\n\0\30\0\6\0\t\0"..., 1024000) = 1024000

[pid 717] 16:04:07 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] 16:04:07 read(25, "\1\"\0\0TT7\0\325\20\0\0\20\200\312\204`\0\0\0\0042\6\0\314Kg-\1\0Nz"..., 1024000) = 1024000

[pid 717] 16:04:07 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] 16:04:07 read(25, "\1\"\0\0$\\7\0\307\20\0\0\344\200U\216nt-family:\313\316\314\345;f"..., 1024000) = 1024000

[pid 716] 16:04:09 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] 16:04:09 read(24, "\1\"\0\0\356\245.\0\343\25\0\0\20\200v5@\0\0\0\1\0\6\0\vMg-\1\0\33F"..., 1024000) = 1024000

[pid 716] 16:04:09 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] 16:04:09 read(24, "\1\"\0\0\276\255.\0\337\25\0\0<\200\3027\0\0\261\240\377\177\0\0\32\0\4\0\0\0\0\0"..., 1024000) = 1024000

[pid 717] 16:04:10 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] 16:04:10 read(25, "\1\"\0\0005U7\0\325\20\0\0\30\201\254\367YTExY3JsMS5jcmww"..., 1024000) = 1024000

[pid 717] 16:04:10 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] 16:04:10 read(25, "\1\"\0\0\5]7\0\307\20\0\0000\200;r:#000200;\"><div "..., 1024000) = 1024000

--//開始以為使用pread函式,沒想到使用read。

# ls -l /proc/719/fd/24 /proc/720/fd/25

lr-x------ 1 oracle oinstall 64 2018-12-13 16:06:59 /proc/719/fd/24 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_10.327.862659471

lr-x------ 1 oracle oinstall 64 2018-12-13 16:06:59 /proc/720/fd/25 -> /u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_15.322.862659525

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 5603 4294967296 512 1594668032 YES ACTIVE 26529592505 2018-12-13 12:04:43 26531584553 2018-12-13 16:07:13

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 4309 4294967296 512 1874407936 YES ACTIVE 26524824015 2018-12-13 02:27:19 26531584555 2018-12-13 16:07:13

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.

--//group#=10,15 正好是standby接收日誌檔案.

# ps -efc | egrep "UI[D]|extrac[t]"

UID PID PPID CLS PRI STIME TTY TIME CMD

oracle 703 2649 TS 24 Sep26 ? 05:23:46 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

oracle 725 2649 TS 24 Sep26 ? 04:54:19 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTCP.prm REPORTFILE /u01/ogg122/dirrpt/EXTCP.rpt PROCESSID EXTCP USESUBDIRS

oracle 745 2649 TS 24 Sep26 ? 05:20:09 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTEMR.prm REPORTFILE /u01/ogg122/dirrpt/EXTEMR.rpt PROCESSID EXTEMR USESUBDIRS

oracle 764 2649 TS 24 Sep26 ? 04:52:00 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTGY.prm REPORTFILE /u01/ogg122/dirrpt/EXTGY.rpt PROCESSID EXTGY USESUBDIRS

oracle 789 2649 TS 24 Sep26 ? 04:52:29 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTLIS.prm REPORTFILE /u01/ogg122/dirrpt/EXTLIS.rpt PROCESSID EXTLIS USESUBDIRS

oracle 811 2649 TS 24 Sep26 ? 05:00:34 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTMS.prm REPORTFILE /u01/ogg122/dirrpt/EXTMS.rpt PROCESSID EXTMS USESUBDIRS

oracle 825 2649 TS 23 Sep26 ? 04:52:44 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTOHS.prm REPORTFILE /u01/ogg122/dirrpt/EXTOHS.rpt PROCESSID EXTOHS USESUBDIRS

oracle 848 2649 TS 24 Sep26 ? 04:53:34 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTYB.prm REPORTFILE /u01/ogg122/dirrpt/EXTYB.rpt PROCESSID EXTYB USESUBDIRS

oracle 859 2649 TS 24 Sep26 ? 05:18:11 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/EXTZY.prm REPORTFILE /u01/ogg122/dirrpt/EXTZY.rpt PROCESSID EXTZY USESUBDIRS

oracle 5773 2649 TS 24 Aug10 ? 05:33:08 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMEMR.prm REPORTFILE /u01/ogg122/dirrpt/PUMEMR.rpt PROCESSID PUMEMR USESUBDIRS

oracle 29015 2649 TS 24 Aug09 ? 03:08:10 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMBA.prm REPORTFILE /u01/ogg122/dirrpt/PUMBA.rpt PROCESSID PUMBA USESUBDIRS

oracle 29030 2649 TS 24 Aug09 ? 03:09:20 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMCP.prm REPORTFILE /u01/ogg122/dirrpt/PUMCP.rpt PROCESSID PUMCP USESUBDIRS

oracle 29070 2649 TS 24 Aug09 ? 02:57:34 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMGY.prm REPORTFILE /u01/ogg122/dirrpt/PUMGY.rpt PROCESSID PUMGY USESUBDIRS

oracle 29114 2649 TS 24 Aug09 ? 03:53:25 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMZY.prm REPORTFILE /u01/ogg122/dirrpt/PUMZY.rpt PROCESSID PUMZY USESUBDIRS

oracle 29202 2649 TS 24 Aug09 ? 03:05:47 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMLIS.prm REPORTFILE /u01/ogg122/dirrpt/PUMLIS.rpt PROCESSID PUMLIS USESUBDIRS

oracle 29211 2649 TS 24 Aug09 ? 03:29:47 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMMS.prm REPORTFILE /u01/ogg122/dirrpt/PUMMS.rpt PROCESSID PUMMS USESUBDIRS

oracle 29222 2649 TS 24 Aug09 ? 03:05:49 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMOHS.prm REPORTFILE /u01/ogg122/dirrpt/PUMOHS.rpt PROCESSID PUMOHS USESUBDIRS

oracle 29230 2649 TS 24 Aug09 ? 03:19:53 /u01/ogg122/extract PARAMFILE /u01/ogg122/dirprm/PUMYB.prm REPORTFILE /u01/ogg122/dirrpt/PUMYB.rpt PROCESSID PUMYB USESUBDIRS

--//一共18個extract程式.9個抽取,9個pump .其中抽取的程式都會大量的讀取接收的日誌.

GGSCI (XXXXdg2) 3> info all

Program Status Group Lag at Chkpt Time Since Chkpt

MANAGER RUNNING

EXTRACT RUNNING EXTBA 00:00:01 00:00:01

EXTRACT RUNNING EXTCP 00:00:00 00:00:00

EXTRACT RUNNING EXTEMR 00:00:03 00:00:01

EXTRACT RUNNING EXTGY 00:00:01 00:00:07

EXTRACT RUNNING EXTLIS 00:00:02 00:00:06

EXTRACT RUNNING EXTMS 00:00:01 00:00:01

EXTRACT RUNNING EXTOHS 00:00:02 00:00:04

EXTRACT RUNNING EXTYB 00:00:04 00:00:01

EXTRACT RUNNING EXTZY 00:00:03 00:00:01

EXTRACT RUNNING PUMBA 00:00:00 00:00:06

EXTRACT RUNNING PUMCP 00:00:00 00:00:06

EXTRACT RUNNING PUMEMR 00:00:00 00:00:03

EXTRACT RUNNING PUMGY 00:00:00 00:00:06

EXTRACT RUNNING PUMLIS 00:00:00 00:00:05

EXTRACT RUNNING PUMMS 00:00:00 00:00:03

EXTRACT RUNNING PUMOHS 00:00:00 00:00:06

EXTRACT RUNNING PUMYB 00:00:00 00:00:05

EXTRACT RUNNING PUMZY 00:00:00 00:00:03

--//9個抽取程式,9個pump程式.

--//可以想像應該9個抽取程式都在讀取standby日誌檔案(注2個例項的standby的日誌).

--//我在想如果是rac環境,ogg又是如何抽取呢? 這樣的抽取方式對於磁碟可能存在更大的壓力.看來要想辦法看看dg的awr報表才行.

--//先執行如下監測open那些檔案控制程式碼.

# strace -p 745 -f -e open | tee /tmp/aa.txt

--//...等

--//再主庫做1個日誌切換.

SYS@XXXX1> alter system archive log current ;

System altered.

# strace -p 745 -f -e open | tee /tmp/aa.txt

Process 745 attached with 12 threads - interrupt to quit

[pid 759] open("/u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_14.323.862659519", O_RDONLY|O_DIRECT) = 23

[pid 758] open("/u01/app/oracle/oradata/XXXXdg2/onlinelog/onlinelog/group_10.327.862659471", O_RDONLY|O_DIRECT) = 25

--//注意看開啟flag.

# man open

...

O_DIRECT

Try to minimize cache effects of the I/O to and from this file. In general this will degrade performance,

but it is useful in special situations, such as when applications do their own caching. File I/O is done

directly to/from user space buffers. The I/O is synchronous, i.e., at the completion of a read(2) or

write(2), data is guaranteed to have been transferred. Under Linux 2.4 transfer sizes, and the alignment

of user buffer and file offset must all be multiples of the logical block size of the file system. Under

Linux 2.6 alignment must fit the block size of the device.

--//這樣讀取效率會低下,ogg這樣用應該有它的道理,也許我不知道.

--//參考連結:http://blog.itpub.net/267265/viewspace-2285296/

--//如果應用產生大量日誌將會產生大量磁碟讀取操作.抽取程式越多.讀取日誌量就會翻倍.

--//不知道是否可以合併1個抽取程式,多個pump程式.

--//自己還有1個疑問,如果在rac+asm的環境下,ogg抽取採用那種讀取日誌模式.沒有環境,無法測試.

--//我開啟iotop接近1天:

# iotop -a

Total DISK READ: 8.68 M/s | Total DISK WRITE: 472.90 K/s

TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND

...

739 be/4 oracle 53.98 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTCP.prm REPORTFILE /u01/ogg122/dirrpt/EXTCP.rpt PROCESSID EXTCP USESUBDIRS

805 be/4 oracle 53.96 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTLIS.prm REPORTFILE /u01/ogg122/dirrpt/EXTLIS.rpt PROCESSID EXTLIS USESUBDIRS

882 be/4 oracle 53.98 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTOHS.prm REPORTFILE /u01/ogg122/dirrpt/EXTOHS.rpt PROCESSID EXTOHS USESUBDIRS

926 be/4 oracle 54.03 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTYB.prm REPORTFILE /u01/ogg122/dirrpt/EXTYB.rpt PROCESSID EXTYB USESUBDIRS

943 be/4 oracle 53.89 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTZY.prm REPORTFILE /u01/ogg122/dirrpt/EXTZY.rpt PROCESSID EXTZY USESUBDIRS

719 be/4 oracle 54.00 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

838 be/4 oracle 54.02 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTMS.prm REPORTFILE /u01/ogg122/dirrpt/EXTMS.rpt PROCESSID EXTMS USESUBDIRS

761 be/4 oracle 54.05 G 0.00 B 0.00 % 0.28 % extract PARAMFILE /u01/ogg122/dirprm/EXTEMR.prm REPORTFILE /u01/ogg122/dirrpt/EXTEMR.rpt PROCESSID EXTEMR USESUBDIRS

783 be/4 oracle 53.95 G 0.00 B 0.00 % 0.27 % extract PARAMFILE /u01/ogg122/dirprm/EXTGY.prm REPORTFILE /u01/ogg122/dirrpt/EXTGY.rpt PROCESSID EXTGY USESUBDIRS

...

933 be/4 oracle 51.41 G 0.00 B 0.01 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTYB.prm REPORTFILE /u01/ogg122/dirrpt/EXTYB.rpt PROCESSID EXTYB USESUBDIRS

784 be/4 oracle 51.43 G 0.00 B 0.01 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTGY.prm REPORTFILE /u01/ogg122/dirrpt/EXTGY.rpt PROCESSID EXTGY USESUBDIRS

740 be/4 oracle 51.40 G 0.00 B 0.00 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTCP.prm REPORTFILE /u01/ogg122/dirrpt/EXTCP.rpt PROCESSID EXTCP USESUBDIRS

840 be/4 oracle 51.35 G 0.00 B 0.01 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTMS.prm REPORTFILE /u01/ogg122/dirrpt/EXTMS.rpt PROCESSID EXTMS USESUBDIRS

762 be/4 oracle 51.41 G 0.00 B 0.01 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTEMR.prm REPORTFILE /u01/ogg122/dirrpt/EXTEMR.rpt PROCESSID EXTEMR USESUBDIRS

886 be/4 oracle 51.46 G 0.00 B 0.01 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTOHS.prm REPORTFILE /u01/ogg122/dirrpt/EXTOHS.rpt PROCESSID EXTOHS USESUBDIRS

720 be/4 oracle 51.46 G 0.00 B 0.00 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTBA.prm REPORTFILE /u01/ogg122/dirrpt/EXTBA.rpt PROCESSID EXTBA USESUBDIRS

806 be/4 oracle 51.48 G 0.00 B 0.02 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTLIS.prm REPORTFILE /u01/ogg122/dirrpt/EXTLIS.rpt PROCESSID EXTLIS USESUBDIRS

949 be/4 oracle 51.49 G 0.00 B 0.01 % 0.09 % extract PARAMFILE /u01/ogg122/dirprm/EXTZY.prm REPORTFILE /u01/ogg122/dirrpt/EXTZY.rpt PROCESSID EXTZY USESUBDIRS

--//將近5X G,9個抽取程式,實際上18個(分別從rac的2個例項讀取日誌).一天有將近18*51G = 918G讀取操作.

--//當然這點IO量對於現在的硬體根本不是問題.

d:\tools\sql>d_arc

DATE WEEK SIZE_MB NUMBER_OF_SWITCHES_PER_DAY

------------- ------------- ---------- --------------------------

2018-12-14 50 FRIDAY 4201 4

2018-12-13 50 THURSDAY 10188 6

2018-12-12 50 WEDNESDAY 11645 7

2018-12-11 50 TUESDAY 4890 4

2018-12-10 50 MONDAY 4932 4

2018-12-09 49 SUNDAY 4864 4

2018-12-08 49 SATURDAY 6646 5

2018-12-07 49 FRIDAY 12147 7

2018-12-06 49 THURSDAY 11557 7

2018-12-05 49 WEDNESDAY 10086 6

2018-12-04 49 TUESDAY 12502 8

2018-12-03 49 MONDAY 11890 6

....

--//一般正常業務每天大約11G上下.12-10,12-11號這兩天偏少,是因為我們這裡放假. ^_^.

--//我不熟悉ogg,也不知道我的分析是否正確,或者有什麼方法規避這樣的讀取操作.或者什麼引數調整規避開啟使用O_DIRECT.

--//在我看來抽取指令碼XXX.prm,前面部分都以一樣的,僅僅後面抽取的表不同.要沒有別的方式可以採取1個抽取,1個pump或者拆分

--//多個pump方式(注我不知道是否可行,感覺應該是個可以),這樣並不會執行緩慢.而且ogg抽取我們並沒有實時性需求.

--//我有點奇怪的是生產系統rac環境,2邊日誌生成量並不相同,正常在大約3:1之間.也就是例項1每天產生8G,例項2每天產生3G上下.

--//而抽取程式讀取兩邊例項日誌的量確非常接近,都是5XG,這樣一定存在重複讀取的情況,也就是讀取大量"垃圾"日誌.看來還給做一些

--//細節分析.

--//read函式里面並沒有偏移引數設定,讀取後自動移到下一個位置.

--//對於ogg實在不熟悉,一些細節下個星期繼續分析看看.

--//附上d_arc.sql的指令碼:

$ cat d_arc.sql

SELECT TO_CHAR (first_time, 'YYYY-MM-DD WW') AS "DATE"

,TO_CHAR (first_time, 'DAY') week

,ROUND (SUM ( (blocks + 1) * block_size) / 1024 / 1024, 0) AS "SIZE_MB"

,COUNT (*) AS "NUMBER_OF_SWITCHES_PER_DAY"

FROM v$archived_log

WHERE dest_id = 1 and first_time>=trunc(sysdate)-40

GROUP BY TO_CHAR (first_time, 'YYYY-MM-DD WW'), TO_CHAR (first_time, 'DAY')

ORDER BY TO_CHAR (first_time, 'YYYY-MM-DD WW') DESC;

quit

[20181213]ogg大量讀取操作.txt

相關文章