01:55:10.752 [25808.14272] <2> read_data: waited for empty buffer 1608 times, delayed 17063 times
01:55:24.908 [21596.7104] <2> write_data: waited for full buffer 365295 times, delayed 1395403 times
For a duplication, bptm does both the read and the write.
So we have:
Source side data ---> Buffers ----> Duplication side
The source side fills up the buffer, and was delayed from doing so 17063 times, each delay is I think 15 milli seconds, so in the dupration of the job, there was a (15 x 17063)/ 1000 second delay = about 255 seconds, where the read side process was doing nothing (well it was waiting for a buffer to become free). Presuming the job length was 'kinda long' , 255 sec isn't worth bothering about (in fact, you usually will get some delays, even in the best tuned system), as it is a small % of the totakl job length. that said, I don;t know what the job length was, so you have to make a judgement as to how significant the delay is.
The write side is the bigget problem:
01:55:24.908 [21596.7104] <2> write_data: waited for full buffer 365295 times, delayed 1395403 times
Here bptm, waited 1395403 for data to be duplicated to be written to the buffer - so although the bptm read process was going through the tape, it was only finding relevant data 'every now and then', so the write process bptm had to wait until the buffer was full of data relevant to the backup being duplicated.
(15 x 1395403 )/ 1000 = 20931 sec = 348 minutes = 5.8 hours.
So, the mpx of the backup, may be contributing up to 5.8 hours of delays, in this specific job.
