[20170315]簡單探究dg的mrp程式.txt

[20170315]簡單探究dg的mrp程式.txt

--//昨天上午在做測試做線上日誌與備用日誌大小不一樣時遇到一個令我困惑的問題,連結:
http://blog.itpub.net/267265/viewspace-2135377/

--//發現mrp程式並沒有開啟資料檔案的控制程式碼.這樣MRP程式如何應用日誌的呢?簡單探究看看:

1.環境:
SYS@192.168.31.8/xxxxxx> @ &r/ver1
PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.3.0     Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

SYS@192.168.31.7/xxxxxxdg> @ &r/dg/dg
PROCESS       PID STATUS       CLIENT_P GROUP#  THREAD#  SEQUENCE#     BLOCK#     BLOCKS DELAY_MINS
--------- ------- ------------ -------- ------- ------- ---------- ---------- ---------- ----------
RFS         15714 IDLE         ARCH     N/A           0          0          0          0          0
ARCH         1549 CONNECTED    ARCH     N/A           0          0          0          0          0
RFS         15720 IDLE         UNKNOWN  N/A           0          0          0          0          0
RFS         15718 IDLE         LGWR     1             1       5242      36608          2          0
ARCH         1551 CLOSING      ARCH     4             1       5238      73728       2030          0
ARCH         1547 CLOSING      ARCH     4             1       5241      73728       2048          0
ARCH         1553 CLOSING      ARCH     4             1       5240          1          1          0
MRP0         1572 APPLYING_LOG N/A      N/A           1       5242      36609     102400          0

8 rows selected.
--//不斷執行可以發現MRP0程式的block#塊數不斷變化.
--//備庫執行:
# ps -eLf | egrep "1572 |PID"
UID        PID  PPID   LWP  C NLWP STIME TTY          TIME CMD
oracle    1572     1  1572  0    1 Feb03 ?        00:00:00 ora_mrp0_xxxxxxdg
root      7214  7174  7214  0    1 09:37 pts/2    00:00:00 egrep 1572 |PID
--//MPR0程式號10912.

2.而如果檢視:

# ls -l /proc/1572/fd
total 0
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2017-03-16 09:38:01 1 -> /dev/null
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 10 -> /dev/zero
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 11 -> /dev/zero
lrwx------ 1 oracle oinstall 64 2017-03-16 09:38:01 12 -> /u01/app/oracle/product/11.2.0/db_1/dbs/hc_xxxxxxdg.dat
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 13 -> /u01/app/oracle/product/11.2.0/db_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 14 -> /proc/1572/fd
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 15 -> /dev/zero
lrwx------ 1 oracle oinstall 64 2017-03-16 09:38:01 16 -> /u01/app/oracle/product/11.2.0/db_1/dbs/hc_xxxxxxdg.dat
l-wx------ 1 oracle oinstall 64 2017-03-16 09:38:01 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2017-03-16 09:38:01 256 -> /u01/app/oracle/oradata/xxxxxx/control01.ctl
lrwx------ 1 oracle oinstall 64 2017-03-16 09:38:01 257 -> /u01/app/oracle/oradata/xxxxxx/control02.ctl
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 4 -> /dev/null
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 5 -> /dev/null
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 6 -> /dev/null
lrwx------ 1 oracle oinstall 64 2017-03-16 09:38:01 7 -> /u01/app/oracle/product/11.2.0/db_1/dbs/hc_xxxxxxdg.dat
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 8 -> /dev/null
lr-x------ 1 oracle oinstall 64 2017-03-16 09:38:01 9 -> /dev/null
--//可以發現這個程式並沒有開啟資料檔案控制程式碼.

#  strace -f -c  -p 1572 -tt
Process 1572 attached - interrupt to quit
Process 1572 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
   nan    0.000000           0        47           getrusage
   nan    0.000000           0        77        77 semtimedop
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                   124        77 total
--//既沒有讀也沒有寫操作相關呼叫.

--//檢視RFS 程式號15718
# strace -f -c  -p 15718  -tt
Process 15718 attached - interrupt to quit
Process 15718 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
66.66    0.001997          29        69           io_submit
33.34    0.000999          14        72           poll
  0.00    0.000000           0       361       145 readv
  0.00    0.000000           0        53           semctl
  0.00    0.000000           0       138           times
  0.00    0.000000           0        69           io_getevents
