Oracle11g物理STANDBY应用日志时进行增量备份导致10分钟等待
上一篇 / 下一篇 2008-01-06 23:51:23 / 个人分类:Bug
又是一个特别长的标题。实在是没有办法,问题发生的条件和版本、是否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
Total System Global Area 267825152 bytesITPUB个人空间F?#h-iuDm4p9j5o
Fixed Size 1299316 bytesITPUB个人空间9}!c yP~2G(a)s
Variable Size 167775372 bytesITPUB个人空间;K0wWk1k [,I
Database Buffers 96468992 bytesITPUB个人空间X.n3h5x
t%vF
Redo Buffers 2281472 bytes
e+CJ"LEZ0Database mounted.
G;b I'TcV0SQL> hostITPUB个人空间3G9E[8Mr n
[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: ORA
RMAN> backup tablespace users;
Starting backup at 19-DEC-07
4i#SIu~*T5ke6]T*v0using target database control file instead of recovery catalog
u6^C2\0zi0allocated channel: ORA_DISK_1
cUL| g6g[0channel ORA_DISK_1: SID=155 device type=DISK
_
}-mgBx0channel ORA_DISK_1: starting full datafile backup set
iBd!vl#h0a#r0channel ORA_DISK_1: specifying datafile(s) in backup set
D^y
h8wB^0input datafile file number=00004 name=/data/oracle/oradata/ora
g3s7ce|-AN0channel ORA_DISK_1: starting piece 1 at 19-DEC-07
*_V)Wm8P)R0channel ORA_DISK_1: finished piece 1 at 19-DEC-07ITPUB个人空间)a,h*];Y+}?.~
piece handle=/data1/backup/1uj3vsf6_1_1 tag=TAG20071219T085502 comment=NONEITPUB个人空间e1RFi;]
xk
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01ITPUB个人空间&S0F5WkP![
Finished backup at 19-DEC-07
RMAN> backup incremental level 0 tablespace users;
Starting backup at 19-DEC-07ITPUB个人空间 U$Y%V
JSIRZ
using channel ORA_DISK_1ITPUB个人空间s_*F:V'F/}%?Q
channel ORA_DISK_1: starting incremental level 0 datafile backup setITPUB个人空间+B~
e'?2V$CR
channel ORA_DISK_1: specifying datafile(s) in backup setITPUB个人空间
ud$b^'Z |[
input datafile file number=00004 name=/data/oracle/oradata/ora
channel ORA_DISK_1: starting piece 1 at 19-DEC-07ITPUB个人空间%[4G@KR
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
-JA!`HE&Pe!u,P;O0piece handle=/data1/backup/1vj3vsfi_1_1 tag=TAG20071219T085514 comment=NONEITPUB个人空间YF.d1C(Eb
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01ITPUB个人空间
N$}H%X\`
Finished backup at 19-DEC-07
RMAN> list backup;
ITPUB个人空间/u)N)G#qJ'w!x
List of Backup SetsITPUB个人空间-e.vH5L.Q0B)Z:J'[o
===================
]0V|5Z)q Ff0BS Key Type LV Size Device Type Elapsed Time Completion TimeITPUB个人空间T$G-i}8LAn
------- ---- -- ---------- ----------- ------------ ---------------
P~O4F"J]8B#v!bC0c052 Full
BP Key: 54 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085502
!a+uY.aRX0 Piece Name: /data1/backup/1uj3vsf6_1_1
R,^9G7sxL q~0 List of Datafiles in backup set 52
I/g }nzE#c
o
nt,d0 File LV Type Ckp SCN Ckp Time NameITPUB个人空间1F.\L!`P6IZ9ZB
---- -- ---- ---------- --------- ----
3f"VUUEu'@0 4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora
BS Key Type LV Size Device Type Elapsed Time Completion Time
8XV4cQZR h0------- ---- -- ---------- ----------- ------------ ---------------ITPUB个人空间f)E_B^c
53 Incr 0
:P]%V,G8AOx$b0 BP Key: 55 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085514
1b/O3X.Zo_e;m o0 Piece Name: /data1/backup/1vj3vsfi_1_1ITPUB个人空间r*ffYZ+H z2s;G#s
List of Datafiles in backup set 53ITPUB个人空间"G(ih.Y4Zi!_;FbH2Q
File LV Type Ckp SCN Ckp Time Name
+X9N W
|gjAu$~#z?0 ---- -- ---- ---------- --------- ----ITPUB个人空间BHa%g{p[0@D
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora
RMAN> delete noprompt backup;
using channel ORA_DISK_1
List of Backup Pieces
1ah!j%m&zu\0BP Key BS Key Pc# Cp# Status Device Type Piece NameITPUB个人空间9S0Ctm q Tm
------- ------- --- --- ----------- ----------- ----------
UV7v9J?G!Qy u054 52 1 1 AVAILABLE DISK /data1/backup/1uj3vsf6_1_1
]H\#\f(yL1Vz055 53 1 1 AVAILABLE DISK /data1/backup/1vj3vsfi_1_1ITPUB个人空间4^;q+uD9b!Vr]%yy
deleted backup piece
C H`)lP)YReu0backup piece handle=/data1/backup/1uj3vsf6_1_1 RECID=54 STAMP=641724902ITPUB个人空间LD4hK"w;~%Q&j5S
deleted backup piece
hv{q6\?V0backup piece handle=/data1/backup/1vj3vsfi_1_1 RECID=55 STAMP=641724929
+x0[+z@zu&D4D0Deleted 2 objects
0fZ8\Ew'R7?0Y'S0RMAN> exit
??cej8[5`0Recovery Manager complete.ITPUB个人空间c.\)E Ng
E
[oracle@yangtk2 ~]$ exit
*_n6\'{3?
@*q4B$TGC0exit
SQL> alter database recover managed standby database disconnect from session;
Database altered.
SQL> hostITPUB个人空间2o0_^Nbl HZI
[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: ORA
RMAN> backup tablespace users;
Starting backup at 19-DEC-07
3[k6\at(t0using target database control file instead of recovery catalog
XDonL%YQbr0allocated channel: ORA_DISK_1
L4nV{7JM0channel ORA_DISK_1: SID=140 device type=DISK
(N$LDslQ%h0channel ORA_DISK_1: starting full datafile backup set
I|s q0\(BG
O$Pg0channel ORA_DISK_1: specifying datafile(s) in backup set
-~+r(s0~_Ti
f0B0input datafile file number=00004 name=/data/oracle/oradata/ora
channel ORA_DISK_1: starting piece 1 at 19-DEC-07ITPUB个人空间ok1Ab^N
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
+@S\2}I*m%SW&Z0piece handle=/data1/backup/20j3vsh9_1_1 tag=TAG20071219T085609 comment=NONE
YR~9P}"[\"b;fT0channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01ITPUB个人空间%HqBs v2?Sm
Finished backup at 19-DEC-07
RMAN> backup incremental level 0 tablespace users;
Starting backup at 19-DEC-07ITPUB个人空间ZPuiaI9z pR
using channel ORA_DISK_1
上面给出的测试是众多测试中比较有代表型的,选择了不同备份和增量备份不应用日志的情况下和应用日志情况下的对比。
在最后这种情况,STANDBY应用日志的时候执行增量备份,问题重现了。发出增量备份命令后,发生了等待现象。用sqlplus登陆数据库,检查等待事件:
SQL> SELECT SID, MODULE FROM V$SESSION WHERE USERNAME IS NOT NULL;
SID MODULEITPUB个人空间uw2UF-NLir-A
---------- ------------------------------------------------
4\6?nZ$So1^V0 138 sqlplus@yangtk2.ytk-thinkpad (TNS V1-V3)ITPUB个人空间r-H$u([kW
140 backup incr datafile
(z0q
i5~z:e1~~0 141 rman@yangtk2.ytk-thinkpad (TNS V1-V3)ITPUB个人空间6ANH5x+u+Fp8e(_
155 rman@yangtk2.ytk-thinkpad (TNS V1-V3)ITPUB个人空间qVhf"V|1v9L z6U
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_WAITITPUB个人空间:tz*W3O1Q-w
gx
---------- ------------------------------------------ ---------------ITPUB个人空间G!q\UL%~4}
140 control file sequential read 375
SQL> SELECT SID, EVENT, SECONDS_IN_WAIT FROM V$SESSION WHERE SID = 140;
SID EVENT SECONDS_IN_WAIT
!oG|%nf[0b!y0---------- ------------------------------------------ ---------------ITPUB个人空间k};sI$Wl}5U
a9f
140 control file sequential read 560
SQL> SELECT SID, EVENT, SECONDS_IN_WAIT FROM V$SESSION WHERE SID = 140;
SID EVENT SECONDS_IN_WAIT
U"u/m}IsB*d0---------- ------------------------------------------ ---------------ITPUB个人空间N.o&{r4A%}a^,M
140 SQL*Net message from client 28
等待600秒后,等待事件结束,备份开始执行:
channel ORA_DISK_1: starting incremental level 0 datafile backup setITPUB个人空间"G%wO`x-@8tp0@NQ7i
channel ORA_DISK_1: specifying datafile(s) in backup setITPUB个人空间`2L2u
iQb/p6W
input datafile file number=00004 name=/data/oracle/oradata/ora
8B)jDKT\5Xpu0channel ORA_DISK_1: starting piece 1 at 19-DEC-07ITPUB个人空间$Rcm u%xRB` Ro9A
channel ORA_DISK_1: finished piece 1 at 19-DEC-07ITPUB个人空间ii2g(k
t
piece handle=/data1/backup/21j3vshk_1_1 tag=TAG20071219T085620 comment=NONE
!i?v ] _&Vi
f0channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01ITPUB个人空间Th;BD)D'ut C
Finished backup at 19-DEC-07
RMAN> list backup;
ITPUB个人空间~*J#];h2r6lYd.] _2v
List of Backup Sets
9l@l`'}HO5TP0===================
ITPUB个人空间e|(ei`!}
_Bb
BS Key Type LV Size Device Type Elapsed Time Completion TimeITPUB个人空间IF:@#W8`&@u5aT
------- ---- -- ---------- ----------- ------------ ---------------
[N ms5m054 Full
BP Key: 56 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085609
C2OCFYXe B+^0 Piece Name: /data1/backup/20j3vsh9_1_1
XUj:]^0~1h0 List of Datafiles in backup set 54
7G#nh
]t0 File LV Type Ckp SCN Ckp Time NameITPUB个人空间DQou8mf.J5u+DH
---- -- ---- ---------- --------- ----ITPUB个人空间}7iyv'oJ R
4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora
BS Key Type LV Size Device Type Elapsed Time Completion Time
1H!MvN Ay3P;kv0------- ---- -- ---------- ----------- ------------ ---------------ITPUB个人空间8Z,|k7x G6Po
55 Incr 0
)F%V)P_&y$x0 BP Key: 57 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085620ITPUB个人空间]5OfR*]"A
Piece Name: /data1/backup/21j3vshk_1_1ITPUB个人空间n L wN1ew!L!u)]
List of Datafiles in backup set 55ITPUB个人空间
c"WF
mL z8^L
File LV Type Ckp SCN Ckp Time Name
iQbA2N0 ---- -- ---- ---------- --------- ----
/I:Z6Y)p0Y;i0 4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora
从备份的执行时间Elapsed Time中也可以看到,RMAN在这里等待了10分钟,感觉这10分钟是一个超时阈值,超过10分钟后,等待超时,备份继续执行。
下面的测试发现,问题还与BLOCK CHANGE TRACKING有关:
RMAN> list backup;
ITPUB个人空间5J)Yrc)dWu+Z PR7`
List of Backup Sets
F$UB`^n'e#|M9Y\0===================
!|mM:ScWqwA'nV0BS Key Type LV Size Device Type Elapsed Time Completion TimeITPUB个人空间z%ttJm[ z7N!yk
------- ---- -- ---------- ----------- ------------ ---------------
HA BYY)N:m#S054 Full
BP Key: 56 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085609ITPUB个人空间n2z4I`%x.}
Piece Name: /data1/backup/20j3vsh9_1_1ITPUB个人空间 RJ0qR ^q8{s
List of Datafiles in backup set 54ITPUB个人空间2]3z)ntU0vJs L
File LV Type Ckp SCN Ckp Time Name
-l
I[$B'q
Mc0 ---- -- ---- ---------- --------- ----
8^i,`.{;s5\t&[0 4 Full 4748472 24-NOV-07 /data/oracle/oradata/ora
BS Key Type LV Size Device Type Elapsed Time Completion TimeITPUB个人空间v8o2^
F6A} a!W3e"Q
------- ---- -- ---------- ----------- ------------ ---------------ITPUB个人空间y(j }x$n:Z2s
55 Incr 0
BP Key: 57 Status: AVAILABLE Compressed: NO Tag: TAG20071219T085620ITPUB个人空间%XHRRTlBg?4C0H
Piece Name: /data1/backup/21j3vshk_1_1ITPUB个人空间0n4Uk#hF^v
?
List of Datafiles in backup set 55ITPUB个人空间n(l&`1^z2NI{
File LV Type Ckp SCN Ckp Time Name
6TlIX.kR0 ---- -- ---- ---------- --------- ----ITPUB个人空间w3x:x6F)B/u4Er+E2^:c
4 0 Incr 4748472 24-NOV-07 /data/oracle/oradata/ora
RMAN> delete noprompt backup;
using channel ORA_DISK_1
List of Backup PiecesITPUB个人空间9axM6C2w6I u
BP Key BS Key Pc# Cp# Status Device Type Piece Name
,`v*[ Nz8A)w yK}0------- ------- --- --- ----------- ----------- ----------ITPUB个人空间/|X
S$J/c @/^T5s'f
56 54 1 1 AVAILABLE DISK /data1/backup/20j3vsh9_1_1
W}e)}KZh6t/]057 55 1 1 AVAILABLE DISK /data1/backup/21j3vshk_1_1
pq$Hz1m&l"SR2A0deleted backup pieceITPUB个人空间wO
Y C3w`x5Q
y
backup piece handle=/data1/backup/20j3vsh9_1_1 RECID=56 STAMP=641724969ITPUB个人空间^sA+_-m1{:\1xG-F
deleted backup piece
:C3zm3v3^p*s0backup piece handle=/data1/backup/21j3vshk_1_1 RECID=57 STAMP=641725580
2C ]:h{ea"|0Deleted 2 objects
ITPUB个人空间8g6`2ZZ6a$Sf(W
RMAN> exit
MnY2B5I.M+ZF~0Recovery Manager complete.ITPUB个人空间Pf*i6X`qb}:d
[oracle@yangtk2 ~]$ exitITPUB个人空间'U9c*U^
{&r"{
exit
SQL> alter database disable block change tracking;
Database altered.
SQL> exitITPUB个人空间 S;r;BG,krZM
Disconnected from Oracle Database
With the Partitioning, OLAP, Data Mining and Real Application Testing options
6rY J:Oe;IJ-zJ4P0[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: ORA
RMAN> backup tablespace users;
Starting backup at 19-DEC-07ITPUB个人空间:{Qw#u(O"d.w.V
using target database control file instead of recovery catalog
J.E[H#~U0allocated channel: ORA_DISK_1
e$E|p#X1Y0channel ORA_DISK_1: SID=143 device type=DISKITPUB个人空间 }\
iP1Va;dCZJ
channel ORA_DISK_1: starting full datafile backup set
(JT,}lw#Zz0channel ORA_DISK_1: specifying datafile(s) in backup set
&rW~gs9U0input datafile file number=00004 name=/data/oracle/oradata/ora
X!NQgZ2bu9or*Ps W0channel ORA_DISK_1: starting piece 1 at 19-DEC-07ITPUB个人空间3Y'_T6y+qh(Q
channel ORA_DISK_1: finished piece 1 at 19-DEC-07ITPUB个人空间!n$I3QR"l&Dxot
piece handle=/data1/backup/22j4010p_1_1 tag=TAG20071219T101241 comment=NONEITPUB个人空间%|ET%G[;rdI
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01ITPUB个人空间mR(DE
JQCc
Finished backup at 19-DEC-07
RMAN> backup cumulative incremental level 0 tablespace users;
Starting backup at 19-DEC-07ITPUB个人空间&pD3lih.b|JI@
using channel ORA_DISK_1ITPUB个人空间IX!A[ } g
channel ORA_DISK_1: starting incremental level 0 datafile backup setITPUB个人空间;`-HE yI:g#NY!a
channel ORA_DISK_1: specifying datafile(s) in backup set
M[l&rY*R}M2U0input datafile file number=00004 name=/data/oracle/oradata/ora
Xx
h7`o0channel ORA_DISK_1: starting piece 1 at 19-DEC-07ITPUB个人空间
lB+f-]$B2a7IU
channel ORA_DISK_1: finished piece 1 at 19-DEC-07
a&SB6`4_3C+B&y"D0piece handle=/data1/backup/23j
;oR2t~f$f;P;W$m0channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
']H1b3p!P8P,F0Finished backup at 19-DEC-07
RMAN> backup incremental level 0 tablespace users;
Starting backup at 19-DEC-07
D,?1pE-]RC
[9fp0using channel ORA_DISK_1ITPUB个人空间qNz!_JS
channel ORA_DISK_1: starting incremental level 0 datafile backup set
n*K-w(HHk
J0Y0channel ORA_DISK_1: specifying datafile(s) in backup set
-?(b/o3Y
]t'g4FD'u0input datafile file number=00004 name=/data/oracle/oradata/ora
channel ORA_DISK_1: starting piece 1 at 19-DEC-07
f V,h1z X2g0channel ORA_DISK_1: finished piece 1 at 19-DEC-07
J:iR&os)fcrC$`0piece handle=/data1/backup/24j40178_1_1 tag=TAG20071219T101607 comment=NONE
Z)iP'U(}I0channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
&MsKWIUlx2]0Finished backup at 19-DEC-07
RMAN> list backup;
ITPUB个人空间!DkK E1lHz{!|)|
List of Backup Sets
M1Ay(H-uD
k0===================
ITPUB个人空间jls)L!`L
BS Key Type LV Size Device Type Elapsed Time Completion Time
4t6o
H#q'J(Pb'b&b2j0------- ---- -- ---------- ----------- ------------ ---------------ITPUB个人空间?1k&v&f