Bug 78651

Summary: Write performance of ext4 degrades linearly as volume fills
Product: File System Reporter: Joseph D. Wagner (joe)
Component: ext4Assignee: fs_ext4 (fs_ext4)
Status: NEW ---    
Severity: normal CC: szg00000, tytso
Priority: P1    
Hardware: x86-64   
OS: Linux   
Kernel Version: 3.14.8-200.fc20.x86_64 Subsystem:
Regression: No Bisected commit-id:
Attachments: dumpe2fs info for ext4 backup destinaton
debugfs extent info on the dump backup files
trace 1gb journal
trace 256mb journal
memstats 1gb journal
memstats 256mb journal

Description Joseph D. Wagner 2014-06-22 05:44:36 UTC 
Created attachment 140591 [details]
dumpe2fs info for ext4 backup destinaton

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.

- This bug report is based upon a conversation on the ext4 mailing list.  I am filing it, because I now have more information and examples.

Summary:
- I've noticed the performance of dump to my ext4 backup degrades linearly as the disk fills.

Details:
Exhibit A (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.

Exhibit B is the same thing, only I reformatted the destination for XFS.  XFS is able to complete the backup in 4:24:16, whereas EXT4 takes 6:27:29.  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).

Exhibit C, run at Theo's suggestion, is EXT4 but with the destination file broken into smaller, multiple files.  The purprose was to determine if the performance was related to the increase in the file size or the decrease in volume free space.  As you can see, performance did not reset with a new file.  It continued to degrade right were the previous file left off.

I am using journal=writeback.

Any help you can provide would be appreciated.

Joseph D. Wagner

(FYI, lvbackup is a script I wrote to 1) create to lvm snapshot, 2) run dump, and 3) drop the snapshot.)

####
#### Exhibit A
####
#### EXT4 - all in one file
####
# 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 

####
#### Exhibit B
####
#### XFS - all in one file
####
# 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 