------ ----------- ----------- --------- --------- ----------------
100.00    0.002996                   762       145 total
--//io_submit 函式io_submit - Submit asynchronous I/O blocks for processing,可以使用man io_submit獲得.

# ls -l /proc/15718/fd
total 0
lr-x------ 1 oracle oinstall 64 2017-03-15 17:25:20 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 2017-03-15 17:25:20 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 2017-03-15 17:25:20 10 -> /u01/app/oracle/diag/rdbms/xxxxxxdg/xxxxxxdg/trace/xxxxxxdg_rfs_15718.trm
lrwx------ 1 oracle oinstall 64 2017-03-15 17:25:20 13 -> socket:[1615732]
l-wx------ 1 oracle oinstall 64 2017-03-15 17:25:20 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 2017-03-15 17:25:20 256 -> /u01/app/oracle/oradata/xxxxxx/control01.ctl
lrwx------ 1 oracle oinstall 64 2017-03-15 17:25:20 257 -> /u01/app/oracle/oradata/xxxxxx/control02.ctl
lrwx------ 1 oracle oinstall 64 2017-03-15 17:25:20 258 -> /u01/app/oracle/oradata/xxxxxx/redostb02.rbo
lr-x------ 1 oracle oinstall 64 2017-03-15 17:25:20 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 2017-03-15 17:25:20 4 -> /dev/null
lr-x------ 1 oracle oinstall 64 2017-03-15 17:25:20 5 -> /u01/app/oracle/product/11.2.0/db_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 2017-03-15 17:25:20 6 -> /proc/15718/fd
lr-x------ 1 oracle oinstall 64 2017-03-15 17:25:20 7 -> /dev/zero
lrwx------ 1 oracle oinstall 64 2017-03-15 17:25:20 8 -> /u01/app/oracle/admin/xxxxxx/adump/xxxxxxdg_ora_15718_1.aud
l-wx------ 1 oracle oinstall 64 2017-03-15 17:25:20 9 -> /u01/app/oracle/diag/rdbms/xxxxxxdg/xxxxxxdg/trace/xxxxxxdg_rfs_15718.trc

# strace -f   -p  15718 -e trace=io_submit -tt
Process 15718 attached - interrupt to quit
09:43:12.375345 io_submit(47908000763904, 1, {{0x2b92736ee890, 0, 1, 0, 258}}) = 1
09:43:12.431387 io_submit(47908000763904, 1, {{0x2b9277141b38, 0, 1, 0, 258}}) = 1
09:43:12.439732 io_submit(47908000763904, 1, {{0x2b92771411a0, 0, 1, 0, 258}}) = 1
09:43:12.452173 io_submit(47908000763904, 1, {{0x2b9277140808, 0, 1, 0, 258}}) = 1
09:43:12.468799 io_submit(47908000763904, 1, {{0x2b927713fe70, 0, 1, 0, 258}}) = 1
09:43:12.510526 io_submit(47908000763904, 1, {{0x2b927713f4d8, 0, 1, 0, 258}}) = 1
09:43:12.615407 io_submit(47908000763904, 1, {{0x2b927713eb40, 0, 1, 0, 258}}) = 1
09:43:13.292328 io_submit(47908000763904, 1, {{0x2b9276bfc840, 0, 1, 0, 258}}) = 1
09:43:13.305197 io_submit(47908000763904, 1, {{0x2b9276bfbea8, 0, 1, 0, 258}}) = 1
09:43:13.323443 io_submit(47908000763904, 1, {{0x2b9276bfb510, 0, 1, 0, 258}}) = 1
09:43:13.502523 io_submit(47908000763904, 1, {{0x2b9276bfab78, 0, 1, 0, 258}}) = 1
09:43:14.504408 io_submit(47908000763904, 1, {{0x2b9276bfa1e0, 0, 1, 0, 258}}) = 1
09:43:15.531130 io_submit(47908000763904, 1, {{0x2b9276bf9848, 0, 1, 0, 258}}) = 1
09:43:16.532472 io_submit(47908000763904, 1, {{0x2b9276bf8eb0, 0, 1, 0, 258}}) = 1
09:43:17.748430 io_submit(47908000763904, 1, {{0x2b9276bf8518, 0, 1, 0, 258}}) = 1
09:43:18.604977 io_submit(47908000763904, 1, {{0x2b9276bf7b80, 0, 1, 0, 258}}) = 1
09:43:18.613206 io_submit(47908000763904, 1, {{0x2b9276bf71e8, 0, 1, 0, 258}}) = 1
09:43:18.713221 io_submit(47908000763904, 1, {{0x2b9276bf6850, 0, 1, 0, 258}}) = 1
09:43:19.238235 io_submit(47908000763904, 1, {{0x2b9276bf5eb8, 0, 1, 0, 258}}) = 1
Process 15718 detached
--//258 對應的就是258 -> /u01/app/oracle/oradata/xxxxxx/redostb02.rbo ,也就是由這個rfs程式寫備用日誌檔案.

