Background:
- I use lvm snapshots on ext4 for backup. I use dump to backup the
snapshots. The backup goes to an external hard drive over usb 3.0. The
external hard drive has 1 partition formatted with ext4.
Problem:
- I've noticed the performance of dump to my ext4 backup degrades
linearly as the disk fills. In the output, the kbps in the status line
keeps getting lower as the percent complete keeps getting higher.
My Thoughts So Far:
- I suspect that either 1) dump is doing something which lowers
performance as the backup progresses, or 2) the ext4 algorithm for
finding and allocating free blocks is vulnerable to performance
degradation as the volume fills.
- I haven't tested this thoroughly. However, performance appears to
improve when I clear out the external drive and do a fresh, full dump
(-0), and performance appears to remain degraded on incremental backups
on a nearly full volume. This leads me to suspect #2.
Help from you:
- What steps can I take to isolate the cause of the problem? If there's
any information I can provide, please let me know.
What I've Done:
- I've run both the short and long SMART tests on the external drive,
which came back clean. They also told me the relocated sector count was
zero.
- I also made sure the disk was connecting in usb 3.0 mode.
- I changed the external drive ext4 mount from journal=ordered to
journal=writeback. The performance difference was nominal.
Any insight would be appreciated.
Thanks.
Joseph D. Wagner
On Sun, Jun 15, 2014 at 10:43:29PM -0700, Joseph D. Wagner wrote:
> Background:
> - I use lvm snapshots on ext4 for backup. I use dump to backup the
> snapshots. The backup goes to an external hard drive over usb 3.0. The
> external hard drive has 1 partition formatted with ext4.
>
> My Thoughts So Far:
> - I suspect that either 1) dump is doing something which lowers performance
> as the backup progresses, or 2) the ext4 algorithm for finding and
> allocating free blocks is vulnerable to performance degradation as the
> volume fills.
>
> - I haven't tested this thoroughly. However, performance appears to improve
> when I clear out the external drive and do a fresh, full dump (-0), and
> performance appears to remain degraded on incremental backups on a nearly
> full volume. This leads me to suspect #2.
The issue is that when the external disk is freshly mounted, we don't
have any of the block allocation bitmaps cached. We also cache at run
information about the largest contiguous free block in a block group.
On a freshly unmounted file system we don't have any of this information.
So it's a known issue that on a freshly mounted file system,
allocation performance is bad for a little while until we have more
information cached. It's not something we've really worked on trying
to improve, but there are a number of things we can do. In
particular, with ext4 file system (as opposed to an ext3 file system
which was upgraded to ext4), the block allocation bitmaps are much
more contiguous. So one of the things we could do is to readahead a
chunk of allocation bitmaps, so we avoid a whole series of 4k random
reads.
> - What steps can I take to isolate the cause of the problem? If there's any
> information I can provide, please let me know.
If you run dumpe2fs on the file system and send us the output, we can
probably confirm this pretty quickly. The e2freefrag program can also
show us whether how fragmented the free space is, but I'm pretty sure
that's not the problem.
Something that might help is simply running "dumpe2fs /dev/sdXX >
/dev/null" or "e2freefrag /dev/hdXX > /dev/null" after you mount the
file system and before you kick off the backup. This will load all of
the block allocation bitmaps into the buffer cache, and the libext2fs
functions used by dumpe2fs and e2freefrag will do so much more
efficiently than the kernel code will as it demand-loads the bitmap
blocks.
Hope this helps!
- Ted
On Jun 15, 2014, at 11:43 PM, Joseph D. Wagner <[email protected]> wrote:
> Background:
> - I use lvm snapshots on ext4 for backup. I use dump to backup the snapshots. The backup goes to an external hard drive over usb 3.0. The external hard drive has 1 partition formatted with ext4.
>
> Problem:
> - I've noticed the performance of dump to my ext4 backup degrades linearly as the disk fills. In the output, the kbps in the status line keeps getting lower as the percent complete keeps getting higher.
One major cause for performance degradation as a disk fills is that the
inner tracks of a disk (higher block addresses) have about 1/2 the
throughput of the outer tracks (lower block addresses). This means it
is basically impossible to get more than 50% of the performance from
blocks that are allocated on the higher addresses in the filesystem.
You could test this by creating a partition on the low blocks of the disk,
one that consumes most of the remaining space, and one at the high blocks
of the disk, create filesystems on the low- and high-block partitions, and
then running benchmarks on them.
Cheers, Andreas
> My Thoughts So Far:
> - I suspect that either 1) dump is doing something which lowers performance as the backup progresses, or 2) the ext4 algorithm for finding and allocating free blocks is vulnerable to performance degradation as the volume fills.
>
> - I haven't tested this thoroughly. However, performance appears to improve when I clear out the external drive and do a fresh, full dump (-0), and performance appears to remain degraded on incremental backups on a nearly full volume. This leads me to suspect #2.
>
> Help from you:
> - What steps can I take to isolate the cause of the problem? If there's any information I can provide, please let me know.
>
> What I've Done:
> - I've run both the short and long SMART tests on the external drive, which came back clean. They also told me the relocated sector count was zero.
>
> - I also made sure the disk was connecting in usb 3.0 mode.
>
> - I changed the external drive ext4 mount from journal=ordered to journal=writeback. The performance difference was nominal.
>
> Any insight would be appreciated.
>
> Thanks.
>
> Joseph D. Wagner
> --
> To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
Cheers, Andreas
On 06/16/2014 05:42 AM, Theodore Ts'o wrote:
> Something that might help is simply running "dumpe2fs /dev/sdXX >
> /dev/null" or "e2freefrag /dev/hdXX > /dev/null" after you mount the
> file system and before you kick off the backup. This will load all of
> the block allocation bitmaps into the buffer cache, and the libext2fs
> functions used by dumpe2fs and e2freefrag will do so much more
> efficiently than the kernel code will as it demand-loads the bitmap
> blocks. Hope this helps! - Ted
I just got done trying that. Below is what I am seeing. It seemed to
do well up until 20%, but then performance drops. Between 31% and 33%,
I reran dumpe2fs in case this was some sort of cache poison issue. As
you can see, it didn't improve performance at the time.
FYI, lvbackup is a script I wrote to 1) create to lvm snapshot, 2) run
dump, and 3) drop the snapshot.
# su -c 'cd /root; dumpe2fs /dev/mapper/backup > /dev/null; nice ionice
-c3 /usr/local/bin/lvbackup /dev/data/home /mnt/backup'
Password:
dumpe2fs 1.42.8 (20-Jun-2013)
DUMP: mount: bad UUID
DUMP: Date of this level 0 dump: Mon Jun 16 20:08:57 2014
DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to
/mnt/backup/backup-data-home-20140616.200856-0.img
DUMP: Label: none
DUMP: Writing 64 Kilobyte records
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 1722505007 blocks.
DUMP: writing QFA positions to
/mnt/backup/backup-data-home-20140616.200856-0.qfa
DUMP: Volume 1 started with block 1 at: Mon Jun 16 20:09:11 2014
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 1.92% done at 110516 kB/s, finished in 4:14
DUMP: 4.05% done at 116142 kB/s, finished in 3:57
DUMP: 6.27% done at 119939 kB/s, finished in 3:44
DUMP: 8.51% done at 122095 kB/s, finished in 3:35
DUMP: 10.73% done at 123209 kB/s, finished in 3:28
DUMP: 12.89% done at 123382 kB/s, finished in 3:22
DUMP: 14.98% done at 122868 kB/s, finished in 3:18
DUMP: 17.05% done at 122380 kB/s, finished in 3:14
DUMP: 18.98% done at 121068 kB/s, finished in 3:12
DUMP: 20.37% done at 116976 kB/s, finished in 3:15
DUMP: 21.72% done at 113360 kB/s, finished in 3:18
DUMP: 23.12% done at 110641 kB/s, finished in 3:19
DUMP: 24.40% done at 107777 kB/s, finished in 3:21
DUMP: 25.76% done at 105628 kB/s, finished in 3:21
DUMP: 27.08% done at 103641 kB/s, finished in 3:21
DUMP: 28.30% done at 101527 kB/s, finished in 3:22
DUMP: 29.50% done at 99508 kB/s, finished in 3:23
DUMP: 30.79% done at 98101 kB/s, finished in 3:22
DUMP: 31.88% done at 96210 kB/s, finished in 3:23
DUMP: 33.31% done at 95509 kB/s, finished in 3:20
DUMP: 34.50% done at 94219 kB/s, finished in 3:19
DUMP: 35.86% done at 93449 kB/s, finished in 3:17
DUMP: 37.25% done at 92860 kB/s, finished in 3:14
DUMP: 38.64% done at 92323 kB/s, finished in 3:10
DUMP: 39.91% done at 91559 kB/s, finished in 3:08
DUMP: 41.18% done at 90845 kB/s, finished in 3:05
DUMP: 42.59% done at 90476 kB/s, finished in 3:02
DUMP: 43.88% done at 89885 kB/s, finished in 2:59
DUMP: 45.09% done at 89188 kB/s, finished in 2:56
DUMP: 46.45% done at 88794 kB/s, finished in 2:53
DUMP: 47.77% done at 88370 kB/s, finished in 2:49
DUMP: 49.12% done at 88029 kB/s, finished in 2:45
DUMP: 50.36% done at 87518 kB/s, finished in 2:42
DUMP: 51.53% done at 86929 kB/s, finished in 2:40
DUMP: 52.65% done at 86276 kB/s, finished in 2:37
DUMP: 53.97% done at 85979 kB/s, finished in 2:33
DUMP: 55.30% done at 85720 kB/s, finished in 2:29
DUMP: 56.58% done at 85388 kB/s, finished in 2:25
DUMP: 57.91% done at 85158 kB/s, finished in 2:21
DUMP: 59.30% done at 85024 kB/s, finished in 2:17
DUMP: 60.66% done at 84848 kB/s, finished in 2:13
DUMP: 61.94% done at 84576 kB/s, finished in 2:09
DUMP: 63.21% done at 84299 kB/s, finished in 2:05
DUMP: 64.24% done at 83730 kB/s, finished in 2:02
DUMP: 65.37% done at 83309 kB/s, finished in 1:59
DUMP: 66.48% done at 82892 kB/s, finished in 1:56
DUMP: 67.69% done at 82599 kB/s, finished in 1:52
DUMP: 68.76% done at 82161 kB/s, finished in 1:49
DUMP: 69.90% done at 81788 kB/s, finished in 1:45
DUMP: 70.95% done at 81365 kB/s, finished in 1:42
DUMP: 72.13% done at 81094 kB/s, finished in 1:38
DUMP: 73.33% done at 80861 kB/s, finished in 1:34
DUMP: 74.42% done at 80510 kB/s, finished in 1:31
DUMP: 75.51% done at 80186 kB/s, finished in 1:27
DUMP: 76.65% done at 79919 kB/s, finished in 1:23
DUMP: 77.72% done at 79577 kB/s, finished in 1:20
DUMP: 78.74% done at 79212 kB/s, finished in 1:17
DUMP: 79.92% done at 79016 kB/s, finished in 1:12
DUMP: 81.00% done at 78728 kB/s, finished in 1:09
DUMP: 82.20% done at 78564 kB/s, finished in 1:05
DUMP: 83.33% done at 78344 kB/s, finished in 1:01
DUMP: 84.39% done at 78048 kB/s, finished in 0:57
DUMP: 85.19% done at 77542 kB/s, finished in 0:54
DUMP: 86.20% done at 77237 kB/s, finished in 0:51
DUMP: 87.19% done at 76919 kB/s, finished in 0:47
DUMP: 88.13% done at 76568 kB/s, finished in 0:44
DUMP: 89.14% done at 76289 kB/s, finished in 0:40
DUMP: 90.08% done at 75961 kB/s, finished in 0:37
DUMP: 91.20% done at 75791 kB/s, finished in 0:33
DUMP: 92.34% done at 75646 kB/s, finished in 0:29
DUMP: 93.56% done at 75563 kB/s, finished in 0:24
DUMP: 94.69% done at 75415 kB/s, finished in 0:20
DUMP: 95.77% done at 75203 kB/s, finished in 0:16
DUMP: 96.83% done at 74995 kB/s, finished in 0:12
DUMP: 97.79% done at 74733 kB/s, finished in 0:08
DUMP: 98.74% done at 74465 kB/s, finished in 0:04
DUMP: 99.67% done at 74171 kB/s, finished in 0:01
DUMP: Closing /mnt/backup/backup-data-home-20140616.200856-0.img
DUMP: Volume 1 completed at: Tue Jun 17 02:36:40 2014
DUMP: Volume 1 1722545856 blocks (1682173.69MB)
DUMP: Volume 1 took 6:27:29
DUMP: Volume 1 transfer rate: 74091 kB/s
DUMP: 1722545856 blocks (1682173.69MB) on 1 volume(s)
DUMP: finished in 23249 seconds, throughput 74091 kBytes/sec
DUMP: Date of this level 0 dump: Mon Jun 16 20:08:57 2014
DUMP: Date this dump completed: Tue Jun 17 02:36:40 2014
DUMP: Average transfer rate: 74091 kB/s
DUMP: Archiving dump to
/mnt/backup/backup-data-home-20140616.200856-0.toc
DUMP: DUMP IS DONE
Logical volume "backup-data-home" successfully removed
Hmm, I've looked at your dumpe2fs, and the free space looks pretty
good. Was this taken before or after you ran the backup?
How big are your full and incremental backups? And were you testing
the time when writing an incremental backup or a full backup?
Finally, can you use the debugfs program, and then use the debugfs's
"extents" commands? i.e.
% debugfs /dev/heap/u1
debugfs: extents linux-image-3.15.0-00037-g7428869-dbg_3.15.0-00037-g7428869-86_amd64.deb
Level Entries Logical Physical Length Flags
0/ 0 1/ 3 0 - 9 16898520 - 16898529 10
0/ 0 2/ 3 10 - 2047 17518592 - 17520629 2038
0/ 0 3/ 3 2048 - 9881 17500160 - 17507993 7834
debugfs: q
... and send me the output?
Thanks!!
- Ted
Hello Theo.
I know you're working-for-free and have other things to do besides
work on my low priority problem. However, I haven't heard from you.
I just wanted to follow-up and make sure you got my attachment,
not that anything fell through the cracks so-to-speak.
Again, thanks for all your help and everything you do!
Joseph Wagner
>> What steps can I take to isolate the cause of the problem?
>> If there's any information I can provide, please let me know.
> If you run dumpe2fs on the file system and send us the output,
> we can probably confirm this pretty quickly. The e2freefrag
> program can also show us whether how fragmented the free space
> is, but I'm pretty sure that's not the problem.
Per your request, output of dumpe2fs attached. Also, just to cover
all the bases, output from e2freefrag is below.
Thanks for your time.
Joseph D. Wagner
Device: /dev/mapper/backup
Blocksize: 4096 bytes
Total blocks: 488377856
Free blocks: 42120116 (8.6%)
Min. free extent: 28 KB
Max. free extent: 2064256 KB
Avg. free extent: 167140 KB
Num. free extent: 1008
HISTOGRAM OF FREE EXTENT SIZES:
Extent Size Range : Free extents Free Blocks Percent
16K... 32K- : 2 14 0.00%
512K... 1024K- : 1 210 0.00%
1M... 2M- : 28 13886 0.03%
2M... 4M- : 7 7158 0.02%
4M... 8M- : 37 74906 0.18%
64M... 128M- : 893 21916758 52.03%
512M... 1024M- : 2 496752 1.18%
1G... 2G- : 38 19610432 46.56%
Below is what I am seeing. It seemed to do well up until 20%, but
then performance drops. Between 31% and 33%, I reran dumpe2fs in
case this was some sort of cache poison issue. As you can see, it
didn't improve performance at the time.
FYI, lvbackup is a script I wrote to 1) create to lvm snapshot,
2) run dump, and 3) drop the snapshot.
# su -c 'cd /root; dumpe2fs /dev/mapper/backup > /dev/null; nice ionice
-c3 /usr/local/bin/lvbackup /dev/data/home /mnt/backup'
Password:
dumpe2fs 1.42.8 (20-Jun-2013)
DUMP: mount: bad UUID
DUMP: Date of this level 0 dump: Mon Jun 16 20:08:57 2014
DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to
/mnt/backup/backup-data-home-20140616.200856-0.img
DUMP: Label: none
DUMP: Writing 64 Kilobyte records
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 1722505007 blocks.
DUMP: writing QFA positions to
/mnt/backup/backup-data-home-20140616.200856-0.qfa
DUMP: Volume 1 started with block 1 at: Mon Jun 16 20:09:11 2014
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 1.92% done at 110516 kB/s, finished in 4:14
DUMP: 4.05% done at 116142 kB/s, finished in 3:57
DUMP: 6.27% done at 119939 kB/s, finished in 3:44
DUMP: 8.51% done at 122095 kB/s, finished in 3:35
DUMP: 10.73% done at 123209 kB/s, finished in 3:28
DUMP: 12.89% done at 123382 kB/s, finished in 3:22
DUMP: 14.98% done at 122868 kB/s, finished in 3:18
DUMP: 17.05% done at 122380 kB/s, finished in 3:14
DUMP: 18.98% done at 121068 kB/s, finished in 3:12
DUMP: 20.37% done at 116976 kB/s, finished in 3:15
DUMP: 21.72% done at 113360 kB/s, finished in 3:18
DUMP: 23.12% done at 110641 kB/s, finished in 3:19
DUMP: 24.40% done at 107777 kB/s, finished in 3:21
DUMP: 25.76% done at 105628 kB/s, finished in 3:21
DUMP: 27.08% done at 103641 kB/s, finished in 3:21
DUMP: 28.30% done at 101527 kB/s, finished in 3:22
DUMP: 29.50% done at 99508 kB/s, finished in 3:23
DUMP: 30.79% done at 98101 kB/s, finished in 3:22
DUMP: 31.88% done at 96210 kB/s, finished in 3:23
DUMP: 33.31% done at 95509 kB/s, finished in 3:20
DUMP: 34.50% done at 94219 kB/s, finished in 3:19
DUMP: 35.86% done at 93449 kB/s, finished in 3:17
DUMP: 37.25% done at 92860 kB/s, finished in 3:14
DUMP: 38.64% done at 92323 kB/s, finished in 3:10
DUMP: 39.91% done at 91559 kB/s, finished in 3:08
DUMP: 41.18% done at 90845 kB/s, finished in 3:05
DUMP: 42.59% done at 90476 kB/s, finished in 3:02
DUMP: 43.88% done at 89885 kB/s, finished in 2:59
DUMP: 45.09% done at 89188 kB/s, finished in 2:56
DUMP: 46.45% done at 88794 kB/s, finished in 2:53
DUMP: 47.77% done at 88370 kB/s, finished in 2:49
DUMP: 49.12% done at 88029 kB/s, finished in 2:45
DUMP: 50.36% done at 87518 kB/s, finished in 2:42
DUMP: 51.53% done at 86929 kB/s, finished in 2:40
DUMP: 52.65% done at 86276 kB/s, finished in 2:37
DUMP: 53.97% done at 85979 kB/s, finished in 2:33
DUMP: 55.30% done at 85720 kB/s, finished in 2:29
DUMP: 56.58% done at 85388 kB/s, finished in 2:25
DUMP: 57.91% done at 85158 kB/s, finished in 2:21
DUMP: 59.30% done at 85024 kB/s, finished in 2:17
DUMP: 60.66% done at 84848 kB/s, finished in 2:13
DUMP: 61.94% done at 84576 kB/s, finished in 2:09
DUMP: 63.21% done at 84299 kB/s, finished in 2:05
DUMP: 64.24% done at 83730 kB/s, finished in 2:02
DUMP: 65.37% done at 83309 kB/s, finished in 1:59
DUMP: 66.48% done at 82892 kB/s, finished in 1:56
DUMP: 67.69% done at 82599 kB/s, finished in 1:52
DUMP: 68.76% done at 82161 kB/s, finished in 1:49
DUMP: 69.90% done at 81788 kB/s, finished in 1:45
DUMP: 70.95% done at 81365 kB/s, finished in 1:42
DUMP: 72.13% done at 81094 kB/s, finished in 1:38
DUMP: 73.33% done at 80861 kB/s, finished in 1:34
DUMP: 74.42% done at 80510 kB/s, finished in 1:31
DUMP: 75.51% done at 80186 kB/s, finished in 1:27
DUMP: 76.65% done at 79919 kB/s, finished in 1:23
DUMP: 77.72% done at 79577 kB/s, finished in 1:20
DUMP: 78.74% done at 79212 kB/s, finished in 1:17
DUMP: 79.92% done at 79016 kB/s, finished in 1:12
DUMP: 81.00% done at 78728 kB/s, finished in 1:09
DUMP: 82.20% done at 78564 kB/s, finished in 1:05
DUMP: 83.33% done at 78344 kB/s, finished in 1:01
DUMP: 84.39% done at 78048 kB/s, finished in 0:57
DUMP: 85.19% done at 77542 kB/s, finished in 0:54
DUMP: 86.20% done at 77237 kB/s, finished in 0:51
DUMP: 87.19% done at 76919 kB/s, finished in 0:47
DUMP: 88.13% done at 76568 kB/s, finished in 0:44
DUMP: 89.14% done at 76289 kB/s, finished in 0:40
DUMP: 90.08% done at 75961 kB/s, finished in 0:37
DUMP: 91.20% done at 75791 kB/s, finished in 0:33
DUMP: 92.34% done at 75646 kB/s, finished in 0:29
DUMP: 93.56% done at 75563 kB/s, finished in 0:24
DUMP: 94.69% done at 75415 kB/s, finished in 0:20
DUMP: 95.77% done at 75203 kB/s, finished in 0:16
DUMP: 96.83% done at 74995 kB/s, finished in 0:12
DUMP: 97.79% done at 74733 kB/s, finished in 0:08
DUMP: 98.74% done at 74465 kB/s, finished in 0:04
DUMP: 99.67% done at 74171 kB/s, finished in 0:01
DUMP: Closing /mnt/backup/backup-data-home-20140616.200856-0.img
DUMP: Volume 1 completed at: Tue Jun 17 02:36:40 2014
DUMP: Volume 1 1722545856 blocks (1682173.69MB)
DUMP: Volume 1 took 6:27:29
DUMP: Volume 1 transfer rate: 74091 kB/s
DUMP: 1722545856 blocks (1682173.69MB) on 1 volume(s)
DUMP: finished in 23249 seconds, throughput 74091 kBytes/sec
DUMP: Date of this level 0 dump: Mon Jun 16 20:08:57 2014
DUMP: Date this dump completed: Tue Jun 17 02:36:40 2014
DUMP: Average transfer rate: 74091 kB/s
DUMP: Archiving dump to
/mnt/backup/backup-data-home-20140616.200856-0.toc
DUMP: DUMP IS DONE
Logical volume "backup-data-home" successfully removed
I think I can prove it's the file system. I reformatted for XFS, and
the
results speak for themselves.
XFS is able to complete the backup in 4:24:16, whereas EXT4 takes
6:27:29.
This difference cannot be explained by the location of the sectors on
the
disk; nor is caching of free sector maps sufficient to explain a 33%
difference is overall performance.
XFS does not dip below 115 mB/s until 64.22%. Even then, the loss in
minimal so that performance never drops below 108 mB/s (6% loss).
EXT4, on the other hand, drops below 115 mB/s at 21.72%. Performance
continues to drop precipitously until reaching 74 mB/s (35% loss).
EXT4 is *doing* *something* to cause a recursive loss in performance.
Joseph D. Wagner
This is xfs.
# su -c 'cd /root; nice ionice -c3 /usr/local/bin/lvbackup
/dev/data/home /mnt/backup'
Password:
DUMP: mount: bad UUID
DUMP: Date of this level 0 dump: Fri Jun 20 10:24:39 2014
DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to
/mnt/backup/backup-data-home-20140620.102438-0.img
DUMP: Label: none
DUMP: Writing 64 Kilobyte records
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 1716954416 blocks.
DUMP: writing QFA positions to
/mnt/backup/backup-data-home-20140620.102438-0.qfa
DUMP: Volume 1 started with block 1 at: Fri Jun 20 10:24:53 2014
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 1.94% done at 110770 kB/s, finished in 4:13
DUMP: 4.05% done at 115842 kB/s, finished in 3:57
DUMP: 6.11% done at 116545 kB/s, finished in 3:50
DUMP: 8.25% done at 118041 kB/s, finished in 3:42
DUMP: 10.38% done at 118825 kB/s, finished in 3:35
DUMP: 12.54% done at 119635 kB/s, finished in 3:29
DUMP: 14.73% done at 120414 kB/s, finished in 3:22
DUMP: 16.94% done at 121214 kB/s, finished in 3:16
DUMP: 19.03% done at 121000 kB/s, finished in 3:11
DUMP: 21.18% done at 121245 kB/s, finished in 3:06
DUMP: 23.23% done at 120878 kB/s, finished in 3:01
DUMP: 25.20% done at 120198 kB/s, finished in 2:58
DUMP: 27.24% done at 119910 kB/s, finished in 2:53
DUMP: 28.93% done at 118256 kB/s, finished in 2:51
DUMP: 30.84% done at 117652 kB/s, finished in 2:48
DUMP: 32.62% done at 116691 kB/s, finished in 2:45
DUMP: 34.37% done at 115692 kB/s, finished in 2:42
DUMP: 36.41% done at 115770 kB/s, finished in 2:37
DUMP: 38.50% done at 115959 kB/s, finished in 2:31
DUMP: 40.37% done at 115530 kB/s, finished in 2:27
DUMP: 42.48% done at 115778 kB/s, finished in 2:22
DUMP: 44.53% done at 115851 kB/s, finished in 2:17
DUMP: 46.61% done at 115969 kB/s, finished in 2:11
DUMP: 48.73% done at 116211 kB/s, finished in 2:06
DUMP: 50.66% done at 115975 kB/s, finished in 2:01
DUMP: 52.36% done at 115249 kB/s, finished in 1:58
DUMP: 54.28% done at 115050 kB/s, finished in 1:53
DUMP: 56.27% done at 115023 kB/s, finished in 1:48
DUMP: 58.35% done at 115161 kB/s, finished in 1:43
DUMP: 60.43% done at 115292 kB/s, finished in 1:38
DUMP: 62.49% done at 115363 kB/s, finished in 1:33
DUMP: 64.22% done at 114853 kB/s, finished in 1:29
DUMP: 65.87% done at 114234 kB/s, finished in 1:25
DUMP: 67.65% done at 113869 kB/s, finished in 1:21
DUMP: 69.25% done at 113243 kB/s, finished in 1:17
DUMP: 70.97% done at 112823 kB/s, finished in 1:13
DUMP: 72.77% done at 112554 kB/s, finished in 1:09
DUMP: 74.52% done at 112228 kB/s, finished in 1:04
DUMP: 76.30% done at 111963 kB/s, finished in 1:00
DUMP: 78.04% done at 111662 kB/s, finished in 0:56
DUMP: 79.68% done at 111220 kB/s, finished in 0:52
DUMP: 81.46% done at 111001 kB/s, finished in 0:47
DUMP: 83.39% done at 110994 kB/s, finished in 0:42
DUMP: 84.95% done at 110498 kB/s, finished in 0:38
DUMP: 86.41% done at 109899 kB/s, finished in 0:35
DUMP: 87.96% done at 109433 kB/s, finished in 0:31
DUMP: 89.49% done at 108970 kB/s, finished in 0:27
DUMP: 91.21% done at 108756 kB/s, finished in 0:23
DUMP: 93.21% done at 108869 kB/s, finished in 0:17
DUMP: 95.23% done at 109007 kB/s, finished in 0:12
DUMP: 97.05% done at 108905 kB/s, finished in 0:07
DUMP: 98.71% done at 108645 kB/s, finished in 0:03
DUMP: Closing /mnt/backup/backup-data-home-20140620.102438-0.img
DUMP: Volume 1 completed at: Fri Jun 20 14:49:09 2014
DUMP: Volume 1 1716994432 blocks (1676752.38MB)
DUMP: Volume 1 took 4:24:16
DUMP: Volume 1 transfer rate: 108286 kB/s
DUMP: 1716994432 blocks (1676752.38MB) on 1 volume(s)
DUMP: finished in 15854 seconds, throughput 108300 kBytes/sec
DUMP: Date of this level 0 dump: Fri Jun 20 10:24:39 2014
DUMP: Date this dump completed: Fri Jun 20 14:49:09 2014
DUMP: Average transfer rate: 108286 kB/s
DUMP: Archiving dump to
/mnt/backup/backup-data-home-20140620.102438-0.toc
DUMP: DUMP IS DONE
Logical volume "backup-data-home" successfully removed
This is ext4.
# su -c 'cd /root; dumpe2fs /dev/mapper/backup > /dev/null; nice ionice
-c3 /usr/local/bin/lvbackup /dev/data/home /mnt/backup'
Password:
dumpe2fs 1.42.8 (20-Jun-2013)
DUMP: mount: bad UUID
DUMP: Date of this level 0 dump: Mon Jun 16 20:08:57 2014
DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to
/mnt/backup/backup-data-home-20140616.200856-0.img
DUMP: Label: none
DUMP: Writing 64 Kilobyte records
DUMP: mapping (Pass I) [regular files]
DUMP: mapping (Pass II) [directories]
DUMP: estimated 1722505007 blocks.
DUMP: writing QFA positions to
/mnt/backup/backup-data-home-20140616.200856-0.qfa
DUMP: Volume 1 started with block 1 at: Mon Jun 16 20:09:11 2014
DUMP: dumping (Pass III) [directories]
DUMP: dumping (Pass IV) [regular files]
DUMP: 1.92% done at 110516 kB/s, finished in 4:14
DUMP: 4.05% done at 116142 kB/s, finished in 3:57
DUMP: 6.27% done at 119939 kB/s, finished in 3:44
DUMP: 8.51% done at 122095 kB/s, finished in 3:35
DUMP: 10.73% done at 123209 kB/s, finished in 3:28
DUMP: 12.89% done at 123382 kB/s, finished in 3:22
DUMP: 14.98% done at 122868 kB/s, finished in 3:18
DUMP: 17.05% done at 122380 kB/s, finished in 3:14
DUMP: 18.98% done at 121068 kB/s, finished in 3:12
DUMP: 20.37% done at 116976 kB/s, finished in 3:15
DUMP: 21.72% done at 113360 kB/s, finished in 3:18
DUMP: 23.12% done at 110641 kB/s, finished in 3:19
DUMP: 24.40% done at 107777 kB/s, finished in 3:21
DUMP: 25.76% done at 105628 kB/s, finished in 3:21
DUMP: 27.08% done at 103641 kB/s, finished in 3:21
DUMP: 28.30% done at 101527 kB/s, finished in 3:22
DUMP: 29.50% done at 99508 kB/s, finished in 3:23
DUMP: 30.79% done at 98101 kB/s, finished in 3:22
DUMP: 31.88% done at 96210 kB/s, finished in 3:23
DUMP: 33.31% done at 95509 kB/s, finished in 3:20
DUMP: 34.50% done at 94219 kB/s, finished in 3:19
DUMP: 35.86% done at 93449 kB/s, finished in 3:17
DUMP: 37.25% done at 92860 kB/s, finished in 3:14
DUMP: 38.64% done at 92323 kB/s, finished in 3:10
DUMP: 39.91% done at 91559 kB/s, finished in 3:08
DUMP: 41.18% done at 90845 kB/s, finished in 3:05
DUMP: 42.59% done at 90476 kB/s, finished in 3:02
DUMP: 43.88% done at 89885 kB/s, finished in 2:59
DUMP: 45.09% done at 89188 kB/s, finished in 2:56
DUMP: 46.45% done at 88794 kB/s, finished in 2:53
DUMP: 47.77% done at 88370 kB/s, finished in 2:49
DUMP: 49.12% done at 88029 kB/s, finished in 2:45
DUMP: 50.36% done at 87518 kB/s, finished in 2:42
DUMP: 51.53% done at 86929 kB/s, finished in 2:40
DUMP: 52.65% done at 86276 kB/s, finished in 2:37
DUMP: 53.97% done at 85979 kB/s, finished in 2:33
DUMP: 55.30% done at 85720 kB/s, finished in 2:29
DUMP: 56.58% done at 85388 kB/s, finished in 2:25
DUMP: 57.91% done at 85158 kB/s, finished in 2:21
DUMP: 59.30% done at 85024 kB/s, finished in 2:17
DUMP: 60.66% done at 84848 kB/s, finished in 2:13
DUMP: 61.94% done at 84576 kB/s, finished in 2:09
DUMP: 63.21% done at 84299 kB/s, finished in 2:05
DUMP: 64.24% done at 83730 kB/s, finished in 2:02
DUMP: 65.37% done at 83309 kB/s, finished in 1:59
DUMP: 66.48% done at 82892 kB/s, finished in 1:56
DUMP: 67.69% done at 82599 kB/s, finished in 1:52
DUMP: 68.76% done at 82161 kB/s, finished in 1:49
DUMP: 69.90% done at 81788 kB/s, finished in 1:45
DUMP: 70.95% done at 81365 kB/s, finished in 1:42
DUMP: 72.13% done at 81094 kB/s, finished in 1:38
DUMP: 73.33% done at 80861 kB/s, finished in 1:34
DUMP: 74.42% done at 80510 kB/s, finished in 1:31
DUMP: 75.51% done at 80186 kB/s, finished in 1:27
DUMP: 76.65% done at 79919 kB/s, finished in 1:23
DUMP: 77.72% done at 79577 kB/s, finished in 1:20
DUMP: 78.74% done at 79212 kB/s, finished in 1:17
DUMP: 79.92% done at 79016 kB/s, finished in 1:12
DUMP: 81.00% done at 78728 kB/s, finished in 1:09
DUMP: 82.20% done at 78564 kB/s, finished in 1:05
DUMP: 83.33% done at 78344 kB/s, finished in 1:01
DUMP: 84.39% done at 78048 kB/s, finished in 0:57
DUMP: 85.19% done at 77542 kB/s, finished in 0:54
DUMP: 86.20% done at 77237 kB/s, finished in 0:51
DUMP: 87.19% done at 76919 kB/s, finished in 0:47
DUMP: 88.13% done at 76568 kB/s, finished in 0:44
DUMP: 89.14% done at 76289 kB/s, finished in 0:40
DUMP: 90.08% done at 75961 kB/s, finished in 0:37
DUMP: 91.20% done at 75791 kB/s, finished in 0:33
DUMP: 92.34% done at 75646 kB/s, finished in 0:29
DUMP: 93.56% done at 75563 kB/s, finished in 0:24
DUMP: 94.69% done at 75415 kB/s, finished in 0:20
DUMP: 95.77% done at 75203 kB/s, finished in 0:16
DUMP: 96.83% done at 74995 kB/s, finished in 0:12
DUMP: 97.79% done at 74733 kB/s, finished in 0:08
DUMP: 98.74% done at 74465 kB/s, finished in 0:04
DUMP: 99.67% done at 74171 kB/s, finished in 0:01
DUMP: Closing /mnt/backup/backup-data-home-20140616.200856-0.img
DUMP: Volume 1 completed at: Tue Jun 17 02:36:40 2014
DUMP: Volume 1 1722545856 blocks (1682173.69MB)
DUMP: Volume 1 took 6:27:29
DUMP: Volume 1 transfer rate: 74091 kB/s
DUMP: 1722545856 blocks (1682173.69MB) on 1 volume(s)
DUMP: finished in 23249 seconds, throughput 74091 kBytes/sec
DUMP: Date of this level 0 dump: Mon Jun 16 20:08:57 2014
DUMP: Date this dump completed: Tue Jun 17 02:36:40 2014
DUMP: Average transfer rate: 74091 kB/s
DUMP: Archiving dump to
/mnt/backup/backup-data-home-20140616.200856-0.toc
DUMP: DUMP IS DONE
Logical volume "backup-data-home" successfully removed
On Thu, Jun 19, 2014 at 11:42:38AM -0700, Joseph D. Wagner wrote:
> Hello Theo.
>
> I know you're working-for-free and have other things to do besides
> work on my low priority problem. However, I haven't heard from you.
> I just wanted to follow-up and make sure you got my attachment,
> not that anything fell through the cracks so-to-speak.
Sorry, I did get your attachment. I've just been crazy busy as of
late. Between work and several other projects, I just haven't had
time to get back to this.
Nothing really obvious is jumping out at me. There are some
tracepoints we could set to try to analyze what might be happening,
but it's going to take a bit of time to describe how to do it, and
more time to analyze the results afterwards, which is why I haven't
gotten back to you.
The short version is we'd want to enable the tracepoints
"ext4_mballoc_alloc" and "ext4_read_block_bitmap_load" and grab some
trace output at the beginning of the backup, and at the end, and see
if anything obvious shows up.
Another experiment that might be worth trying to run the backup to 30%
or so, and then stop the backup, and rename the backup file so it's
not overwritten, and then start a fresh full backup. What we would be
trying to determine is whether the decreased performance is due to the
disk space fillin gup, or due the size of the backup file that is
being written which is causing the slow down.
Cheers,
- Ted
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
On 6/19/2014 2:42 PM, Joseph D. Wagner wrote:
> Hello Theo.
>
> I know you're working-for-free and have other things to do besides
> work on my low priority problem. However, I haven't heard from
> you. I just wanted to follow-up and make sure you got my
> attachment, not that anything fell through the cracks so-to-speak.
Just thought I'd suggest two things you might try:
1) dump to /dev/null to make sure it is a read problem, and not a
problem writing the output file.
2) You might try throwing e2defrag at the fs and see if that helps (
after a full backup of course ). In the past I have seen significant
slowness when dumping due to my Maildir being fragmented all to hell.
If you have any sets of large numbers of relatively small files, that
could be what you are seeing. An e2defrag pass will completely clear
this up.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (MingW32)
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJT2Ao/AAoJEI5FoCIzSKrwsOYH/R/k7GLCUEV59/didyUml6jC
MMZ3LlHBcFZQeWrZ8f0VlIJ46Kc3Cc7Xmc82GDFbhg6m+m2vkz48/78wj+CpQvn3
Rw/l6aJw9pC6c6riA6OzXdzYESJZI7njH+IEOJFJdtziUrBRcZ6W8UpIxkZ3DAWl
66CGz7UxfBYLme4RftIe1+dz6YKORNlwQ3Mnu16nocsggkA09gHbGqYQvMIpWGdj
3YiGhg95AT/KCpoyUoxkVq79tzay6c1JPn4mMSB2mOZpTx99oHd9WUk1yasIghk0
4yDOPtO2G1ZN0Mda3C3+cSs/FKoJu1U7ZDSklEGHlFy+cI1EZRi32+PLiMwfS+o=
=/SM9
-----END PGP SIGNATURE-----
On 07/29/2014 1:55 pm, Phillip Susi wrote:
> Just thought I'd suggest two things you might try:
>
> 1) dump to /dev/null to make sure it is a read problem, and not a
> problem writing the output file.
It's not a read problem. It's a write problem. I confirmed this by
reformatting the *destination* media from ext4 to xfs. The problem
disappears on xfs. The problem also disappears on ext4 without a
journal, suggesting the problem is in the journal.
Curiously, formatting with this option also makes the problem disappear:
-E lazy_itable_init=0,lazy_journal_init=0
I filed all of this in a kernel bug report. You may want to take a
look.
https://bugzilla.kernel.org/show_bug.cgi?id=78651
> 2) You might try throwing e2defrag at the fs and see if that helps (
> after a full backup of course ). In the past I have seen significant
> slowness when dumping due to my Maildir being fragmented all to hell.
> If you have any sets of large numbers of relatively small files, that
> could be what you are seeing. An e2defrag pass will completely clear
> this up.
Since the problem disappears when using different options on the
*destination* media, I'm going to assume this is unnecessary for the
source files. As for the img file dump creates, all the extents are 128
MB in size (the maximum extent size on ext4) except for the last one.
Joseph D. Wagner