####
#### Exhibit C
####
#### EXT4 - multiple files max 512 GiB
####
# 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: Sat Jun 21 12:00:26 2014
  DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to /mnt/backup/backup-data-home-20140621.120025-0.img001
  DUMP: Label: none
  DUMP: Writing 64 Kilobyte records
  DUMP: mapping (Pass I) [regular files]
  DUMP: mapping (Pass II) [directories]
  DUMP: estimated 1718217407 blocks on 3.20 tape(s).
  DUMP: writing QFA positions to /mnt/backup/backup-data-home-20140621.120025-0.qfa
  DUMP: Dumping volume 1 on /mnt/backup/backup-data-home-20140621.120025-0.img001
  DUMP: Volume 1 started with block 1 at: Sat Jun 21 12:00:42 2014
  DUMP: dumping (Pass III) [directories]
  DUMP: dumping (Pass IV) [regular files]
  DUMP: 1.64% done at 94129 kB/s, finished in 4:59
  DUMP: 3.35% done at 96074 kB/s, finished in 4:48
  DUMP: 5.23% done at 99826 kB/s, finished in 4:31
  DUMP: 6.88% done at 97657 kB/s, finished in 4:33
  DUMP: 8.84% done at 100622 kB/s, finished in 4:19
  DUMP: 10.41% done at 98807 kB/s, finished in 4:19
  DUMP: 12.09% done at 98448 kB/s, finished in 4:15
  DUMP: 13.85% done at 98746 kB/s, finished in 4:09
  DUMP: 15.65% done at 99248 kB/s, finished in 4:03
  DUMP: 17.30% done at 98760 kB/s, finished in 3:59
  DUMP: 18.71% done at 97100 kB/s, finished in 3:59
  DUMP: 20.00% done at 95147 kB/s, finished in 4:00
  DUMP: 21.30% done at 93573 kB/s, finished in 4:00
  DUMP: 22.72% done at 92703 kB/s, finished in 3:58
  DUMP: 23.99% done at 91372 kB/s, finished in 3:58
  DUMP: 25.18% done at 89908 kB/s, finished in 3:58
  DUMP: 26.47% done at 88963 kB/s, finished in 3:56
  DUMP: 27.66% done at 87791 kB/s, finished in 3:55
  DUMP: 28.79% done at 86590 kB/s, finished in 3:55
  DUMP: 30.20% done at 86291 kB/s, finished in 3:51
  DUMP: Closing /mnt/backup/backup-data-home-20140621.120025-0.img001
  DUMP: Volume 1 completed at: Sat Jun 21 13:45:37 2014
  DUMP: Volume 1 536870912 blocks (524288.00MB)
  DUMP: Volume 1 took 1:44:55
  DUMP: Volume 1 transfer rate: 85285 kB/s
  DUMP: Dumping volume 2 on /mnt/backup/backup-data-home-20140621.120025-0.img002
  DUMP: Volume 2 started with block 536870913 at: Sat Jun 21 13:45:37 2014
  DUMP: Volume 2 begins with blocks from inode 72884598
  DUMP: 31.35% done at 103402 kB/s, finished in 3:50
  DUMP: 32.72% done at 79585 kB/s, finished in 3:46
  DUMP: 33.86% done at 72674 kB/s, finished in 3:45
  DUMP: 35.17% done at 73506 kB/s, finished in 3:41
  DUMP: 36.64% done at 76084 kB/s, finished in 3:36
  DUMP: 37.99% done at 76331 kB/s, finished in 3:32
  DUMP: 39.34% done at 76531 kB/s, finished in 3:28
  DUMP: 40.59% done at 75612 kB/s, finished in 3:25
  DUMP: 42.05% done at 76594 kB/s, finished in 3:20
  DUMP: 43.44% done at 76949 kB/s, finished in 3:15
  DUMP: 44.67% done at 76327 kB/s, finished in 3:12
  DUMP: 46.06% done at 76613 kB/s, finished in 3:07
  DUMP: 47.41% done at 76573 kB/s, finished in 3:03
  DUMP: 48.79% done at 76742 kB/s, finished in 2:58
  DUMP: 50.11% done at 76661 kB/s, finished in 2:54
  DUMP: 51.20% done at 75751 kB/s, finished in 2:51
  DUMP: 52.38% done at 75231 kB/s, finished in 2:48
  DUMP: 53.53% done at 74696 kB/s, finished in 2:45
  DUMP: 54.91% done at 74892 kB/s, finished in 2:40
  DUMP: 56.25% done at 75005 kB/s, finished in 2:35
  DUMP: 57.56% done at 74987 kB/s, finished in 2:31
  DUMP: 58.97% done at 75267 kB/s, finished in 2:26
  DUMP: 60.28% done at 75223 kB/s, finished in 2:21
  DUMP: 61.66% done at 75385 kB/s, finished in 2:17
  DUMP: Closing /mnt/backup/backup-data-home-20140621.120025-0.img002
  DUMP: Volume 2 completed at: Sat Jun 21 15:44:26 2014
  DUMP: Volume 2 536870912 blocks (524288.00MB)
  DUMP: Volume 2 took 1:58:49
  DUMP: Volume 2 transfer rate: 75308 kB/s
  DUMP: Dumping volume 3 on /mnt/backup/backup-data-home-20140621.120025-0.img003
  DUMP: Volume 3 started with block 1073741825 at: Sat Jun 21 15:44:26 2014
  DUMP: Volume 3 begins with blocks from inode 73008151
  DUMP: 62.92% done at 70800 kB/s, finished in 2:12
  DUMP: 64.05% done at 66272 kB/s, finished in 2:09
  DUMP: 65.20% done at 65845 kB/s, finished in 2:05
  DUMP: 66.32% done at 65453 kB/s, finished in 2:02
  DUMP: 67.52% done at 66171 kB/s, finished in 1:58
  DUMP: 68.54% done at 64677 kB/s, finished in 1:54
  DUMP: 69.66% done at 64530 kB/s, finished in 1:51
  DUMP: 70.85% done at 65029 kB/s, finished in 1:47
  DUMP: 71.98% done at 65002 kB/s, finished in 1:43
  DUMP: 73.10% done at 64898 kB/s, finished in 1:39
  DUMP: 74.23% done at 64856 kB/s, finished in 1:35
  DUMP: 75.29% done at 64495 kB/s, finished in 1:32
  DUMP: 76.44% done at 64603 kB/s, finished in 1:28
  DUMP: 77.58% done at 64634 kB/s, finished in 1:23
  DUMP: 78.65% done at 64423 kB/s, finished in 1:20
  DUMP: 79.75% done at 64317 kB/s, finished in 1:16
  DUMP: 80.81% done at 64101 kB/s, finished in 1:12
  DUMP: 82.02% done at 64408 kB/s, finished in 1:08
  DUMP: 83.15% done at 64405 kB/s, finished in 1:03
  DUMP: 84.18% done at 64132 kB/s, finished in 1:00
  DUMP: 85.11% done at 63617 kB/s, finished in 0:56
  DUMP: 86.08% done at 63220 kB/s, finished in 0:53
  DUMP: 87.09% done at 62987 kB/s, finished in 0:49
  DUMP: 88.09% done at 62750 kB/s, finished in 0:46
  DUMP: 89.01% done at 62316 kB/s, finished in 0:42
  DUMP: 89.95% done at 61974 kB/s, finished in 0:39
  DUMP: 91.03% done at 61976 kB/s, finished in 0:35
  DUMP: 92.16% done at 62074 kB/s, finished in 0:30
  DUMP: 93.28% done at 62154 kB/s, finished in 0:26
  DUMP: Closing /mnt/backup/backup-data-home-20140621.120025-0.img003
  DUMP: Volume 3 completed at: Sat Jun 21 18:08:21 2014
  DUMP: Volume 3 536870912 blocks (524288.00MB)
  DUMP: Volume 3 took 2:23:55
  DUMP: Volume 3 transfer rate: 62173 kB/s
  DUMP: Dumping volume 4 on /mnt/backup/backup-data-home-20140621.120025-0.img004
  DUMP: Volume 4 started with block 1610612737 at: Sat Jun 21 18:08:21 2014
  DUMP: Volume 4 begins with blocks from inode 85721100
  DUMP: 94.43% done at 66325 kB/s, finished in 0:21
  DUMP: 95.62% done at 66893 kB/s, finished in 0:17
  DUMP: 96.63% done at 63366 kB/s, finished in 0:13
  DUMP: 97.56% done at 60584 kB/s, finished in 0:09
  DUMP: 98.49% done at 59004 kB/s, finished in 0:05
  DUMP: 99.41% done at 57866 kB/s, finished in 0:02
  DUMP: Closing /mnt/backup/backup-data-home-20140621.120025-0.img004
  DUMP: Volume 4 completed at: Sat Jun 21 18:40:14 2014
  DUMP: Volume 4 107596224 blocks (105074.44MB)
  DUMP: Volume 4 took 0:31:53
  DUMP: Volume 4 transfer rate: 56244 kB/s
  DUMP: 1718208960 blocks (1677938.44MB) on 4 volume(s)
  DUMP: finished in 23972 seconds, throughput 71675 kBytes/sec
  DUMP: Date of this level 0 dump: Sat Jun 21 12:00:26 2014
  DUMP: Date this dump completed:  Sat Jun 21 18:40:14 2014
  DUMP: Average transfer rate: 69752 kB/s
  DUMP: Archiving dump to /mnt/backup/backup-data-home-20140621.120025-0.toc
  DUMP: DUMP IS DONE
  Logical volume "backup-data-home" successfully removed
Comment 1 Joseph D. Wagner 2014-06-22 05:45:43 UTC 
Created attachment 140601 [details]
debugfs extent info on the dump backup files
Comment 2 Joseph D. Wagner 2014-06-22 23:18:10 UTC 
I changed the script to run "perf record" on the dump command.  I turned tracing on for all jbd2 and ext4 events.  (I had to stop it about half way through, because the perf.data file was getting too big.)  All non-zero results are below.

Are some of these events supposed to be balanced?  For example, there were 8 ext4:ext4_es_shrink_enter, but 0 ext4:ext4_es_shrink_exit.  I'm wondering if some of this code is being called recursively without proper unwinding.  It could explain the recursive loss in performance.

499M ext4:ext4_journal_start: 356 chunks LOST!
252M jbd2:jbd2_handle_stats: 4 chunks LOST!
252M jbd2:jbd2_handle_start: 1 chunks LOST!
252M ext4:ext4_mark_inode_dirty: 3 chunks LOST!
246M ext4:ext4_ext_show_extent: 1 chunks LOST!
246M ext4:ext4_ext_map_blocks_exit: 1 chunks LOST!
246M ext4:ext4_ext_map_blocks_enter: 26 chunks LOST!
246M ext4:ext4_es_lookup_extent_exit
246M ext4:ext4_es_lookup_extent_enter: 1 chunks LOST!
246M ext4:ext4_es_insert_extent
246M ext4:ext4_da_write_end: 6 chunks LOST!
246M ext4:ext4_da_write_begin: 441 chunks LOST!
246M ext4:ext4_da_reserve_space
150 ext4:ext4_drop_inode
77 ext4:ext4_releasepage
17 ext4:ext4_es_cache_extent
8 ext4:ext4_sync_fs
8 ext4:ext4_es_shrink_enter
5 ext4:ext4_es_find_delayed_extent_range_exit
5 ext4:ext4_es_find_delayed_extent_range_enter
3 ext4:ext4_request_inode
3 ext4:ext4_allocate_inode
2 ext4:ext4_ext_load_extent
Comment 3 Joseph D. Wagner 2014-07-05 17:14:07 UTC 
To try to isolate the cause, I reformatted for EXT4 without a journal.  It took 4:57:08, which is 1:30:21 faster than journal=writeback.  The performance is also in line with XFS -- solid performance until about 60%, then a slow loss.