# strace -f   -p 15718 -e trace=readv  -tt
Process 15718 attached - interrupt to quit
09:44:38.968628 readv(13, [{"\0H\0\0\17\0\0\0\0\0\0\2\0\0\10$\0\0\0\2\0$\10\0\0\0\0\0\0\0\0\0"..., 72}], 1) = 72
09:44:38.968866 readv(13, [{"\1\0\0\0\0\0\0\0\1\0\0\0\361\234\0\0\4\0\0\0\0\0\0\0\310\347V`\3\0\0\0"..., 36}], 1) = 36
09:44:38.968942 readv(13, [{"\1\"\0\0\361\234\0\0z\24\0\0\20\200d\340\30\6\0\0\r\0\3\0\306\347V`\1\0\0\1"..., 2048}], 1) = 2048
09:44:38.975307 readv(13, 0x17654fd0, 1) = -1 EAGAIN (Resource temporarily unavailable)
09:44:38.975389 readv(13, 0x17654fd0, 1) = -1 EAGAIN (Resource temporarily unavailable)
09:44:38.985228 readv(13, [{"\0H\0\0\17\0\0\0\0\0\0\2\0\0\6$\0\0\0\2\0$\6\0\0\0\0\0\0\0\0\0"..., 72}], 1) = 72
09:44:38.985378 readv(13, [{"\1\0\0\0\0\0\0\0\1\0\0\0\365\234\0\0\3\0\0\0\0\0\0\0\312\347V`\3\0\0\0"..., 36}], 1) = 36
09:44:38.985549 readv(13, [{"\1\"\0\0\365\234\0\0z\24\0\0\20\200\236s|\0\0\0\5\304\3\0\307\347V`\1\0005\37"..., 1536}], 1) = 1536
09:44:38.987276 readv(13, 0x17654fd0, 1) = -1 EAGAIN (Resource temporarily unavailable)
09:44:38.987331 readv(13, 0x17654fd0, 1) = -1 EAGAIN (Resource temporarily unavailable)
09:44:38.997682 readv(13, [{"\0H\0\0\17\0\0\0\0\0\0\2\0\0\n$\0\0\0\2\0$\n\0\0\0\0\0\0\0\0\0"..., 72}], 1) = 72
09:44:38.997832 readv(13, [{"\1\0\0\0\0\0\0\0\1\0\0\0\370\234\0\0\5\0\0\0\0\0\0\0\314\347V`\3\0\0\0"..., 36}], 1) = 36
09:44:38.997976 readv(13, [{"\1\"\0\0\370\234\0\0z\24\0\0\20\200B@|\0\0\0\5\0\3\0\311\347V`\1\0\0\0"..., 2560}], 1) = 2560
09:44:38.999316 readv(13, 0x17654fd0, 1) = -1 EAGAIN (Resource temporarily unavailable)
09:44:38.999371 readv(13, 0x17654fd0, 1) = -1 EAGAIN (Resource temporarily unavailable)
Process 15718 detached

--//13 -> socket:[1615732],我估計報錯,是因為快取已經讀空.
--//可以透過如下命令觀察.
# strace  -f   -p 15718 -e trace=io_submit -e write=all -tt
# strace  -f   -p 15718 -e trace=readv     -e read=all -tt

--//可以看出mrp0實際上乾的事情很少,僅僅顯示日誌應該到那裡.
--//真正幹活的是那個程式呢? 使用iotop觀察.在主備庫同時啟動iotop -a -u oracle並觀察(觀察10分鐘).

--//在主庫觀察:
# iotop -a -u oracle
Total DISK READ: 0.00 B/s | Total DISK WRITE: 30.77 K/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
3831 be/4 oracle        0.00 B     24.50 M  1.11 %  2.80 % ora_ckpt_xxxxxx
3829 be/4 oracle        0.00 B      8.38 M  0.00 %  2.48 % ora_lgwr_xxxxxx
3827 be/4 oracle        0.00 B      7.59 M  0.00 %  1.11 % ora_dbw0_xxxxxx
24598 be/4 oracle        0.00 B      0.00 B -19.60 %  0.40 % oraclexxxxxx (LOCAL=NO)

