[20151111]跟蹤除錯rman.txt

[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);