Very slow `bup backup`

[Ben Gamari]

I'm currently trying to back up a RAID10 md volume formatted with
ext4. The volume has roughly 5TBytes of heterogeneous files: while many
are small, a fair fraction of the overall space usage is due to
multigigabyte files.

The backup is being performed using `bup save --remote=$HOST:$PATH` over
remote machine over gigabit ethernet. iperf indicates that network
performance is quite good,

[ 3] 0.0-10.0 sec 768 MBytes 644 Mbits/sec

bonnie++ (below) has suggests that disk IO is also quite
reasonable. Moreover, rsync copies at roughly 50MByte/s. Despite this,
bup is remarkably sluggish (confirmed with iotop),

Saving: 0.94% (43104997/4582845750k, 2140/1505320 files) 797h57m 1500k/s

Looking at top, it seems that the process uses very little CPU time,
instead spending most of its time blocked in sleep_on_page_killable. In
13 minutes of user time, the process produces,

* 1.9 million major page faults (roughly 2000 per second)
* 500k minor page faults

Given bup is doing mostly disk IO, this isn't terribly
surprising. Unfortunately, the IO patterns its using

Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
md0 0.00 0.00 90.60 0.00 0.92 0.00 20.70 0.00 0.00 0.00 0.00 0.00 0.00



bonnie++ output:

Version 1.97 ------Sequential Output------ --Sequential Input- --Random-
Concurrency 1 -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP /sec %CP
goldnerlab 36112M 888 82 121659 10 64914 8 1637 66 170522 13 247.2 19
Latency 8334us 1338ms 2793ms 620ms 236ms 620ms
Version 1.97 ------Sequential Create------ --------Random Create--------
goldnerlab -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
files /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP /sec %CP
16 20020 20 +++++ +++ 22571 13 +++++ +++ +++++ +++ +++++ +++
Latency 12964us 644us 796us 348us 117us 802us
1.97,1.97,goldnerlab,1,1382027828,36112M,,888,82,121659,10,64914,8,1637,66,170522,13,247.2,19,16,,,,,20020,20,+++++,+++,22571,13,+++++,+++,+++++,+++,+++++,+++,8334us,1338ms,2793ms,620ms,236ms,620ms,12964us,644us,796us,348us,117us,802us

[Ben Gamari]

Ben Gamari <bga...@gmail.com> writes:

> I'm currently trying to back up a RAID10 md volume formatted with
> ext4. The volume has roughly 5TBytes of heterogeneous files: while many
> are small, a fair fraction of the overall space usage is due to
> multigigabyte files.
>

This was a draft that I sentn accidentally; please disregard. The
finished message will be coming shortly.

Cheers,

- Ben

[Ben Gamari]

I'm currently trying to back up a RAID10 md volume formatted with
ext4. The volume has roughly 5TBytes of heterogeneous files: while many
are small, a fair fraction of the overall space usage is due to
multigigabyte files.

The backup is being performed using `bup save --remote=$HOST:$PATH` over
remote machine over gigabit ethernet. iperf indicates that network
performance is quite good,

[ 3] 0.0-10.0 sec 768 MBytes 644 Mbits/sec

bonnie++ (below) has suggests that disk IO is also quite
reasonable. Moreover, rsync copies at roughly 50MByte/s. Despite this,
bup is remarkably sluggish (confirmed with iotop),

Saving: 0.94% (43104997/4582845750k, 2140/1505320 files) 797h57m 1500k/s

Looking at top, it seems that the process uses very little CPU time,
instead spending most of its time blocked in sleep_on_page_killable. In
13 minutes of user time, the process produces,

* 1.9 million major page faults (roughly 2000 per second)
* 500k minor page faults

Given bup is doing mostly disk IO, this isn't terribly

surprising. The low throughput, however, is unexpected. Strangely, the
IO patterns don't seem to be too terrible (from iostat),

Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
md0 0.00 0.00 90.60 0.00 0.92 0.00 20.70 0.00 0.00 0.00 0.00 0.00 0.00

where the average read request size is 20 (4kByte) sectors (roughly
100kBytes). Has anyone else seen this sort of unexpectedly low
performance from bup? Any ideas on how I might track this down further?

Cheers,

- Ben

[Gabriel Filion]