I think it's reasonable to conclude that the problem is either 1) in the journal, or 2) exasperated by the journal.  Full details below.

Joseph D. Wagner

####
#### Exhibit D
####
#### EXT4 without a journal
####
#  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 Jul  4 20:56:18 2014
  DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to /mnt/backup/backup-data-home-20140704.205617-0.img
  DUMP: Label: none
  DUMP: Writing 64 Kilobyte records
  DUMP: mapping (Pass I) [regular files]
  DUMP: mapping (Pass II) [directories]
  DUMP: estimated 1683858285 blocks.
  DUMP: writing QFA positions to /mnt/backup/backup-data-home-20140704.205617-0.qfa
  DUMP: Volume 1 started with block 1 at: Fri Jul  4 20:56:34 2014
  DUMP: dumping (Pass III) [directories]
  DUMP: dumping (Pass IV) [regular files]
  DUMP: 2.07% done at 115916 kB/s, finished in 3:57
  DUMP: 4.06% done at 113802 kB/s, finished in 3:56
  DUMP: 6.16% done at 115264 kB/s, finished in 3:48
  DUMP: 8.22% done at 115393 kB/s, finished in 3:43
  DUMP: 10.22% done at 114721 kB/s, finished in 3:39
  DUMP: 12.24% done at 114460 kB/s, finished in 3:35
  DUMP: 14.13% done at 113336 kB/s, finished in 3:32
  DUMP: 16.08% done at 112677 kB/s, finished in 3:29
  DUMP: 18.06% done at 112519 kB/s, finished in 3:24
  DUMP: 19.92% done at 111700 kB/s, finished in 3:21
  DUMP: 21.74% done at 110805 kB/s, finished in 3:18
  DUMP: 23.41% done at 109263 kB/s, finished in 3:16
  DUMP: 25.23% done at 108728 kB/s, finished in 3:12
  DUMP: 26.88% done at 107565 kB/s, finished in 3:10
  DUMP: 28.76% done at 107411 kB/s, finished in 3:06
  DUMP: 30.24% done at 105899 kB/s, finished in 3:04
  DUMP: 31.88% done at 105088 kB/s, finished in 3:01
  DUMP: 33.34% done at 103814 kB/s, finished in 3:00
  DUMP: 34.70% done at 102363 kB/s, finished in 2:59
  DUMP: 36.17% done at 101378 kB/s, finished in 2:56
  DUMP: 37.71% done at 100673 kB/s, finished in 2:53
  DUMP: 39.44% done at 100494 kB/s, finished in 2:49
  DUMP: 41.38% done at 100855 kB/s, finished in 2:43
  DUMP: 43.05% done at 100558 kB/s, finished in 2:38
  DUMP: 44.90% done at 100692 kB/s, finished in 2:33
  DUMP: 46.76% done at 100787 kB/s, finished in 2:28
  DUMP: 48.71% done at 101101 kB/s, finished in 2:22
  DUMP: 50.25% done at 100583 kB/s, finished in 2:18
  DUMP: 51.99% done at 100462 kB/s, finished in 2:14
  DUMP: 53.77% done at 100449 kB/s, finished in 2:09
  DUMP: 55.59% done at 100497 kB/s, finished in 2:04
  DUMP: 57.36% done at 100404 kB/s, finished in 1:59
  DUMP: 59.07% done at 100261 kB/s, finished in 1:54
  DUMP: 60.89% done at 100320 kB/s, finished in 1:49
  DUMP: 62.66% done at 100288 kB/s, finished in 1:44
  DUMP: 64.16% done at 99842 kB/s, finished in 1:40
  DUMP: 65.73% done at 99529 kB/s, finished in 1:36
  DUMP: 67.26% done at 99174 kB/s, finished in 1:32
  DUMP: 68.50% done at 98419 kB/s, finished in 1:29
  DUMP: 70.10% done at 98196 kB/s, finished in 1:25
  DUMP: 71.73% done at 97990 kB/s, finished in 1:20
  DUMP: 73.28% done at 97734 kB/s, finished in 1:16
  DUMP: 74.80% done at 97447 kB/s, finished in 1:12
  DUMP: 76.43% done at 97252 kB/s, finished in 1:08
  DUMP: 77.87% done at 96884 kB/s, finished in 1:04
  DUMP: 79.49% done at 96739 kB/s, finished in 0:59
  DUMP: 81.09% done at 96596 kB/s, finished in 0:54
  DUMP: 82.91% done at 96708 kB/s, finished in 0:49
  DUMP: 84.45% done at 96502 kB/s, finished in 0:45
  DUMP: 85.60% done at 95864 kB/s, finished in 0:42
  DUMP: 87.12% done at 95659 kB/s, finished in 0:37
  DUMP: 88.67% done at 95490 kB/s, finished in 0:33
  DUMP: 90.15% done at 95260 kB/s, finished in 0:29
  DUMP: 91.97% done at 95387 kB/s, finished in 0:23
  DUMP: 93.62% done at 95328 kB/s, finished in 0:18
  DUMP: 95.20% done at 95216 kB/s, finished in 0:14
  DUMP: 96.63% done at 94950 kB/s, finished in 0:09
  DUMP: 98.19% done at 94824 kB/s, finished in 0:05
  DUMP: 99.64% done at 94595 kB/s, finished in 0:01
  DUMP: Closing /mnt/backup/backup-data-home-20140704.205617-0.img
  DUMP: Volume 1 completed at: Sat Jul  5 01:53:42 2014
  DUMP: Volume 1 1683896576 blocks (1644430.25MB)
  DUMP: Volume 1 took 4:57:08
  DUMP: Volume 1 transfer rate: 94452 kB/s
  DUMP: 1683896576 blocks (1644430.25MB) on 1 volume(s)
  DUMP: finished in 17810 seconds, throughput 94547 kBytes/sec
  DUMP: Date of this level 0 dump: Fri Jul  4 20:56:18 2014
  DUMP: Date this dump completed:  Sat Jul  5 01:53:42 2014
  DUMP: Average transfer rate: 94452 kB/s
  DUMP: Archiving dump to /mnt/backup/backup-data-home-20140704.205617-0.toc
  DUMP: DUMP IS DONE
  Logical volume "backup-data-home" successfully removed
