equal physical addresses in dedup

[kakra]

Whoops, red text in systemd journal log... What does this mean? An uneducated guess: Bees already processed these extents in a previous run and was interrupted before the checkpoint...

Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: equal physical addresses in dedup
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: --- BEGIN TRACE ---
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: Found matching range: BeesRangePair: 4K src[0x110a0c000..0x110a0d000] dst[0x110a18000..0x110a19000]
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: src = 33 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: dst = 33 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: creating brp (4K [0x110a0c000..0x110a0d000] fid = 263:322 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi', 4K [0x110a18000..0x110a19000] fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi')
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: Opening src bfr 4K [0x110a0c000..0x110a0d000] fid = 263:322 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi'
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: chase_extent_ref ino BtrfsInodeOffsetRoot { .m_inum = 322, .m_offset = 0x110a0c000, .m_root = 263 } bbd BeesBlockData { 4K 0x110a18000 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi', data[4096] = '#\x01!\x01#\x01\xe3\x00!\x01"\x01...' }
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: ino_off_root BtrfsInodeOffsetRoot { .m_inum = 322, .m_offset = 0x110a0c000, .m_root = 263 }
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: for_each_extent_ref BeesBlockData { 4K 0x110a18000 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi', data[4096] = '#\x01!\x01#\x01\xe3\x00!\x01"\x01...' } at 0x1751cfb000zb000: 1 found
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: overlap_bfr 0 (..0x0]
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: Opening dst bfr 4K [0x110a18000..0x110a19000] fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi'
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: replace_dst dst_bfr 4K [0x110a18000..0x110a19000] fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi'
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: finding one match (out of 1) at 0x1751cfb000zb000 for BeesBlockData { 4K 0x110a18000 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi', address = 0xbf7246000z4000, hash = 0x665d6159fc99bc28, data[4096] = '#\x01!\x01#\x01\xe3\x00!\x01"\x01...' }
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: resolved_addrs.size() = 1
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: Pushing hash 0x665d6159fc99bc28 addr 0xbf7246000z4000 bbd BeesBlockData { 4K 0x110a18000 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi', address = 0xbf7246000z4000, hash = 0x665d6159fc99bc28, data[4096] = '#\x01!\x01#\x01\xe3\x00!\x01"\x01...' }
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: scan bbd BeesBlockData { 4K 0x110a18000 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi', address = 0xbf7246000z4000, hash = 0x665d6159fc99bc28, data[4096] = '#\x01!\x01#\x01\xe3\x00!\x01"\x01...' }
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: Extent { begin = 0x110a14000, end = 0x110a1f000, physical = 0xbf7246000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0xb000, logical_len = 0xb000 } block_count 11
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: scan extent Extent { begin = 0x110a14000, end = 0x110a1f000, physical = 0xbf7246000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0xb000, logical_len = 0xb000 }
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: scan_forward 44K [0x110a14000..0x110a1f000] fid = 263:322 fd = 33 'home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi'
Jan 21 02:10:36 jupiter beesd[31282]: crawl_263[31309]: ---  END  TRACE ---

[Zygo]

bees doesn't currently build a complete extent map due to the limitations of LOGICAL_INO (v1) and because bees doesn't have data structures to efficiently use the data. It currently works off partial information from the subvol tree.

If a single extent contains multiple identical blocks and a second extent contains another copy of these blocks, bees can thrash by constantly replacing some references to one of the blocks with references to the other two. The second extent triggers the problem because without it bees would never detect two instances of data in the same extent (such data is not added to the hash table until after the extent is scanned for duplicates to try to avoid this problem). The second extent is usually eliminated, but the first extent (which has two copies of the block) keeps getting new references to the "other" duplicate block because the old references are never fully deleted and there is no extent-tree lookup to see if both blocks belong to the same extent. The new extent refs feed back into the scanner, so the offending extent refs get deduped on every pass over a subvol, which is a waste of time.

bees can detect when it's doing this by looking up the physical addresses of both extents in dedup. If they share a physical extent bytenr, we know that we are doing a pointless dedup, and we can avoid feeding the extent back into the next pass.

So bees detects this pathological case and bombs out with an exception. That could be improved--we can just quietly log and return dedup failure. The exception was useful to collect the data to understand this phenomenon but now that I understand what is happening the exception is no longer necessary.

A proper extent-based scanner would not make this kind of mistake--it would fully map each physical extent, map and dedup on the physical extent level instead of the subvol extent ref or block levels, so that any block that is deduped is fully removed from the filesystem on the first pass and never visited again. Each matching block is mapped to its extent and any self-references ignored. When bees gets one of those, this issue just goes away.