[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的流量)。
如图:
[20121227]dataguard下执行延迟recover的问题.txt
(我监测的是服务器,绿色标识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流量图看,几乎掩盖了其他磁盘操作,导致看到的
流量图会很平,而且流量很大。





 

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

上一篇:2.0解析系列 | OceanBase 2.0 之 索引实时生效


下一篇:【2018中国计算机大会】阿里云分布式存储架构师谈 自研分布式文件系统服务