[20151111]跟踪调试rman.txt
-- 上午查找在rman下执行list backup慢的问题,总结收集一些调试技巧,顺便在查看问题:
1.方法1,使用debug trace 参数:
--执行如下:
$ rman target / debug trace /tmp/aaa.txt
--为了显示的好看,我格式化其中一行.
DBGMISC: EXITED krmkgal with status Done [10:52:04.659] elapsed time [00:00:00:00.031]
DBGMISC: ENTERED krmkgal [10:52:04.659]
DBGSQL: TARGET>
DECLARE
thread NUMBER;
sequence NUMBER;
recid NUMBER;
alRec dbms_rcvman.alRec_t;
BEGIN
dbms_rcvman.getArchivedLog (alRec => alRec);
IF ( :rlscn = alRec.rlgSCN
AND :stopthr = alRec.thread
AND ( (alRec.sequence >= :stopseq AND :toclause = 0)
OR (alRec.sequence > :stopseq AND :toclause = 1)))
THEN
:flag := 1;
ELSE
:flag := 0;
:al_key:al_key_i := alRec.key;
:recid:recid_i := alRec.recid;
:stamp:stamp_i := alRec.stamp;
:thread := alRec.thread;
:sequence := alRec.sequence;
:fileName:fileName_i := alRec.fileName;
:lowSCN := alRec.lowSCN;
:lowTime := alRec.lowTime;
:nextSCN := alRec.nextSCN;
:nextTime := NVL (alRec.nextTime, TO_DATE ('12/31/9999', 'MM/DD/YYYY'));
:rlgSCN := alRec.rlgSCN;
:rlgTime := alRec.rlgTime;
:blocks := alRec.blocks;
:blockSize := alRec.blockSize;
:status := alRec.status;
:compTime:compTime_i := alRec.compTime;
:duplicate := alRec.duplicate;
:compressed:compressed_i := alRec.compressed;
:isrdf:isrdf_i := alRec.isrdf;
:stby := alRec.stby;
:terminal := alRec.terminal;
:site_key:site_key_i := alRec.site_key;
:source_dbid := alRec.source_dbid;
END IF;
END;
DBGSQL: sqlcode = 0
DBGSQL: B :flag = 0
DBGSQL: B :al_key = 5545
DBGSQL: B :recid = 5545
DBGSQL: B :stamp = 891060419
DBGSQL: B :thread = 1
DBGSQL: B :sequence = 3705
DBGSQL: B :fileName = NULL
DBGSQL: B :lowSCN = 13202585849
DBGSQL: B :lowTime = "2015-09-21 22:01:36"
DBGSQL: B :nextSCN = 13202624095
DBGSQL: B :nextTime = "2015-09-22 04:46:58"
DBGSQL: B :rlgSCN = 3011113647
DBGSQL: B :rlgTime = "2012-11-05 11:58:00"
DBGSQL: B :blocks = 75872
DBGSQL: B :blockSize = 512
DBGSQL: B :status = D
DBGSQL: B :compTime = "2015-09-22 04:46:59"
DBGSQL: B :duplicate = 0
DBGSQL: B :compressed = NO
DBGSQL: B :isrdf = NO
DBGSQL: B :stby = N
DBGSQL: B :terminal = NO
DBGSQL: B :site_key = 0
DBGSQL: B :source_dbid = 0
DBGSQL: B :rlscn = 3011113647
DBGSQL: B :stopthr = 0
DBGSQL: B :stopseq = 0
DBGSQL: B :toclause = 0
DBGRCVMAN: ENTERING getArchivedLog
DBGRCVMAN: getArchivedLog - resetscn=3011113647 thread=1 seq=3705 lowscn=13202585849 nextscn=13202624095 terminal=NO site_key_order_col=0 isrdf=NO stamp=891060419
DBGRCVMAN: getArchivedLogLast(translateArcLogSCNRange2) := local
DBGRCVMAN: getArchivedLogLast := local
DBGRCVMAN: EXITING getArchivedLog
DBGMISC: EXITED krmkgal with status Done [10:52:05.124] elapsed time [00:00:00:00.465]
DBGMISC: ENTERED krmkgal [10:52:05.124]
--上下对比时间10:52:04.659,10:52:05.124 ,说明单独执行一次需要: 5.124-4.659=0.465秒,真不知道为什么这么慢?
$ grep "DBGMISC: EXITED krmkgal with status Done" /tmp/aaa.txt
DBGMISC: EXITED krmkgal with status Done [15:55:15.831] elapsed time [00:00:00:00.007]
DBGMISC: EXITED krmkgal with status Done [15:55:16.283] elapsed time [00:00:00:00.452]
DBGMISC: EXITED krmkgal with status Done [15:55:16.778] elapsed time [00:00:00:00.495]
DBGMISC: EXITED krmkgal with status Done [15:55:17.249] elapsed time [00:00:00:00.470]
DBGMISC: EXITED krmkgal with status Done [15:55:17.726] elapsed time [00:00:00:00.477]
DBGMISC: EXITED krmkgal with status Done [15:55:18.197] elapsed time [00:00:00:00.470]
--而dg上执行相同的命令:
DBGMISC: EXITED krmkgal with status Done [15:52:31.585] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.588] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.591] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.594] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.598] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.601] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.604] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.607] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.611] elapsed time [00:00:00:00.003]
DBGMISC: EXITED krmkgal with status Done [15:52:31.614] elapsed time [00:00:00:00.003]
--两者执行时间上相差也太大.不过dg上的cpu,磁盘都强健许多,但是差距也太大.相差100倍以上.
2.使用10046跟踪:
--在rman下调用如下:
sql "alter session set events ''10046 trace name context forever, level 12''";
list backupset;
--也可以这样调用:
run
{
allocate channel c1 type disk ;
sql "alter session set events ''10046 trace name context forever, level 12''";
backup spfile;
##list backup;
release channel c1 ;
}
--不过奇怪的是不能run里面执行list backup的命令.
RMAN> run
2> {
3> list backup;
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-00558: error encountered while parsing input commands
RMAN-01009: syntax error: found "list": expecting one of: "advise, allocate, alter, backup, @, catalog, change,
configure, convert, copy, crosscheck, delete, duplicate, execute, flashback, host, mount, open, recover, release,
repair, report, restore, resync, send, set, show, shutdown, sql, startup, switch, transport, validate, "
RMAN-01007: at line 3 column 1 file: standard input
--但是执行如下,没有问题,真搞不懂oracle rman的语法.
run
{
report schema ;
}
总结:
--依旧无法定位,暂时放弃.上午的测试仅仅减少了循环的次数,但是每次的执行时间依旧不变,目前仅仅手工清除记录在控制文件的archivelog信息.
-- execute dbms_backup_restore.resetcfilesection(11);