Rajib Sarkar (rssarkar)
STSM Db2 Support

Dec. 2, 2014.

Starting DB2 v9.7 if you want to understand how the backup or restore is working ( especially if its slow ) there's a feature which was put in which can be enabled by setting the regvar DB2_BAR_STATS=YES ( recycle required ) and it will print something like this in the db2diag.log after a backup is complete:

2013-09-30-20.55.02.862821-240 E839641A1560         LEVEL: Info

PID     : 917934               TID : 3086           PROC : db2sysc

INSTANCE: rsarkar              NODE : 000           DB   : SAMPLE

APPHDL  : 0-141                APPID: *LOCAL.rsarkar.131001005458

AUTHID  : RSARKAR              HOSTNAME: p6db2serv

EDUID   : 3086                 EDUNAME: db2agent (SAMPLE)

FUNCTION: DB2 UDB, database utilities, sqluxLogDataStats, probe:393

MESSAGE : Performance statistics

DATA #1 : String, 1058 bytes

Number of buffers = 5

Buffer size       = 3149824 (769 4kB pages)

BM#    Total      I/O      MsgQ      WaitQ      Buffers   kBytes

---  --------  --------  --------  --------    --------  --------

000      3.59      3.50      0.00      0.00          56    165696

001      3.59      0.18      0.00      3.40           6     16128

002      3.59      0.27      0.00      3.31           4     11520

003      3.59      0.12      0.00      3.47           2      4864

004      3.59      0.10      0.00      3.48           1       864

---  --------  --------  --------  --------    --------  --------

TOT     17.97      4.19      0.00     13.68          69    199072

MC#    Total      I/O      MsgQ      WaitQ      Buffers   kBytes

---  --------  --------  --------  --------    --------  --------

000      3.59      0.00      3.59      0.00          70    209200

---  --------  --------  --------  --------    --------  --------

TOT      3.59      0.00      3.59      0.00          70    209200

Starting v10.1 it is enabled by default and after every backup / restore is complete it will print the results as above in the db2diag.log

The decode of each of the columns is:

BM#

- the number we assigned to an individual Buffer Manipulator.  BM's READ data from the databases tablespace during a backup and place them into buffers.  Or WRITE data back out to the database from the buffer during a restore.  

MC#

- the number assigned to an individual Media Controller.  MC's WRITE  buffers out to the target location on backup and READ buffer on restore.

Total

- The total amount of time spent by the process in seconds.   

I/O

- The amount of time spent either reading or writing data.  For the BM's this represents time reading data from tablespace, and filling the buffer.  For MC it's time spent reading from buffer and sending it to the target destination.

MsgQ

- This is the amount of time we spend waiting to get a buffer.  For BM's it's how long is spent waiting to get an empty buffer for filling.  For MC's it's time spent waiting to get a full buffer in order to write out.

Wait Q

- Amount of time spent waiting on directives from the agent overseeing the whole backup.

Buffers

- The number of Buffers Processed by a particular BM or MC.  A BM filled X number of buffers.  An MC wrote out X number of buffers.

Mbytes

- The amount of data handled by a particular BM or MC in Mbytes.  NOTE that the sum of all MC's written bytes is the amount of total data sent.

So, from this data you can easily tell in where the backup or restore is spending its time i.e. in the Reading portion or Writing portion and then focus on that part to find out what is wrong. 

For example, look for the I/O times of the BMs and MC to see which one is spending more time in I/O and then also look at the MsgQ values to find out if there's an inordinate time waiting on buffers which means the reader or writer are having slowdowns which is why the buffers are not being freed quick enough. 

This is a pretty useful statistic to know of the inner working of Backup / Restore and can be used to understand where the bottleneck is.

Here is a link to a blog written by Dale McInnis having a much more detailed explanation of the above output. 

Hope you found this blog useful!