[20121227]dataguard下执行recover managed standby database disconnect from session delay 720.txt
recover managed standby database disconnect from session delay 720 ;
alter database recover managed standby database disconnect from session delay 720 ;
100.31机器,从网络流量看，出现一个很奇怪的情况，流量很大。也就是从IP 存储上有大量的物理读（前46week的流量）。
如图：
（我监测的是服务器，绿色标识in bound，对于IP存储出，也就是从IP存储上读取信息）
如果执行alter database open read only ;,流量下降下来。
我开始以为SGA设置不合理，检查发现：
SQL> show sga
Total System Global Area 2147483648 bytes
Fixed Size 2085360 bytes
Variable Size 385879568 bytes
Database Buffers 1744830464 bytes
Redo Buffers 14688256 bytes
SQL> show parameter 32k
NAME TYPE VALUE
------------------------------------ ----------- -----
db_32k_cache_size big integer 256M
--应该是正常，也是db_32k_cache_size设置小一点，设置为512M。
recover managed standby database disconnect from session delay 720 ;
top -c 观察，隔一段时间出现在前面:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
19628 oracle 15 0 2221m 37m 16m S 1.0 0.9 0:00.67 ora_mrp0_icarestd
使用strace跟踪发现：
$ strace -p 19628 -t -e pread -o /tmp/aa1
....
15:05:48 pread(17, "\25\302\0\0\260\3\0\0\35\312\23\0\377\377\1\4\212\245\0"..., 49152, 137101312) = 49152
15:05:48 pread(17, "\25\302\0\0\307\1\0\0\257\311\23\0\377\377\1\4\346\r\0"..., 16384, 126861312) = 16384
15:05:48 pread(18, "\25\302\0\0\310\1\0\0\260\311\23\0\377\377\1\4\303\r\0"..., 16384, 229507072) = 16384
15:05:53 pread(17, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\24\232\0\0\0\0\0\0"..., 16384, 125845504) = 16384
15:05:53 pread(17, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\24\232\0\0\0\0\0\0"..., 16384, 429932544) = 16384
--通过偏移确定读取什么有一些困难。
....
lrwx------ 1 oracle oinstall 64 Dec 10 15:07 17 -> /dev/raw/raw1
lrwx------ 1 oracle oinstall 64 Dec 10 15:07 18 -> /dev/raw/raw2
$ cut -f1 -d' ' /tmp/aa1 | uniq -c
212 15:05:48
164 15:05:53
48 15:05:54
212 15:05:59
212 15:06:04
69 15:06:09
143 15:06:10
--基本上间隔5秒，读/dev/raw/raw[12].
--过滤^15:05:59。
$ grep '^15:05:59' /tmp/aa1 | cut -f2 -d '=' > /tmp/aa2
$ wc -l /tmp/aa2
212 /tmp/aa2
--后面写入211个+，并且加入pq
$ cat /tmp/aa2 | dc
20267008
--读取了 20267008/1024/1024=19.328125M,分摊到5秒的时间内，确实正好4M上下。基本和流量图一致。
# dstat -n -N eth1,eth0,total 1 100
--net/eth1----net/eth0---net/total-
recv send: recv send: recv send
0 0 : 0 0 : 0 0
20M 5043k:2545k 64k: 22M 5108k
0 0 : 0 0 : 0 0
19k 81k: 24k 2168B: 44k 83k
0 0 : 0 0 : 0 0
5634B 108k: 60k 6982B: 66k 114k
0 0 : 0 0 : 0 0
20M 161k: 17k 2524B: 20M 164k
0 0 : 0 0 : 0 0
17k 37k: 958B 624B: 18k 38k
0 0 : 0 0 : 0 0
11M 109k: 29k 2232B: 11M 111k
0 0 : 0 0 : 0 0
9227k 89k:4685B 962B:9231k 90k
0 0 : 0 0 : 0 0
27k 297k: 144k 12k: 172k 309k
0 0 : 0 0 : 0 0
20M 254k: 82k 3384B: 20M 257k
0 0 : 0 0 : 0 0
18k 43k:3890B 962B: 22k 43k
0 0 : 0 0 : 0 0
--基本验证。注意查看eth1网卡的流量。
# dstat -d -D sda,sdb,total 1 100
--dsk/sda-----dsk/sdb----dsk/total-
read writ: read writ: read writ
252B 13k:6134B 11k:6387B 24k
0 0 : 0 59k: 0 59k
0 0 : 16k 37k: 16k 37k
0 0 : 0 0 : 0 0
0 0 : 19M 481k: 19M 481k
0 168k: 16k 62k: 16k 230k
0 0 : 0 108k: 0 108k
0 0 : 0 18k: 0 18k
0 0 : 16k 46k: 16k 46k
0 0 : 16M 9216B: 16M 9216B
0 0 :3568k 18k:3568k 18k
0 0 : 16k 58k: 16k 58k
0 0 : 0 4096B: 0 4096B
0 0 : 0 14k: 0 14k
0 0 : 16k 40k: 16k 40k
0 0 : 19M 5120B: 19M 5120B
0 0 : 0 40k: 0 40k
0 0 : 16k 47k: 16k 47k
0 0 : 0 0 : 0 0
0 0 : 12M 132k: 12M 132k
0 0 : 48M 32k: 48M 32k
0 0 : 0 168k: 0 168k
0 0 : 0 14k: 0 14k
0 0 : 16k 180k: 16k 180k
0 16k: 0 4096B: 0 20k
0 0 :5776k 153k:5776k 153k
0 0 : 14M 36k: 14M 36k
0 0 : 0 5120B: 0 5120B
0 0 : 0 78k: 0 78k
0 0 : 16k 80k: 16k 80k
0 0 : 0 176k: 0 176k
--问题是不知道mrp进程到底读取什么????
分析过程:
$ man pread
PREAD(2) Linux Programmer's Manual PREAD(2)
NAME
pread, pwrite - read from or write to a file descriptor at a given offset
SYNOPSIS
#define _XOPEN_SOURCE 500
#include
ssize_t pread(int fd, void *buf, size_t count, off_t offset);
ssize_t pwrite(int fd, const void *buf, size_t count, off_t offset);
--第1个是句柄，第2个参数缓存地址指针，第3个是读取长度，第4个是偏移量。
单独看两个：
15:05:48 pread(17, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\24\232\0\0\0\0\0\0"..., 16384, 125845504) = 16384
15:05:48 pread(17, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\24\232\0\0\0\0\0\0"..., 16384, 429932544) = 16384
125845504/1024/1024=120.015625
429932544/1024/1024=410.015625
0.015625*1024*1024=16384 --??
SQL> column path format a40
SQL> select DISK_NUMBER,GROUP_NUMBER,PATH from v$asm_disk where GROUP_NUMBER=1 and DISK_NUMBER in(1,0);
DISK_NUMBER GROUP_NUMBER PATH
----------- ------------ ----------------------------------------
0 1 /dev/raw/raw1
1 1 /dev/raw/raw2
--可以确定文件句柄对应的是17对应的DISK_NUMBER=0.
SQL> SELECT disk_kffxp, au_kffxp, xnum_kffxp,GROUP_KFFXP,NUMBER_KFFXP FROM x$kffxp WHERE (au_kffxp=120 or au_kffxp=410) and disk_kffxp=0;
DISK_KFFXP AU_KFFXP XNUM_KFFXP GROUP_KFFXP NUMBER_KFFXP
---------- ---------- ---------- ----------- ------------
0 120 0 1 1805
0 410 0 1 2011
asmcmd看：
ls -l
Type Redund Striped Time Sys Name
CONTROLFILE UNPROT FINE DEC 10 08:00:00 Y current.1805.772818275
CONTROLFILE UNPROT FINE DEC 10 08:00:00 Y current.2011.772818275
--从这里也可以确定文件号1805,2011.
--做如下查询:
SQL> column type format a12
SQL> select * from v$asm_file where TYPE'ARCHIVELOG' and TYPE'AUTOBACKUP' and TYPE='CONTROLFILE' order by type;
GROUP_NUMBER FILE_NUMBER COMPOUND_INDEX INCARNATION BLOCK_SIZE BLOCKS BYTES SPACE TYPE REDUNDANCY STRIPED CREATION_DATE MODIFICATION_DATE RE
------------ ----------- -------------- ----------- ---------- ---------- ---------- ---------- ------------ ------------ ------------ ------------------- ------------------- --
1 1805 16779021 772818275 16384 3081 50479104 58720256 CONTROLFILE UNPROT FINE 2012-01-17 15:44:34 2012-12-10 08:00:00 U
1 2011 16779227 772818275 16384 3081 50479104 58720256 CONTROLFILE UNPROT FINE 2012-01-17 15:44:35 2012-12-10 08:00:00 U
--再次证明读取的地方是控制文件。
--再拿这个来看看:
15:05:48 pread(18, "\25\302\0\0(\0\0\0)w\35\0\377\377\1\4Iz\0\0\0\0008\0\0"..., 16384, 233832448) = 16384
15:05:48 pread(18, "\25\302\0\0\304\3\0\0\351\310\23\0\377\377\1\4\2537\0\0"..., 16384, 237961216) = 16384
233832448/1024/1024=223
237961216/1024/1024=226.9375
SQL> SELECT disk_kffxp, au_kffxp, xnum_kffxp,GROUP_KFFXP,NUMBER_KFFXP FROM x$kffxp WHERE (au_kffxp=223 or au_kffxp=226) and disk_kffxp=1;
DISK_KFFXP AU_KFFXP XNUM_KFFXP GROUP_KFFXP NUMBER_KFFXP
---------- ---------- ---------- ----------- ------------
1 223 5 1 1805
1 226 8 1 1805
--可以再次确定读取的就是控制文件。
--如果拿一台使用文件系统做dataguard看，也很容易确定读取的就是控制文件。但是如果使用dstat -d -D观察，发现使用文件系统并没
--有读操作。这是由于使用文件系统有一定的缓存，dstat根本监测到磁盘读操作,基本在内存进行。而asm使用裸设备，没有文件系统的
--缓存，导致在这样延迟日志使用的模式下要每隔5秒读取控制文件，出现大量的磁盘读取操作（注：当然一些存储自身带有缓存，也许
--根本没有读取磁盘）。
总结：
可以看出在使用recover managed standby database disconnect from session delay 720 ，会每隔5秒读取控制文件，如果使用的是文件系统，
由于文件系统有一定的缓存。dstat，iostat几乎看不见磁盘读取操作，而使用asm的磁盘就不同了。由于没有文件系统的缓存，基本是直接读取磁
盘设备，读取的大小与congtrol文件保存的东西有关。我们的数据库每次多达19M，这样从cacti流量图看，几乎掩盖了其他磁盘操作，导致看到的
流量图会很平，而且流量很大。
snap.jpg