--//在備庫觀察:
Total DISK READ: 0.00 B/s | Total DISK WRITE: 102.41 K/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
1522 be/4 oracle        4.00 K     41.76 M  0.00 %  2.10 % ora_dbw0_xxxxxxdg
15718 be/4 oracle        0.00 B      8.81 M  0.00 %  0.87 % oraclexxxxxxdg (LOCAL=NO)
1526 be/4 oracle        0.00 B     26.62 M  2.10 %  0.79 % ora_ckpt_xxxxxxdg
7159 be/4 oracle        6.56 M      0.00 B  0.01 %  0.07 % oraclexxxxxxdg (LOCAL=NO)

--//對比可以發現在備庫上真正幹活的是dbw0,ckpt程式.

--//而單獨跟蹤備庫的dbw0程式:
# strace  -f   -p 1522 -e trace=io_submit  -tt
Process 1522 attached - interrupt to quit
09:53:29.280121 io_submit(46981453172736, 12, {{0x2abab87f24c0, 0, 1, 0, 260}, {0x2abab8aa2540, 0, 1, 0, 260}, {0x2abab87f3b20, 0, 1, 0, 260}, {0x2abab8a8b9a8, 0, 1, 0, 260}, {0x2abab8a236b8, 0, 1, 0, 260}, {0x2abab88dd958, 0, 1, 0, 260}, {0x2abab88a8718, 0, 1, 0, 260}, {0x2abab8b15b30, 0, 1, 0, 260}, {0x2abab8988e48, 0, 1, 0, 264}, {0x2abab8b2b068, 0, 1, 0, 264}, {0x2abab8c1c418, 0, 1, 0, 264}, {0x2abab8c55978, 0, 1, 0, 264}}) = 12
09:53:32.317414 io_submit(46981453172736, 26, {{0x2abab88159b8, 0, 1, 0, 260}, {0x2abab8c13840, 0, 1, 0, 260}, {0x2abab8ae7e68, 0, 1, 0, 260}, {0x2abab87f24c0, 0, 1, 0, 260}, {0x2abab8b2b068, 0, 1, 0, 260}, {0x2abab8ad2ec8, 0, 1, 0, 260}, {0x2abab8c1c418, 0, 1, 0, 264}, {0x2abab8a40c98, 0, 1, 0, 264}, {0x2abab88dd958, 0, 1, 0, 264}, {0x2abab8c65ac8, 0, 1, 0, 264}, {0x2abab8a236b8, 0, 1, 0, 264}, {0x2abab8988e48, 0, 1, 0, 264}, {0x2abab8b15b30, 0, 1, 0, 264}, {0x2abab8876cc8, 0, 1, 0, 264}, {0x2abab8a4bf98, 0, 1, 0, 264}, {0x2abab8a8b9a8, 0, 1, 0, 264}, {0x2abab87f3b20, 0, 1, 0, 264}, {0x2abab8c55978, 0, 1, 0, 264}, {0x2abab87cd968, 0, 1, 0, 264}, {0x2abab88c19d8, 0, 1, 0, 264}, {0x2abab8b09768, 0, 1, 0, 264}, {0x2abab87cb7d8, 0, 1, 0, 264}, {0x2abab8c84708, 0, 1, 0, 264}, {0x2abab8aa2540, 0, 1, 0, 264}, {0x2abab88a8718, 0, 1, 0, 264}, {0x2abab8ba9958, 0, 1, 0, 264}}) = 26
09:53:35.425030 io_submit(46981453172736, 51, {{0x2abab8977100, 0, 1, 0, 260}, {0x2abab88bd120, 0, 1, 0, 260}, {0x2abab8c94df0, 0, 1, 0, 260}, {0x2abab898aa40, 0, 1, 0, 260}, {0x2abab8a7c388, 0, 1, 0, 260}, {0x2abab87a4af0, 0, 1, 0, 260}, {0x2abab8a42e28, 0, 1, 0, 260}, {0x2abab8a9aa30, 0, 1, 0, 260}, {0x2abab8a24d18, 0, 1, 0, 260}, {0x2abab88dd958, 0, 1, 0, 260}, {0x2abab881f0c0, 0, 1, 0, 260}, {0x2abab8c84708, 0, 1, 0, 260}, {0x2abab89e8560, 0, 1, 0, 260}, {0x2abab8aa2540, 0, 1, 0, 260}, {0x2abab89caf80, 0, 1, 0, 260}, {0x2abab88159b8, 0, 1, 0, 260}, {0x2abab8c55978, 0, 1, 0, 262}, {0x2abab87cd968, 0, 1, 0, 262}, {0x2abab87f3b20, 0, 1, 0, 262}, {0x2abab87a8e10, 0, 1, 0, 264}, {0x2abab88c19d8, 0, 1, 0, 264}, {0x2abab8b2b068, 0, 1, 0, 264}, {0x2abab8a8b9a8, 0, 1, 0, 264}, {0x2abab8920b58, 0, 1, 0, 264}, {0x2abab87f24c0, 0, 1, 0, 264}, {0x2abab87cb7d8, 0, 1, 0, 264}, {0x2abab8ae7e68, 0, 1, 0, 264}, {0x2abab8c13840, 0, 1, 0, 264}, {0x2abab8ba9958, 0, 1, 0, 264}, {0x2abab8ade760, 0, 1, 0, 264}, {0x2abab87a7218, 0, 1, 0, 264}, {0x2abab8a4bf98, 0, 1, 0, 264}, {0x2abab8ad2ec8, 0, 1, 0, 264}, {0x2abab8c65ac8, 0, 1, 0, 264}, {0x2abab8876cc8, 0, 1, 0, 264}, {0x2abab8bc20e8, 0, 1, 0, 264}, {0x2abab8b97678, 0, 1, 0, 264}, {0x2abab8b86f90, 0, 1, 0, 264}, {0x2abab8b15b30, 0, 1, 0, 264}, {0x2abab8988e48, 0, 1, 0, 264}, {0x2abab88a8718, 0, 1, 0, 264}, {0x2abab8a236b8, 0, 1, 0, 264}, {0x2abab8b395c0, 0, 1, 0, 264}, {0x2abab8aec188, 0, 1, 0, 264}, {0x2abab8b0f0e8, 0, 1, 0, 264}, {0x2abab8b3e410, 0, 1, 0, 264}, {0x2abab89b54b0, 0, 1, 0, 264}, {0x2abab8b09768, 0, 1, 0, 264}, {0x2abab89141f8, 0, 1, 0, 264}, {0x2abab8bd7088, 0, 1, 0, 264}, {0x2abab8819cd8, 0, 1, 0, 264}}) = 51
Process 1522 detached
--//都是批次的寫入操作.

