As you (should) know, Oracle introduced the concept of the block change tracking file a while back (v10) to help shorten the length of time taken to perform an incremental backup. Their implementation is quite simple – record the file_ID and block ID for each block that gets changed by a transaction in a dedicated file and then instead of scanning every data file for changed blocks (based on SCN headers) during an incremental backup, just the use block change tracking file as an index containing pointers of all the changed blocks to be backed up. A significant boost in efficiency and reduction in resources required to perform a backup. Not to mention time.
A colleague has a database with a 3TB datafile (this might be sounding familiar by now) and noticed that this database goes through around 1TB of redo logs per day. Remembering that a level 1 backup can only use one thread for a BIGFILE tablespace and that block change tracking has been enabled, it’s curious to see that a single channel can still take 12+ hours.
The regular RMAN script output doesn’t provide any really interesting clues; for that we have to delve deeper. It may surprise some, but RMAN is just like many other Oracle processes – you can trace it. Let’s get started
[oracle@exadb01 ~]$ rman target / debug trace=rman.trc log=rman.log RMAN> set echo on; RMAN> sql "alter system set max_dump_file_size=UNLIMITED"; RMAN> sql "alter session set events ''10046 trace name context forever, level 12''"; RMAN> backup incremental level 1 tablespace partitioned_data; RMAN> exit
Note that I had to remember to type exit because all output was directed into my log file (or you could wait here all day if you don’t notice the prompt reappear). The trace commands should look very familiar.
What you end up with here will be a rman.trc file, a rman.log file and in your trace directory for the database, a number of trace files (you should find one per channel). What we’re looking for is anything to do with block change tracking. If you’ve kept on top of trace file management, a simple ‘grep “change tracking” *trc’ should suffice. Having found the file, let’s see what it’s doing.
krbiwtrc : (icdstart - Action set to 0000011 STARTED9) *** MODULE NAME:(backup incr datafile) 2015-02-10 13:03:45.610 *** ACTION NAME:(0000011 STARTED9) 2015-02-10 13:03:45.610 Got krbibsdf ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ +++ Backup conversation started +++ +++ type: 1 incremental: 1 level_null: 0 +++ +++ level: 1 nochecksum: 0 logical: 0 +++ +++ copyc: 0 convertto: 0 convertfr: 0 +++ +++ sameendian: 0 nocatalog: 0 validate: 0 +++ +++ pltfrmto: 0 pltfrmfr: 0 convertdb: 0 +++ +++ keep_options: 0 +++ +++ keep_until: 0 +++ +++ tag: TAG20150210T130344 +++ ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ krbbcb - Returning; x->stamp_krbbx=871304625, x->count_krbbx=25055 *** ACTION NAME:(0000011 FINISHED9) 2015-02-10 13:03:45.651 <removed for "brevity"> krbbhdr - Piece will have hard block numbers krbbhdr - Piece will be compressed using BASIC 11.2 algorithm krbbhdr - header; x->pieceno_krbbx=1, ph->filecnt_krbph=1, ph->dircnt_krbph=1 krbb1de - Placing file 32 in directory, flags= 0 krbbhdr - directory; filled=1, pr->count_krbpr=1, pr->size_krbpr=196, pr->offset_krbpr=28 krbDiskBufsiz; stripe_size=0, stripe_disk=0, *bufsize=0, *bufcnt=0 krbdralc - obtained ksfq context (0): 0x2ab1202007c0 krbdralc; pkrbdc->bufsize_krbdc=1048576, pkrbdc->bufcnt_krbdc=4 krbbtgb - Done with auxiliary thread, nxtblk: 02ab120678908, end: 02ab120678908 krbb1po - Trying to use change tracking for file +DATA/xxx/datafile/partitioned_data.281.871279997, as level: 1 and ckpscn: 375901027103 > incscn: 375854109700 krbb1po - Using change tracking for datafile; f->name_krbbf=+DATA/xxx/datafile/partitioned_data.281.871279997 krbb1po - ending krbbnbf - entering; fno=32, *bno=1, fd->gnb_bno_krbbfd=1, fd->gnb_bct_krbbfd=1, lastblk=262272 krbbnbf - Using change tracking file to speed up backup; fno=32 krbbnbf - non SAGE alignment; bbuf=512, readalnz=4194304 krbbnbf - ready with; fno=32, lbno=1, lbct=511, fd->gnb_bno_krbbfd=512, fd->gnb_bct_krbbfd=245256 krbavblk added; vblk->bno_krbvblk=1, vblk->count_krbvblk=511, vblk->eof_krbvblk=0 krbbnbf - krbavblk called; fno=32, *bno=1, *bct=511, f->blocks_read_krbbf=0 krbbnbf - entering; fno=32, *bno=512, fd->gnb_bno_krbbfd=512, fd->gnb_bct_krbbfd=245256, lastblk=262272 krbbnbf - non SAGE alignment; bbuf=512, readalnz=4194304 krbbnbf - ready with; fno=32, lbno=512, lbct=512, fd->gnb_bno_krbbfd=1024, fd->gnb_bct_krbbfd=244744 krbavblk merge1; vblk->bno_krbvblk=1, vblk->count_krbvblk=1023, vblk->eof_krbvblk=0 krbbnbf - krbavblk called; fno=32, *bno=512, *bct=512, f->blocks_read_krbbf=0 krbbnbf - entering; fno=32, *bno=1024, fd->gnb_bno_krbbfd=1024, fd->gnb_bct_krbbfd=244744, lastblk=262272 krbbnbf - non SAGE alignment; bbuf=512, readalnz=4194304 krbbnbf - ready with; fno=32, lbno=1024, lbct=512, fd->gnb_bno_krbbfd=1536, fd->gnb_bct_krbbfd=244232 krbavblk merge1; vblk->bno_krbvblk=1, vblk->count_krbvblk=1535, vblk->eof_krbvblk=0 krbbnbf - krbavblk called; fno=32, *bno=1024, *bct=512, f->blocks_read_krbbf=0 krbbnbf - entering; fno=32, *bno=1536, fd->gnb_bno_krbbfd=1536, fd->gnb_bct_krbbfd=244232, lastblk=262272 krbbnbf - non SAGE alignment; bbuf=512, readalnz=4194304 krbbnbf - ready with; fno=32, lbno=1536, lbct=512, fd->gnb_bno_krbbfd=2048, fd->gnb_bct_krbbfd=243720
So whilst the rest of that section of the trace file is not too informative, it does confirm that the block change tracking file was used for this level 1 backup.
Dig around in these trace files; you may pick up some useful stuff.