Oracle … as usual

Oracle by Laurent Leturgez

Measuring RMAN IO Rates

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 !

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: