The RMAN debug option is usually used by Oracle support to get internal information etc. Nevertheless, you can use this option to get information on RMAN backup IO Rates.
For example, you have ran this command:
[oracle@oel ~]$ rman target / trace uncompressed_dbg.trc
RMAN> debug on
RMAN> backup as backupset database;
RMAN> debug off
RMAN> exit
Note: if you want a lightweight trace which includes only IO related events, you can use the “debug io” command.
If you grep the trace file and search the DBGIO pattern, you will print very interesting information about IO Rates:
[oracle@oel ~]$ grep DBGIO uncompressed_dbg.trc
DBGIO: channel ORA_DISK_1: set_stamp=780338716 set_count=39 [16:45:16.809] (budf_start)
DBGIO: channel ORA_DISK_1: blocks=93440 block_size=8192 [16:45:16.816] (budf_name)
DBGIO: channel ORA_DISK_1: blocks=6400 block_size=8192 [16:45:16.825] (budf_name)
DBGIO: channel ORA_DISK_1: blocks=1280 block_size=8192 [16:45:16.833] (budf_name)
DBGIO: channel ORA_DISK_1: blocks=19200 block_size=8192 [16:45:16.840] (budf_name)
DBGIO: channel ORA_DISK_1: blocks=84480 block_size=8192 [16:45:16.844] (budf_name)
DBGIO: Type %Comp Blocks Tot Blocks Blksize ElpTime(s) IO Rt(b/s) Name [16:46:22.229] (krmkqio)
DBGIO: ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [16:46:22.229] (krmkqio)
DBGIO: IN 3.0 192 6400 8192 0 0 +DATA/orcl/datafile/aud_ts.256.752779503 [16:46:22.229] (krmkqio)
DBGIO: IN 1.3 256 19200 8192 0 0 +DATA/orcl/datafile/t.258.769108187 [16:46:22.247] (krmkqio)
DBGIO: IN 100.0 1280 1280 8192 0 0 +DATA/orcl/datafile/test.257.764769441 [16:46:22.258] (krmkqio)
DBGIO: IN 94.1 79488 84480 8192 54 12058624 /u02/oradata/orcl/sysaux01.dbf [16:46:22.258] (krmkqio)
DBGIO: IN 99.6 93056 93440 8192 59 12920589 /u02/oradata/orcl/system01.dbf [16:46:22.259] (krmkqio)
DBGIO: OUT 147602 8192 59 20494162 /u01/app/oracle/fast_recovery_area/ORCL/backupset/2012_04_11/o1_mf_nnndf_TAG20120411T164516_7rc67wtn_.bkp [16:46:22.259] (krmkqio)
DBGIO: AGG 85.1 174272 204800 8192 59 24197224 [16:46:22.282] (krmkqio)
DBGIO: channel ORA_DISK_1: set_stamp=780338782 set_count=40 [16:46:22.485] (budf_start)
DBGIO: channel ORA_DISK_1: blocks=71680 block_size=8192 [16:46:22.633] (budf_name)
DBGIO: Type %Comp Blocks Tot Blocks Blksize ElpTime(s) IO Rt(b/s) Name [16:46:29.692] (krmkqio)
DBGIO: ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [16:46:29.692] (krmkqio)
DBGIO: IN 15.3 10944 71680 8192 2 44826624 /u02/oradata/orcl/undotbs01.dbf [16:46:29.692] (krmkqio)
DBGIO: OUT 690 8192 3 1884160 /u01/app/oracle/fast_recovery_area/ORCL/backupset/2012_04_11/o1_mf_nnndf_TAG20120411T164516_7rc69yo2_.bkp [16:46:29.692] (krmkqio)
DBGIO: AGG 15.3 10944 71680 8192 2 44826624 [16:46:29.692] (krmkqio)
DBGIO: channel ORA_DISK_1: set_stamp=780338789 set_count=41 [16:46:29.770] (budf_start)
DBGIO: channel ORA_DISK_1: blocks=44240 block_size=8192 [16:46:29.774] (budf_name)
DBGIO: Type %Comp Blocks Tot Blocks Blksize ElpTime(s) IO Rt(b/s) Name [16:46:44.898] (krmkqio)
DBGIO: ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [16:46:44.898] (krmkqio)
DBGIO: IN 90.1 39872 44240 8192 6 54438570 /u02/oradata/orcl/example01.dbf [16:46:44.899] (krmkqio)
DBGIO: OUT 8818 8192 7 10319579 /u01/app/oracle/fast_recovery_area/ORCL/backupset/2012_04_11/o1_mf_nnndf_TAG20120411T164516_7rc6b5rf_.bkp [16:46:44.899] (krmkqio)
DBGIO: AGG 90.1 39872 44240 8192 6 54438570 [16:46:44.900] (krmkqio)
DBGIO: channel ORA_DISK_1: set_stamp=780338804 set_count=42 [16:46:45.025] (budf_start)
DBGIO: channel ORA_DISK_1: blocks=36320 block_size=8192 [16:46:45.029] (budf_name)
DBGIO: Type %Comp Blocks Tot Blocks Blksize ElpTime(s) IO Rt(b/s) Name [16:47:00.056] (krmkqio)
DBGIO: ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [16:47:00.056] (krmkqio)
DBGIO: IN 72.6 26368 36320 8192 4 54001664 /u02/oradata/orcl/users01.dbf [16:47:00.056] (krmkqio)
DBGIO: OUT 26269 8192 4 53798912 /u01/app/oracle/fast_recovery_area/ORCL/backupset/2012_04_11/o1_mf_nnndf_TAG20120411T164516_7rc6bo1h_.bkp [16:47:00.056] (krmkqio)
DBGIO: AGG 72.6 26368 36320 8192 4 54001664 [16:47:00.056] (krmkqio)
To simplify the reading of this output, I will focus on the “users01.dbf” datafile backup in the backupset “/u01/app/oracle/fast_recovery_area/ORCL/backupset/2012_04_11/o1_mf_nnndf_TAG20120411T164516_7rc6bo1h_.bkp” (Highlighted in red).
In this part, we can read information above:
TYPE = IN: when rman reads the source file, OUT when it writes it, AGG represents aggregated data for the complete operation (read files and write the backupset to disk or to tape). .
For example, if we read the IN line, we know that 26368 blocks have been read on a total of 36320 blocks (block size is 8kb), this represents a total of 26368/36320 = 72,6 % of all the datafile blocks. (RMAN backs up only used blocks). This datafile has been read in 4 seconds at a rate of 54001664 bytes per second (51,5 Mb/sec).
You have the same line for the OUTput operation (ie. writing the backupset to disk).
Others things to see about this tip is the differences between a simple uncompressed backup of a datafile to disk, a compressed (default algorithm) backup of this datafile to disk, and an uncompressed backup of a datafile on disk using the oracle SBT library.
Note: I have flushed my linux filesystem cache between each test. (# echo 3 > /proc/sys/vm/drop_caches)
Here are the results :
- Default : uncompressed backup to disk
[oracle@oel debug]$ rman target / debug trace debug.trc
RMAN> run {
2> backup as backupset datafile 4;
3> }
[oracle@oel debug]$ grep DBGIO debug.trc
DBGIO: channel ORA_DISK_1: set_stamp=780405759 set_count=62 [11:22:39.138] (budf_start)
DBGIO: channel ORA_DISK_1: blocks=36320 block_size=8192 [11:22:39.409] (budf_name)
DBGIO: Type %Comp Blocks Tot Blocks Blksize ElpTime(s) IO Rt(b/s) Name [11:23:04.562] (krmkqio)
DBGIO: ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [11:23:04.562] (krmkqio)
DBGIO: IN 72.6 26368 36320 8192 16 13500416 /u02/oradata/orcl/users01.dbf [11:23:04.562] (krmkqio)
DBGIO: OUT 26269 8192 17 12658567 /u01/app/oracle/fast_recovery_area/ORCL/backupset/2012_04_12/o1_mf_nnndf_TAG20120412T112238_7rf7pzlp_.bkp [11:23:04.562] (krmkqio)
DBGIO: AGG 72.6 26368 36320 8192 16 13500416 [11:23:04.563] (krmkqio)
- Compressed backup to disk
[oracle@oel debug]$ rman target / debug trace debug_comp.trc
RMAN> run {
2> backup as compressed backupset datafile 4;
3> }
[oracle@oel debug]$ grep DBGIO debug_comp.trc
DBGIO: channel ORA_DISK_1: set_stamp=780405692 set_count=60 [11:21:32.609] (budf_start)
DBGIO: channel ORA_DISK_1: blocks=36320 block_size=8192 [11:21:32.871] (budf_name)
DBGIO: Type %Comp Blocks Tot Blocks Blksize ElpTime(s) IO Rt(b/s) Name [11:21:48.006] (krmkqio)
DBGIO: ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [11:21:48.007] (krmkqio)
DBGIO: IN 72.6 26368 36320 8192 11 19636968 /u02/oradata/orcl/users01.dbf [11:21:48.007] (krmkqio)
DBGIO: OUT 3737 8192 12 2551125 /u01/app/oracle/fast_recovery_area/ORCL/backupset/2012_04_12/o1_mf_nnndf_TAG20120412T112132_7rf7nx2s_.bkp [11:21:48.007] (krmkqio)
DBGIO: AGG 72.6 26368 36320 8192 11 19636968 [11:21:48.007] (krmkqio)
Here we can see there’s less blocks writing to disk, and the IO rate is not the same than the default backup compression.
- Uncompressed backup to disk using SBT libraries (Only for testing purpose, don’t use this in production)
[oracle@oel debug]$ rman target / debug trace debug_sbt.trc
RMAN> run {
2> allocate channel 'tape1' type 'sbt_tape' parms 'SBT_LIBRARY=oracle.disksbt,ENV=(BACKUP_DIR=/u02/sbt_bkp)';
3> backup as backupset datafile 4;
4> }
[oracle@oel debug]$ grep DBGIO debug_sbt.trc
DBGIO: channel tape1: set_stamp=780405909 set_count=64 [11:25:09.810] (budf_start)
DBGIO: channel tape1: blocks=36320 block_size=8192 [11:25:10.061] (budf_name)
DBGIO: Type %Comp Blocks Tot Blocks Blksize ElpTime(s) IO Rt(b/s) Name [11:25:45.304] (krmkqio)
DBGIO: ---- ----- ---------- ---------- ---------- ---------- ---------- ----- [11:25:45.304] (krmkqio)
DBGIO: IN 100.0 36320 36320 8192 25 11901337 /u02/oradata/orcl/users01.dbf [11:25:45.304] (krmkqio)
DBGIO: OUT 36352 8192 27 11029466 20n8834l_1_1 [11:25:45.304] (krmkqio)
DBGIO: AGG 100.0 36320 36320 8192 25 11901337 [11:25:45.305] (krmkqio)
In this example, we can see that, when SBT channel is used, all the blocks of the datafile are read. We can verify this in the MOS note (360443.1):
Unused Block Compression cannot be used by:
-
3rd party media managers – the whole file is scanned every time a tape backup is done
-
Incremental backups – to get faster incremenals use Block Change Tracking
-
RMAN backup VALIDATE command
Thanks to my colleague Pierre Labrousse (aka Pierre the great 😉 ) who gave me this precious note reference !
Data ... as usual 