Stray 4k extents with slow buffered writes
Here's an observation that is not a bug (as in data corruption), just somewhat odd and unnecessary behaviour. It could be considered a performance or scalability bug.
I've noticed that slow slow buffered writes create a huge number of unnecessary 4k sized extents. At first I wrote it off as odd buffering behaviour of the application (a download manager), but it can be easily reproduced. For example:
holger>wget --limit-rate=1m https://cdn.kernel.org/pub/linux/kernel/v4.x/testing/linux-4.5-rc6.tar.xz
(..downloads with 1 MB/s..)
holger>sync
holger>filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is: 9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext: logical_offset: physical_offset: length: expected: flags:
0: 0.. 14219: 230807476.. 230821695: 14220: 1: 14220.. 14223: 230838148.. 230838151: 4: 230821696: 2: 14224.. 29215: 230822324.. 230837315: 14992: 230838152: 3: 29216.. 44207: 230838152.. 230853143: 14992: 230837316: 4: 44208.. 44211: 230869576.. 230869579: 4: 230853144: 5: 44212.. 59199: 230853968.. 230868955: 14988: 230869580: 6: 59200.. 74191: 230869588.. 230884579: 14992: 230868956: 7: 74192.. 74195: 230898332.. 230898335: 4: 230884580: 8: 74196.. 86291: 230885620.. 230897715: 12096: 230898336: last,eof
linux-4.5-rc6.tar.xz: 9 extents found
Slower writes will generate even more extents; another ~200MB file had >900 extents.
As expected defragment will collapse these stray extents with their successors:
holger>btrfs filesystem defragment linux-4.5-rc6.tar.xz holger>sync
holger>filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is: 9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext: logical_offset: physical_offset: length: expected: flags:
0: 0.. 14219: 230807476.. 230821695: 14220: 1: 14220.. 29215: 230922128.. 230937123: 14996: 230821696: 2: 29216.. 44207: 230838152.. 230853143: 14992: 230937124: 3: 44208.. 59199: 230937124.. 230952115: 14992: 230853144: 4: 59200.. 74191: 230869588.. 230884579: 14992: 230952116: 5: 74192.. 86291: 230952116.. 230964215: 12100: 230884580: last,eof
linux-4.5-rc6.tar.xz: 6 extents found
The obviously page-sized 4k extents happen to coincide with the 30s tx commit (2 * ~15 MB at 1 MB/s). It looks like a benign race, as if the last dirty page gets special treatment instead of being merged into wherever it should go. That just seems wasteful to me.
Anyone got an idea?
-h
Quoted 46 lines · Holger Hoffstätte
Here's an observation that is not a bug (as in data corruption), just somewhat odd and unnecessary behaviour. It could be considered a performance or scalability bug.
I've noticed that slow slow buffered writes create a huge number of unnecessary 4k sized extents. At first I wrote it off as odd buffering behaviour of the application (a download manager), but it can be easily reproduced. For example:
holger>wget --limit-rate=1m https://cdn.kernel.org/pub/linux/kernel/v4.x/testing/linux-4.5-rc6.tar.xz
(..downloads with 1 MB/s..)
holger>sync
holger>filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is:9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 14219: 230807476.. 230821695: 14220: 1: 14220.. 14223: 230838148.. 230838151: 4: 230821696: 2: 14224.. 29215: 230822324.. 230837315: 14992: 230838152: 3: 29216.. 44207: 230838152.. 230853143: 14992: 230837316: 4: 44208.. 44211: 230869576.. 230869579: 4: 230853144: 5: 44212.. 59199: 230853968.. 230868955: 14988: 230869580: 6: 59200.. 74191: 230869588.. 230884579: 14992: 230868956: 7: 74192.. 74195: 230898332.. 230898335: 4: 230884580: 8: 74196.. 86291: 230885620.. 230897715: 12096: 230898336: last,eoflinux-4.5-rc6.tar.xz: 9 extents found
Slower writes will generate even more extents; another ~200MB file had >900 extents.
As expected defragment will collapse these stray extents with their successors:
holger>btrfs filesystem defragment linux-4.5-rc6.tar.xz holger>sync
holger>filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is:9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 14219: 230807476.. 230821695: 14220: 1: 14220.. 29215: 230922128.. 230937123: 14996: 230821696: 2: 29216.. 44207: 230838152.. 230853143: 14992: 230937124: 3: 44208.. 59199: 230937124.. 230952115: 14992: 230853144: 4: 59200.. 74191: 230869588.. 230884579: 14992: 230952116: 5: 74192.. 86291: 230952116.. 230964215: 12100: 230884580: last,eof
Quoted 8 lines
linux-4.5-rc6.tar.xz: 6 extents found
The obviously page-sized 4k extents happen to coincide with the 30s tx commit (2 * ~15 MB at 1 MB/s). It looks like a benign race, as if the last dirty page gets special treatment instead of being merged into wherever it should go. That just seems wasteful to me.
Anyone got an idea?
On a new fresh btrfs, I cannot reproduce the fragmented layout with "wget --limit-rate=1m",
[root@10-11-17-236 btrfs]# filefrag -v -b linux-4.5-rc6.tar.xz Filesystem type is: 9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks, blocksize 1024)
ext logical physical expected length flags
0 0 143744 5264 1 5264 149008 35884 2 41148 220848 184892 4 3 41152 184896 220852 35948 4 77100 220852 220844 9192 eof
linux-4.5-rc6.tar.xz: 4 extents found
My mount point has,/dev/loop0 /mnt/btrfs btrfs rw,seclabel,relatime,space_cache,subvolid=5,subvol=/ 0 0
And I'm using 4.5.0-rc4.
# btrfs fi show /mnt/btrfs
Label: none uuid: 599d68ae-b874-4db1-a3c3-33c4b783bfdd
Total devices 1 FS bytes used 94.62MiB
devid 1 size 2.00GiB used 436.75MiB path /dev/loop0# btrfs fi df /mnt/btrfs Data, single: total=216.00MiB, used=94.40MiB System, DUP: total=8.00MiB, used=16.00KiB Metadata, DUP: total=102.38MiB, used=208.00KiB GlobalReserve, single: total=16.00MiB, used=0.00B
Can you gather your mount options and 'btrfs fi show/df' output?
Thanks,
-liubo
Quoted 1 line · Liu Bo
On Thu, Mar 03, 2016 at 01:28:29PM +0100, Holger Hoffstätte wrote:
(..)
Quoted 6 lines
Quoted 4 lines
I've noticed that slow slow buffered writes create a huge number of unnecessary 4k sized extents. At first I wrote it off as odd buffering behaviour of the application (a download manager), but it can be easily reproduced. For example:
On a new fresh btrfs, I cannot reproduce the fragmented layout with "wget --limit-rate=1m",
For better effect lower the bandwidth, 100k or so.
Quoted 8 lines
[root@10-11-17-236 btrfs]# filefrag -v -b linux-4.5-rc6.tar.xz Filesystem type is:
9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks, blocksize 1024)
ext logical physical expected length flags0 0 143744 5264 1 5264 149008 35884 2 41148 220848 184892 4
So you also have one, after ~35 MB. See below.
Quoted 3 lines
3 41152 184896 220852 35948 4 77100 220852 220844 9192 eoflinux-4.5-rc6.tar.xz: 4 extents found
No sync? filefrag is a notorious liar. ;)
It changes things because you likely have a higher value set for vm/dirty_expire_centisecs or dirty_bytes explicitly configured; I have it set to 1000 (10s) to prevent large writebacks from choking everything. The default is probably still 30s aka 3000.
I understand that I should get smaller extents overall, but not the stray 4k sized ones in regular intervals.
Quoted 1 line
Can you gather your mount options and 'btrfs fi show/df' output?
I can reproduce that on another machine/drive where it also initially didn't show the 4k extents in a parallel-running filefrag, but did after a sync (when the extents were written). That was surprising.
Anyway, it's just an external scratch drive..the mount options really don't matter much:
$mount | grep sdf/dev/sdf1 on /mnt/usb type btrfs (rw,relatime,space_cache=v2,subvolid=5,subvol=/)
$btrfs fi df /mnt/usb
Data, single: total=4.00GiB, used=3.31GiB
System, single: total=32.00MiB, used=16.00KiB
Metadata, single: total=1.00GiB, used=4.45MiB
GlobalReserve, single: total=16.00MiB, used=0.00B
$btrfs fi show /mnt/usb
Label: 'Test' uuid: 1d37a067-5b7d-4dcf-b2c1-7c5745b9c7a5
Total devices 1 FS bytes used 3.32GiB devid 1 size 111.79GiB used 5.03GiB path /dev/sdf1
I then remounted with -ocommit=300 and set dirty_expire_centisecs=10000 (100s). That results in a single large extent, even after sync, so writeback expiry and commit definitely play a part.
Here is what it looks like when both dirty_expire and commit are set to very low 5s:
$filefrag -ek linux-4.4.4.tar.bz2
Filesystem type is: 9123683e
File size of linux-4.4.4.tar.bz2 is 105008928 (102548 blocks of 1024 bytes)
ext: logical_offset: physical_offset: length: expected: flags:
0: 0.. 5199: 227197920.. 227203119: 5200: 1: 5200.. 5203: 227169600.. 227169603: 4: 227203120: 2: 5204.. 15407: 227203124.. 227213327: 10204: 227169604: 3: 15408.. 20623: 227213332.. 227218547: 5216: 227213328: 4: 20624.. 20627: 227169604.. 227169607: 4: 227218548: 5: 20628.. 30831: 227218552.. 227228755: 10204: 227169608: 6: 30832.. 36047: 227228760.. 227233975: 5216: 227228756: 7: 36048.. 36051: 227169608.. 227169611: 4: 227233976: 8: 36052.. 41263: 227233980.. 227239191: 5212: 227169612: 9: 41264.. 46479: 227271164.. 227276379: 5216: 227239192: 10: 46480.. 46483: 227239196.. 227239199: 4: 227276380: 11: 46484.. 51695: 227276384.. 227281595: 5212: 227239200: 12: 51696.. 61903: 227281600.. 227291807: 10208: 227281596: 13: 61904.. 61907: 227239200.. 227239203: 4: 227291808: 14: 61908.. 67119: 227291812.. 227297023: 5212: 227239204: 15: 67120.. 77327: 227297028.. 227307235: 10208: 227297024: 16: 77328.. 77331: 227239204.. 227239207: 4: 227307236: 17: 77332.. 82543: 227307240.. 227312451: 5212: 227239208: 18: 82544.. 92751: 227312456.. 227322663: 10208: 227312452: 19: 92752.. 92755: 227239208.. 227239211: 4: 227322664: 20: 92756.. 97967: 227322668.. 227327879: 5212: 227239212: 21: 97968.. 102547: 227239212.. 227243791: 4580: 227327880: last,eof
linux-4.4.4.tar.bz2: 22 extents found
There's definitely a pattern here.
Out of curiosity I also tried the above run with autodefrag enabled, and that helped a little bit: it merges those 4k extents into 256k-sized ones with the adjacent followup extent. That was nice, but still a bit unexpected since we've been told autodefrag is for random writes.
It also doesn't really explain the original behaviour.
I guess I need to add autodefrag everywhere now. :)
Thanks,
Holger
Quoted 27 lines · Holger Hoffstätte
Quoted 1 line · Liu Bo
On Thu, Mar 03, 2016 at 01:28:29PM +0100, Holger Hoffstätte wrote:
(..)
Quoted 6 lines
Quoted 4 lines
I've noticed that slow slow buffered writes create a huge number of unnecessary 4k sized extents. At first I wrote it off as odd buffering behaviour of the application (a download manager), but it can be easily reproduced. For example:
On a new fresh btrfs, I cannot reproduce the fragmented layout with "wget --limit-rate=1m",
For better effect lower the bandwidth, 100k or so.
Quoted 8 lines
[root@10-11-17-236 btrfs]# filefrag -v -b linux-4.5-rc6.tar.xz Filesystem type is:
9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks, blocksize 1024)
ext logical physical expected length flags0 0 143744 5264 1 5264 149008 35884 2 41148 220848 184892 4So you also have one, after ~35 MB. See below.
Quoted 3 lines
3 41152 184896 220852 35948 4 77100 220852 220844 9192 eoflinux-4.5-rc6.tar.xz: 4 extents found
Quoted 6 lines
No sync? filefrag is a notorious liar. ;)
It changes things because you likely have a higher value set for vm/dirty_expire_centisecs or
dirty_bytesexplicitly configured; I have it set to 1000 (10s) to prevent large writebacks from choking everything. The default is probably still 30s aka 3000.
Last I looked (about a month ago), the default was still 3000.
Quoted 10 lines
I understand that I should get smaller extents overall, but not the stray 4k sized ones in regular intervals.
Quoted 1 line
Can you gather your mount options and 'btrfs fi show/df' output?
I can reproduce that on another machine/drive where it also initially didn't show the 4k extents in a parallel-running filefrag, but did after a sync (when the extents were written). That was surprising.
Quoted 5 lines
Anyway, it's just an external scratch drive..the mount options really don't matter much:
$mount | grep sdf
/dev/sdf1on/mnt/usbtype btrfs (rw,relatime,space_cache=v2,subvolid=5,subvol=/)
Do you still see the same behavior with the old space_cache format? This appears to be an issue of space management and allocation, so this may be playing a part.
Quoted 12 lines
$btrfs fi df
/mnt/usb
Data, single: total=4.00GiB, used=3.31GiB
System, single: total=32.00MiB, used=16.00KiB
Metadata, single: total=1.00GiB, used=4.45MiB
GlobalReserve, single: total=16.00MiB, used=0.00B$btrfs fi show
/mnt/usb
Label: 'Test' uuid: 1d37a067-5b7d-4dcf-b2c1-7c5745b9c7a5Total devices 1 FS bytes used 3.32GiB devid 1 size 111.79GiB used 5.03GiB path /dev/sdf1
Quoted 6 lines
I then remounted with -ocommit=300 and set dirty_expire_centisecs=10000 (100s). That results in a single large extent, even after sync, so writeback expiry and commit definitely play a part.
Here is what it looks like when both
dirty_expireand commit are set to very low 5s:
I'd be somewhat curious to see if something similar happens on other filesystems with such low writeback timeouts. My thought in this case is that the issue is that BTRFS's allocator isn't smart enough to try and merge new extents into existing ones when possible.
Quoted 27 lines
$filefrag -ek linux-4.4.4.tar.bz2
Filesystem type is:9123683e
File size of linux-4.4.4.tar.bz2 is 105008928 (102548 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 5199: 227197920.. 227203119: 5200: 1: 5200.. 5203: 227169600.. 227169603: 4: 227203120: 2: 5204.. 15407: 227203124.. 227213327: 10204: 227169604: 3: 15408.. 20623: 227213332.. 227218547: 5216: 227213328: 4: 20624.. 20627: 227169604.. 227169607: 4: 227218548: 5: 20628.. 30831: 227218552.. 227228755: 10204: 227169608: 6: 30832.. 36047: 227228760.. 227233975: 5216: 227228756: 7: 36048.. 36051: 227169608.. 227169611: 4: 227233976: 8: 36052.. 41263: 227233980.. 227239191: 5212: 227169612: 9: 41264.. 46479: 227271164.. 227276379: 5216: 227239192: 10: 46480.. 46483: 227239196.. 227239199: 4: 227276380: 11: 46484.. 51695: 227276384.. 227281595: 5212: 227239200: 12: 51696.. 61903: 227281600.. 227291807: 10208: 227281596: 13: 61904.. 61907: 227239200.. 227239203: 4: 227291808: 14: 61908.. 67119: 227291812.. 227297023: 5212: 227239204: 15: 67120.. 77327: 227297028.. 227307235: 10208: 227297024: 16: 77328.. 77331: 227239204.. 227239207: 4: 227307236: 17: 77332.. 82543: 227307240.. 227312451: 5212: 227239208: 18: 82544.. 92751: 227312456.. 227322663: 10208: 227312452: 19: 92752.. 92755: 227239208.. 227239211: 4: 227322664: 20: 92756.. 97967: 227322668.. 227327879: 5212: 227239212: 21: 97968.. 102547: 227239212.. 227243791: 4580: 227327880: last,eof
Quoted 3 lines
linux-4.4.4.tar.bz2: 22 extents found
There's definitely a pattern here.
What I find particularly interesting here is that the small extents appear to be packed out of order into the spaces being left between the bigger ones. For something that you don't need super fast access to, this is actually a good thing because it reduces free space fragmentation, but BTRFS has no way of knowing whether this trade off is worth it for that particular file.
Quoted 8 lines
Out of curiosity I also tried the above run with autodefrag enabled, and that helped a little bit: it merges those 4k extents into 256k-sized ones with the adjacent followup extent. That was nice, but still a bit unexpected since we've been told autodefrag is for random writes.
It also doesn't really explain the original behaviour.I guess I need to add autodefrag everywhere now. :)
Quoted 5 lines · Austin S. Hemmelgarn
Quoted 2 lines
$mount | grep sdf
/dev/sdf1on/mnt/usbtype btrfs (rw,relatime,space_cache=v2,subvolid=5,subvol=/)Do you still see the same behavior with the old
space_cacheformat? This appears to be an issue of space management and allocation, so this may be playing a part.
I just did the clear_cache,space_cache=v1 dance. Now a download with bandwidth-limit=1M, dirty_expire=20s, commit=30 and *no* autodefrag first ended up looking like this:
$filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is: 9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext: logical_offset: physical_offset: length: expected: flags:
0: 0.. 7427: 227197920.. 227205347: 7428: 1: 7428.. 33027: 227205348.. 227230947: 25600: 2: 33028.. 53011: 227271164.. 227291147: 19984: 227230948: 3: 53012.. 72995: 227291148.. 227311131: 19984: 4: 72996.. 86291: 227311132.. 227324427: 13296: last,eof
linux-4.5-rc6.tar.xz: 2 extents found
Yay! But wait, there's more!
$sync
$filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is: 9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext: logical_offset: physical_offset: length: expected: flags:
0: 0.. 7423: 227197920.. 227205343: 7424: 1: 7424.. 7427: 227169600.. 227169603: 4: 227205344: 2: 7428.. 33023: 227205348.. 227230943: 25596: 227169604: 3: 33024.. 33027: 227169604.. 227169607: 4: 227230944: 4: 33028.. 53007: 227271164.. 227291143: 19980: 227169608: 5: 53008.. 53011: 227230948.. 227230951: 4: 227291144: 6: 53012.. 72991: 227291148.. 227311127: 19980: 227230952: 7: 72992.. 72995: 227230952.. 227230955: 4: 227311128: 8: 72996.. 86291: 227311132.. 227324427: 13296: 227230956: last,eof
linux-4.5-rc6.tar.xz: 9 extents found
Now I'm like ¯\(ツ)/¯
With autodefrag the same happens, though it then eventually does the merging from 4k -> 256k. I went searching for that hardcoded 256k value and found it as default in ioctl.c:btrfs_defrag_file() when no threshold has been passed, as is the case for autodefrag. I'll try to increase that and see how much I can destroy.
Also, rsync with --bwlimit=1m does _not_ seem to create files like this:
$rsync (..)
$filefrag -ek linux-4.4.4.tar.bz2
Filesystem type is: 9123683e
File size of linux-4.4.4.tar.bz2 is 105008928 (102548 blocks of 1024 bytes)
ext: logical_offset: physical_offset: length: expected: flags:
0: 0.. 4095: 227197920.. 227202015: 4096: 1: 4096.. 25599: 227202016.. 227223519: 21504: 2: 25600.. 51199: 227271164.. 227296763: 25600: 227223520: 3: 51200.. 76799: 227296764.. 227322363: 25600: 4: 76800.. 102547: 227322364.. 227348111: 25748: last,eof
linux-4.4.4.tar.bz2: 2 extents found
Which looks exactly as one would expect, probably - as Chris' mail just explained - it doesn't use O_APPEND, whereas wget apparently does.
Quoted 4 lines
I'd be somewhat curious to see if something similar happens on other filesystems with such low writeback timeouts. My thought in this case is that the issue is that BTRFS's allocator isn't smart enough to try and merge new extents into existing ones when possible.
ext4 creates 1-2 extents, regardless of method.
Holger
Quoted 38 lines · Holger Hoffstätte
Quoted 5 lines · Austin S. Hemmelgarn
Quoted 2 lines
$mount | grep sdf
/dev/sdf1on/mnt/usbtype btrfs (rw,relatime,space_cache=v2,subvolid=5,subvol=/)Do you still see the same behavior with the old
space_cacheformat? This appears to be an issue of space management and allocation, so this may be playing a part.I just did the clear_cache,space_cache=v1 dance. Now a download with bandwidth-limit=1M, dirty_expire=20s, commit=30 and *no* autodefrag first ended up looking like this:
$filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is:9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 7427: 227197920.. 227205347: 7428: 1: 7428.. 33027: 227205348.. 227230947: 25600: 2: 33028.. 53011: 227271164.. 227291147: 19984: 227230948: 3: 53012.. 72995: 227291148.. 227311131: 19984: 4: 72996.. 86291: 227311132.. 227324427: 13296: last,eoflinux-4.5-rc6.tar.xz: 2 extents found
Yay! But wait, there's more!
$sync
$filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is:9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 7423: 227197920.. 227205343: 7424: 1: 7424.. 7427: 227169600.. 227169603: 4: 227205344: 2: 7428.. 33023: 227205348.. 227230943: 25596: 227169604: 3: 33024.. 33027: 227169604.. 227169607: 4: 227230944: 4: 33028.. 53007: 227271164.. 227291143: 19980: 227169608: 5: 53008.. 53011: 227230948.. 227230951: 4: 227291144: 6: 53012.. 72991: 227291148.. 227311127: 19980: 227230952: 7: 72992.. 72995: 227230952.. 227230955: 4: 227311128: 8: 72996.. 86291: 227311132.. 227324427: 13296: 227230956: last,eof
Quoted 3 lines
linux-4.5-rc6.tar.xz: 9 extents found
Now I'm like ¯\(ツ)/¯
Yeah, after sync, I also get this file layout.
Quoted 19 lines
With autodefrag the same happens, though it then eventually does the merging from 4k -> 256k. I went searching for that hardcoded 256k value and found it as default in ioctl.c:btrfs_defrag_file() when no threshold has been passed, as is the case for autodefrag. I'll try to increase that and see how much I can destroy.
Also, rsync with --bwlimit=1m does _not_ seem to create files like this:
$rsync (..)
$filefrag -ek linux-4.4.4.tar.bz2
Filesystem type is:9123683e
File size of linux-4.4.4.tar.bz2 is 105008928 (102548 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 4095: 227197920.. 227202015: 4096: 1: 4096.. 25599: 227202016.. 227223519: 21504: 2: 25600.. 51199: 227271164.. 227296763: 25600: 227223520: 3: 51200.. 76799: 227296764.. 227322363: 25600: 4: 76800.. 102547: 227322364.. 227348111: 25748: last,eof
Quoted 4 lines
linux-4.4.4.tar.bz2: 2 extents found
Which looks exactly as one would expect, probably - as Chris' mail just explained - it doesn't use
O_APPEND, whereas wget apparently does.
Interesting, my strace log shows wget doesn't open the file with O_APPEND.
open("linux-4.5-rc6.tar.xz", O_WRONLY|O_CREAT|O_EXCL, 0666) = 4
Thanks,
-liubo
Quoted 14 lines
Quoted 5 lines
I'd be somewhat curious to see if something similar happens on other filesystems with such low writeback timeouts. My thought in this case is that the issue is that BTRFS's allocator isn't smart enough to try and merge new extents into existing ones when possible.
ext4 creates 1-2 extents, regardless of method.
Holger
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Quoted 41 lines · Liu Bo
Quoted 40 lines · Holger Hoffstätte
Quoted 5 lines · Austin S. Hemmelgarn
Quoted 2 lines
$mount | grep sdf
/dev/sdf1on/mnt/usbtype btrfs (rw,relatime,space_cache=v2,subvolid=5,subvol=/)Do you still see the same behavior with the old
space_cacheformat? This appears to be an issue of space management and allocation, so this may be playing a part.I just did the clear_cache,space_cache=v1 dance. Now a download with bandwidth-limit=1M, dirty_expire=20s, commit=30 and *no* autodefrag first ended up looking like this:
$filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is:9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 7427: 227197920.. 227205347: 7428: 1: 7428.. 33027: 227205348.. 227230947: 25600: 2: 33028.. 53011: 227271164.. 227291147: 19984: 227230948: 3: 53012.. 72995: 227291148.. 227311131: 19984: 4: 72996.. 86291: 227311132.. 227324427: 13296: last,eoflinux-4.5-rc6.tar.xz: 2 extents found
Yay! But wait, there's more!
$sync
$filefrag -ek linux-4.5-rc6.tar.xz
Filesystem type is:9123683e
File size of linux-4.5-rc6.tar.xz is 88362576 (86292 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 7423: 227197920.. 227205343: 7424: 1: 7424.. 7427: 227169600.. 227169603: 4: 227205344: 2: 7428.. 33023: 227205348.. 227230943: 25596: 227169604: 3: 33024.. 33027: 227169604.. 227169607: 4: 227230944: 4: 33028.. 53007: 227271164.. 227291143: 19980: 227169608: 5: 53008.. 53011: 227230948.. 227230951: 4: 227291144: 6: 53012.. 72991: 227291148.. 227311127: 19980: 227230952: 7: 72992.. 72995: 227230952.. 227230955: 4: 227311128: 8: 72996.. 86291: 227311132.. 227324427: 13296: 227230956: last,eoflinux-4.5-rc6.tar.xz: 9 extents found
Quoted 3 lines
Quoted 1 line
Now I'm like ¯\(ツ)/¯
Yeah, after sync, I also get this file layout.
OK...I think I've found why we get this weird layout, it's because btrfs applies COW for overwrites while ext4 just updates it in place.
Here is my filefrag output after sync,
# !filefrag
filefrag -vb /mnt/btrfs/linux-4.5-rc6.tar.xz
Filesystem type is: 9123683e
File size of /mnt/btrfs/linux-4.5-rc6.tar.xz is 88362576 (86292 blocks, blocksize 1024)
ext logical physical expected length flags
0 0 12352 5020
1 5020 17376 17372 4 2 5024 133504 17380 30908 3 35932 195296 164412 4 4 35936 164416 195300 30876 5 66812 195300 195292 19480 eof
/mnt/btrfs/linux-4.5-rc6.tar.xz: 6 extents found
And the output of btrfs_dirty_pages, I grep for the first 4k single extent,
# trace-cmd report -i /tmp/trace.dat | grep "dirty_page" | grep $((5020 << 10)) -A 2 -B 2 wget-29482 [003] 783746.039682: bprint: btrfs_dirty_pages: page start 5124096 end 5132287 wget-29482 [003] 783746.039771: bprint: btrfs_dirty_pages: page start 5128192 end 5144575 wget-29482 [003] 783746.263238: bprint: btrfs_dirty_pages: page start 5140480 end 5148671 wget-29482 [003] 783746.263304: bprint: btrfs_dirty_pages: page start 5144576 end 5160959 wget-29482 [003] 783746.263546: bprint: btrfs_dirty_pages: page start 5156864 end 5165055
So it turns out to be that wget writes the data as an overlapped way, extent [5140480, 4096) is written twice, and the second write to the extent can trigger a COW write when the first write to the extent has finish the endio.
With mount -onodatacow,
# !filefrag
filefrag -vb /mnt/btrfs/linux-4.5-rc6.tar.xz
Filesystem type is: 9123683e
File size of /mnt/btrfs/linux-4.5-rc6.tar.xz is 88362576 (86292 blocks, blocksize 1024)
ext logical physical expected length flags
0 0 12416 5292
1 5292 133504 17708 35872 2 41164 169376 30880 3 72044 200256 14248 eof
/mnt/btrfs/linux-4.5-rc6.tar.xz: 2 extents found
Anyway it's not due to any btrfs allocator bug (although I was thinking it was and trying to find it out...).
Thanks,
-liubo
Quoted 51 lines
Quoted 20 lines
With autodefrag the same happens, though it then eventually does the merging from 4k -> 256k. I went searching for that hardcoded 256k value and found it as default in ioctl.c:btrfs_defrag_file() when no threshold has been passed, as is the case for autodefrag. I'll try to increase that and see how much I can destroy.
Also, rsync with --bwlimit=1m does _not_ seem to create files like this:
$rsync (..)
$filefrag -ek linux-4.4.4.tar.bz2
Filesystem type is:9123683e
File size of linux-4.4.4.tar.bz2 is 105008928 (102548 blocks of 1024 bytes)
ext:logical_offset:physical_offset: length: expected: flags:0: 0.. 4095: 227197920.. 227202015: 4096: 1: 4096.. 25599: 227202016.. 227223519: 21504: 2: 25600.. 51199: 227271164.. 227296763: 25600: 227223520: 3: 51200.. 76799: 227296764.. 227322363: 25600: 4: 76800.. 102547: 227322364.. 227348111: 25748: last,eofQuoted 4 lines
linux-4.4.4.tar.bz2: 2 extents found
Which looks exactly as one would expect, probably - as Chris' mail just explained - it doesn't use
O_APPEND, whereas wget apparently does.Interesting, my strace log shows wget doesn't open the file with
O_APPEND.
open("linux-4.5-rc6.tar.xz", O_WRONLY|O_CREAT|O_EXCL, 0666)= 4Thanks,
-liubo
Quoted 6 lines
Quoted 5 lines
I'd be somewhat curious to see if something similar happens on other filesystems with such low writeback timeouts. My thought in this case is that the issue is that BTRFS's allocator isn't smart enough to try and merge new extents into existing ones when possible.
Quoted 8 lines
ext4 creates 1-2 extents, regardless of method.
Holger
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Holger Hoffstätte posted on Thu, 03 Mar 2016 20:53:57 +0100 as excerpted:
Quoted 5 lines
It changes things because you likely have a higher value set for vm/dirty_expire_centisecs or
dirty_bytesexplicitly configured; I have it set to 1000 (10s) to prevent large writebacks from choking everything.
The default is probably still 30s aka 3000.
[This is a comment on write-cache management strategy in the above context, not on the buffered write 4k extents issue.]
Interesting strategy.
I left the expire (aka foreground priority) timeout at its default 30 seconds, here, and actually upped the writeback (background priority) timeout to 10 seconds, from its default 5.
I don't like large writebacks choking things either, but I chose to use the size knobs (after all, the descriptor at issue here is "large", not "old") to deal with that, not the time knobs. As a result, I set the background ratio to 1% (it defaults to 5%), and foreground ratio to 3% (it defaults to 10%).
With 16 gig of RAM, that's ~160 MiB background, about five seconds worth at the 30 MiB/sec random write that's a reasonable if perhaps a bit pessimistic estimate for spinning rust, ~ half a GiB foreground (15 seconds worth). Tho obviously as I'm at 1%, I'd have to switch to the bytes instead of ratio knobs if I were to up my memory or want to go lower or wanted more precise knobs.
It just seems to me more logical to fiddle the size knob if I'm worried about the /size/ of the writeback, and with size now dealt with and off the table, I decided doubling the low priority background writeback timeout to 10 seconds was equally logical, giving writes additional time to accumulate, for better write combining and elevator ordering, before actually starting low priority writeback, since if sizes started ballooning the lower size thresholds would trigger writeback anyway. And with size already dealt with, the higher priority foreground expiry default of 30 seconds was fine, so I didn't change that at all.
And, it seems to me, that might be part of your problem, since you're forcing high priority writeback at only 10 seconds, even if it's under the 4K block size, thus forcing COW rewrites when more data is appended to those blocks, with COW predictably playing havoc with your extents, now that you're forcing sub-4K writes to storage at high priority so fast they have little chance to be consolidated into whole 4K block writes.
Signature · 3 lines
Duncan - List replies preferred. No HTML msgs. "Every nonfree program has a lord, a master -- and if you use the program, he is your master." Richard Stallman
Quoted 9 lines · Holger Hoffstätte
Here's an observation that is not a bug (as in data corruption), just somewhat odd and unnecessary behaviour. It could be considered a performance or scalability bug.
I've noticed that slow slow buffered writes create a huge number of unnecessary 4k sized extents. At first I wrote it off as odd buffering behaviour of the application (a download manager), but it can be easily reproduced. For example:
We saw this here with slowly appending log files. The basic problem is the VM triggers dirty writeback on the tail end of the file and either starts on the last page or our clustering code pulls in the last page.
It leads to latencies because we start writing the last page in the file to disk and the application has to wait for the IO to finish before it can append to the file again.
I'll get our patches in for the next merge window, it's basically just:
don't write the last incomplete page in the file if we're O_APPEND and it isn't a data integrity writeback. We may want to rework it to drop the O_APPEND check.
-chris