Oracle11g物理STANDBY应用日志时进行增量备份导致10分钟等待
又是一个特别长的标题。实在是没有办法，问题发生的条件和版本、是否STANDBY数据库、STANDBY数据库状态以及备份类型都有关系，不这样描述无法说清楚问题。
问题的发现是备份的时候等待时间很长，RMAN接受命令后等待了很长的时间也没有开始真正备份，等了10分钟左右备份才开始。从数据库中检查Oracle的等待事件为：control file sequential read。
问题出现的时候情况比较复杂：数据库版本Oracle 11.1.0.6 for Enterprise Linux 5 for X86，部署了物理STANDBY环境。当前是在物理STANDBY数据库中测试BLOCK CHANGE TRACKING对增量备份的影响。STANDBY数据库的应用日志是开启的。而且数据库之前已经执行过不少复杂的造成，例如数据库启用日志的应用、关闭日志应用等。
上面的任何的一种或多种条件都可能是造成问题的原因，因此进行了大量的测试，每次只变动其中的一个条件，来检测问题是否存在，通过这种方式来定位问题的原因。
最后终于重现了这个问题：
[oracle@yangtk2 ~]$ sqlplus "/ as sysdba"
SQL*Plus: Release 11.1.0.6.0 - Production on Wed Dec 19 08:54:26 2007
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Connected to an idle instance.
SQL> startup mount
ORACLE instance started.
Total System Global Area 267825152 bytes
Fixed Size 1299316 bytes
Variable Size 167775372 bytes
Database Buffers 96468992 bytes
Redo Buffers 2281472 bytes
Database mounted.
SQL> host
[oracle@yangtk2 ~]$ rman target /
Recovery Manager: Release 11.1.0.6.0 - Production on Wed Dec 19 08:54:57 2007
Copyright (c) 1982, 2007, Oracle. All rights reserved.
connected to target database: ORA11G (DBID=4026820313, not open)
RMAN> backup tablespace users;
Starting backup at 19-DEC-07
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=155 device type=DISK
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/1uj3vsf6_1_1 tag=TAG20071219T085502 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> backup incremental level 0 tablespace users;
Starting backup at 19-DEC-07
using channel ORA_DISK_1
channel ORA_DISK_1: starting incremental level 0 datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/1vj3vsfi_1_1 tag=TAG20071219T085514 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> list backup;
List of Backup Sets
===================
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
52 Full 8.23M DISK 00:00:01 19-DEC-07
BP Key: 54 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085502
Piece Name: /data1/backup/1uj3vsf6_1_1
List of Datafiles in backup set 52
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
53 Incr 0 8.23M DISK 00:00:16 19-DEC-07
BP Key: 55 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085514
Piece Name: /data1/backup/1vj3vsfi_1_1
List of Datafiles in backup set 53
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
RMAN> delete noprompt backup;
using channel ORA_DISK_1
List of Backup Pieces
BP Key BS Key Pc# Cp# Status Device Type Piece Name
------- ------- --- --- ----------- ----------- ----------
54 52 1 1 AVAILABLE DISK /data1/backup/1uj3vsf6_1_1
55 53 1 1 AVAILABLE DISK /data1/backup/1vj3vsfi_1_1
deleted backup piece
backup piece handle=/data1/backup/1uj3vsf6_1_1 RECID=54 STAMP=641724902
deleted backup piece
backup piece handle=/data1/backup/1vj3vsfi_1_1 RECID=55 STAMP=641724929
Deleted 2 objects
RMAN> exit
Recovery Manager complete.
[oracle@yangtk2 ~]$ exit
exit
SQL> alter database recover managed standby database disconnect from session;
Database altered.
SQL> host
[oracle@yangtk2 ~]$ rman target /
Recovery Manager: Release 11.1.0.6.0 - Production on Wed Dec 19 08:56:03 2007
Copyright (c) 1982, 2007, Oracle. All rights reserved.
connected to target database: ORA11G (DBID=4026820313, not open)
RMAN> backup tablespace users;
Starting backup at 19-DEC-07
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=140 device type=DISK
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/20j3vsh9_1_1 tag=TAG20071219T085609 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> backup incremental level 0 tablespace users;
Starting backup at 19-DEC-07
using channel ORA_DISK_1
上面给出的测试是众多测试中比较有代表型的，选择了不同备份和增量备份不应用日志的情况下和应用日志情况下的对比。
在最后这种情况，STANDBY应用日志的时候执行增量备份，问题重现了。发出增量备份命令后，发生了等待现象。用sqlplus登陆数据库，检查等待事件：
SQL> SELECT SID, MODULE FROM V$SESSION WHERE USERNAME IS NOT NULL;
SID MODULE
---------- ------------------------------------------------
138 sqlplus@yangtk2.ytk-thinkpad (TNS V1-V3)
140 backup incr datafile
141 rman@yangtk2.ytk-thinkpad (TNS V1-V3)
155 rman@yangtk2.ytk-thinkpad (TNS V1-V3)
170 sqlplus@yangtk2.ytk-thinkpad (TNS V1-V3)
SQL> SELECT SID, EVENT, SECONDS_IN_WAIT FROM V$SESSION WHERE SID = 140;
SID EVENT SECONDS_IN_WAIT
---------- ------------------------------------------ ---------------
140 control file sequential read 375
SQL> SELECT SID, EVENT, SECONDS_IN_WAIT FROM V$SESSION WHERE SID = 140;
SID EVENT SECONDS_IN_WAIT
---------- ------------------------------------------ ---------------
140 control file sequential read 560
SQL> SELECT SID, EVENT, SECONDS_IN_WAIT FROM V$SESSION WHERE SID = 140;
SID EVENT SECONDS_IN_WAIT
---------- ------------------------------------------ ---------------
140 SQL*Net message from client 28
等待600秒后，等待事件结束，备份开始执行：
channel ORA_DISK_1: starting incremental level 0 datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/21j3vshk_1_1 tag=TAG20071219T085620 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> list backup;
List of Backup Sets
===================
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
54 Full 8.23M DISK 00:00:00 19-DEC-07
BP Key: 56 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085609
Piece Name: /data1/backup/20j3vsh9_1_1
List of Datafiles in backup set 54
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
55 Incr 0 8.23M DISK 00:10:01 19-DEC-07
BP Key: 57 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085620
Piece Name: /data1/backup/21j3vshk_1_1
List of Datafiles in backup set 55
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
从备份的执行时间Elapsed Time中也可以看到，RMAN在这里等待了10分钟，感觉这10分钟是一个超时阈值，超过10分钟后，等待超时，备份继续执行。
下面的测试发现，问题还与BLOCK CHANGE TRACKING有关：
RMAN> list backup;
List of Backup Sets
===================
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
54 Full 8.23M DISK 00:00:00 19-DEC-07
BP Key: 56 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085609
Piece Name: /data1/backup/20j3vsh9_1_1
List of Datafiles in backup set 54
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
55 Incr 0 8.23M DISK 00:10:01 19-DEC-07
BP Key: 57 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085620
Piece Name: /data1/backup/21j3vshk_1_1
List of Datafiles in backup set 55
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
RMAN> delete noprompt backup;
using channel ORA_DISK_1
List of Backup Pieces
BP Key BS Key Pc# Cp# Status Device Type Piece Name
------- ------- --- --- ----------- ----------- ----------
56 54 1 1 AVAILABLE DISK /data1/backup/20j3vsh9_1_1
57 55 1 1 AVAILABLE DISK /data1/backup/21j3vshk_1_1
deleted backup piece
backup piece handle=/data1/backup/20j3vsh9_1_1 RECID=56 STAMP=641724969
deleted backup piece
backup piece handle=/data1/backup/21j3vshk_1_1 RECID=57 STAMP=641725580
Deleted 2 objects
RMAN> exit
Recovery Manager complete.
[oracle@yangtk2 ~]$ exit
exit
SQL> alter database disable block change tracking;
Database altered.
SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@yangtk2 ~]$ rman target /
Recovery Manager: Release 11.1.0.6.0 - Production on Wed Dec 19 10:12:37 2007
Copyright (c) 1982, 2007, Oracle. All rights reserved.
connected to target database: ORA11G (DBID=4026820313, not open)
RMAN> backup tablespace users;
Starting backup at 19-DEC-07
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=143 device type=DISK
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/22j4010p_1_1 tag=TAG20071219T101241 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> backup cumulative incremental level 0 tablespace users;
Starting backup at 19-DEC-07
using channel ORA_DISK_1
channel ORA_DISK_1: starting incremental level 0 datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/23j4016g_1_1 tag=TAG20071219T101543 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> backup incremental level 0 tablespace users;
Starting backup at 19-DEC-07
using channel ORA_DISK_1
channel ORA_DISK_1: starting incremental level 0 datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/24j40178_1_1 tag=TAG20071219T101607 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> list backup;
List of Backup Sets
===================
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
56 Full 8.23M DISK 00:00:01 19-DEC-07
BP Key: 58 Status: AVAILABLE Compressed: NO Tag: TAG20071219T101241
Piece Name: /data1/backup/22j4010p_1_1
List of Datafiles in backup set 56
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
57 Incr 0 8.23M DISK 00:00:15 19-DEC-07
BP Key: 59 Status: AVAILABLE Compressed: NO Tag: TAG20071219T101543
Piece Name: /data1/backup/23j4016g_1_1
List of Datafiles in backup set 57
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
58 Incr 0 8.23M DISK 00:00:15 19-DEC-07
BP Key: 60 Status: AVAILABLE Compressed: NO Tag: TAG20071219T101607
Piece Name: /data1/backup/24j40178_1_1
List of Datafiles in backup set 58
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
再次ENABLE BLOCK CHANGE TRACKING，问题重现，看来问题和11G的物理STANDBY的BLOCK CHANGE TRACKING特性有关。
[oracle@yangtk2 ~]$ sqlplus "/ as sysdba"
SQL*Plus: Release 11.1.0.6.0 - Production on Wed Dec 19 10:18:22 2007
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> alter database enable block change tracking using file '/data1/track.trc';
Database altered.
SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@yangtk2 ~]$ rman target /
Recovery Manager: Release 11.1.0.6.0 - Production on Wed Dec 19 10:18:54 2007
Copyright (c) 1982, 2007, Oracle. All rights reserved.
connected to target database: ORA11G (DBID=4026820313, not open)
RMAN> backup tablespace users;
Starting backup at 19-DEC-07
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=155 device type=DISK
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/25j401cl_1_1 tag=TAG20071219T101901 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> backup cumulative incremental level 0 tablespace users;
Starting backup at 19-DEC-07
using channel ORA_DISK_1
channel ORA_DISK_1: starting incremental level 0 datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
piece handle=/data1/backup/26j401dc_1_1 tag=TAG20071219T101923 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 19-DEC-07
RMAN> list backup;
List of Backup Sets
===================
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
59 Full 8.23M DISK 00:00:00 19-DEC-07
BP Key: 61 Status: AVAILABLE Compressed: NO Tag: TAG20071219T101901
Piece Name: /data1/backup/25j401cl_1_1
List of Datafiles in backup set 59
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
BS Key Type LV Size Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
60 Incr 0 8.23M DISK 00:10:00 19-DEC-07
BP Key: 62 Status: AVAILABLE Compressed: NO Tag: TAG20071219T101923
Piece Name: /data1/backup/26j401dc_1_1
List of Datafiles in backup set 60
File LV Type Ckp SCN Ckp Time Name
---- -- ---- ---------- --------- ----
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora11g/ORA11G_P/datafile/o1_mf_users_3d37bq45_.dbf
目前还没有在Metalink上发现这个问题的类似描述。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/4227/viewspace-3144195/ ，如需转载，请注明出处，否则将追究法律责任。