On 17/10/13 05:50 PM, Ben Gamari wrote:
> Saving: 0.94% (43104997/4582845750k, 2140/1505320 files) 797h57m 1500k/s
>
> Looking at top, it seems that the process uses very little CPU time,
> instead spending most of its time blocked in sleep_on_page_killable. In
> 13 minutes of user time, the process produces,
>
> * 1.9 million major page faults (roughly 2000 per second)
> * 500k minor page faults
>
> Given bup is doing mostly disk IO, this isn't terribly
> surprising. The low throughput, however, is unexpected. Strangely, the
> IO patterns don't seem to be too terrible (from iostat),
>
> Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
> md0 0.00 0.00 90.60 0.00 0.92 0.00 20.70 0.00 0.00 0.00 0.00 0.00 0.00

humm that's pretty slow..

I'm just venturing a guess: is bup reading one of the multi-gigabyte
files when showing slow transfer speeds?

--
Gabriel Filion

[sr.steph...@gmail.com]

 I can confirm this. Right now i'm waiting for a backup of a almost full 1TB disk to complete. Shortly after starting bup save, the data rate dropped to 600k/s, while cpu load is only about 10%. i don't know if it is only a problem with large files, but at the moment it is working on a 500MB vob file...

estimated completion time for the remaining 500GB: 197 hours!

[Rob Browning]

Which bup version, what platform, what filesystem, etc.?

Thanks
--
Rob Browning
rlb @defaultvalue.org and @debian.org
GPG as of 2011-07-10 E6A9 DA3C C9FD 1FF8 C676 D2C4 C0F0 39E9 ED1B 597A
GPG as of 2002-11-03 14DD 432F AE39 534D B592 F9A0 25C8 D377 8C7E 73A4

[sr.steph...@gmail.com]

god point, sorry, i forgot.

i have bup 0.22a-1 installed on ubuntu server 12.04 x64.

The source of the backup resides on an ext3 formatted 1TB drive, the destination is an ext4 formatted partition on a raid 5 system. all drives connected via SATA.

let me know, if you need any further details.

[Rob Browning]

sr.steph...@gmail.com writes:

> i have bup 0.22a-1 installed on ubuntu server 12.04 x64.
>
> The source of the backup resides on an ext3 formatted 1TB drive, the
> destination is an ext4 formatted partition on a raid 5 system. all drives
> connected via SATA.
>
> let me know, if you need any further details.

So if/when you have time, it would be interesting to see how 0.25
behaves. Some of the improvements we've made may (or may not) help you.

This is one of the changes that comes to mind:

commit f3c4f057d98f84f411c436c28c3e50230aed2f45
Enforce MAX_PER_TREE by always _squish()ing in spit_to_shalist().

Though that one will only help in some cases:

Previously bup would ignore MAX_PER_TREE whenever it hit a long run
of data that didn't produce a non-zero hashplit "level" (see the
discussion of fanout in DESIGN). That can happen, for example, when
traversing a file containing large zero regions (sparse or not).

As a result, bup could produce an arbitrarily large number of blobs
at level 0 of the hashsplit tree, causing it to consume increasing
memory during split/save, and to behave badly during join/restore.

So save should behave better across the board in this situation, but
restore will only behave better when working with trees created by the
fixed save.

And note that you can run bup directly from the build directory via
/some/where/bup-0.25/bup (or a symlink to that executable) if that
helps.

However, unless you're sure you're ready to migrate to 0.25, you should
only test on a copy of your BUP_DIR.