Comment 4 Joseph D. Wagner 2014-07-06 12:52:41 UTC 
Another piece to this puzzle.  I added a journal but mounted with nodelalloc.  Performance was about 42 mB/s (36%) worse than without a journal.  Does delayed allocation work without a journal?

Joseph D. Wagner

####
#### Exhibit E
####
#### EXT4 nodelalloc (journal=writeback)
####
#  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: Sat Jul  5 22:32:02 2014
  DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to /mnt/backup/backup-data-home-20140705.223201-0.img
  DUMP: Label: none
  DUMP: Writing 64 Kilobyte records
  DUMP: mapping (Pass I) [regular files]
  DUMP: mapping (Pass II) [directories]
  DUMP: estimated 1681821740 blocks.
  DUMP: writing QFA positions to /mnt/backup/backup-data-home-20140705.223201-0.qfa
  DUMP: Volume 1 started with block 1 at: Sat Jul  5 22:32:19 2014
  DUMP: dumping (Pass III) [directories]
  DUMP: dumping (Pass IV) [regular files]
  DUMP: 1.31% done at 73586 kB/s, finished in 6:15
  DUMP: 2.70% done at 75693 kB/s, finished in 6:00
  DUMP: 4.07% done at 75953 kB/s, finished in 5:54
  DUMP: 5.48% done at 76649 kB/s, finished in 5:45
  DUMP: 6.95% done at 77753 kB/s, finished in 5:35
  DUMP: 8.46% done at 78880 kB/s, finished in 5:25
  DUMP: 10.04% done at 80296 kB/s, finished in 5:14
  DUMP: 11.55% done at 80829 kB/s, finished in 5:06
  DUMP: 12.99% done at 80580 kB/s, finished in 5:02
  DUMP: 14.50% done at 80968 kB/s, finished in 4:56
  DUMP: 15.98% done at 81181 kB/s, finished in 4:50
  DUMP: 17.25% done at 80318 kB/s, finished in 4:48
  DUMP: 18.47% done at 79445 kB/s, finished in 4:47
  DUMP: 19.74% done at 78843 kB/s, finished in 4:45
  DUMP: 20.97% done at 78122 kB/s, finished in 4:43
  DUMP: 22.18% done at 77472 kB/s, finished in 4:41
  DUMP: 23.32% done at 76680 kB/s, finished in 4:40
  DUMP: 24.56% done at 76288 kB/s, finished in 4:37
  DUMP: 25.79% done at 75880 kB/s, finished in 4:34
  DUMP: 26.82% done at 74889 kB/s, finished in 4:33
  DUMP: 27.95% done at 74327 kB/s, finished in 4:31
  DUMP: 29.05% done at 73752 kB/s, finished in 4:29
  DUMP: 30.06% done at 73005 kB/s, finished in 4:28
  DUMP: 31.29% done at 72833 kB/s, finished in 4:24
  DUMP: 32.43% done at 72439 kB/s, finished in 4:21
  DUMP: 33.71% done at 72335 kB/s, finished in 4:16
  DUMP: 35.02% done at 72379 kB/s, finished in 4:11
  DUMP: 36.28% done at 72291 kB/s, finished in 4:07
  DUMP: 37.52% done at 72184 kB/s, finished in 4:02
  DUMP: 38.73% done at 72045 kB/s, finished in 3:58
  DUMP: 39.93% done at 71853 kB/s, finished in 3:54
  DUMP: 41.22% done at 71815 kB/s, finished in 3:49
  DUMP: 42.48% done at 71726 kB/s, finished in 3:44
  DUMP: 43.71% done at 71612 kB/s, finished in 3:40
  DUMP: 44.97% done at 71594 kB/s, finished in 3:35
  DUMP: 46.16% done at 71404 kB/s, finished in 3:31
  DUMP: 47.46% done at 71436 kB/s, finished in 3:26
  DUMP: 48.62% done at 71273 kB/s, finished in 3:22
  DUMP: 49.63% done at 70838 kB/s, finished in 3:19
  DUMP: 50.62% done at 70453 kB/s, finished in 3:16
  DUMP: 51.67% done at 70170 kB/s, finished in 3:13
  DUMP: 52.74% done at 69937 kB/s, finished in 3:09
  DUMP: 53.89% done at 69806 kB/s, finished in 3:05
  DUMP: 54.98% done at 69580 kB/s, finished in 3:01
  DUMP: 56.13% done at 69420 kB/s, finished in 2:57
  DUMP: 57.21% done at 69230 kB/s, finished in 2:53
  DUMP: 58.37% done at 69147 kB/s, finished in 2:48
  DUMP: 59.45% done at 68962 kB/s, finished in 2:44
  DUMP: 60.57% done at 68834 kB/s, finished in 2:40
  DUMP: 61.64% done at 68662 kB/s, finished in 2:36
  DUMP: 62.58% done at 68354 kB/s, finished in 2:33
  DUMP: 63.62% done at 68164 kB/s, finished in 2:29
  DUMP: 64.71% done at 68023 kB/s, finished in 2:25
  DUMP: 65.79% done at 67893 kB/s, finished in 2:21
  DUMP: 66.89% done at 67774 kB/s, finished in 2:16
  DUMP: 67.91% done at 67586 kB/s, finished in 2:13
  DUMP: 68.95% done at 67427 kB/s, finished in 2:09
  DUMP: 70.08% done at 67319 kB/s, finished in 2:04
  DUMP: 71.22% done at 67244 kB/s, finished in 1:59
  DUMP: 72.32% done at 67147 kB/s, finished in 1:55
  DUMP: 73.36% done at 67006 kB/s, finished in 1:51
  DUMP: 74.43% done at 66891 kB/s, finished in 1:47
  DUMP: 75.52% done at 66776 kB/s, finished in 1:42
  DUMP: 76.58% done at 66641 kB/s, finished in 1:38
  DUMP: 77.67% done at 66555 kB/s, finished in 1:34
  DUMP: 78.66% done at 66390 kB/s, finished in 1:30
  DUMP: 79.71% done at 66275 kB/s, finished in 1:25
  DUMP: 80.81% done at 66207 kB/s, finished in 1:21
  DUMP: 81.95% done at 66148 kB/s, finished in 1:16
  DUMP: 83.01% done at 66054 kB/s, finished in 1:12
  DUMP: 84.03% done at 65931 kB/s, finished in 1:07
  DUMP: 84.90% done at 65691 kB/s, finished in 1:04
  DUMP: 85.88% done at 65541 kB/s, finished in 1:00
  DUMP: 86.85% done at 65398 kB/s, finished in 0:56
  DUMP: 87.81% done at 65240 kB/s, finished in 0:52
  DUMP: 88.83% done at 65074 kB/s, finished in 0:48
  DUMP: 89.79% done at 64922 kB/s, finished in 0:44
  DUMP: 90.84% done at 64848 kB/s, finished in 0:39
  DUMP: 91.94% done at 64805 kB/s, finished in 0:34
  DUMP: 93.02% done at 64688 kB/s, finished in 0:30
  DUMP: 94.06% done at 64605 kB/s, finished in 0:25
  DUMP: 95.10% done at 64518 kB/s, finished in 0:21
  DUMP: 96.11% done at 64418 kB/s, finished in 0:16
  DUMP: 97.07% done at 64296 kB/s, finished in 0:12
  DUMP: 97.98% done at 64133 kB/s, finished in 0:08
  DUMP: 98.93% done at 64006 kB/s, finished in 0:04
  DUMP: 99.78% done at 63799 kB/s, finished in 0:00
  DUMP: Closing /mnt/backup/backup-data-home-20140705.223201-0.img
  DUMP: Volume 1 completed at: Sun Jul  6 05:52:02 2014
  DUMP: Volume 1 1681955840 blocks (1642535.00MB)
  DUMP: Volume 1 took 7:19:43
  DUMP: Volume 1 transfer rate: 63751 kB/s
  DUMP: 1681955840 blocks (1642535.00MB) on 1 volume(s)
  DUMP: finished in 26383 seconds, throughput 63751 kBytes/sec
  DUMP: Date of this level 0 dump: Sat Jul  5 22:32:02 2014
  DUMP: Date this dump completed:  Sun Jul  6 05:52:02 2014
  DUMP: Average transfer rate: 63751 kB/s
  DUMP: Archiving dump to /mnt/backup/backup-data-home-20140705.223201-0.toc
  DUMP: DUMP IS DONE
  Logical volume "backup-data-home" successfully removed
