Veritas-bu

[Veritas-bu] Duplication - 6 hours for one 230M fragment!

2002-04-02 15:03:57
Subject: [Veritas-bu] Duplication - 6 hours for one 230M fragment!
From: Karl.Rossing AT Federated DOT CA (Karl.Rossing AT Federated DOT CA)
Date: Tue, 2 Apr 2002 14:03:57 -0600
What is your NET_BUFFER_SZ set to?

If it's not set try this:
winnipeg:/opt/openv/netbackup>$ cat /opt/openv/netbackup/NET_BUFFER_SZ
262144

Previously i had it set to the default value(i think it's 32k). Apparently 
this needs to be set high when doing a dupplication.

Karl-Frédéric Rössing
Technical Analyst
Federated Insurance Companies of Canada
http://www.federated.ca




"Donaldson, Mark" <Mark.Donaldson AT experianems DOT com>
Sent by: veritas-bu-admin AT mailman.eng.auburn DOT edu
04/02/2002 12:11 PM

 
        To:     "Veritasbu (E-mail)" <veritas-bu AT mailman.eng.auburn DOT edu>
        cc: 
        Subject:        [Veritas-bu] Duplication - 6 hours for one 230M 
fragment!


I create offsite backups by duplicating a select set of backup images. 
These images were laid down as multiplexed backups from a half dozen 
servers in several different classes.  I have only one master/media server 
(v3.4.1 on Sol 2.6), the duplications therefore are taking place within 
the library (DTL7000) that created them.
When I duplicate these images, I specifically don't use the -mpx option on 
bpduplicate.  It seemed to put more tape drives in service and I'm trying 
to keep a some of them in reserve for other activities.
My problem, the duplication of 10 images (less than 350G) has been running 
for 5 days now.  Way too long - big time way too long.  One image 
duplication (~5Gig, 280000 files) took 17 hours to duplicate.
If you look at the bptm log snippet below, it's more than six hours from 
start to finish for one fragment. 
>From "read_backup: begin" to "read_backup: successfully read" is 371 
minutes.  The machine says the read-rate was 180 Kbytes/sec but some quick 
math says 234496 KB in 371 minutes averages merely 6.4 KB/sec. 
By the way, all the fragments for this image were arranged sequentially on 
the same tape according to the logged positioning info so I don't think 
it's a positioning/mechanical delay.
Most of the big time delays were flanked by this pair of notes: 
02:58:20 [25598] <2> get_tape_position_for_read: absolute block position 
prior to reading is 82012 
09:07:54 [25598] <2> read_data: stopping mpx read because 234496 Kbytes of 
234496 were read 
I've been searching the support site and found technote 243197 about 
NET_BUFFER_SZ and adjusted that yesterday to match my SIZE_DATA_BUFFERS 
setting.  I haven't seen a significant change from this but, frankly, it's 
still early - the first bptm child since this change just started about 2 
hours ago.
So - basically - does anybody know what's going on with this? 
-Mark 
Here's just one fragment from bptm log... 
02:58:20 [25598] <2> read_backup: current media id is 000351, next media 
id is 0 
00351 
02:58:20 [25598] <2> io_position_for_read: positioning 000351 to file 
number 13 
02:58:20 [25598] <2> io_read_back_header: drive index 3, reading backup 
header 
02:58:20 [25598] <2> io_read_back_header: drive index 3, reading backup 
header 
02:58:20 [25598] <2> io_read_back_header: drive index 3, reading backup 
header 
02:58:20 [25598] <2> io_read_back_header: drive index 3, reading backup 
header 
02:58:20 [25598] <2> io_position_for_read: successfully positioned 000351 
to fil 
e number 13, mpx_header = 1 
02:58:20 [25598] <2> getsockconnected: host=backup00 service=bpdbm 
address=192.1 
68.1.30 protocol=tcp non-reserved port=13721 
02:58:20 [25598] <4> read_backup: begin reading backup id 
tools00.lodo_101727692 
3 (duplicate), copy 1, fragment 11 from media id 000351 on drive index 3 
02:58:20 [25598] <2> read_data: last_frag = 0, opt_bytes_left = 0, 
tape_Kbytes_l 
eft = 234496, opt_remainder = 0 
02:58:20 [25598] <2> get_tape_position_for_read: absolute block position 
prior t 
o reading is 82012 
09:07:54 [25598] <2> read_data: stopping mpx read because 234496 Kbytes of 
23449 
6 were read 
09:07:54 [25598] <2> io_ioctl: command (1)MTFSF 1 from (bptm.c.9438) on 
drive in 
dex 3 
09:09:14 [25598] <2> read_data: waited for empty buffer 0 times, delayed 0 
times 
09:09:14 [25598] <2> getsockconnected: host=backup00 service=bpdbm 
address=192.1 
68.1.30 protocol=tcp non-reserved port=13721 
09:09:14 [25598] <4> read_backup: successfully read (duplicate) backup id 
tools0 
0.lodo.in.exactis.com_1017276923, copy 1, fragment 11, 234496 Kbytes at 
180.137 
Kbytes/sec 




<Prev in Thread] Current Thread [Next in Thread>