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部落格 ” ，連結：http://blog.itpub.net/4227/viewspace-103786/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- Oracle11g物理STANDBY開啟模式應用歸檔時無法執行備份Oracle模式
- Standby_file_management引數導致日誌無法應用
- TSM備份時因歸檔日誌丟失而導致備份失敗
- compatible相容引數不正確導致DG物理備庫不能應用日誌應用日誌
- mysqldump全量備份+mysqlbinlog二進位制日誌增量備份MySql
- 誤刪歸檔日誌除導致備份歸檔日誌失敗
- 建立測試物理Standby日誌
- dataguard之物理standby 日誌切換
- Backup And Recovery User's Guide-進行增量備份-進行VSS快照的增量備份（略）GUIIDE
- Oracle 11g Data Guard 物理備庫開啟日誌延時應用流程Oracle
- Backup And Recovery User's Guide-建立和更新增量備份-進行增量備份GUIIDE
- Oracle 11g物理備庫出現壞塊，導致歸檔日誌應用報錯（ORA-10562、ORA-01110）Oracle
- MySQL 定時增量備份MySql
- 基於Linux指令碼，對日誌進行定時壓縮備份Linux指令碼
- 用RMAN備份歸檔日誌時檢查歸檔日誌是否存在
- Linux作業系統啟動時自動啟用oracle standby備庫日誌應用Linux作業系統Oracle
- 在rman中如果有增量備份的話恢復時系統不會找歸檔日誌進行恢復
- Oracle11g Data Guard 暫停物理備庫的日誌傳輸Oracle
- 使用RMAN增量備份前滾STANDBY資料庫資料庫
- 實時備份mysql binlog日誌MySql
- RMAN關於物理檔案copy的增量備份
- 【Azure 應用服務】備份網站時由於檔案太大了，導致應用服務備份失敗。如何解決？網站
- Data Guard備庫日誌的實時應用與非實時應用
- SQL Server 2008進行備份事務日誌SQLServer
- 事務日誌備份檔案達到 47G 大小，啥原因導致 ？
- 使用 xtrabackup 進行MySQL資料庫物理備份MySql資料庫
- Data Guard 之RMAN備份線上搭建物理standby
- rman備份後為什麼要同時備份歸檔日誌
- 備份策略 增量備份中的差異備份：週日和週三執行0級備份，其他每天執行1級備份
- Oracle11g的Dataguard測試，建立物理備庫(Physical Standby Database)OracleDatabase
- 手工刪除歸檔日誌導致RMAN備份時報ORA-19625錯誤
- DG-備庫日誌的應用遲時檢查
- [重慶思莊每日技術分享]-由於備庫閃回區過小導致的備庫無法實時應用日誌應用日誌
- 備份之歸檔重做日誌備份
- 備份歸檔日誌
- sqlserver的日誌備份SQLServer
- 配置Oracle11g的Dataguard測試，建立物理備庫(Physical Standby Database)OracleDatabase
- Oracle之差異增量備份與累積增量備份Oracle