Comment 5 Theodore Tso 2014-07-06 17:57:24 UTC 
Delayed allocation certainly works with or without the journal.  But disabling delayed allocation will _significantly_ impact performance.   There's certainly no surprise there.   Delalloc is one of the reasons why ext4 is significantly more performant than ext3, and the mode that we use in Google is ext4 with delalloc in no journal mode.

In answer to your other questions, no the es_shrink_enter and es_shrink_exit calls are not balanced.  In particular, the ext4_es_shrink_enter tracepoint gets called from two different functions (which is a bad thing; recent shrinker infrastructure changes added a s_es_shrinker_.count_objects() callback, and the person converted the ext4 shirnker over to the new setup duplicated the tracepoint instead of creating a new one.   Also, in ext4_es_scan(), if nr_to_scan is zero, we don't end up calling the ext4_es_shrinker_exit tracepoint.

Some other things to try.  (1)  Try collecting copies of /proc/meminfo and /proc/slabinfo every 10% of the dump process or so.  That might be useful.  (2) Try reformatting with a much larger journal, and see if that makes a difference.  I doubt it will, but it's worth a try.   (3)   Either using /sys/kernel/debug, or the ftrace command (don't use perf; since we need the data associated with the tracepoints, not just the count), enable the jbd2_checkpoint and jbd2_run_stats and collect the tracepoint data during the run.
Comment 6 Joseph D. Wagner 2014-07-07 06:00:12 UTC 
I formatted with these options.  The performance difference has been profound.

# mke2fs \
 -E lazy_itable_init=0,lazy_journal_init=0 \
 -J size=1024 -L backup -m 1 -t ext4 -v /dev/mapper/backup

