Veritas-bu

[Veritas-bu] Backups taking alittle too long

2003-03-24 15:09:24
Subject: [Veritas-bu] Backups taking alittle too long
From: benr AT cuddletech DOT com (Ben Rockwood)
Date: Mon, 24 Mar 2003 12:09:24 -0800 (PST)
Hello NB Masters.

In the last couple days one of our restores has started to take long that
usual to restore, at the worst, about an hour longer.  Data size hasn't
changed.  On looking into this problem I got curious about something in
the logs (bptm).  Below are 2 logs, one from the 15th, one from last
night.
3/24/03:
02:44:45 [18638] <2> mpx_read_data: sent keepalive signal to bpbrm, reset
count to 61002:45:24 [18638] <2> mpx_read_data: sent keepalive signal to bpbrm, 
reset
count to 61002:46:19 [18638] <2> mpx_read_data: sent keepalive signal to bpbrm, 
reset
count to 610          <-- --> 02:54:20 Tape Change - Ready at 2:55:14
03:23:34 [18638] <2> mpx_read_data: sent keepalive signal to bpbrm, reset
count to 610          <--03:47:18 [18638] <2> mpx_read_data: waited for empty 
buffer 4262 times,
delayed 147363 times    <--
3/15/03:
02:29:22 [16810] <2> mpx_read_data: sent keepalive signal to bpbrm, reset
count to 61002:29:58 [16810] <2> mpx_read_data: sent keepalive signal to bpbrm, 
reset
count to 61002:30:39 [16810] <2> mpx_read_data: sent keepalive signal to bpbrm, 
reset
count to 610  <--02:36:39 [16810] <2> mpx_read_data: sent keepalive signal to 
bpbrm, reset
count to 610  <--03:08:50 [16810] <2> mpx_read_data: sent keepalive signal to 
bpbrm, reset
count to 610  <--03:11:17 [16810] <2> mpx_read_data: waited for empty buffer 
3957 times,
delayed 96898 times <--

Obviously I chopped alot of the log out.  There are 2 intersting things,
one is that the backup last night is splitting tapes, about 2:54am it hits
EOM and swaps tapes, 2 minutes later it's back restoring data.  Could this
change out alone extend my restore time that much?  The change out only
takes 2 minutes, but could the fact that it's got to get back up to speed
make that sort of impact?  I checked all the data sizes and speeds and
found the following:
3/15:
16810 - 2:04-3:12  4.6G @ 1.2M/s
16840 - 2:04-3:07  6.9G @ 2.0M/s

3/24:
18638 - 2:04-3:51  4.7G @ 797K/s
18666 - 2:04-3:42  6.9G @ 1.2M/s

You can see that I'm slowing down quite a bit.  Is that tape change
possibly my problem?

The second interesting thing from the logs above that interests me is that
for the majority of the restore I see keepalive messages on average every
minute untill the end of the restore when I go from a 1minute delay
between messages to a gap of 30 minutes between and then nother of about
25 minutes before completion.  I see this in both the log from the 24th
(the problem date) and on the 15th (the good date).  Why do I see this
lapse?  Could this reflect the buffer empty delays?

Ideas welcome!  Thank you for any help.  I'll summerise when complete if
needbe.
benr.


-- 
//Ben Rockwood - UNIX Systems Admin
//email: benr AT cuddletech DOT com
//web: www.cuddletech.com
//-> We do what we can, We give what we have,
//-> Our doubt is our passion, and our passion is our task,
//-> The rest is the madness of Art.
//->   -Henry James




<Prev in Thread] Current Thread [Next in Thread>
  • [Veritas-bu] Backups taking alittle too long, Ben Rockwood <=