[20121227]dataguard下执行延迟recover的问题.txt

[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