I will update with the details when it completes.
Comment 7 Joseph D. Wagner 2014-07-07 06:53:50 UTC 
####
#### Exhibit F
####
#### EXT4 1 GB journal
####
# su -c 'cd /root; nice ionice -c3 /usr/local/bin/lvbackup /dev/data/home /mnt/backup'
Password: 
/sys/kernel/debug/tracing/events/jbd2/jbd2_checkpoint/filter
/sys/kernel/debug/tracing/events/jbd2/jbd2_run_stats/filter
  DUMP: mount: bad UUID
  DUMP: Date of this level 0 dump: Sun Jul  6 18:36:26 2014
  DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to /mnt/backup/backup-data-home-20140706.183624-0.img
  DUMP: Label: none
  DUMP: Writing 64 Kilobyte records
  DUMP: mapping (Pass I) [regular files]
  DUMP: mapping (Pass II) [directories]
  DUMP: estimated 1666619218 blocks.
  DUMP: writing QFA positions to /mnt/backup/backup-data-home-20140706.183624-0.qfa
  DUMP: Volume 1 started with block 1 at: Sun Jul  6 18:36:42 2014
  DUMP: dumping (Pass III) [directories]
  DUMP: dumping (Pass IV) [regular files]
  DUMP: 1.55% done at 86242 kB/s, finished in 5:17
  DUMP: 3.36% done at 93335 kB/s, finished in 4:47
  DUMP: 5.22% done at 96715 kB/s, finished in 4:32
  DUMP: 7.09% done at 98405 kB/s, finished in 4:22
  DUMP: 8.94% done at 99348 kB/s, finished in 4:14
  DUMP: 10.62% done at 98331 kB/s, finished in 4:12
  DUMP: 12.47% done at 98982 kB/s, finished in 4:05
  DUMP: 14.15% done at 98263 kB/s, finished in 4:02
  DUMP: 15.89% done at 98070 kB/s, finished in 3:58
  DUMP: 17.40% done at 96691 kB/s, finished in 3:57
  DUMP: 19.23% done at 97105 kB/s, finished in 3:51
  DUMP: 21.03% done at 97361 kB/s, finished in 3:45
  DUMP: 22.61% done at 96606 kB/s, finished in 3:42
  DUMP: 24.33% done at 96548 kB/s, finished in 3:37
  DUMP: 25.94% done at 96077 kB/s, finished in 3:34
  DUMP: 27.53% done at 95589 kB/s, finished in 3:30
  DUMP: 29.01% done at 94808 kB/s, finished in 3:27
  DUMP: 30.79% done at 95038 kB/s, finished in 3:22
  DUMP: 32.15% done at 93991 kB/s, finished in 3:20
  DUMP: 33.90% done at 94088 kB/s, finished in 3:15
  DUMP: 35.77% done at 94549 kB/s, finished in 3:08
  DUMP: 37.53% done at 94696 kB/s, finished in 3:03
  DUMP: 39.31% done at 94872 kB/s, finished in 2:57
  DUMP: 41.12% done at 95118 kB/s, finished in 2:51
  DUMP: 43.11% done at 95737 kB/s, finished in 2:45
  DUMP: 44.80% done at 95672 kB/s, finished in 2:40
  DUMP: 46.80% done at 96235 kB/s, finished in 2:33
  DUMP: 48.55% done at 96267 kB/s, finished in 2:28
  DUMP: 49.95% done at 95624 kB/s, finished in 2:25
  DUMP: 51.51% done at 95330 kB/s, finished in 2:21
  DUMP: 53.29% done at 95446 kB/s, finished in 2:15
  DUMP: 54.89% done at 95239 kB/s, finished in 2:11
  DUMP: 56.79% done at 95557 kB/s, finished in 2:05
  DUMP: 58.40% done at 95315 kB/s, finished in 2:01
  DUMP: 60.23% done at 95500 kB/s, finished in 1:55
  DUMP: 61.75% done at 95187 kB/s, finished in 1:51
  DUMP: 62.96% done at 94432 kB/s, finished in 1:48
  DUMP: 64.49% done at 94186 kB/s, finished in 1:44
  DUMP: 65.93% done at 93828 kB/s, finished in 1:40
  DUMP: 67.35% done at 93448 kB/s, finished in 1:37
  DUMP: 68.86% done at 93222 kB/s, finished in 1:32
  DUMP: 70.56% done at 93248 kB/s, finished in 1:27
  DUMP: 71.99% done at 92934 kB/s, finished in 1:23
  DUMP: 73.30% done at 92374 kB/s, finished in 1:20
  DUMP: 74.70% done at 92057 kB/s, finished in 1:16
  DUMP: 76.02% done at 91644 kB/s, finished in 1:12
  DUMP: 77.55% done at 91509 kB/s, finished in 1:08
  DUMP: 78.96% done at 91230 kB/s, finished in 1:04
  DUMP: 80.47% done at 91079 kB/s, finished in 0:59
  DUMP: 81.97% done at 90928 kB/s, finished in 0:55
  DUMP: 83.59% done at 90913 kB/s, finished in 0:50
  DUMP: 84.79% done at 90443 kB/s, finished in 0:46
  DUMP: 85.95% done at 89932 kB/s, finished in 0:43
  DUMP: 87.34% done at 89636 kB/s, finished in 0:39
  DUMP: 88.69% done at 89368 kB/s, finished in 0:35
  DUMP: 89.94% done at 89007 kB/s, finished in 0:31
  DUMP: 91.49% done at 88921 kB/s, finished in 0:26
  DUMP: 92.76% done at 88568 kB/s, finished in 0:22
  DUMP: 94.17% done at 88401 kB/s, finished in 0:18
  DUMP: 95.94% done at 88563 kB/s, finished in 0:12
  DUMP: 97.21% done at 88271 kB/s, finished in 0:08
  DUMP: 98.70% done at 88179 kB/s, finished in 0:04
  DUMP: 99.90% done at 87843 kB/s, finished in 0:00
  DUMP: Closing /mnt/backup/backup-data-home-20140706.183624-0.img
  DUMP: Volume 1 completed at: Sun Jul  6 23:53:22 2014
  DUMP: Volume 1 1666753856 blocks (1627689.31MB)
  DUMP: Volume 1 took 5:16:40
  DUMP: Volume 1 transfer rate: 87723 kB/s
  DUMP: 1666753856 blocks (1627689.31MB) on 1 volume(s)
  DUMP: finished in 18982 seconds, throughput 87807 kBytes/sec
  DUMP: Date of this level 0 dump: Sun Jul  6 18:36:26 2014
  DUMP: Date this dump completed:  Sun Jul  6 23:53:22 2014
  DUMP: Average transfer rate: 87723 kB/s
  DUMP: Archiving dump to /mnt/backup/backup-data-home-20140706.183624-0.toc
  DUMP: DUMP IS DONE
Kernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 2700
oldest event ts: 20069.317440
now ts: 20510.416153
dropped events: 0
read events: 2031

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 2892
oldest event ts: 19851.942578
now ts: 20510.416250
dropped events: 0
read events: 1350

CPU: 2
entries: 0
overrun: 0
commit overrun: 0
bytes: 300
oldest event ts: 20470.055223
now ts: 20510.416299
dropped events: 0
read events: 1087

CPU: 3
entries: 0
overrun: 0
commit overrun: 0
bytes: 3484
oldest event ts: 19290.268932
now ts: 20510.416342
dropped events: 0
read events: 761

CPU: 4
entries: 0
overrun: 0
commit overrun: 0
bytes: 992
oldest event ts: 18981.386433
now ts: 20510.416382
dropped events: 0
read events: 130

CPU: 5
entries: 0
overrun: 0
commit overrun: 0
bytes: 500
oldest event ts: 20037.773385
now ts: 20510.416420
dropped events: 0
read events: 166

CPU: 6
entries: 0
overrun: 0
commit overrun: 0
bytes: 3160
oldest event ts: 17983.470194
now ts: 20510.416457
dropped events: 0
read events: 235

CPU: 7
entries: 0
overrun: 0
commit overrun: 0
bytes: 3200
oldest event ts:  1610.477599
now ts: 20510.416493
dropped events: 0
read events: 32

CPU0 data recorded at offset=0x448000
    208896 bytes in size
CPU1 data recorded at offset=0x47b000
    139264 bytes in size
CPU2 data recorded at offset=0x49d000
    114688 bytes in size
CPU3 data recorded at offset=0x4b9000
    77824 bytes in size
CPU4 data recorded at offset=0x4cc000
    16384 bytes in size
CPU5 data recorded at offset=0x4d0000
    20480 bytes in size
CPU6 data recorded at offset=0x4d5000
    24576 bytes in size
CPU7 data recorded at offset=0x4db000
    4096 bytes in size
  Logical volume "backup-data-home" successfully removed
Comment 8 Theodore Tso 2014-07-07 12:29:38 UTC 
*Very* interesting.  If increasing the journal helped significantly, I'd really like to get the traces from enabling jbd2_checkpoint and jbd2_run_stats, with both with the original and new journal size.  (Note, you'll need to use "trace-cmd report" to get the actual traces, and then delete the trace.dat file between runs.   The traces will be quite voluminous, but they should compress well.)