--//而單獨跟蹤主庫的dbw0程式:
# strace  -f   -p 3827 -e trace=io_submit  -tt
Process 3827 attached - interrupt to quit
09:56:20.831067 io_submit(47150328119296, 1, {{0x2ae20a596c68, 0, 1, 0, 264}}) = 1
09:56:20.843466 io_submit(47150328119296, 1, {{0x2ae20a596c68, 0, 1, 0, 264}}) = 1
09:56:20.851023 io_submit(47150328119296, 1, {{0x2ae20a596c68, 0, 1, 0, 264}}) = 1
09:56:20.861885 io_submit(47150328119296, 1, {{0x2ae20a596c68, 0, 1, 0, 264}}) = 1
09:56:26.848136 io_submit(47150328119296, 1, {{0x2ae20a596c68, 0, 1, 0, 264}}) = 1
09:56:41.886321 io_submit(47150328119296, 1, {{0x2ae20a596c68, 0, 1, 0, 264}}) = 1
09:56:41.919465 io_submit(47150328119296, 1, {{0x2ae20a596c68, 0, 1, 0, 260}}) = 1

--//可以發現備庫在應用日誌時存在大量的寫入操作.第2個引數數量一般都很大.

# man io_submit
IO_SUBMIT(2)               Linux Programmer's Manual              IO_SUBMIT(2)

NAME
       io_submit - Submit asynchronous I/O blocks for processing

SYNOPSIS
       #include <libaio.h>

       long io_submit (aio_context_t ctx_id, long nr, struct iocb **iocbpp);

DESCRIPTION
       io_submit() queues nr I/O request blocks for processing in the AIO context ctx_id. iocbpp should be an array of
       nr AIO request blocks, which will be submitted to context ctx_id.

RETURN VALUE
       io_submit() returns the number of iocbs submitted and 0 if nr is zero.