(And of course I'd still recommend a non-bup backstop for now.)

Hope this helps.

[sr.steph...@gmail.com]

Thank you for your suggestions!

I've been patient and waited about a week for the backup to complete.

Yesterday i cloned bup, checked out the version tagged "0.25", built and installed it.
I currently run a backup of a folder which was previously excluded from the backup, but which is highly redundant with the previously backup-ed folders. Again, i'm only achieving a data rate of aproximateley 760k/s and an estimated remaining time of another 163 hours.

Just one guess: Does bup, while comparing the input-to-backup with existing backups has to read a lot of data from the already existing packfiles or something similar? How can i find out?

best wishes for the new year!

Stephan

[sr.steph...@gmail.com]

I just found out, how to measure disk I/O. But there's no indication of a bottleneck, here:

All i see is low I/O, low CPU usage and a low rate of backup progress. Further suggestions?

Am Dienstag, 31. Dezember 2013 17:38:59 UTC+1 schrieb Rob Browning:

[Gao Yongwei]

2014/1/9 <sr.steph...@gmail.com>

I just found out, how to measure disk I/O. But there's no indication of a bottleneck, here:

All i see is low I/O, low CPU usage and a low rate of backup progress. Further suggestions?

Can you have try with the follow command ?

  bup save -v -n Datenplatte -0 /media/Datenplatte

[sr.steph...@gmail.com]

I can (in a few days) - what's the purpose of the "-0" flag? Can't see it using "man bup save"

[Rob Browning]

sr.steph...@gmail.com writes:

> <https://lh4.googleusercontent.com/-bJYPzdSexI4/Us5OgZkgnsI/AAAAAAAAAEQ/dJLJGpk3jY0/s1600/stat.png>

> I just found out, how to measure disk I/O. But there's no indication of a
> bottleneck, here:

Another tool is "atop" (in the sysstat package in debian). If you have
a big enough terminal, it displays (too much?) information, but can be a
quick way to try to see where the system is swamped (angry red lines).

Also, if you didn't, I'd run iostat with a reasonable interval,
i.e. "iostat -m 5 ..." and see how it looks.

> All i see is low I/O, low CPU usage and a low rate of backup progress.
> Further suggestions?

Right, I'd expect *something* to be heavily loaded (disk, cpu, net). I
see that your md0's at about 200tps -- is that high?

[Rob Browning]

Rob Browning <r...@defaultvalue.org> writes:

> Right, I'd expect *something* to be heavily loaded (disk, cpu, net). I
> see that your md0's at about 200tps -- is that high?

Oh, and if you do try atop, it can show you the avio times. Looks like
iostat can do something similar (with even more detail) via -x.

[sr.steph...@gmail.com]

So i run atop, screenshot attached. no red values here.


Also i tried to push my md0's tps value by copying some bulk data:

$> if=/dev/urandom of=test.test bs=128 count=10000
$> date; for I in $(seq 1 1000); do cat test.test >> test.2; done; date; du -h test.2

it takes 49 sec to write the 1.2 GB, tps goes up to 350, so 200tps while running bup save is not an terribly high value.

some more stat':

root@server:~# iostat -m 10 md0 sdb
Linux 3.8.0-35-generic (server)         10.01.2014      _x86_64_        (1 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           4,13    0,04    2,48   91,38    0,00    1,97

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sdb               8,68         0,69         0,00     106562        447
md0             231,37         2,78         0,32     426407      49180

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           3,01    0,00    1,41   94,98    0,00    0,60

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sdb               5,62         0,60         0,00          6          0
md0             106,73         0,56         0,00          5          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2,81    0,00    1,91   94,38    0,00    0,90

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sdb               5,32         0,60         0,00          6          0
md0             113,84         0,66         0,22          6          2

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2,62    0,00    1,71   95,17    0,00    0,50

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sdb               6,34         0,71         0,00          7          0
md0             111,67         0,58         0,00          5          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           2,51    0,00    2,21   94,48    0,00    0,80

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn
sdb               4,71         0,50         0,00          5          0
md0             117,05         0,80         0,00          7          0

Xingxing Gao suggested to switch of compression. While this might be worth a try (and i definitely will try), i don't think it is due to compression, as cpu load indicates no bottleneck here?

[Rob Browning]

sr.steph...@gmail.com writes:

> <https://lh5.googleusercontent.com/-zfFQi5I7p5Y/UtAFuGvMMzI/AAAAAAAAAEg/qR8tIZ8D_xE/s1600/atop.png>

> So i run atop, screenshot attached. no red values here.

Right, though the blue ones indicate sdc and sdh are fairly busy.

> avg-cpu: %user %nice %system %iowait %steal %idle
> 4,13 0,04 2,48 91,38 0,00 1,97

The consistently over 90% iowait values also suggest that bup is just IO
bound, presumably seek-bound.

And assuming I read it correctly, I just noticed (via atop) that your
system has about 500M. If that's right, then I suspect additional RAM
might make a substantial difference, but I'm not postive offhand.

Hope this helps.

[Rob Browning]

Rob Browning <r...@defaultvalue.org> writes:

> So if/when you have time, it would be interesting to see how 0.25
> behaves. Some of the improvements we've made may (or may not) help you.

Just wanted to check and see if any of you have had a chance to test a
more recent bup to see if we still have a problem with large files.

Thanks

[karl.ri...@gmail.com]

I just checked out version 0.25-48-ge3297ae and I'm experiencing some similar issues (with bup index, but I guess it doesn't matter). In general, all operations which require reading and writing appear slow because switching between writing and reading occurs to often. A reason might be that buffers are too small, at least maybe someone can give it a try who is familiar with the code (I just took a look for a couple of minutes, but I didn't figure out anything...). Depending on how fragmentation on ext4 works (I don't know), it makes sense that the issue is not reproducible constantly.

[Rob Browning]

karl.ri...@gmail.com writes:

> I just checked out version 0.25-48-ge3297ae and I'm experiencing some
> similar issues (with bup index, but I guess it doesn't matter). In general,
> all operations which require reading and writing appear slow because
> switching between writing and reading occurs to often. A reason might be
> that buffers are too small, at least maybe someone can give it a try who is
> familiar with the code (I just took a look for a couple of minutes, but I
> didn't figure out anything...). Depending on how fragmentation on ext4
> works (I don't know), it makes sense that the issue is not reproducible
> constantly.

I looked back at your original report, and it would also be useful to
see what's going on via something like "iostat", i.e. "iostat -m 5 sda"
or whatever -- i.e. what are the read/write and seek rates, and how do
those compare to what you see from the relevant destination when using
other tools like cp -a, etc.

[Patrick Rouleau]

On Friday, February 14, 2014 8:40:29 PM UTC-5, Rob Browning wrote:

Rob Browning <r...@defaultvalue.org> writes:

> So if/when you have time, it would be interesting to see how 0.25
> behaves.  Some of the improvements we've made may (or may not) help you.

Just wanted to check and see if any of you have had a chance to test a
more recent bup to see if we still have a problem with large files.

On my side, the backup speed is fine, while the restore speed slows down because bup fills up the RAM with all the restored files' details. My file server only have 2GB of RAM, so after restoring thousands of files, it begins to swap as hell.

My solution is at the end of this thead[1]. It is really simple. I can resent it with a proper commit message.

Regards,

P.Rouleau

[1] https://groups.google.com/forum/#!topic/bup-list/3Ql-A04HmoI

[Rob Browning]

Patrick Rouleau <proul...@gmail.com> writes:

> On my side, the backup speed is fine, while the restore speed slows down
> because bup fills up the RAM with all the restored files' details. My file
> server only have 2GB of RAM, so after restoring thousands of files, it
> begins to swap as hell.
>
> My solution is at the end of this thead[1]. It is really simple. I can
> resent it with a proper commit message.

Ahh, right -- I haven't gotten back to that thread yet. Probably no
need to re-send until I have a chance to take a closer look.

Thanks for the help.

[sr.steph...@gmail.com]

Am Freitag, 10. Januar 2014 18:11:59 UTC+1 schrieb Rob Browning:

sr.steph...@gmail.com writes:

> <https://lh5.googleusercontent.com/-zfFQi5I7p5Y/UtAFuGvMMzI/AAAAAAAAAEg/qR8tIZ8D_xE/s1600/atop.png>
> So i run atop, screenshot attached. no red values here.

Right, though the blue ones indicate sdc and sdh are fairly busy.

> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>            4,13    0,04    2,48   91,38    0,00    1,97

The consistently over 90% iowait values also suggest that bup is just IO
bound, presumably seek-bound.

And assuming I read it correctly, I just noticed (via atop) that your
system has about 500M.  If that's right, then I suspect additional RAM
might make a substantial difference, but I'm not postive offhand.

Hope this helps.
--

right. Just yesterday i upgraded the hardware of my server. now i have a dual-threaded pentium 4 processor running at 3GHz and 2GB of RAM.
Bup now shows an (average?) throughput of 7800k/s which on the one hand is about 10 times as fast as it was before. On the other hand, i still would expect a faster backup, as about 99% percent of the 1TB have been backed up in preceding runs.

Some more iostat -m 5 md0:

Linux 3.8.0-44-generic (server)         29.10.2014      _x86_64_        (2 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

          12,46    0,03    3,47   24,26    0,00   59,78

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn

md0            1041,50        16,97         0,01    1398403        721

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

          12,02    0,00    1,20   19,34    0,00   67,43

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn

md0              61,80         0,24         0,00          1          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

          12,14    0,00    1,20   20,76    0,00   65,90

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn

md0              61,80         0,24         0,00          1          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

          11,53    0,00    1,50   19,06    0,00   67,90

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn

md0              61,80         0,24         0,00          1          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

          11,35    0,00    1,61   20,48    0,00   66,57

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn

md0              67,20         0,26         0,00          1          0

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

          11,72    0,00    1,40   16,83    0,00   70,04

Device:            tps    MB_read/s    MB_wrtn/s    MB_read    MB_wrtn

md0              62,60         0,24         0,00          1          0

[Patrick Rouleau]

On Wednesday, October 29, 2014 9:21:42 AM UTC-4, sr.steph...@gmail.com wrote:

Am Freitag, 10. Januar 2014 18:11:59 UTC+1 schrieb Rob Browning:

sr.steph...@gmail.com writes:

> <https://lh5.googleusercontent.com/-zfFQi5I7p5Y/UtAFuGvMMzI/AAAAAAAAAEg/qR8tIZ8D_xE/s1600/atop.png>
> So i run atop, screenshot attached. no red values here.

Right, though the blue ones indicate sdc and sdh are fairly busy.

> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>            4,13    0,04    2,48   91,38    0,00    1,97

The consistently over 90% iowait values also suggest that bup is just IO
bound, presumably seek-bound.

And assuming I read it correctly, I just noticed (via atop) that your
system has about 500M.  If that's right, then I suspect additional RAM
might make a substantial difference, but I'm not postive offhand.

Hope this helps.
--

right. Just yesterday i upgraded the hardware of my server. now i have a dual-threaded pentium 4 processor running at 3GHz and 2GB of RAM.
Bup now shows an (average?) throughput of 7800k/s which on the one hand is about 10 times as fast as it was before. On the other hand, i still would expect a faster backup, as about 99% percent of the 1TB have been backed up in preceding runs.

About the speed, I get around 15000k/s with a Quad-i7. Did you try to backup something from your RAID? It may be your 1TB who is slow (or maybe heavily fragmented?).

About the amount of data, does the / (root dir) was upgraded too? (ie does it have the same device id as before.) I believe bup is using the device id to recognize the file systems, so your 1TB is not recognized and it have to be fully backuped. 

--

P.Rouleau

[sr.steph...@gmail.com]

Am Donnerstag, 30. Oktober 2014 03:43:34 UTC+1 schrieb Patrick Rouleau:

On Wednesday, October 29, 2014 9:21:42 AM UTC-4, sr.steph...@gmail.com wrote:

Am Freitag, 10. Januar 2014 18:11:59 UTC+1 schrieb Rob Browning:

sr.steph...@gmail.com writes:

> <https://lh5.googleusercontent.com/-zfFQi5I7p5Y/UtAFuGvMMzI/AAAAAAAAAEg/qR8tIZ8D_xE/s1600/atop.png>
> So i run atop, screenshot attached. no red values here.

Right, though the blue ones indicate sdc and sdh are fairly busy.

> avg-cpu:  %user   %nice %system %iowait  %steal   %idle
>            4,13    0,04    2,48   91,38    0,00    1,97

The consistently over 90% iowait values also suggest that bup is just IO
bound, presumably seek-bound.

And assuming I read it correctly, I just noticed (via atop) that your
system has about 500M.  If that's right, then I suspect additional RAM
might make a substantial difference, but I'm not postive offhand.

Hope this helps.
--

right. Just yesterday i upgraded the hardware of my server. now i have a dual-threaded pentium 4 processor running at 3GHz and 2GB of RAM.
Bup now shows an (average?) throughput of 7800k/s which on the one hand is about 10 times as fast as it was before. On the other hand, i still would expect a faster backup, as about 99% percent of the 1TB have been backed up in preceding runs.

About the speed, I get around 15000k/s with a Quad-i7. Did you try to backup something from your RAID? It may be your 1TB who is slow (or maybe heavily fragmented?).

About the amount of data, does the / (root dir) was upgraded too? (ie does it have the same device id as before.) I believe bup is using the device id to recognize the file systems, so your 1TB is not recognized and it have to be fully backuped. 

The situation is the following: ich only changed the main board, so the device ids of the hard disks have not changed.
Regarding the raid: the directory I'm backing up has a size of almost 1TB and resides on a partition on a single 2TB drive. The destination of the backup is on a 4 disk raid 5 volume.
How can i tell, whether my source drive is fragmented?

regards,
Stephan

[Patrick Rouleau]

Oh Ok. I based my reply on the old message where you said the 1TB data was on a nearly full 1TB partition. That's why I thought about the fragmentation as an issue. The disk can also be "too old" or wearing out, that's why I suggested to compare the backup speed by backuping something from the RAID itself.

 

How can i tell, whether my source drive is fragmented?

You can use fsck.ext2 (even if the partition is ext3):

sudo fsck.ext2 -fn /dev/sdXY

If fragmentation is at play, we have to move the data to a new partition, since ext3 does not have tools to defragment.

--

P.Rouleau

regards,
Stephan

[sr.steph...@gmail.com]

Good news!

I don't understand how and why, but after a few more slow backups, the problem has gone. Now the hardware update seems to turn to account; the whole backup now only takes a few minutes.