To explain what you'll see:

     jbd2/sda3-8-331   [000] ...2 35527.318772: jbd2_run_stats: dev 8,3 tid 14512411 wait 0 request_delay 0 running 5290 locked 0 flushing 0 logging 0 handle_count 33 blocks 7 blocks_logged 8

This means that we spent a bit over five seconds letting the transaction run, and in that transaction contained 33 handles ("micro transactions") which covered 7 blocks, and it used 8 blocks of space in the journal.

     jbd2/sda3-8-331   [000] ...2 35534.133232: jbd2_run_stats: dev 8,3 tid 14512413 wait 0 request_delay 0 running 440 locked 0 flushing 0 logging 10 handle_count 27 blocks 8 blocks_logged 9

This is an example of a transaction that only ran for less than half a second (440 jiffies); since it ran for less than the default five seconds, we can surmise that there was an explicit fsync() that triggered the transaction.  If the number of blocks logged was very high, it's possible it was triggered by running out of room in the journal, but in that case, you'd see a lot of jbd2_checkpoint tracepoint data as well.

So now that we know that the journal size is making a difference, this will allow us to figure out *why* the journal size is making a difference.
Comment 9 Joseph D. Wagner 2014-07-08 13:42:19 UTC 
This is entirely unexpected.  Performance wasn't that bad.  The only thing I did differently was using this option in mke2fs:
"-E lazy_itable_init=0,lazy_journal_init=0"

Could the lazy initialization be tripping it up?  That doesn't make much sense, because I had been having this problem for some time before doing all these formatting experiments.

I will attach ftrace and memstats shortly.

Joseph D. Wagner

####
#### Exhibit G
####
#### EXT4 256 MB journal
####
# su -c 'cd /root; nice ionice -c3 /usr/local/bin/lvbackup /dev/data/home /mnt/backup'
Password: 
/sys/kernel/debug/tracing/events/jbd2/jbd2_checkpoint/filter
/sys/kernel/debug/tracing/events/jbd2/jbd2_run_stats/filter
  DUMP: mount: bad UUID
  DUMP: Date of this level 0 dump: Mon Jul  7 22:32:53 2014
  DUMP: Dumping /dev/data/backup-data-home (an unlisted file system) to /mnt/backup/backup-data-home-20140707.223252-0.img
  DUMP: Label: none
  DUMP: Writing 64 Kilobyte records
  DUMP: mapping (Pass I) [regular files]
  DUMP: mapping (Pass II) [directories]
  DUMP: estimated 1664540695 blocks.
  DUMP: writing QFA positions to /mnt/backup/backup-data-home-20140707.223252-0.qfa
  DUMP: Volume 1 started with block 1 at: Mon Jul  7 22:33:10 2014
  DUMP: dumping (Pass III) [directories]
  DUMP: dumping (Pass IV) [regular files]
  DUMP: 1.52% done at 84065 kB/s, finished in 5:25
  DUMP: 3.38% done at 93765 kB/s, finished in 4:45
  DUMP: 5.21% done at 95705 kB/s, finished in 4:34
  DUMP: 7.13% done at 98469 kB/s, finished in 4:21
  DUMP: 9.16% done at 101232 kB/s, finished in 4:08
  DUMP: 11.09% done at 102248 kB/s, finished in 4:01
  DUMP: 13.24% done at 104623 kB/s, finished in 3:50
  DUMP: 15.25% done at 105362 kB/s, finished in 3:43
  DUMP: 17.08% done at 104930 kB/s, finished in 3:39
  DUMP: 19.05% done at 105326 kB/s, finished in 3:33
  DUMP: 21.08% done at 106019 kB/s, finished in 3:26
  DUMP: 22.80% done at 105141 kB/s, finished in 3:23
  DUMP: 24.57% done at 104591 kB/s, finished in 3:20
  DUMP: 26.17% done at 103451 kB/s, finished in 3:18
  DUMP: 28.00% done at 103348 kB/s, finished in 3:13
  DUMP: 29.65% done at 102589 kB/s, finished in 3:10
  DUMP: 31.33% done at 102054 kB/s, finished in 3:06
  DUMP: 32.94% done at 101356 kB/s, finished in 3:03
  DUMP: 34.72% done at 101206 kB/s, finished in 2:58
  DUMP: 36.69% done at 101617 kB/s, finished in 2:52
  DUMP: 38.28% done at 100972 kB/s, finished in 2:49
  DUMP: 39.92% done at 100523 kB/s, finished in 2:45
  DUMP: 41.82% done at 100747 kB/s, finished in 2:40
  DUMP: 43.61% done at 100688 kB/s, finished in 2:35
  DUMP: 45.59% done at 101036 kB/s, finished in 2:29
  DUMP: 47.33% done at 100878 kB/s, finished in 2:24
  DUMP: 48.89% done at 100304 kB/s, finished in 2:21
  DUMP: 50.36% done at 99618 kB/s, finished in 2:18
  DUMP: 51.93% done at 99191 kB/s, finished in 2:14
  DUMP: 53.74% done at 99175 kB/s, finished in 2:09
  DUMP: 55.55% done at 99220 kB/s, finished in 2:04
  DUMP: 57.41% done at 99354 kB/s, finished in 1:58
  DUMP: 59.29% done at 99500 kB/s, finished in 1:53
  DUMP: 61.40% done at 100007 kB/s, finished in 1:47
  DUMP: 62.90% done at 99529 kB/s, finished in 1:43
  DUMP: 64.38% done at 98954 kB/s, finished in 1:39
  DUMP: 65.86% done at 98497 kB/s, finished in 1:36
  DUMP: 67.41% done at 98173 kB/s, finished in 1:32
  DUMP: 68.88% done at 97749 kB/s, finished in 1:28
  DUMP: 70.55% done at 97621 kB/s, finished in 1:23
  DUMP: 72.06% done at 97286 kB/s, finished in 1:19
  DUMP: 73.46% done at 96809 kB/s, finished in 1:16
  DUMP: 75.17% done at 96766 kB/s, finished in 1:11
  DUMP: 76.74% done at 96552 kB/s, finished in 1:06
  DUMP: 78.29% done at 96316 kB/s, finished in 1:02
  DUMP: 79.98% done at 96264 kB/s, finished in 0:57
  DUMP: 81.59% done at 96111 kB/s, finished in 0:53
  DUMP: 83.19% done at 95963 kB/s, finished in 0:48
  DUMP: 84.59% done at 95591 kB/s, finished in 0:44
  DUMP: 85.90% done at 95129 kB/s, finished in 0:41
  DUMP: 87.31% done at 94801 kB/s, finished in 0:37
  DUMP: 88.88% done at 94635 kB/s, finished in 0:32
  DUMP: 90.40% done at 94436 kB/s, finished in 0:28
  DUMP: 92.01% done at 94342 kB/s, finished in 0:23
  DUMP: 93.66% done at 94287 kB/s, finished in 0:18
  DUMP: 95.48% done at 94409 kB/s, finished in 0:13
  DUMP: 97.04% done at 94271 kB/s, finished in 0:08
  DUMP: 98.43% done at 93972 kB/s, finished in 0:04
  DUMP: 99.76% done at 93637 kB/s, finished in 0:00
  DUMP: Closing /mnt/backup/backup-data-home-20140707.223252-0.img
  DUMP: Volume 1 completed at: Tue Jul  8 03:29:43 2014
  DUMP: Volume 1 1664675072 blocks (1625659.25MB)
  DUMP: Volume 1 took 4:56:33
  DUMP: Volume 1 transfer rate: 93557 kB/s
  DUMP: 1664675072 blocks (1625659.25MB) on 1 volume(s)
  DUMP: finished in 17783 seconds, throughput 93610 kBytes/sec
  DUMP: Date of this level 0 dump: Mon Jul  7 22:32:53 2014
  DUMP: Date this dump completed:  Tue Jul  8 03:29:43 2014
  DUMP: Average transfer rate: 93557 kB/s
  DUMP: Archiving dump to /mnt/backup/backup-data-home-20140707.223252-0.toc
  DUMP: DUMP IS DONE
Kernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 1400
oldest event ts: 24220.806656
now ts: 25076.920627
dropped events: 0
read events: 614

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 3168
oldest event ts: 23960.588658
now ts: 25076.920710
dropped events: 0
read events: 756

CPU: 2
entries: 0
overrun: 0
commit overrun: 0
bytes: 1092
oldest event ts: 24801.889841
now ts: 25076.920772
dropped events: 0
read events: 865

CPU: 3
entries: 0
overrun: 0
commit overrun: 0
bytes: 1700
oldest event ts: 24551.112688
now ts: 25076.920828
dropped events: 0
read events: 702

CPU: 4
entries: 0
overrun: 0
commit overrun: 0
bytes: 400
oldest event ts: 24162.567661
now ts: 25076.920883
dropped events: 0
read events: 85

CPU: 5
entries: 0
overrun: 0
commit overrun: 0
bytes: 2168
oldest event ts: 22049.515769
now ts: 25076.920936
dropped events: 0
read events: 144

CPU: 6
entries: 0
overrun: 0
commit overrun: 0
bytes: 2868
oldest event ts: 21979.076019
now ts: 25076.920988
dropped events: 0
read events: 233

CPU: 7
entries: 0
overrun: 0
commit overrun: 0
bytes: 900
oldest event ts:  8080.390207
now ts: 25076.921039
dropped events: 0
read events: 9

CPU0 data recorded at offset=0x449000
    65536 bytes in size
CPU1 data recorded at offset=0x459000
    77824 bytes in size
CPU2 data recorded at offset=0x46c000
    90112 bytes in size
CPU3 data recorded at offset=0x482000
    73728 bytes in size
CPU4 data recorded at offset=0x494000
    12288 bytes in size
CPU5 data recorded at offset=0x497000
    16384 bytes in size
CPU6 data recorded at offset=0x49b000
    24576 bytes in size
CPU7 data recorded at offset=0x4a1000
    4096 bytes in size
  Logical volume "backup-data-home" successfully removed
Comment 10 Joseph D. Wagner 2014-07-08 13:42:41 UTC 
Created attachment 142461 [details]
trace 1gb journal
Comment 11 Joseph D. Wagner 2014-07-08 13:43:02 UTC 
Created attachment 142471 [details]
trace 256mb journal
Comment 12 Joseph D. Wagner 2014-07-08 13:43:27 UTC 
Created attachment 142481 [details]
memstats 1gb journal
Comment 13 Joseph D. Wagner 2014-07-08 13:43:46 UTC 
Created attachment 142491 [details]
memstats 256mb journal
Comment 14 Theodore Tso 2014-07-08 14:23:41 UTC 
What device (in major, minor number) were you writing to?   It looks like the active devices were 253,1 and 253,3 and 253,5

And did you have the same lazyinit settings for the 1gb and 256mb journal?   If you did enable the jbd2_checkpoint, I don't see any evidence that we ever needed to run a checkpoint.  And the number of blocks used for each transaction is quite small, so it looks like the journal size shouldn't be making a difference.

It's possible the lazy initialization could be stealing enough bandwidth that it would be making a difference.  I'm surprised that it would cause a gradual decrease over time, though.   The design was that it would steal a roughly constant percentage of disk time to initialize the inode tables.   If you are immediately unmounting the file system once you are done with the backups, it could be that the lazy initialization is never finishing, but we do mark each block group as its inode table gets initialized, so the next time you remount it, it should pick up where it left off, until the inode tables are fully initialized.   If you tell mke2fs to disable the lazy init feature, then the mke2fs takes longer, but it does initialize all of the inode table all at once.
Comment 15 Joseph D. Wagner 2014-07-09 03:27:45 UTC 
Assuming these don't change across reboots:
253, 1 -> /dev/dm-1 -> system-os
253, 3 -> /dev/dm-3 -> backup (destination)
253, 5 -> /dev/dm-5 -> data-home (source)

I used the same options for formatting.  Here are the exact commands:

$ mke2fs -E lazy_itable_init=0,lazy_journal_init=0 -J size=1024 -L backup -m 1 -t ext4 -v /dev/mapper/backup

$ mke2fs -E lazy_itable_init=0,lazy_journal_init=0 -J size=256 -L backup -m 1 -t ext4 -v /dev/mapper/backup

Here is the exact command for the ftrace and dump:

$ trace-cmd record -o /root/ftrace/trace.dat \
  -e jbd2:jbd2_checkpoint \
  -e jbd2:jbd2_run_stats \
dump -${DUMPLEVEL} -a -b 64 -u -A "${TARGET_TOC}" -f "${TARGET_IMG}" -Q "${TARGET_QFA}" "${SNAPSHOT_PATH}"

Often (but not always), I would set the system to shutdown immediately after backup.  However, it was mounted automatically by /etc/fstab on each boot, and it was left mounted in the background.

Prior to submitting these bug report, I had been running without reformatting for a number of months.  I just finally got sick of it when I submitted my report.

What do you think should be the next step?  Reformat with those options, and rerun with a trace?
Comment 16 Joseph D. Wagner 2014-07-09 03:30:46 UTC 
*Correction* Reformat with default options, and rerun with a trace?