Git Product home page Git Product logo

bees's Introduction

BEES

Best-Effort Extent-Same, a btrfs deduplication agent.

About bees

bees is a block-oriented userspace deduplication agent designed for large btrfs filesystems. It is an offline dedupe combined with an incremental data scan capability to minimize time data spends on disk from write to dedupe.

Strengths

  • Space-efficient hash table and matching algorithms - can use as little as 1 GB hash table per 10 TB unique data (0.1GB/TB)
  • Daemon incrementally dedupes new data using btrfs tree search
  • Works with btrfs compression - dedupe any combination of compressed and uncompressed files
  • Works around btrfs filesystem structure to free more disk space
  • Persistent hash table for rapid restart after shutdown
  • Whole-filesystem dedupe - including snapshots
  • Constant hash table size - no increased RAM usage if data set becomes larger
  • Works on live data - no scheduled downtime required
  • Automatic self-throttling based on system load

Weaknesses

  • Whole-filesystem dedupe - has no include/exclude filters, does not accept file lists
  • Requires root privilege (or CAP_SYS_ADMIN)
  • First run may require temporary disk space for extent reorganization
  • First run may increase metadata space usage if many snapshots exist
  • Constant hash table size - no decreased RAM usage if data set becomes smaller
  • btrfs only

Installation and Usage

Recommended Reading

More Information

Bug Reports and Contributions

Email bug reports and patches to Zygo Blaxell [email protected].

You can also use Github:

    https://github.com/Zygo/bees

Copyright & License

Copyright 2015-2023 Zygo Blaxell [email protected].

GPL (version 3 or later).

bees's People

Contributors

cybershadow avatar dagelf avatar gin66 avatar javivilarroig avatar kakra avatar khalilsantana avatar nefelim4ag avatar nilninull avatar nobodyxu avatar peejay avatar pixeliz3d avatar rakino avatar reacocard avatar rsjaffe avatar seerlite avatar suorcd avatar

Stargazers

 avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar

Watchers

 avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar  avatar

bees's Issues

Bees don't free FD, so deleted files are still use space

I did some tests with bees with NFS share for VM's,
so i clone VM's several times and after some time delete it,
but bees didn't finish deduping, and after 24h space not freed and bees continue deduping deleted data.

So, may be you can add some code, to free FD of deleted file?
P.S. as bees show "(deleted)" in the log, bees understand when file already deleted and if i understand correctly, can free FD.

Thanks.

Almost all threads are named "bees" now

Sometime after v0.5, probably during adding worker queues, all threads identify as "bees" which seems to come from return "bees" in src/bees.cc. This would mean that thread names are no longer set and tl_name is just empty:

136 string
137 BeesNote::get_name()
138 {
139     if (tl_name.empty()) {
140         return "bees";
141     } else {
142         return tl_name;
143     }
144 }

During startup, it says that threads are created with their correct names but it's not picked up later during logging.

Compilation fails

Getting this on current master:

[svenstaro:~/src/bees] master 9s 2 ± make
make -C lib
make[1]: Entering directory '/home/svenstaro/src/bees/lib'
g++ -Wall -Wextra -Werror -O3 -march=native -I../include -ggdb -D_FILE_OFFSET_BITS=64 -std=c++11 -Wold-style-cast -fPIC -o fs.o -c fs.cc
fs.cc: In member function ‘size_t crucible::BtrfsIoctlSearchHeader::set_data(const std::vector<char>&, size_t)’:
fs.cc:704:61: error: ‘void* memcpy(void*, const void*, size_t)’ writing to an object of type ‘struct crucible::BtrfsIoctlSearchHeader’ with no trivial copy-assignment; use copy-assignment or copy-initialization instead [-Werror=class-memaccess]
   memcpy(this, &v[offset], sizeof(btrfs_ioctl_search_header));
                                                             ^
In file included from fs.cc:1:
../include/crucible/fs.h:150:9: note: ‘struct crucible::BtrfsIoctlSearchHeader’ declared here
  struct BtrfsIoctlSearchHeader : public btrfs_ioctl_search_header {
         ^~~~~~~~~~~~~~~~~~~~~~
cc1plus: all warnings being treated as errors

gcc 8.1.0
btrfs-progs 4.16.1

Linking ussie Ubuntu 16.04 (Server)

Hi, i try compile bees for lab, and after i installing some missing headers i catch this:

g++ -Wall -Wextra -Werror -O3 -I../include -ggdb -fpic -std=c++11 -Wold-style-cast -o "../bin/bees" bees.o bees-context.o bees-hash.o bees-resolve.o bees-roots.o bees-thread.o bees-types.o  -L../lib -Wl,-rpath=/root/bees/lib -lcrucible -lpthread
../lib/libcrucible.so: undefined reference to `uuid_unparse'
collect2: error: ld returned 1 exit status
Makefile:36: recipe for target '../bin/bees' failed

May be i miss something?

# gcc --version
gcc (Ubuntu 5.4.0-6ubuntu1~16.04.4) 5.4.0 20160609
# apt-cache policy uuid uuidcdef uuid-dev uuid-runtime libuuid1
uuid:
  Installed: 1.6.2-1.5build2
  Candidate: 1.6.2-1.5build2
  Version table:
 *** 1.6.2-1.5build2 500
        500 http://by.archive.ubuntu.com/ubuntu xenial/universe amd64 Packages
        100 /var/lib/dpkg/status
uuidcdef:
  Installed: 0.3.13-5
  Candidate: 0.3.13-5
  Version table:
 *** 0.3.13-5 500
        500 http://by.archive.ubuntu.com/ubuntu xenial/main amd64 Packages
        100 /var/lib/dpkg/status
uuid-dev:
  Installed: 2.27.1-6ubuntu3.1
  Candidate: 2.27.1-6ubuntu3.1
  Version table:
 *** 2.27.1-6ubuntu3.1 500
        500 http://by.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     2.27.1-6ubuntu3 500
        500 http://by.archive.ubuntu.com/ubuntu xenial/main amd64 Packages
uuid-runtime:
  Installed: 2.27.1-6ubuntu3.1
  Candidate: 2.27.1-6ubuntu3.1
  Version table:
 *** 2.27.1-6ubuntu3.1 500
        500 http://by.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     2.27.1-6ubuntu3 500
        500 http://by.archive.ubuntu.com/ubuntu xenial/main amd64 Packages
libuuid1:
  Installed: 2.27.1-6ubuntu3.1
  Candidate: 2.27.1-6ubuntu3.1
  Version table:
 *** 2.27.1-6ubuntu3.1 500
        500 http://by.archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     2.27.1-6ubuntu3 500
        500 http://by.archive.ubuntu.com/ubuntu xenial/main amd64 Packages

Saving memory if bees is inactive.

Is it possible to add a function with an additional thread in bees to monitor disk activity. if there is zero write activity and no crawler activity this monitoring thread send a SIGSTOP to the process and after a configurable amount of written data (no metadata) the crawler gets reactivated with SIGCONT
So the hashtable could be swapped out by the kernel and it's saving memory.

Make DB_SIZE= resize the hashtable

Hi,

is it possible to make changing the DB_SIZE= in the beesd config trigger a resizing of the hastable?
How would I actually resize the hashtable myself, without loosing all the existing hashtable?

Service wrapper that doesn't require UUID to be known at config generation time?

The current wrapper requires on-disk configuration to be aware of the filesystem's UUID. If trying to build configuration ahead of a machine's instantiation, this is not ideal.

I've implemented an alternate wrapper as part of a PR to NixOS adding bees support, at https://github.com/NixOS/nixpkgs/blob/7f8d1ddb49963fb04dec2c7669489317948343d7/pkgs/tools/filesystems/bees/bees-service-wrapper (the larger PR is NixOS/nixpkgs#48423). I'm not necessarily proposing that exact code for merge to upstream bees, but having something like it -- permitting increased flexibility -- would be helpful.

RFE: Improve checksum lookup and support nodatasum

@Zygo wrote:

Some more thoughts...

We can identify nodatasum extents fairly easily--just look up the extent bytenr in the csum tree, and the sums should be there or not. This would allow the extents to be marked differently to avoid attempting to dedup them with the other kind of extent. It's a little more complicated than that (e.g. when bees grows matching pairs of extents, the src might spill over onto differently-summed extents) but still doable. This case comes up for toxic extents too, although in the toxic extent case we just throw the exception and move on, while in the nodatasum case we would need to stop growing and continue with the dedup.

The temporary file class could just have two instances, one for datasum extents, one for non-datasum extents, and the extent rewriter could use the appropriate one for a match.

Meh, or we just patch the kernel to allow these dedups. But then again it might be the right thing to do to support the two kinds of extent as separate duplicate classes. I keep going back and forth on this.

Bees reserves the bottom 12 bits of physical addresses in the hash table for various flags: 6 bits for compressed offsets, 1 for compression, 1 for unaligned EOF, 1 for toxic (although in practice there are so few toxic extents it makes more sense to just save them in a small text file instead of using a whole bit per DDT entry for them). That leaves 2 (3) more. Lots of bits are 0 in btrfs physical addresses because they're byte offsets on a filesystem with at least a 4K block size (so the bottom 12 bits are effectively always 0, as well as several at the top). There's no need to steal bits from the hash yet.

If we read the checksums directly out of the checksum tree, we can use them instead of reading and hashing blocks. 32 bits is too short for a hash--the collision rate after 16TB of unique data is too high, about 48-54 bytes are required for filesystems up to ~100TB; however, two consecutive 4K block CRC32s can be catenated to make a 64-bit hash, and that is long enough. If done correctly, bees won't need to read files at all while scanning them, only the reads during compare and dedup will be required. We'd lose some efficiency on compressed files, but I think the current design which tries to chop up compressed extents into smaller dedupable pieces isn't saving as much space as I'd like for the time it takes.

while the extent rewriter achieves much much higher io rates

Note that the extent rewriter almost always re-reads something that was very recently read by the scanner, so the data will still be in the VFS page cache (unless you are really low on memory). Extent rewrite typically has near-zero read overhead because the scanner does all the heavy lifting on reads, and the writes from dedup tend to get paid for by LOGICAL_INO and TREE_SEARCH_V2 requests that follow (or any other ioctl on the filesystem that joins a transaction and thereby waits for a commit and/or flush).

I am planning to do a rewrite that caches more stuff on reads and defers more writes to dedicated threads, partly to improve IO performance, but mostly to avoid bisecting extents almost all the time.

failed constraint check (ipos <= new_vec.rbegin()->m_end)

I'm seeing many of the following messages mostly in the context of the same file. After a while, I see these messages repeating again for another file.

Sep 19 21:35:10 jupiter beesd[7483]: crawl: *** EXCEPTION ***
Sep 19 21:35:10 jupiter beesd[7483]: crawl:         exception type std::runtime_error: ipos = 15650891, new_vec.rbegin()->m_end = 15650820 failed constraint check (ipos <= new_vec.rbegin()->m_end)
Sep 19 21:35:10 jupiter beesd[7483]: crawl: ***

ipos doesn't change while the file context doesn't change:

Sep 19 21:35:10 jupiter beesd[7483]: crawl:         exception type std::runtime_error: ipos = 15650891, new_vec.rbegin()->m_end = 15650820 failed constraint check (ipos <= new_vec.rbegin()->m_end)
Sep 19 21:35:10 jupiter beesd[7483]: crawl:         exception type std::runtime_error: ipos = 15650891, new_vec.rbegin()->m_end = 15650820 failed constraint check (ipos <= new_vec.rbegin()->m_end)
Sep 19 21:35:10 jupiter beesd[7483]: crawl:         exception type std::runtime_error: ipos = 15650891, new_vec.rbegin()->m_end = 15650820 failed constraint check (ipos <= new_vec.rbegin()->m_end)
Sep 19 21:35:10 jupiter beesd[7483]: crawl:         exception type std::runtime_error: ipos = 15650891, new_vec.rbegin()->m_end = 15650820 failed constraint check (ipos <= new_vec.rbegin()->m_end)

WARNING: CPU: 0 PID: 5655 at fs/btrfs/backref.c:1255 find_parent_nodes+0xac7/0xf90 [btrfs]

I'm seeing this on two different systems now:

[175724.544700] ------------[ cut here ]------------
[175724.544717] WARNING: CPU: 0 PID: 5655 at fs/btrfs/backref.c:1255 find_parent_nodes+0xac7/0xf90 [btrfs]
[175724.544718] Modules linked in: ntfs uas usb_storage btrfs xor zstd_decompress zstd_compress xxhash zlib_deflate raid6_pq efivarfs
[175724.544726] CPU: 0 PID: 5655 Comm: crawl Tainted: G        W       4.14.11-gentoo-r2 #11
[175724.544727] Hardware name: VMware, Inc. VMware7,1/440BX Desktop Reference Platform, BIOS VMW71.00V.0.B64.1307300729 07/30/2013
[175724.544727] task: ffff99bf55c58cc0 task.stack: ffffb23ac32f8000
[175724.544737] RIP: 0010:find_parent_nodes+0xac7/0xf90 [btrfs]
[175724.544738] RSP: 0018:ffffb23ac32fbb40 EFLAGS: 00010286
[175724.544739] RAX: 00000000ffffffff RBX: ffff99bf82638528 RCX: 0000000000000001
[175724.544740] RDX: 0000000000000000 RSI: ffff99bf9c3d03b8 RDI: ffff99bf82638e18
[175724.544740] RBP: ffffb23ac32fbc50 R08: 0000000000000000 R09: ffffffffc039df84
[175724.544741] R10: ffffe3abc170f400 R11: ffff99c177001c00 R12: 0000000000000001
[175724.544742] R13: ffff99bf82638e18 R14: ffff99bf9c3d0d60 R15: ffffb23ac32fbbf0
[175724.544743] FS:  00007fd71023e700(0000) GS:ffff99c17fc00000(0000) knlGS:0000000000000000
[175724.544744] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[175724.544745] CR2: 00007fd7003a1b28 CR3: 000000013031f000 CR4: 00000000000406f0
[175724.544807] Call Trace:
[175724.544824]  ? btrfs_find_all_roots_safe+0x8e/0x100 [btrfs]
[175724.544836]  btrfs_find_all_roots_safe+0x8e/0x100 [btrfs]
[175724.544850]  ? extent_same_check_offsets+0x60/0x60 [btrfs]
[175724.544861]  iterate_extent_inodes+0x154/0x270 [btrfs]
[175724.544871]  ? extent_same_check_offsets+0x60/0x60 [btrfs]
[175724.544880]  ? iterate_inodes_from_logical+0x81/0x90 [btrfs]
[175724.544888]  iterate_inodes_from_logical+0x81/0x90 [btrfs]
[175724.544898]  btrfs_ioctl+0x892/0x23e0 [btrfs]
[175724.544902]  ? _copy_to_user+0x22/0x30
[175724.544905]  ? cp_new_stat+0x138/0x150
[175724.544907]  ? do_vfs_ioctl+0x8a/0x5c0
[175724.544909]  do_vfs_ioctl+0x8a/0x5c0
[175724.544911]  ? SYSC_newfstat+0x29/0x40
[175724.544913]  SyS_ioctl+0x36/0x70
[175724.544916]  entry_SYSCALL_64_fastpath+0x1a/0x7d
[175724.544917] RIP: 0033:0x7fd710533817
[175724.544918] RSP: 002b:00007fd71023b218 EFLAGS: 00000246
[175724.544919] Code: 30 ff ff ff 57 4d 8b 4c 24 20 4d 8b 44 24 50 8d 48 01 e9 5c fc ff ff 85 c0 0f 85 57 fa ff ff e9 ba f9 ff ff 31 c0 e9 e1 fc ff ff <0f> ff 4d 85 f6 0f 84 33 fa ff ff e9 d2 f9 ff ff 41 8b 45 34 85
[175724.544940] ---[ end trace 96f30706e682f0bd ]---

System Hangs

Hi, i just give a try to bees on my notebook, i have only one btrfs partition for all data.

After some processing, my system hangs not completely but looks like btrfs thread are hung and i don't see something in the dmesg (and i can't execute any command, as a IO Hung).

After reboot and short time i get this hang again, so looks like a problem with part of fs (but i catch it only by bees).

After reset system, i get a corrupted kernel image and to fix this, i must boot from iso and reinstall kernel.
So it's a expected behavior? I think what extent_same can't corrupt any data -_-'.

May be it's a bad idea run bees on the root partition?

Archlinux x86_64
Linux 4.8.10
Bees - latest git


Update:
I leave it's working for several hours (~10h), and system not hangs, or may be hungs is a just long btrfs transactions. But after reboot i get corrupted kernel image again =
Thoughts?

Controlling logging severity

Currently it seems like a lot of unnecessary information is being written to stdout (which in turn causes a log spam when used with systemd). From quick look at the code, the concept of log levels seems to be implemented already, but I can't find a way to set the minimum level, so that all the ones below it are ignored. It would be nice if this could be controlled using command line arguments (and in turn via the config file).

Documentation of hash table stats

An interpretation of what the hash table page occupancy histogram shows may be useful. One filesystem has an occupancy of 42% and a large heap around 40% on the x axis, another filesystem has an occupancy of 98%+, and a smaller heap around 40% and a large heap around 95%.

What does it mean, and what should I do?

Please explain, for that Bees use Dat file

I have test it on my notebook, as i don't want put it in test lab or production servers
(i don't trust enough at now bees and bees + btrfs, sorry)

So, i have ~80G of data, for that i preallocate 1G dat file. But maximum usage of that file has been ~240 kb.
Before, i think this file used for persistent store of hashes, as bees working for several days on it, and several times show "No more data for processing", i think bees already process all my data.

So, i don't know what bees must do with this file, can you explain?

Thank.

Compiling problem

Hi Zygo, i've try package your bees for AUR, and get the following compiling errors:

bees git:(master) make   
make -C lib
make[1]: Entering directory '/home/nefelim4ag/Insync/Documents/Dump/Coding/bees/lib'
g++ -Wall -Wextra -Werror -O3 -I../include -ggdb -fpic -std=c++11 -Wold-style-cast -o chatter.o -c chatter.cc
In file included from chatter.cc:1:0:
../include/crucible/chatter.h: In member function ‘crucible::Chatter& crucible::ChatterTraits<std::basic_ostream<char>&>::operator()(crucible::Chatter&, std::ostream&)’:
../include/crucible/chatter.h:94:15: error: no match for ‘operator<<’ (operand types are ‘std::ostream {aka std::basic_ostream<char>}’ and ‘std::ostream {aka std::basic_ostream<char>}’)
    c.get_os() << arg;
    ~~~~~~~~~~~^~~~~~
../include/crucible/chatter.h:94:15: note: candidate: operator<<(int, int) <built-in>
../include/crucible/chatter.h:94:15: note:   no known conversion for argument 2 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘int’
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:108:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(std::basic_ostream<_CharT, _Traits>::__ostream_type& (*)(std::basic_ostream<_CharT, _Traits>::__ostream_type&)) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(__ostream_type& (*__pf)(__ostream_type&))
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:108:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘std::basic_ostream<char>::__ostream_type& (*)(std::basic_ostream<char>::__ostream_type&) {aka std::basic_ostream<char>& (*)(std::basic_ostream<char>&)}’
/usr/include/c++/6.2.1/ostream:117:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(std::basic_ostream<_CharT, _Traits>::__ios_type& (*)(std::basic_ostream<_CharT, _Traits>::__ios_type&)) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>; std::basic_ostream<_CharT, _Traits>::__ios_type = std::basic_ios<char>]
       operator<<(__ios_type& (*__pf)(__ios_type&))
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:117:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘std::basic_ostream<char>::__ios_type& (*)(std::basic_ostream<char>::__ios_type&) {aka std::basic_ios<char>& (*)(std::basic_ios<char>&)}’
/usr/include/c++/6.2.1/ostream:127:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(std::ios_base& (*)(std::ios_base&)) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(ios_base& (*__pf) (ios_base&))
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:127:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘std::ios_base& (*)(std::ios_base&)’
/usr/include/c++/6.2.1/ostream:166:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(long int) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(long __n)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:166:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘long int’
/usr/include/c++/6.2.1/ostream:170:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(long unsigned int) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(unsigned long __n)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:170:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘long unsigned int’
/usr/include/c++/6.2.1/ostream:174:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(bool) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(bool __n)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:174:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘bool’
In file included from /usr/include/c++/6.2.1/ostream:638:0,
                 from /usr/include/c++/6.2.1/iostream:39,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/bits/ostream.tcc:91:5: note: candidate: std::basic_ostream<_CharT, _Traits>& std::basic_ostream<_CharT, _Traits>::operator<<(short int) [with _CharT = char; _Traits = std::char_traits<char>]
     basic_ostream<_CharT, _Traits>::
     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/usr/include/c++/6.2.1/bits/ostream.tcc:91:5: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘short int’
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:181:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(short unsigned int) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(unsigned short __n)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:181:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘short unsigned int’
In file included from /usr/include/c++/6.2.1/ostream:638:0,
                 from /usr/include/c++/6.2.1/iostream:39,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/bits/ostream.tcc:105:5: note: candidate: std::basic_ostream<_CharT, _Traits>& std::basic_ostream<_CharT, _Traits>::operator<<(int) [with _CharT = char; _Traits = std::char_traits<char>]
     basic_ostream<_CharT, _Traits>::
     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/usr/include/c++/6.2.1/bits/ostream.tcc:105:5: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘int’
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:192:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(unsigned int) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(unsigned int __n)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:192:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘unsigned int’
/usr/include/c++/6.2.1/ostream:201:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(long long int) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(long long __n)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:201:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘long long int’
/usr/include/c++/6.2.1/ostream:205:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(long long unsigned int) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(unsigned long long __n)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:205:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘long long unsigned int’
/usr/include/c++/6.2.1/ostream:220:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(double) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(double __f)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:220:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘double’
/usr/include/c++/6.2.1/ostream:224:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(float) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(float __f)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:224:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘float’
/usr/include/c++/6.2.1/ostream:232:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(long double) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(long double __f)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:232:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘long double’
/usr/include/c++/6.2.1/ostream:245:7: note: candidate: std::basic_ostream<_CharT, _Traits>::__ostream_type& std::basic_ostream<_CharT, _Traits>::operator<<(const void*) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__ostream_type = std::basic_ostream<char>]
       operator<<(const void* __p)
       ^~~~~~~~
/usr/include/c++/6.2.1/ostream:245:7: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘const void*’
In file included from /usr/include/c++/6.2.1/ostream:638:0,
                 from /usr/include/c++/6.2.1/iostream:39,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/bits/ostream.tcc:119:5: note: candidate: std::basic_ostream<_CharT, _Traits>& std::basic_ostream<_CharT, _Traits>::operator<<(std::basic_ostream<_CharT, _Traits>::__streambuf_type*) [with _CharT = char; _Traits = std::char_traits<char>; std::basic_ostream<_CharT, _Traits>::__streambuf_type = std::basic_streambuf<char>]
     basic_ostream<_CharT, _Traits>::
     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/usr/include/c++/6.2.1/bits/ostream.tcc:119:5: note:   no known conversion for argument 1 from ‘std::ostream {aka std::basic_ostream<char>}’ to ‘std::basic_ostream<char>::__streambuf_type* {aka std::basic_streambuf<char>*}’
In file included from /usr/include/c++/6.2.1/string:52:0,
                 from /usr/include/c++/6.2.1/stdexcept:39,
                 from /usr/include/c++/6.2.1/array:39,
                 from /usr/include/c++/6.2.1/tuple:39,
                 from /usr/include/c++/6.2.1/functional:55,
                 from ../include/crucible/chatter.h:4,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/bits/basic_string.h:5325:5: note: candidate: template<class _CharT, class _Traits, class _Alloc> std::basic_ostream<_CharT, _Traits>& std::operator<<(std::basic_ostream<_CharT, _Traits>&, const std::__cxx11::basic_string<_CharT, _Traits, _Alloc>&)
     operator<<(basic_ostream<_CharT, _Traits>& __os,
     ^~~~~~~~
/usr/include/c++/6.2.1/bits/basic_string.h:5325:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   ‘std::ostream {aka std::basic_ostream<char>}’ is not derived from ‘const std::__cxx11::basic_string<_CharT, _Traits, _Alloc>’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/bits/ios_base.h:46:0,
                 from /usr/include/c++/6.2.1/ios:42,
                 from /usr/include/c++/6.2.1/ostream:38,
                 from /usr/include/c++/6.2.1/iostream:39,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/system_error:209:5: note: candidate: template<class _CharT, class _Traits> std::basic_ostream<_CharT, _Traits>& std::operator<<(std::basic_ostream<_CharT, _Traits>&, const std::error_code&)
     operator<<(basic_ostream<_CharT, _Traits>& __os, const error_code& __e)
     ^~~~~~~~
/usr/include/c++/6.2.1/system_error:209:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘const std::error_code&’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:497:5: note: candidate: template<class _CharT, class _Traits> std::basic_ostream<_CharT, _Traits>& std::operator<<(std::basic_ostream<_CharT, _Traits>&, _CharT)
     operator<<(basic_ostream<_CharT, _Traits>& __out, _CharT __c)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:497:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   deduced conflicting types for parameter ‘_CharT’ (‘char’ and ‘std::basic_ostream<char>’)
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:502:5: note: candidate: template<class _CharT, class _Traits> std::basic_ostream<_CharT, _Traits>& std::operator<<(std::basic_ostream<_CharT, _Traits>&, char)
     operator<<(basic_ostream<_CharT, _Traits>& __out, char __c)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:502:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘char’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:508:5: note: candidate: template<class _Traits> std::basic_ostream<char, _Traits>& std::operator<<(std::basic_ostream<char, _Traits>&, char)
     operator<<(basic_ostream<char, _Traits>& __out, char __c)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:508:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘char’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:514:5: note: candidate: template<class _Traits> std::basic_ostream<char, _Traits>& std::operator<<(std::basic_ostream<char, _Traits>&, signed char)
     operator<<(basic_ostream<char, _Traits>& __out, signed char __c)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:514:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘signed char’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:519:5: note: candidate: template<class _Traits> std::basic_ostream<char, _Traits>& std::operator<<(std::basic_ostream<char, _Traits>&, unsigned char)
     operator<<(basic_ostream<char, _Traits>& __out, unsigned char __c)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:519:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘unsigned char’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:539:5: note: candidate: template<class _CharT, class _Traits> std::basic_ostream<_CharT, _Traits>& std::operator<<(std::basic_ostream<_CharT, _Traits>&, const _CharT*)
     operator<<(basic_ostream<_CharT, _Traits>& __out, const _CharT* __s)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:539:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   mismatched types ‘const _CharT*’ and ‘std::basic_ostream<char>’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/ostream:638:0,
                 from /usr/include/c++/6.2.1/iostream:39,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/bits/ostream.tcc:321:5: note: candidate: template<class _CharT, class _Traits> std::basic_ostream<_CharT, _Traits>& std::operator<<(std::basic_ostream<_CharT, _Traits>&, const char*)
     operator<<(basic_ostream<_CharT, _Traits>& __out, const char* __s)
     ^~~~~~~~
/usr/include/c++/6.2.1/bits/ostream.tcc:321:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘const char*’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:556:5: note: candidate: template<class _Traits> std::basic_ostream<char, _Traits>& std::operator<<(std::basic_ostream<char, _Traits>&, const char*)
     operator<<(basic_ostream<char, _Traits>& __out, const char* __s)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:556:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘const char*’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:569:5: note: candidate: template<class _Traits> std::basic_ostream<char, _Traits>& std::operator<<(std::basic_ostream<char, _Traits>&, const signed char*)
     operator<<(basic_ostream<char, _Traits>& __out, const signed char* __s)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:569:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘const signed char*’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:574:5: note: candidate: template<class _Traits> std::basic_ostream<char, _Traits>& std::operator<<(std::basic_ostream<char, _Traits>&, const unsigned char*)
     operator<<(basic_ostream<char, _Traits>& __out, const unsigned char* __s)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:574:5: note:   template argument deduction/substitution failed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:18: note:   cannot convert ‘arg’ (type ‘std::ostream {aka std::basic_ostream<char>}’) to type ‘const unsigned char*’
    c.get_os() << arg;
                  ^~~
In file included from /usr/include/c++/6.2.1/iostream:39:0,
                 from ../include/crucible/chatter.h:5,
                 from chatter.cc:1:
/usr/include/c++/6.2.1/ostream:628:5: note: candidate: std::basic_ostream<_CharT, _Traits>& std::operator<<(std::basic_ostream<_CharT, _Traits>&&, const _Tp&) [with _CharT = char; _Traits = std::char_traits<char>; _Tp = std::basic_ostream<char>] <near match>
     operator<<(basic_ostream<_CharT, _Traits>&& __os, const _Tp& __x)
     ^~~~~~~~
/usr/include/c++/6.2.1/ostream:628:5: note:   conversion of argument 1 would be ill-formed:
In file included from chatter.cc:1:0:
../include/crucible/chatter.h:94:12: error: cannot bind ‘std::ostream {aka std::basic_ostream<char>}’ lvalue to ‘std::basic_ostream<char>&&’
    c.get_os() << arg;
    ~~~~~~~~^~
chatter.cc: At global scope:
chatter.cc:18:9: error: ‘template<class> class std::auto_ptr’ is deprecated [-Werror=deprecated-declarations]
  static auto_ptr<set<string>> chatter_names;
         ^~~~~~~~
In file included from /usr/include/c++/6.2.1/memory:81:0,
                 from ../include/crucible/resource.h:8,
                 from ../include/crucible/process.h:4,
                 from chatter.cc:4:
/usr/include/c++/6.2.1/bits/unique_ptr.h:49:28: note: declared here
   template<typename> class auto_ptr;
                            ^~~~~~~~
cc1plus: all warnings being treated as errors
make[1]: *** [Makefile:34: chatter.o] Error 1
make[1]: Leaving directory '/home/nefelim4ag/Insync/Documents/Dump/Coding/bees/lib'
make: *** [Makefile:9: lib] Error 2

Host Arch x64
g++ (GCC) 6.2.1 20160830
GNU Make 4.2.1

Thanks.

exception type std::runtime_error: FIXME: bailing out here, need to fix this further up the call stack

I am getting quite a lot of the below exceptions - are they something I should worry about? I've screwed up this filesystem twice now trying to dedupe it, so I'm trying to find out what the trouble is. I've ruled out hardware as it was perfect until I tried deduping, and the same disks contain another filesystem which is operating correctly. (Two raid1s sharing the same pair of discs, 1/2 each.)
Kernel last time was 4.15.latest, this time is 4.14.24.

<6>crawl_258[23593]: scan: 4K 0x4aa4000 [D] 0x4aa5000 /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<6>crawl_258[23593]: dedup: src 4K [0x4aa4000..0x4aa5000] {0xa643e000z3000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<6>crawl_258[23593]:        dst 4K [0x4aa7000..0x4aa8000] {0xa6439000z7000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<6>crawl_258[23593]: dedup: src 4K [0x4a8a000..0x4a8b000] {0xa6421000z4000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<6>crawl_258[23593]:        dst 4K [0x4aa8000..0x4aa9000] {0xa6439000z8000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<3>crawl_258[23598]: Opening src bfr 4K [0x4806000..0x4807000] fid = 258:697 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23598]: chase_extent_ref ino BtrfsInodeOffsetRoot { .m_inum = 697, .m_offset = 0x4805000, .m_root = 258 } bbd BeesBlockData { 4K 0x4a43000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', data[4096] }
<3>crawl_258[23598]: ino_off_root BtrfsInodeOffsetRoot { .m_inum = 697, .m_offset = 0x4805000, .m_root = 258 }
<3>crawl_258[23598]: for_each_extent_ref BeesBlockData { 4K 0x4a43000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', data[4096] } at 0xa6421000z5000: 2053 found
<3>crawl_258[23598]: overlap_bfr 0 (..0x0]
<3>crawl_258[23598]: Opening dst bfr 4K [0x4a43000..0x4a44000] fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23598]: replace_dst dst_bfr 4K [0x4a43000..0x4a44000] fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23598]: finding one match (out of 2053) at 0xa6421000z5000 for BeesBlockData { 4K 0x4a43000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6420000z7000, hash = 0x661fd10b39c0f81e, data[4096] }
<3>crawl_258[23598]: resolved_addrs.size() = 3
<3>crawl_258[23598]: Pushing hash 0x661fd10b39c0f81e addr 0xa6420000z7000 bbd BeesBlockData { 4K 0x4a43000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6420000z7000, hash = 0x661fd10b39c0f81e, data[4096] }
<3>crawl_258[23598]: scan bbd BeesBlockData { 4K 0x4a43000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6420000z7000, hash = 0x661fd10b39c0f81e, data[4096] }
<3>crawl_258[23598]: Extent { begin = 0x4a43000, end = 0x4a44000, physical = 0xa6420000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x7000 } block_count 1
<3>crawl_258[23598]: scan extent Extent { begin = 0x4a43000, end = 0x4a44000, physical = 0xa6420000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x7000 }
<3>crawl_258[23598]:
<3>crawl_258[23598]:
<3>crawl_258[23598]: *** EXCEPTION ***
<3>crawl_258[23598]:    exception type std::runtime_error: FIXME: bailing out here, need to fix this further up the call stack
<3>crawl_258[23598]: ***
<6>crawl_258[23595]: dedup: src 4K [0x4a67000..0x4a68000] {0xa6421000z2000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<6>crawl_258[23595]:        dst 4K [0x4aa0000..0x4aa1000] {0xa6420000z7000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<3>crawl_258[23593]: Opening src bfr 4K [0x47e7000..0x47e8000] fid = 258:697 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23593]: chase_extent_ref ino BtrfsInodeOffsetRoot { .m_inum = 697, .m_offset = 0x47e2000, .m_root = 258 } bbd BeesBlockData { 4K 0x4aa8000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', data[4096] }
<3>crawl_258[23593]: ino_off_root BtrfsInodeOffsetRoot { .m_inum = 697, .m_offset = 0x47e2000, .m_root = 258 }
<3>crawl_258[23593]: for_each_extent_ref BeesBlockData { 4K 0x4aa8000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', data[4096] } at 0xa6421000z7000: 2111 found
<3>crawl_258[23593]: overlap_bfr 0 (..0x0]
<3>crawl_258[23593]: Opening dst bfr 4K [0x4aa8000..0x4aa9000] fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23593]: replace_dst dst_bfr 4K [0x4aa8000..0x4aa9000] fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23593]: finding one match (out of 2111) at 0xa6421000z7000 for BeesBlockData { 4K 0x4aa8000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6439000z8000, hash = 0xf8ad5e859508bb0d, data[4096] }
<3>crawl_258[23593]: resolved_addrs.size() = 2
<3>crawl_258[23593]: Pushing hash 0xf8ad5e859508bb0d addr 0xa6439000z8000 bbd BeesBlockData { 4K 0x4aa8000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6439000z8000, hash = 0xf8ad5e859508bb0d, data[4096] }
<3>crawl_258[23593]: scan bbd BeesBlockData { 4K 0x4aa8000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6439000z8000, hash = 0xf8ad5e859508bb0d, data[4096] }
<3>crawl_258[23593]: Extent { begin = 0x4aa5000, end = 0x4ac0000, physical = 0xa6439000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1b000, offset = 0x5000 } block_count 27
<3>crawl_258[23593]: scan extent Extent { begin = 0x4aa5000, end = 0x4ac0000, physical = 0xa6439000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1b000, offset = 0x5000 }
<3>crawl_258[23593]:
<3>crawl_258[23593]:
<3>crawl_258[23593]: *** EXCEPTION ***
<3>crawl_258[23593]:    exception type std::runtime_error: FIXME: bailing out here, need to fix this further up the call stack
<3>crawl_258[23593]: ***
<3>crawl_258[23595]: Opening src bfr 4K [0x4806000..0x4807000] fid = 258:697 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23595]: chase_extent_ref ino BtrfsInodeOffsetRoot { .m_inum = 697, .m_offset = 0x4805000, .m_root = 258 } bbd BeesBlockData { 4K 0x4aa0000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', data[4096] }
<3>crawl_258[23595]: ino_off_root BtrfsInodeOffsetRoot { .m_inum = 697, .m_offset = 0x4805000, .m_root = 258 }
<3>crawl_258[23595]: for_each_extent_ref BeesBlockData { 4K 0x4aa0000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', data[4096] } at 0xa6421000z5000: 2174 found
<3>crawl_258[23595]: overlap_bfr 0 (..0x0]
<3>crawl_258[23595]: Opening dst bfr 4K [0x4aa0000..0x4aa1000] fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23595]: replace_dst dst_bfr 4K [0x4aa0000..0x4aa1000] fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp'
<3>crawl_258[23595]: finding one match (out of 2174) at 0xa6421000z5000 for BeesBlockData { 4K 0x4aa0000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6420000z7000, hash = 0x661fd10b39c0f81e, data[4096] }
<3>crawl_258[23595]: resolved_addrs.size() = 3
<3>crawl_258[23595]: Pushing hash 0x661fd10b39c0f81e addr 0xa6420000z7000 bbd BeesBlockData { 4K 0x4aa0000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6420000z7000, hash = 0x661fd10b39c0f81e, data[4096] }
<3>crawl_258[23595]: scan bbd BeesBlockData { 4K 0x4aa0000 fd = 370 '/media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp', address = 0xa6420000z7000, hash = 0x661fd10b39c0f81e, data[4096] }
<3>crawl_258[23595]: Extent { begin = 0x4aa0000, end = 0x4aa1000, physical = 0xa6420000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x7000 } block_count 1
<3>crawl_258[23595]: scan extent Extent { begin = 0x4aa0000, end = 0x4aa1000, physical = 0xa6420000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x1000, offset = 0x7000 }
<3>crawl_258[23595]:
<3>crawl_258[23595]:
<3>crawl_258[23595]: *** EXCEPTION ***
<3>crawl_258[23595]:    exception type std::runtime_error: FIXME: bailing out here, need to fix this further up the call stack
<3>crawl_258[23595]: ***
<6>crawl_258[23599]: dedup: src 4K [0x4aa0000..0x4aa1000] {0xa6421000z2000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp
<6>crawl_258[23599]:        dst 4K [0x4a82000..0x4a83000] {0xa6420000z7000} /media/backup/jones/2018-03-09/pj-google/Gigatech/invoice template.bmp

Just a curios, why CRC64?

Just a curios, why CRC64?
i.e. AFAIK CRC without HW acceleration not fastest checksum,
and as i see in code CRC64 are full SW.

Thanks.

Seems to crawl the same two files over and over again

Currently I see bees crawling the same two files over and over again since days. It seems to be constantly reading those files without any progress (always offset 0), and it generates 100% CPU during the process due to constantly hashing the same blocks.

This is from the logs:

Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawled inline 1 data 0 other 121 unknown 0 gen_low 1 gen_high 0 BeesCrawlState 857:271 offset 0x35894488 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago) in 0.001s
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawling BeesCrawlState 857:271 offset 0x35894488 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawl empty BeesCrawlState 857:271 offset 0x35894488 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Deferring next transid in BeesCrawlState 857:271 offset 0x35894488 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Next transid in BeesCrawlState 1002:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Restarting crawl BeesCrawlState 1002:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawling BeesCrawlState 1002:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawl empty BeesCrawlState 1002:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Deferring next transid in BeesCrawlState 1002:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Next transid in BeesCrawlState 1844:5330 offset 0x1 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Restarting crawl BeesCrawlState 1844:5330 offset 0x1 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawling BeesCrawlState 1844:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawling 60 results from BeesCrawlState 1844:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawled inline 1 data 45 other 14 unknown 0 gen_low 17 gen_high 0 BeesCrawlState 1844:5332 offset 0x1 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago) in 0.001s
Okt 27 19:26:26 jupiter beesd[714]: crawl: Next transid in BeesCrawlState 1849:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Restarting crawl BeesCrawlState 1849:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawling BeesCrawlState 1849:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawl empty BeesCrawlState 1849:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Deferring next transid in BeesCrawlState 1849:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Next transid in BeesCrawlState 258:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Restarting crawl BeesCrawlState 258:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawling BeesCrawlState 258:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawl empty BeesCrawlState 258:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Deferring next transid in BeesCrawlState 258:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Next transid in BeesCrawlState 261:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Restarting crawl BeesCrawlState 261:0 offset 0x0 transid 1266978..1267007 started 2017-10-27-19-03-16 (908s ago)
Okt 27 19:26:26 jupiter beesd[714]: crawl: Crawling BeesCrawlState 261:0 offset 0x0 transid 1267007..1267034 started 2017-10-27-19-18-24 (0s ago)

The state file switches between both files every few seconds:

THREADS:
        tid 783: [83957s] main
        tid 849: crawl: searching at offset 0x159000 in file /run/bees/mnt/bc201ce5-8f2b-4263-995a-6641e89d4c88/home/kakra/.local/share/Steam/userdata/126535081/310560/remote/savegame@profile_backup#QKIGMYYI.LKR
        for BeesBlockData { 4K 0x1cb000 fd = 34 '/run/bees/mnt/bc201ce5-8f2b-4263-995a-6641e89d4c88/home/kakra/.local/share/Steam/userdata/126535081/310560/remote/savegame@profile_backup#QKIGMYYI.LKR', data[4096] = '\xad\xacB\x07H}\xe8Kl\x83\x0bQ...' }
        tid 850: status: writing status to file '/run/bees//bc201ce5-8f2b-4263-995a-6641e89d4c88.status'
        tid 851: crawl_writeback: [246s] BeesCrawlState 259:6594754 offset 0x1 transid 1267021..1267048 started 2017-10-27-19-26-26 (401s ago)
        tid 853: hash_writeback: [9.874s] flush rate limited at extent #18 (18 of 61)
        tid 854: hash_prefetch: [989.118s] idle 3600s

THREADS:
        tid 783: [83998s] main
        tid 849: crawl: searching at offset 0x119000 in file /run/bees/mnt/bc201ce5-8f2b-4263-995a-6641e89d4c88/home/kakra/.local/share/Steam/userdata/126535081/310560/remote/savegame@profile#QKIGMYYI.LKR
        for BeesBlockData { 4K 0x1d9000 fd = 34 '/run/bees/mnt/bc201ce5-8f2b-4263-995a-6641e89d4c88/home/kakra/.local/share/Steam/userdata/126535081/310560/remote/savegame@profile_backup#QKIGMYYI.LKR', data[4096] = '\xad\xacB\x07H}\xe8Kl\x83\x0bQ...' }
        tid 850: status: writing status to file '/run/bees//bc201ce5-8f2b-4263-995a-6641e89d4c88.status'
        tid 851: crawl_writeback: [287.023s] BeesCrawlState 259:6594754 offset 0x1 transid 1267021..1267048 started 2017-10-27-19-26-26 (442s ago) (dirty)
        tid 853: hash_writeback: [8.709s] flush rate limited at extent #22 (21 of 61)
        tid 854: hash_prefetch: [1030.14s] idle 3600s

THREADS:
        tid 783: [84038s] main
        tid 849: crawl: searching at offset 0x1f9000 in file /run/bees/mnt/bc201ce5-8f2b-4263-995a-6641e89d4c88/home/kakra/.local/share/Steam/userdata/126535081/310560/remote/savegame@profile#QKIGMYYI.LKR
        for BeesBlockData { 4K 0x1e7000 fd = 34 '/run/bees/mnt/bc201ce5-8f2b-4263-995a-6641e89d4c88/home/kakra/.local/share/Steam/userdata/126535081/310560/remote/savegame@profile_backup#QKIGMYYI.LKR', data[4096] = '\xad\xacB\x07H}\xe8Kl\x83\x0bQ...' }
        tid 850: status: writing status to file '/run/bees//bc201ce5-8f2b-4263-995a-6641e89d4c88.status'
        tid 851: crawl_writeback: [327.041s] BeesCrawlState 259:6594754 offset 0x1 transid 1267021..1267048 started 2017-10-27-19-26-26 (482s ago) (dirty)
        tid 853: hash_writeback: [6.538s] flush rate limited at extent #25 (24 of 61)
        tid 854: hash_prefetch: [1070.16s] idle 3600s

What changes over time is the transid range...

I don't think something is accessing the files all the time:

lsof|fgrep savegame yields nothing. Timestamps (atime, ctime, and mtime) are weeks ago, eventually even months.

kernel: [297410.332718] BTRFS error (device bcache3): bdev /dev/bcache3 errs: wr 0, rd 1, flush 0, corrupt 0, gen 0

When running bees, I see the following kernel message from time to time:

[297410.332718] BTRFS error (device bcache3): bdev /dev/bcache3 errs: wr 0, rd 1, flush 0, corrupt 0, gen 0

This is very very rare, with increasing rd errors in timescales of months.

However, all the files seem to be okay, HDD surfaces are okay (according to smartctl). There are no other errors in the kernel log around these messages.

Using journalctl I am able to get this in context with the bees logs:

Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: dedup: src 128K [0x20000..0x40000] {0x8970578000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl:        dst 128K [0x20000..0x40000] {0x897090c000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0x20000 [Dddddddddddddddddddddddddddddddd] 0x40000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: dedup: src 20K [0x9db55f000..0x9db564000] {0x2adc78f000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl:        dst 20K [0x979ee4000..0x979ee9000] {0x291627e000z19000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: scan: 20K 0x979ee4000 [DDDdd] 0x979ee9000 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: dedup: src 128K [0x40000..0x60000] {0x8970580000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl:        dst 128K [0x40000..0x60000] {0x8970914000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0x40000 [Dddddddddddddddddddddddddddddddd] 0x60000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: WORKAROUND: abandoned toxic match for hash 0x88ae7d417641951e addr 0x29151e5000tz1e000
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: dedup: src 128K [0x60000..0x80000] {0x8970585000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl:        dst 128K [0x60000..0x80000] {0x8970919000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0x60000 [Dddddddddddddddddddddddddddddddd] 0x80000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: WORKAROUND: abandoned toxic match for hash 0x7bdb4b8d1a2774d1 addr 0x2a7fe95000t
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: dedup: src 128K [0x80000..0xa0000] {0x897058a000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl:        dst 128K [0x80000..0xa0000] {0x897091e000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0x80000 [Dddddddddddddddddddddddddddddddd] 0xa0000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: dedup: src 12K [0x9b7099000..0x9b709c000] {0x2915780000z0} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl:        dst 12K [0x979eeb000..0x979eee000] {0x2960aaf000z0} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:56 jupiter beesd[12654]: tid 12711 crawl: scan: 12K 0x979eeb000 [DDD] 0x979eee000 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter kernel: BTRFS error (device bcache3): bdev /dev/bcache3 errs: wr 0, rd 1, flush 0, corrupt 0, gen 0
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 128K [0xa0000..0xc0000] {0x8970590000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 128K [0xa0000..0xc0000] {0x8970924000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0xa0000 [Dddddddddddddddddddddddddddddddd] 0xc0000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 32K [0x9ab9a9000..0x9ab9b1000] {0x290fed4000z3000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 32K [0x979eee000..0x979ef6000] {0x2917d02000z3000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 32K 0x979eee000 [DDdddddd] 0x979ef6000 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 128K [0xc0000..0xe0000] {0x897059b000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 128K [0xc0000..0xe0000] {0x897092f000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0xc0000 [Dddddddddddddddddddddddddddddddd] 0xe0000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 32K [0x9b7a64000..0x9b7a6c000] {0x2915d64000zb000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 32K [0x979ef6000..0x979efe000] {0x2917b80000zb000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 32K 0x979ef6000 [DDdddddd] 0x979efe000 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 100K [0xe0000..0xf9000] {0x5575ef000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 100K [0xe0000..0xf9000] {0x897093a000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 12K [0x110000..0x113000] {0x89707d0000z13000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 12K [0xfd000..0x100000] {0x897093a000z1d000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: copy: 16K [0xf9000..0xfd000] fd = 112 'home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim'
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 16K [0xc2d6000..0xc2da000] {0xd02550000z0} #3208 (deleted)
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 16K [0xf9000..0xfd000] {0x897093a000z19000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0xe0000 [ddddddddddddddddddddddddd++++ddd] 0x100000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 16K [0x9b9a7f000..0x9b9a83000] {0x29177c6000z13000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 16K [0x979efe000..0x979f02000] {0x2917f06000z13000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 16K 0x979efe000 [DDdd] 0x979f02000 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 60K [0x113000..0x122000] {0x89707d0000z16000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt_to_idle_hurt.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 60K [0x100000..0x10f000] {0x897093e000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 16K [0x110000..0x114000] {0x89705aa000z1000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 16K [0x10f000..0x113000] {0x897093e000zf000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 52K [0xff000..0x10c000] {0x89705aa000z5000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 52K [0x113000..0x120000] {0x897093e000z13000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 128K 0x100000 [DddddddddddddddDdddDdddddddddddd] 0x120000 home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 36K [0x9b6290000..0x9b6299000] {0x2915108000z17000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 36K [0x979f02000..0x979f0b000] {0x2917fe8000z17000} home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: scan: 36K 0x979f02000 [DDddddddd] 0x979f0b000 home/kakra/.VirtualBox/VDI/WindowsXPPro_C.vdi
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl: dedup: src 32K [0x10c000..0x114000] {0x89705aa000z12000} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_hurt.dae_anim
Jan 18 03:47:57 jupiter beesd[12654]: tid 12711 crawl:        dst 32K [0x120000..0x128000] {0x897093f000z0} home/kakra/.local/share/Steam/SteamApps/common/SOMA/entities/character/robot/kate_soma/animations/move_to_idle.dae_anim

Maybe bees triggers another kernel bug?

Problems with handle beeshash.dat unaligned by 16MiB

Hi, i've try try test how bees behave if db size are unaligned (256MiB -> 257MiB),
and if i understood correctly the code, bees must die/crash on that.

(Sorry i'm have a problems with C++ magic, that happens in bees code).

But i see, so i think something broken,
at least that it lie that problem happens with beesstats.txt:

bees version v0.5-11-gd5bcdae
2018-01-11 00:01:54 22494.22494 main: set_root_path /mnt/
2018-01-11 00:01:54 22494.22494 main: set_root_fd /mnt
2018-01-11 00:01:54 22494.22494 main: Filesystem UUID is 00000000-0000-0000-0000-000000004321
2018-01-11 00:01:54 22494.22494 main: BeesStringFile /mnt/.beeshome/beescrawl.dat max size 1M
2018-01-11 00:01:54 22494.22494 main: BeesThread exec crawl
2018-01-11 00:01:54 22494.22494 main: returning from set_root_fd in /mnt
2018-01-11 00:01:54 22494.22494 main: BeesThread construct status
2018-01-11 00:01:54 22494.22494 main: BeesThread exec status
2018-01-11 00:01:54 22494.22495 bees: Starting thread crawl
2018-01-11 00:01:54 22494.22495 crawl: loading crawl state
2018-01-11 00:01:54 22494.22496 bees: Starting thread status
2018-01-11 00:01:54 22494.22496 status: Exiting thread status, 0.001 sec
2018-01-11 00:01:54 22494.22495 crawl: Read line: root 5 objectid 18446744073709551605 offset 1 min_transid 685382 max_transid 709570 started 1515618040 start_ts 2018-01-11-00-00-40
2018-01-11 00:01:54 22494.22495 crawl: loaded_state BeesCrawlState 5:18446744073709551605 offset 0x1 transid 685382..709570 started 2018-01-11-00-00-40 (74s ago)
2018-01-11 00:01:54 22494.22495 crawl: Read line: root 1092 objectid 48569 offset 1 min_transid 679441 max_transid 681131 started 1515520058 start_ts 2018-01-09-20-47-38
2018-01-11 00:01:54 22494.22495 crawl: loaded_state BeesCrawlState 1092:48569 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Read line: root 1093 objectid 324440 offset 1192 min_transid 585545 max_transid 674792 started 1515518238 start_ts 2018-01-09-20-17-18
2018-01-11 00:01:54 22494.22495 crawl: loaded_state BeesCrawlState 1093:324440 offset 0x4a8 transid 585545..674792 started 2018-01-09-20-17-18 (99876s ago)
2018-01-11 00:01:54 22494.22495 crawl: Read line: root 1094 objectid 118686 offset 73138177 min_transid 0 max_transid 585545 started 1515392468 start_ts 2018-01-08-09-21-08
2018-01-11 00:01:54 22494.22495 crawl: loaded_state BeesCrawlState 1094:118686 offset 0x45c0001 transid 0..585545 started 2018-01-08-09-21-08 (225646s ago)
2018-01-11 00:01:54 22494.22495 crawl: Read line: root 1140 objectid 293 offset 1 min_transid 679441 max_transid 681131 started 1515520058 start_ts 2018-01-09-20-47-38
2018-01-11 00:01:54 22494.22495 crawl: loaded_state BeesCrawlState 1140:293 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: BeesThread exec crawl_writeback
2018-01-11 00:01:54 22494.22497 bees: Starting thread crawl_writeback
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 5:18446744073709551605 offset 0x1 transid 685382..709570 started 2018-01-11-00-00-40 (74s ago)
2018-01-11 00:01:54 22494.22497 crawl_writeback: open_root_nocache 1092: /mnt/@ccache
2018-01-11 00:01:54 22494.22495 crawl: Crawl empty BeesCrawlState 5:18446744073709551605 offset 0x1 transid 685382..709570 started 2018-01-11-00-00-40 (74s ago)
2018-01-11 00:01:54 22494.22495 crawl: Deferring next transid in BeesCrawlState 5:18446744073709551605 offset 0x1 transid 685382..709570 started 2018-01-11-00-00-40 (74s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1092:48569 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22497 crawl_writeback: Saving crawl state
2018-01-11 00:01:54 22494.22497 crawl_writeback: Saved crawl state in 0.001s
2018-01-11 00:01:54 22494.22495 crawl: Crawl empty BeesCrawlState 1092:48569 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Next transid in BeesCrawlState 1092:48569 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Restarting crawl BeesCrawlState 1092:48569 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1092:0 offset 0x0 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling 3473 results from BeesCrawlState 1092:0 offset 0x0 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawled inline 37 data 0 other 3436 unknown 0 gen_low 37 gen_high 0 BeesCrawlState 1092:440 offset 0x5c transid 681131..709598 started 2018-01-11-00-01-54 (0s ago) in 0.006s
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1092:440 offset 0x5c transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling 3116 results from BeesCrawlState 1092:440 offset 0x5c transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawled inline 30 data 0 other 3086 unknown 0 gen_low 30 gen_high 0 BeesCrawlState 1092:591 offset 0x13348cb8 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago) in 0.005s
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1092:591 offset 0x13348cb8 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling 3285 results from BeesCrawlState 1092:591 offset 0x13348cb8 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawled inline 34 data 0 other 3251 unknown 0 gen_low 34 gen_high 0 BeesCrawlState 1092:795 offset 0xff7462b transid 681131..709598 started 2018-01-11-00-01-54 (0s ago) in 0.005s
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1092:795 offset 0xff7462b transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling 3069 results from BeesCrawlState 1092:795 offset 0xff7462b transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawled inline 37 data 5 other 3027 unknown 0 gen_low 42 gen_high 0 BeesCrawlState 1092:1049 offset 0x57c350f transid 681131..709598 started 2018-01-11-00-01-54 (0s ago) in 0.004s
2018-01-11 00:01:54 22494.22495 crawl: BeesStringFile /mnt/.beeshome/beesstats.txt max size 1M
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_prefetch no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_writeback no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: scan extent Extent { begin = 0x0, end = 0x148e, physical = 0x43a3bba000, flags = FIEMAP_EXTENT_LAST, physical_len = 0x2000, logical_len = 0x2000 }
2018-01-11 00:01:54 22494.22495 crawl: 
2018-01-11 00:01:54 22494.22495 crawl: 
2018-01-11 00:01:54 22494.22495 crawl: *** EXCEPTION ***
2018-01-11 00:01:54 22494.22495 crawl:  exception type std::invalid_argument: new_size = 270532608 failed constraint check ((new_size % BLOCK_SIZE_HASHTAB_EXTENT) == 0)
2018-01-11 00:01:54 22494.22495 crawl: ***
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1093:324440 offset 0x4a8 transid 585545..674792 started 2018-01-09-20-17-18 (99876s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling 2796 results from BeesCrawlState 1093:324440 offset 0x4a8 transid 585545..674792 started 2018-01-09-20-17-18 (99876s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawled inline 220 data 882 other 1694 unknown 0 gen_low 1098 gen_high 0 BeesCrawlState 1093:330874 offset 0x50abd transid 585545..674792 started 2018-01-09-20-17-18 (99876s ago) in 0.011s
2018-01-11 00:01:54 22494.22495 crawl: BeesStringFile /mnt/.beeshome/beesstats.txt max size 1M
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_prefetch no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_writeback no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: scan extent Extent { begin = 0x0, end = 0xd12, physical = 0x5c3a604000, flags = FIEMAP_EXTENT_LAST, physical_len = 0x1000, logical_len = 0x1000 }
2018-01-11 00:01:54 22494.22495 crawl: 
2018-01-11 00:01:54 22494.22495 crawl: 
2018-01-11 00:01:54 22494.22495 crawl: *** EXCEPTION ***
2018-01-11 00:01:54 22494.22495 crawl:  exception type std::invalid_argument: new_size = 270532608 failed constraint check ((new_size % BLOCK_SIZE_HASHTAB_EXTENT) == 0)
2018-01-11 00:01:54 22494.22495 crawl: ***
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1094:118686 offset 0x45c0001 transid 0..585545 started 2018-01-08-09-21-08 (225646s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling 4092 results from BeesCrawlState 1094:118686 offset 0x45c0001 transid 0..585545 started 2018-01-08-09-21-08 (225646s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawled inline 0 data 4084 other 8 unknown 0 gen_low 0 gen_high 0 BeesCrawlState 1094:118692 offset 0x4ce0001 transid 0..585545 started 2018-01-08-09-21-08 (225646s ago) in 0.008s
2018-01-11 00:01:54 22494.22495 crawl: BeesStringFile /mnt/.beeshome/beesstats.txt max size 1M
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_prefetch no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_writeback no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: scan extent Extent { begin = 0xec0000, end = 0xee0000, physical = 0x5439992000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x20000 }
2018-01-11 00:01:54 22494.22495 crawl: 
2018-01-11 00:01:54 22494.22495 crawl: 
2018-01-11 00:01:54 22494.22495 crawl: *** EXCEPTION ***
2018-01-11 00:01:54 22494.22495 crawl:  exception type std::invalid_argument: new_size = 270532608 failed constraint check ((new_size % BLOCK_SIZE_HASHTAB_EXTENT) == 0)
2018-01-11 00:01:54 22494.22495 crawl: ***
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1140:293 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawl empty BeesCrawlState 1140:293 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Next transid in BeesCrawlState 1140:293 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Restarting crawl BeesCrawlState 1140:293 offset 0x1 transid 679441..681131 started 2018-01-09-20-47-38 (98056s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling BeesCrawlState 1140:0 offset 0x0 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawling 1863 results from BeesCrawlState 1140:0 offset 0x0 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago)
2018-01-11 00:01:54 22494.22495 crawl: Crawled inline 0 data 1863 other 0 unknown 0 gen_low 0 gen_high 0 BeesCrawlState 1140:257 offset 0xf480001 transid 681131..709598 started 2018-01-11-00-01-54 (0s ago) in 0.003s
2018-01-11 00:01:54 22494.22495 crawl: BeesStringFile /mnt/.beeshome/beesstats.txt max size 1M
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_prefetch no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: Thread hash_writeback no thread ptr
2018-01-11 00:01:54 22494.22495 crawl: scan extent Extent { begin = 0xbc0000, end = 0xbe0000, physical = 0x45c7061000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x20000 }

*Many many similar lines*

Estimating progress in bees

It would be nice if bees could estimate progress, i.e. how much of the filesystem has been scanned or needs to be scanned before bees can return to an idle state.

For subvol scans (root 5 and all roots 256 and higher), in .beeshome/beescrawl.dat we can see the position of the extent iterators:

root 5 objectid 18446744073709551611 offset 193891 min_transid 1345204 max_transid 1345216 started 1537886291 start_ts 2018-09-25-10-38-11
root 258 objectid 6385071 offset 540699 min_transid 1345204 max_transid 1345216 started 1537886291 start_ts 2018-09-25-10-38-11
root 259 objectid 0 offset 0 min_transid 1345204 max_transid 1345216 started 1537886291 start_ts 2018-09-25-10-38-11
root 289 objectid 92116 offset 257 min_transid 1345204 max_transid 1345216 started 1537886291 start_ts 2018-09-25-10-38-11

The 'objectid' field is the inode number within the subvol. If you know the largest inode number in a subvol (let's call it max_objectid), then the percentage progress is:

progress_percent = 100 * objectid / max_objectid

The scan mode (-m) option scans subvols differently:

  • In mode 0, all subvols are scanned in lock-step, i.e. they all progress at the same rate, and they all restart at the same time.
  • In mode 1, all subvols are scanned in parallel with no synchronization. Each subvol scan restarts immediately. A small subvol will be scanned many times while a large subvol is scanned once.
  • In mode 2, all subvols are scanned in order of start_ts, with root ID to break ties. When a subvol is completed it will not be scanned again until all other subvols have been scanned.

At the end of each subvol scan (100% completion), the max_transid field is copied to the min_transid field and the scan starts over. If all subvols have no new data, scanning stops until 10 transids have passed.

When a new subvol is detected, the lowest value for any subvol's min_transid field is copied to the min_transid field of the new subvol, since any extent older than the lowest min_transid has already been scanned.

If the min_transid field of all subvols is non-zero then at least one scan has been completed for the entire filesystem.

For root 2 (extent) or root 7 (csum) scans the objectid is a data block bytenr. In these cases the entire filesystem is scanned in a single pass; however, data block bytenrs are not contiguous, so some extra work (scans of device tree 4) has to be done to determine which parts of the bytenr space are occupied by data in order to produce an accurate estimate.

one filesystem flag?

Looking why the EXTENT_SAME ioctls are returning EINVAL, I notice that bees was looking at files from a different filesystem mount within btrfs space. Should there be a flag to not go over filesystem boundaries?

Potential sensitive data leak

Bees should not expose potential sensitive data to the logs by default, that is the "data[]" parameter spooled to the logs. While that may be interesting while developing and running on test data, bees should really not do that by default.

I propose to introduce a cmdline parameter which enables exposure of such data, and it should not have a short option, maybe giving it a speaking name like "--expose-sensitive-data".

What do you think?

RFE: Configuration files

I started working on a branch https://github.com/kakra/bees/tree/feature/configuration-files for implementing configuration files. This issue is here for discussion and review requests.

My proposal is to have configuration files in the following format:

[global]
# common options can be put here
no-timestamps
thread-factor=1.5

[/mnt/for/bees]
scan-mode=0

[/mnt/another/bees]
scan-mode=1

What do you think?

Should we add a news file?

Since there seems to be interesting progress with each release, should we add a NEWS file to the project root? Maybe listing contributors and important issues fixed...

Thread count not parsed

beesd -c=1 6aae3d24-a25f-45d5-b3aa-d3ec97b9e5cd
uuidparse: invalid option -- 'c'
Try 'uuidparse --help' for more information.
Usage: beesd [options] <btrfs_uuid>


bees version v0.6-6-g14b35e3

"--thread-count=1" has been tried too

refs=0, does it make sense?

Why am I seeing

Jan 13 03:40:34 jupiter beesd[749]: tid 813 crawl: PERFORMANCE: 2.974 sec: Resolving addr 0x3204ada000 in /run/bees/mnt/26a832d7-73a5-4de5-b272-69f73e1daf5e refs 0
Jan 13 03:40:39 jupiter beesd[749]: tid 813 crawl: PERFORMANCE: 2.515 sec: Resolving addr 0x3204ae3000 in /run/bees/mnt/26a832d7-73a5-4de5-b272-69f73e1daf5e refs 0
Jan 13 03:40:41 jupiter beesd[749]: tid 813 crawl: PERFORMANCE: 2.552 sec: Resolving addr 0x3204ae4000 in /run/bees/mnt/26a832d7-73a5-4de5-b272-69f73e1daf5e refs 0

Does it make sense to see something resolving with refs=0, and why does bees care?

JFYI: Some tests

Kernel 4.9.0-12 Ubuntu

  • btrfs nodatacow mount option or inode attribute (could work, but might not)
    Bees show exeption, when trying dedup COW & NOCOW blocks. Without crash issues.

  • open(O_DIRECT)
    Work as rocksolid (fio as a load)

  • Busy NFS+Bees
    Without compression, work as rocksolid, with compression, btrfs some times get a hangs

Thanks.

Looks like problem with access to env vars

So, i try set vars and get bees works:

env | grep BEES; sudo bees /mnt/
BEESHOME=/var/lib/bees/
BEESSTATUS=/run/bees.status
2016-11-25 19:10:16 7465.7465 main: 
2016-11-25 19:10:16 7465.7465 main: 
2016-11-25 19:10:16 7465.7465 main: *** EXCEPTION ***
2016-11-25 19:10:16 7465.7465 main:     exception type std::runtime_error: Environment variable BEESHOME not defined
2016-11-25 19:10:16 7465.7465 main: ***
2016-11-25 19:10:16 7465.7465 main: WARNING: no filesystems added
2016-11-25 19:10:16 7465.7465 main: BeesThread construct status
2016-11-25 19:10:16 7465.7465 main: BeesThread exec status
2016-11-25 19:10:16 7465.7466 bees: Starting thread status
2016-11-25 19:10:16 7465.7466 status: Exiting thread status, 0.001 sec

I use /etc/profile.d/ to setup env
and stuff in the /var/lib/bees:

➜  ~ ls -al /var/lib/bees 
total 16
drwxr-xr-x 1 root root         32 Nov 25 19:09 .
drwxr-xr-x 1 root root        408 Nov 25 17:22 ..
-rwx------ 1 root root 1073741824 Nov 25 17:42 beeshash.dat

Thanks, for any comments.

bees is polling but not returning

Hi,

on one of my USB btrfs drives, I have bees running for many days successfully, but now it is always running into a polling state and can't be terminated or killed anymore, still using 25% cpu which is one of 4 cores I guess.
I'm using space_cache=v2 on that btrfs and it turned out that there was some kernel trace in the syslog when mounting, and freezing the mount somehow. I have run a btrfs check and deleted the space cache. Now the check is fine and btrfs scrub has finished without errors. The btrfs seems to be sane.

2018-10-02 13:46:59 32289.22505<6> crawl_1899:        dst 40K [0x724ee000..0x724f8000] {0x84d2cc000z4000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22505<6> crawl_1899: scan: 56K 0x566da000 [+++d++++++++++] 0x566e8000 snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22506<6> crawl_1899: copy: 4K [0x56820000..0x56821000] fd = 3554 'snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi'
2018-10-02 13:46:59 32289.22492<6> crawl_1899: dedup: src 4K [0x73447000..0x73448000] {0xb2e7b5000zf000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22492<6> crawl_1899:        dst 4K [0x5683b000..0x5683c000] {0x84b8c2000z7000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22492<6> crawl_1899: copy: 28K [0x56834000..0x5683b000] fd = 3554 'snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi'
2018-10-02 13:46:59 32289.22505<6> crawl_1899: dedup: src 4K [0x17ce5d000..0x17ce5e000] {0x13d73566000z5000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22505<6> crawl_1899:        dst 4K [0x56841000..0x56842000] {0x84d2f5000z3000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22505<6> crawl_1899: dedup: src 4K [0x71c79000..0x71c7a000] {0x74a92a000z1000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22505<6> crawl_1899:        dst 4K [0x56845000..0x56846000] {0x84d2f5000z7000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:46:59 32289.22505<6> crawl_1899: copy: 12K [0x5683e000..0x56841000] fd = 3554 'snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi'
2018-10-02 13:47:00 32289.22506<6> crawl_1899: scan: 68K 0x56810000 [+++++ddd++++++dd+] 0x56821000 snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:47:00 32289.22507<6> crawl_1899: copy: 12K [0x566ae000..0x566b1000] fd = 3554 'snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi'
2018-10-02 13:47:00 32289.22506<6> crawl_1899: dedup: src 4K [0x178971000..0x178972000] {0x13d7428a000z9000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:47:00 32289.22506<6> crawl_1899:        dst 4K [0x568c1000..0x568c2000] {0x84d311000z5000} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:47:00 32289.22506<6> crawl_1899: copy: 20K [0x568bc000..0x568c1000] fd = 3554 'snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi'
2018-10-02 13:47:01 32289.22492<6> crawl_1899: dedup: src 28K [0x68000..0x6f000] {0x3714ef000z0} #281 (deleted)
2018-10-02 13:47:01 32289.22492<6> crawl_1899:        dst 28K [0x56834000..0x5683b000] {0x84b8c2000z0} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:47:01 32289.22492<6> crawl_1899: copy: 4K [0x5683c000..0x5683d000] fd = 3554 'snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi'
2018-10-02 13:47:01 32289.22507<6> crawl_1899: scan: 36K 0x566a8000 [++dd+d+++] 0x566b1000 snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:47:01 32289.22506<6> crawl_1899: dedup: src 20K [0x67000..0x6c000] {0x371943000z0} #280 (deleted)
2018-10-02 13:47:01 32289.22506<6> crawl_1899:        dst 20K [0x568bc000..0x568c1000] {0x84d311000z0} snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:47:01 32289.22506<6> crawl_1899: copy: 24K [0x568c2000..0x568c8000] fd = 3554 'snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi'
2018-10-02 13:47:01 32289.22492<6> crawl_1899: scan: 36K 0x56834000 [+++++++d+] 0x5683d000 snapshots/VirtualMachines/VirtualMachines.20171130T104151+0100/OpenSuse LEAP/OpenSuse LEAP.vdi
2018-10-02 13:49:22 32289.32295<7> crawl_transid: Polling 196.448s for next 10 transid RateEstimator { count = 1059175, raw = 33.98 / 667.595, ratio = 33.98 / 667.621, rate = 0.0508971, duration(1) = 19.6475, seconds_for(1) = 19.6211 }
2018-10-02 13:52:38 32289.32295<7> crawl_transid: Polling 254.871s for next 10 transid RateEstimator { count = 1059175, raw = 33.6402 / 857.395, ratio = 33.6402 / 857.396, rate = 0.0392353, duration(1) = 25.4872, seconds_for(1) = 25.486 }
2018-10-02 13:53:21 32289.32308<6> crawl_writeback: Saving crawl state




2018-10-02 13:56:53 32289.32295<7> crawl_transid: Polling 331.401s for next 10 transid RateEstimator { count = 1059175, raw = 33.3038 / 1103.69, ratio = 33.3038 / 1103.69, rate = 0.0301748, duration(1) = 33.1402, seconds_for(1) = 33.1394 }


2018-10-02 14:02:24 32289.32295<7> crawl_transid: Polling 431.915s for next 10 transid RateEstimator { count = 1059175, raw = 32.9708 / 1424.06, ratio = 32.9708 / 1424.06, rate = 0.0231526, duration(1) = 43.1916, seconds_for(1) = 43.1908 }

2018-10-02 14:09:36 32289.32295<7> crawl_transid: Polling 564.239s for next 10 transid RateEstimator { count = 1059175, raw = 32.6411 / 1841.74, ratio = 32.6411 / 1841.74, rate = 0.017723, duration(1) = 56.4239, seconds_for(1) = 56.4231 }
^C^C^C^C^C^C^C^C




^C^C^C

And today is 2018-10-04, so no output since 2 days.

Possible optimisation idea

When I first tried bees I noticed that 1 cpu was running at 100% but diskio was barely reaching 20%. Being curious if I could optimise something I ran perf to see what was happening:

 PerfTop:    1595 irqs/sec  kernel: 8.0%  exact:  0.0% [4000Hz cycles],  (target_pid: 27591)

    77.24%  libc-2.22.so         [.] __memset_sse2
     2.19%  libc-2.22.so         [.] _int_malloc
     1.64%  [kernel]             [k] copy_user_generic_string
     1.55%  libc-2.22.so         [.] malloc
     1.51%  libc-2.22.so         [.] _int_free
     1.15%  libc-2.22.so         [.] __memmove_sse2
     0.94%  libcrucible.so       [.] crucible::BtrfsExtentWalker::get_extent_map
     0.72%  libc-2.22.so         [.] __strcmp_sse2
     0.70%  libcrucible.so       [.] crucible::ranged_cast<long, unsigned long long>
     0.61%  libc-2.22.so         [.] malloc_consolidate
     0.58%  libcrucible.so       [.] crucible::get_struct_ptr<btrfs_file_extent_item>
     0.57%  [kernel]             [k] read_extent_buffer
     0.54%  libcrucible.so       [.] crucible::BtrfsIoctlSearchHeader::set_data
     0.48%  [kernel]             [k] copy_to_sk.isra.13
     0.47%  libcrucible.so       [.] crucible::Digest::CRC::crc64
     0.46%  [kernel]             [k] map_private_extent_buffer
     0.45%  [kernel]             [k] __radix_tree_lookup
#
# Children      Self  Command         Shared Object        Symbol
# ........  ........  ..............  ...................  ..................
#
    88.06%     0.14%  bees            libcrucible.so       [.] crucible::ExtentWalker::run_fiemap
                      |
                      ---crucible::ExtentWalker::run_fiemap
                         |
                          --0.87%-- crucible::ExtentWalker::seek
                                    |
                                    |--0.18%-- crucible::BtrfsExtentWalker::BtrfsExtentWalker
                                    |
                                     --0.04%-- crucible::BtrfsExtentWalker::BtrfsExtentWalker

    87.19%     0.89%  bees            libcrucible.so       [.] crucible::BtrfsExtentWalker::get_extent_map
                      |
                      ---crucible::BtrfsExtentWalker::get_extent_map
                         crucible::ExtentWalker::run_fiemap

    80.68%     0.04%  bees            libcrucible.so       [.] crucible::BtrfsIoctlSearchKey::do_ioctl
                      |
                      ---crucible::BtrfsIoctlSearchKey::do_ioctl
                         crucible::BtrfsExtentWalker::get_extent_map
                         crucible::ExtentWalker::run_fiemap

    80.65%     0.27%  bees            libcrucible.so       [.] crucible::BtrfsIoctlSearchKey::do_ioctl_nothrow
                      |
                      ---crucible::BtrfsIoctlSearchKey::do_ioctl_nothrow
                         |
                         |--80.65%-- crucible::BtrfsIoctlSearchKey::do_ioctl
                         |          crucible::BtrfsExtentWalker::get_extent_map
                         |          crucible::ExtentWalker::run_fiemap
                         |
                          --0.01%-- crucible::ranged_cast<long, unsigned long long>
                                    crucible::BtrfsExtentWalker::get_extent_map
                                    crucible::ExtentWalker::run_fiemap

    69.44%     0.02%  bees            bees                 [.] std::vector<char, std::allocator<char> >::_M_fill_insert
                      |
                      ---std::vector<char, std::allocator<char> >::_M_fill_insert
                         crucible::BtrfsIoctlSearchKey::do_ioctl_nothrow
                         crucible::BtrfsIoctlSearchKey::do_ioctl
                         crucible::BtrfsExtentWalker::get_extent_map
                         crucible::ExtentWalker::run_fiemap

    69.10%    68.77%  bees            libc-2.22.so         [.] __memset_sse2
                      |
                      ---__memset_sse2
                         |
                         |--69.00%-- std::vector<char, std::allocator<char> >::_M_fill_insert
                         |          crucible::BtrfsIoctlSearchKey::do_ioctl_nothrow
                         |          crucible::BtrfsIoctlSearchKey::do_ioctl
                         |          crucible::BtrfsExtentWalker::get_extent_map
                         |          crucible::ExtentWalker::run_fiemap

So it seems at first glance that there is some vector magic happening, possibly in lib/fs.cc:714 inside the vector resize. I don't understand the code enough to fix it, but I'm guessing there must be a way to modify it to use uninitialised memory or something?

deduplicating same file

Am I reading this right, that bees has picked out the same file to deduplicate against itself?

2018-02-13 13:21:45 20975.20983<3> crawl_5: ***
2018-02-13 13:21:45 20975.20981<6> crawl_5: dedup: src 128K [0x1c893000..0x1c8b3000] {0x173c5b000z0} /tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img
2018-02-13 13:21:45 20975.20981<6> crawl_5:        dst 128K [0x10891000..0x108b1000] {0x16adbc000z0} /tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img
2018-02-13 13:21:45 20975.20981<3> crawl_5: Found matching range: BeesRangePair: 128K src[0x1c893000..0x1c8b3000] dst[0x10891000..0x108b1000]
2018-02-13 13:21:45 20975.20981<3> crawl_5: src = 4 /tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img
2018-02-13 13:21:45 20975.20981<3> crawl_5: dst = 4 /tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img
2018-02-13 13:21:45 20975.20981<3> crawl_5: creating brp (4K [0x1c893000..0x1c894000] fid = 5:443796 fd = 4 '/tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img', 4K [0x10891000..0x10892000] fd = 4 '/tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img')
2018-02-13 13:21:45 20975.20981<3> crawl_5: Opening src bfr 4K [0x1c893000..0x1c894000] fid = 5:443796 fd = 4 '/tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img'
2018-02-13 13:21:45 20975.20981<3> crawl_5: chase_extent_ref ino BtrfsInodeOffsetRoot { .m_inum = 443796, .m_offset = 0x1c893000, .m_root = 5 } bbd BeesBlockData { 4K 0x10891000 fd = 4 '/tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img', data[4096] }
2018-02-13 13:21:45 20975.20981<3> crawl_5:
2018-02-13 13:21:45 20975.20981<3> crawl_5:
2018-02-13 13:21:45 20975.20981<3> crawl_5: *** EXCEPTION ***
2018-02-13 13:21:45 20975.20981<3> crawl_5: 	exception type std::system_error: btrfs-extent-same: BtrfsExtentSame { .m_fd = 4 '/tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img', .logical_offset = 0x1c893000, .length = 0x20000, .dest_count = 1, .reserved1 = 0, .reserved2 = 0, .info[] = { [0] = btrfs_ioctl_same_extent_info { .fd = 4 '/tmp/foo/nanopi-neo-air_eflasher_4.11.2_20170819.img', .logical_offset = 0x10891000, .bytes_deduped = 0x0, .status = -22 (Invalid argument), .reserved = 0 }, }: Invalid argument

Sending/receiving incremental snapshots failing after bees

Hi, I can't provide a precise error description. I like to discuss the impact of bees to sending/receiving incremental snapshots.

I have 3 btrfs. One main filesystem on bcache and 2 USB btrfs as "backups" receiving incremental snapshots via btrbk. (Please don't insist on the suitability of a btrfs as a backup for another btrfs... you need to trust btrfs a lot for doing that)

As in best case all snapshots received are already incremental, a lot is already de-duplicated. But one of the 2 backup-btrfs is a mobile device that I use for backups of different machines and subvolumes. So each subvolume line is incremental but de-duplication is still beneficial between the machines, as most of the machines have almost identical installations.

After bees was finished on all the 3 btrfs and starting another incremental backup, I expected that the difference could be big based on the many changed extents on the source. But there are many errors on receiving:

ERROR: send ioctl failed with -5: Input/output error
ERROR: unexpected EOF in stream

And in the syslog I see many lines like

BTRFS error (device dm-0): Send: inconsistent snapshot, found updated extent for inode 38464 without updated inode item, send root is 1977, parent root is 1970

Here is the complete btrbk stdout:

# btrbk --progress run default
Creating backup: /mnt/usb/data/snapshots/root/root.20181009T072639+0200
 611KiB 0:00:02 [ 289KiB/s] [ 289KiB/s]
WARNING: [send/receive] (send=/mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200, receive=/mnt/usb/data/snapshots/root) At subvol /mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200
WARNING: [send/receive] (send=/mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200, receive=/mnt/usb/data/snapshots/root) ERROR: send ioctl failed with -5: Input/output error
WARNING: [send/receive] (send=/mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200, receive=/mnt/usb/data/snapshots/root) ERROR: unexpected EOF in stream
WARNING: [send/receive] (send=/mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200, receive=/mnt/usb/data/snapshots/root) At snapshot root.20181009T072639+0200
ERROR: Failed to send/receive btrfs subvolume: /mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200 [/mnt/btrfs-top-lvl/snapshots/root/root.20181004T112940+0200] -> /mnt/usb/data/snapshots/root
WARNING: Deleted partially received (garbled) subvolume: /mnt/usb/data/snapshots/root/root.20181009T072639+0200
ERROR: Error while resuming backups, aborting
Creating backup: /mnt/usb/mobiledata/snapshots/bm73/root/root.20181009T072639+0200
^C
ERROR: Cought SIGINT, dumping transaction log:
localtime type status target_url source_url parent_url message
2018-10-09T13:09:46+0200 startup v0.27.0-dev - - - # btrbk command line client, version 0.27.0-dev
2018-10-09T13:09:46+0200 snapshot starting /mnt/btrfs-top-lvl/snapshots/root/root.20181009T130946+0200 /mnt/btrfs-top-lvl/root - -
2018-10-09T13:09:47+0200 snapshot success /mnt/btrfs-top-lvl/snapshots/root/root.20181009T130946+0200 /mnt/btrfs-top-lvl/root - -
2018-10-09T13:09:47+0200 snapshot starting /mnt/btrfs-top-lvl/snapshots/home/home.20181009T130946+0200 /mnt/btrfs-top-lvl/home - -
2018-10-09T13:09:48+0200 snapshot success /mnt/btrfs-top-lvl/snapshots/home/home.20181009T130946+0200 /mnt/btrfs-top-lvl/home - -
2018-10-09T13:09:48+0200 send-receive starting /mnt/usb/data/snapshots/root/root.20181009T072639+0200 /mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200 /mnt/btrfs-top-lvl/snapshots/root/root.20181004T112940+0200 -
2018-10-09T13:11:23+0200 send-receive ERROR /mnt/usb/data/snapshots/root/root.20181009T072639+0200 /mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200 /mnt/btrfs-top-lvl/snapshots/root/root.20181004T112940+0200 -
2018-10-09T13:11:23+0200 delete_garbled starting /mnt/usb/data/snapshots/root/root.20181009T072639+0200 - - -
2018-10-09T13:11:39+0200 delete_garbled success /mnt/usb/data/snapshots/root/root.20181009T072639+0200 - - -
2018-10-09T13:11:39+0200 abort_target ABORT /mnt/usb/data/snapshots/root - - # Failed to send/receive subvolume
2018-10-09T13:11:39+0200 send-receive starting /mnt/usb/mobiledata/snapshots/bm73/root/root.20181009T072639+0200 /mnt/btrfs-top-lvl/snapshots/root/root.20181009T072639+0200 /mnt/btrfs-top-lvl/snapshots/root/root.20181005T130053+0200 -
2018-10-09T13:11:40+0200 signal SIGINT - - - -
mbuffer: warning: error during output to <stdout>: canceled

I started now another run with "incremental no", which is working but transferring all snapshots as deep copies, after that bees will have a big task to de-duplicate again. I did not have the courage to run bees in background of send/receive. I will check if the subsequent runs of btrbk, bees, btrbk, bees will lead to some stable incremental snapshotting.

exception type std::system_error: ioctl(fd, FS_IOC_SETFLAGS, &attr): Invalid argument

I installed bees via the bees-git package in AUR, copied /etc/bees/based.conf.sample' to /etc/bees/based.conf' and added my BTRFS filesystem's UUID to the config file.

Then I executed beesd as root with the UUID as only argument but stopped it after a couple seconds because it was throwing exceptions all over the place.

Here are parts of the output:

INFO: Find 8d2b3f38-f8ac-4ab3-948b-767c1b10741f in //etc/bees//beesd.conf, use as conf
INFO: Check: Disk exists
INFO: Check: Disk with btrfs
INFO: WORK DIR: /run/bees/
INFO: MOUNT DIR: /run/bees//mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f
bees version v0.5-125-gc21518d
2018-04-22 21:50:27 19704.19704<6> bees: setting rlimit NOFILE to 10340
2018-04-22 21:50:27 19704.19704<6> bees: set_root_path /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f
2018-04-22 21:50:27 19704.19704<6> bees: set_root_fd /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f
2018-04-22 21:50:27 19704.19704<6> bees: Filesystem UUID is 8d2b3f38-f8ac-4ab3-948b-767c1b10741f
2018-04-22 21:50:27 19704.19704<6> bees: BeesStringFile /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/.beeshome/beescrawl.dat max size 1M
2018-04-22 21:50:27 19704.19704<7> bees: BeesThread exec crawl_transid
2018-04-22 21:50:27 19704.19704<6> bees: returning from set_root_fd in /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f
2018-04-22 21:50:27 19704.19704<7> bees: BeesThread construct status
2018-04-22 21:50:27 19704.19704<7> bees: BeesThread exec status
2018-04-22 21:50:27 19704.19717<7> crawl_transid: Starting thread crawl_transid
2018-04-22 21:50:27 19704.19718<7> status: Starting thread status
2018-04-22 21:50:27 19704.19718<6> status: Writing status to file '/run/bees//8d2b3f38-f8ac-4ab3-948b-767c1b10741f.status' every 1 sec
2018-04-22 21:50:27 19704.19717<6> crawl_transid: loading crawl state
2018-04-22 21:50:27 19704.19717<7> crawl_transid: BeesThread exec crawl_writeback
2018-04-22 21:50:27 19704.19719<7> crawl_writeback: Starting thread crawl_writeback
2018-04-22 21:50:27 19704.19719<6> crawl_writeback: Saving crawl state
2018-04-22 21:50:27 19704.19719<6> crawl_writeback: Nothing to save
2018-04-22 21:50:27 19704.19717<6> crawl_transid: Crawl master resumed after 0.00607176s at transid 81720
2018-04-22 21:50:27 19704.19717<7> crawl_transid: Polling 9.99803s for next 10 transid RateEstimator { count = 81720, raw = 0 / 0.00414007, ratio = 1 / 1, rate = 1, duration(1) = 1, seconds_for(1) = 1 }
2018-04-22 21:50:27 19704.19714<6> crawl_master: Crawl finished BeesCrawlState 258:256 offset 0x45922147 transid 0..81720 started 2018-04-22-21-50-27 (0s ago)
2018-04-22 21:50:27 19704.19710<6> crawl_9926: BeesStringFile /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/.beeshome/beesstats.txt max size 1M
2018-04-22 21:50:27 19704.19710<6> crawl_9926: opened hash table filename 'beeshash.dat' length 1073741824
2018-04-22 21:50:27 19704.19710<6> crawl_9926: 	cells 67108864, buckets 262144, extents 64
2018-04-22 21:50:27 19704.19710<6> crawl_9926: 	flush rate limit 1.19305e+06
2018-04-22 21:50:27 19704.19710<6> crawl_9926: mapping hash table size 1073741824 with flags MAP_PRIVATE|MAP_ANONYMOUS
2018-04-22 21:50:27 19704.19710<6> crawl_9926: mmap done in 0.001 sec
2018-04-22 21:50:27 19704.19710<7> crawl_9926: BeesThread exec hash_writeback
2018-04-22 21:50:27 19704.19710<7> crawl_9926: BeesThread exec hash_prefetch
2018-04-22 21:50:27 19704.19720<7> hash_writeback: Starting thread hash_writeback
2018-04-22 21:50:27 19704.19710<7> crawl_9926: Adding 9926:257 to blacklist
2018-04-22 21:50:27 19704.19721<7> hash_prefetch: Starting thread hash_prefetch
2018-04-22 21:50:27 19704.19710<3> crawl_9926: Setting FS_COMPR_FL on m_fd /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/#2839788 (deleted) flags 0x404
2018-04-22 21:50:27 19704.19710<3> crawl_9926: Getting FS_COMPR_FL on m_fd /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/#2839788 (deleted)
2018-04-22 21:50:27 19704.19710<3> crawl_9926: dup_extent 128K [0x3060000..0x3080000] fd = 6 '/run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/.beeshome/beeshash.dat'
2018-04-22 21:50:27 19704.19710<3> crawl_9926: last
2018-04-22 21:50:27 19704.19710<3> crawl_9926: next_p 0x3080000 p 0x307f000 last_p 0x3060000
2018-04-22 21:50:27 19704.19705<3> crawl_9926: Setting FS_COMPR_FL on m_fd /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/#2839789 (deleted) flags 0x404
2018-04-22 21:50:27 19704.19710<3> crawl_9926: Rewriting extent Extent { begin = 0x3060000, end = 0x3080000, physical = 0x7ce3ffa5000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x20000 }
2018-04-22 21:50:27 19704.19705<3> crawl_9926: Getting FS_COMPR_FL on m_fd /run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/#2839789 (deleted)
2018-04-22 21:50:27 19704.19710<3> crawl_9926: Extent { begin = 0x3060000, end = 0x3080000, physical = 0x7ce3ffa5000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x20000 } block_count 32
2018-04-22 21:50:27 19704.19710<3> crawl_9926: scan extent Extent { begin = 0x3060000, end = 0x3080000, physical = 0x7ce3ffa5000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x20000, logical_len = 0x20000 }
2018-04-22 21:50:27 19704.19705<3> crawl_9926: dup_extent 128K [0x3140000..0x3160000] fd = 6 '/run/bees/mnt/8d2b3f38-f8ac-4ab3-948b-767c1b10741f/.beeshome/beeshash.dat'
2018-04-22 21:50:27 19704.19710<3> crawl_9926: 
2018-04-22 21:50:27 19704.19710<3> crawl_9926: 
2018-04-22 21:50:27 19704.19710<3> crawl_9926: *** EXCEPTION ***
2018-04-22 21:50:27 19704.19710<3> crawl_9926: 	exception type std::system_error: ioctl(fd, FS_IOC_SETFLAGS, &attr): Invalid argument
2018-04-22 21:50:27 19704.19705<3> crawl_9926: last
2018-04-22 21:50:27 19704.19710<3> crawl_9926: ***

(more messages like this)

2018-04-22 21:50:27 19704.19714<6> crawl_master: Crawl finished BeesCrawlState 9926:258 offset 0x101 transid 0..81720 started 2018-04-22-21-50-27 (0s ago)
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: Now:     2018-04-22-21-50-28
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: Uptime:  1.18181 seconds
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: Version: v0.5-125-gc21518d
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: Hash table page occupancy histogram (311777/67108864 cells occupied, 0%)
2018-04-22 21:50:28 19704.19721<6> hash_prefetch:                                                                  262144 pages
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #                                                                131072
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #                                                                65536
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #                                                                32768
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #                                                                16384
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: ###                                                              8192
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: ####                                                             4096
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: ####                                                             2048
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #####                                                            1024
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #####                                                            512
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #####                                                            256
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: ######                                                           128
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: ######                                                           64
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: ######                                                           32
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: ######                                                           16
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #######                                                          8
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #######                                                          4
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #######                                                          2
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: #######                                                          1
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 0%      |      25%      |      50%      |      75%      |   100% page fill
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: compressed 81501 (26%)
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: uncompressed 230276 (73%) unaligned_eof 4126 (1%) toxic 2 (0%)
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: TOTAL:
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	addr_block=6687 addr_compressed_offset=545 addr_eof_e=22 addr_uncompressed=6142
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	block_bytes=27291046 block_hash=6676 block_ms=4543 block_read=6676 block_zero=384
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	crawl_blacklisted=651 crawl_create=3 crawl_empty=2 crawl_hole=6 crawl_inline=16 crawl_items=61653 crawl_ms=6 crawl_nondata=59642 crawl_push=1338 crawl_scan=1269 crawl_search=64
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	dedup_copy=1572864
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	exception_caught=12
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	hash_already=624 hash_bump=596 hash_extent_in=64 hash_extent_out=1 hash_insert=5668 hash_lookup=6292
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	inserted_block=6292
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	matched_0=6292
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	open_file=33 open_hit=33 open_ino_ms=51 open_lookup_ok=33
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	root_found=1 root_ok=1 root_parent_open_ok=1 root_parent_open_try=1
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	scan_blacklisted=1001 scan_block=6687 scan_extent=154 scan_forward=1156 scan_found=1220 scan_hash_preinsert=6676 scan_lookup=6292 scan_twice=1220 scan_zero_compressed=12
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	scanf_extent=131 scanf_extent_ms=13096 scanf_total=143 scanf_total_ms=13318
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	tmp_create=12
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: RATES:
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	addr_block=5658.01 addr_compressed_offset=461.136 addr_eof_e=18.615 addr_uncompressed=5196.87
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	block_bytes=2.30915e+07 block_hash=5648.7 block_ms=3843.93 block_read=5648.7 block_zero=324.911
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	crawl_blacklisted=550.825 crawl_create=2.539 crawl_empty=1.693 crawl_hole=5.077 crawl_inline=13.538 crawl_items=52165.9 crawl_ms=5.077 crawl_nondata=50464.3 crawl_push=1132.11 crawl_scan=1073.73 crawl_search=54.152
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	dedup_copy=1.33083e+06
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	exception_caught=10.154
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	hash_already=527.98 hash_bump=504.288 hash_extent_in=54.152 hash_extent_out=0.847 hash_insert=4795.81 hash_lookup=5323.79
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	inserted_block=5323.79
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	matched_0=5323.79
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	open_file=27.922 open_hit=27.922 open_ino_ms=43.153 open_lookup_ok=27.922
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	root_found=0.847 root_ok=0.847 root_parent_open_ok=0.847 root_parent_open_try=0.847
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	scan_blacklisted=846.967 scan_block=5658.01 scan_extent=130.303 scan_forward=978.116 scan_found=1032.27 scan_hash_preinsert=5648.7 scan_lookup=5323.79 scan_twice=1032.27 scan_zero_compressed=10.154
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	scanf_extent=110.842 scanf_extent_ms=11080.8 scanf_total=120.996 scanf_total_ms=11268.6
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: 	tmp_create=10.154
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: mlock(1G)...
2018-04-22 21:50:28 19704.19721<6> hash_prefetch: mlock(1G) done in 0.072 sec

and then even more exceptions, you get the idea.

I have no idea whether I set it up right, the readme was not very clear on whether or not anything else needed to be done. It didn't even tell me to edit the config file but I assumed that was needed because the script complained about it otherwise.

Relative reliability on read-only snapshots w.r.t. duperemove

I use the excellent btrbk to take snapshots (which are read-only), and send them to an external disk.

I see in the Bad Btrfs Feature Interactions:

  • btrfs read-only snapshots (never tested, probably wouldn't work well)

I'm currently using duperemove whose man page says:

   -A     Opens files readonly when deduping; currently requires root
          privileges (and is enabled by default for root). Allows use on
          readonly snapshots or when the file might be open for exec.

I've never had a problem using duperemove -A with read-only snapshots.

Should using bees be just as reliable as duperemove -A?

Does it use any different system calls to dedupe other than duperemove which uses the Linux kernel extent-same ioctl?

Linux 4.4. NFS+Btrfs+Bees Hang

I've try bees on NFS server and it's kill it %)

Do you know this bug? May be it's already fixed?

[21000.179365] INFO: task nfsd:8796 blocked for more than 120 seconds.
[21000.179463]       Not tainted 4.4.0-51-generic #72-Ubuntu
[21000.179545] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[21000.179651] nfsd            D ffff8804a65e7aa0     0  8796      2 0x00000000
[21000.179654]  ffff8804a65e7aa0 ffffea0006024fc0 ffff8804a981a580 ffff8804a55a0000
[21000.179656]  ffff8804a65e8000 ffff8804a65701f0 ffff8804a6570000 ffff8804a65701f0
[21000.179658]  0000000000000001 ffff8804a65e7ab8 ffffffff81831f45 ffff8804a961cbd0
[21000.179661] Call Trace:
[21000.179662]  [<ffffffff81831f45>] schedule+0x35/0x80
[21000.179676]  [<ffffffffc03d6fd3>] wait_current_trans.isra.21+0xd3/0x120 [btrfs]
[21000.179679]  [<ffffffff810c3ec0>] ? wake_atomic_t_function+0x60/0x60
[21000.179692]  [<ffffffffc03d88a5>] start_transaction+0x275/0x4b0 [btrfs]
[21000.179706]  [<ffffffffc03d8b37>] btrfs_join_transaction+0x17/0x20 [btrfs]
[21000.179720]  [<ffffffffc03de1c5>] btrfs_dirty_inode+0x35/0xd0 [btrfs]
[21000.179734]  [<ffffffffc03de2df>] btrfs_update_time+0x7f/0xc0 [btrfs]
[21000.179736]  [<ffffffff8122a778>] touch_atime+0xa8/0xd0
[21000.179739]  [<ffffffff81240902>] generic_file_splice_read+0x72/0x80
[21000.179740]  [<ffffffff8123f1d9>] do_splice_to+0x69/0x80
[21000.179742]  [<ffffffff8123f2aa>] splice_direct_to_actor+0xba/0x210
[21000.179749]  [<ffffffffc0546ec0>] ? fsid_source+0x60/0x60 [nfsd]
[21000.179755]  [<ffffffffc0547e59>] nfsd_splice_read+0x69/0xa0 [nfsd]
[21000.179762]  [<ffffffffc054836f>] nfsd_read+0xef/0x100 [nfsd]
[21000.179769]  [<ffffffffc055115c>] nfsd3_proc_read+0xbc/0x150 [nfsd]
[21000.179775]  [<ffffffffc0542e78>] nfsd_dispatch+0xb8/0x200 [nfsd]
[21000.179786]  [<ffffffffc04d8eda>] svc_process_common+0x42a/0x690 [sunrpc]
[21000.179797]  [<ffffffffc04da2c3>] svc_process+0x103/0x1c0 [sunrpc]
[21000.179803]  [<ffffffffc05428cf>] nfsd+0xef/0x160 [nfsd]
[21000.179809]  [<ffffffffc05427e0>] ? nfsd_destroy+0x60/0x60 [nfsd]
[21000.179810]  [<ffffffff810a09d8>] kthread+0xd8/0xf0
[21000.179812]  [<ffffffff810a0900>] ? kthread_create_on_node+0x1e0/0x1e0
[21000.179814]  [<ffffffff818363cf>] ret_from_fork+0x3f/0x70
[21000.179816]  [<ffffffff810a0900>] ? kthread_create_on_node+0x1e0/0x1e0
[21000.179818] INFO: task nfsd:8797 blocked for more than 120 seconds.
[21000.179916]       Not tainted 4.4.0-51-generic #72-Ubuntu
[21000.179999] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[21000.180152] nfsd            D ffff8804a82e3c38     0  8797      2 0x00000000
[21000.180157]  ffff8804a82e3c38 ffff88035aa4a240 ffff8804a55a0000 ffff8804a981b200
[21000.180160]  ffff8804a82e4000 ffff8804991a67ec ffff8804a981b200 00000000ffffffff
[21000.180162]  ffff8804991a67f0 ffff8804a82e3c50 ffffffff81831f45 ffff8804991a67e8
[21000.180166] Call Trace:
[21000.180172]  [<ffffffff81831f45>] schedule+0x35/0x80
[21000.180173]  [<ffffffff818321ee>] schedule_preempt_disabled+0xe/0x10
[21000.180175]  [<ffffffff81833e29>] __mutex_lock_slowpath+0xb9/0x130
[21000.180177]  [<ffffffff81833ebf>] mutex_lock+0x1f/0x30
[21000.180184]  [<ffffffffc0547412>] nfsd_lookup_dentry+0xb2/0x470 [nfsd]
[21000.180190]  [<ffffffffc054699a>] ? fh_verify+0x18a/0x650 [nfsd]
[21000.180194]  [<ffffffff810f5360>] ? getboottime64+0x20/0x30
[21000.180200]  [<ffffffffc0547852>] nfsd_lookup+0x82/0x140 [nfsd]
[21000.180207]  [<ffffffffc0550493>] nfsd3_proc_lookup+0xc3/0x120 [nfsd]
[21000.180213]  [<ffffffffc0542e78>] nfsd_dispatch+0xb8/0x200 [nfsd]
[21000.180224]  [<ffffffffc04d8eda>] svc_process_common+0x42a/0x690 [sunrpc]
[21000.180235]  [<ffffffffc04da2c3>] svc_process+0x103/0x1c0 [sunrpc]
[21000.180241]  [<ffffffffc05428cf>] nfsd+0xef/0x160 [nfsd]
[21000.180247]  [<ffffffffc05427e0>] ? nfsd_destroy+0x60/0x60 [nfsd]
[21000.180249]  [<ffffffff810a09d8>] kthread+0xd8/0xf0
[21000.180251]  [<ffffffff810a0900>] ? kthread_create_on_node+0x1e0/0x1e0
[21000.180253]  [<ffffffff818363cf>] ret_from_fork+0x3f/0x70
[21000.180255]  [<ffffffff810a0900>] ? kthread_create_on_node+0x1e0/0x1e0
[21000.180257] INFO: task nfsd:8798 blocked for more than 120 seconds.
[21000.180359]       Not tainted 4.4.0-51-generic #72-Ubuntu
[21000.180441] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[21000.180547] nfsd            D ffff8800b60bfc88     0  8798      2 0x00000000
[21000.180549]  ffff8800b60bfc88 ffff8804991c5b40 ffff8804a981b200 ffff8804a55a0c80
[21000.180552]  ffff8800b60c0000 ffff8804991a67ec ffff8804a55a0c80 00000000ffffffff
[21000.180554]  ffff8804991a67f0 ffff8800b60bfca0 ffffffff81831f45 ffff8804991a67e8
[21000.180556] Call Trace:
[21000.180558]  [<ffffffff81831f45>] schedule+0x35/0x80
[21000.180560]  [<ffffffff818321ee>] schedule_preempt_disabled+0xe/0x10
[21000.180561]  [<ffffffff81833e29>] __mutex_lock_slowpath+0xb9/0x130
[21000.180564]  [<ffffffff81833ebf>] mutex_lock+0x1f/0x30
[21000.180570]  [<ffffffffc0549f43>] do_nfsd_create+0x173/0x590 [nfsd]
[21000.180578]  [<ffffffffc0550bf6>] nfsd3_proc_create+0x116/0x190 [nfsd]
[21000.180584]  [<ffffffffc0542e78>] nfsd_dispatch+0xb8/0x200 [nfsd]
[21000.180595]  [<ffffffffc04d8eda>] svc_process_common+0x42a/0x690 [sunrpc]
[21000.180606]  [<ffffffffc04da2c3>] svc_process+0x103/0x1c0 [sunrpc]
[21000.180612]  [<ffffffffc05428cf>] nfsd+0xef/0x160 [nfsd]
[21000.180619]  [<ffffffffc05427e0>] ? nfsd_destroy+0x60/0x60 [nfsd]
[21000.180621]  [<ffffffff810a09d8>] kthread+0xd8/0xf0
[21000.180623]  [<ffffffff810a0900>] ? kthread_create_on_node+0x1e0/0x1e0
[21000.180625]  [<ffffffff818363cf>] ret_from_fork+0x3f/0x70
[21000.180626]  [<ffffffff810a0900>] ? kthread_create_on_node+0x1e0/0x1e0

beesd documentation

The README tells how to use if you don't want to use beesd, but not how to use if you do want to use beesd. The README says there's no config file (for bees) which is a bit confusing since beesd requires a config file.

When I run beesd without options it says beesd [options] <btrfs_uuid> , but there's no definition of what the options are.

It would be nice if there was some documentation on how to use beesd. Things like a list of options, a note telling where to put the file, and where to find the sample config would all be helpful.

No FD in /media/backup/ for 40K [0x1ce76000..0x1ce80000] fid = 5:117983

I'm not sure if this is an issue or not. I am getting lots of "No FD in /media/backup/ for..." messages.
This is with kernel 4.10.6. I've checked the filesystem with scrub and btrfs check, both report no errors.

2017-04-05 22:16:26 26275.26276 crawl: scan: 40K 0x1bbfc0000 [Dddddddddd] 0x1bbfca000 /media/backup/*****/2017-02-01/linux/var/lib/mysql/RealEstate/Valuation.ibd 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2017-03-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: dst 512K [0x1300000..0x1380000] (0x1056a79000->0x3c481ee000) /media/backup/*****/2017-04-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: scan: 512K 0x1300000 [Dddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd] 0x1380000 /media/backup/*****/2017-04-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: No FD in /media/backup/ for 32K [0x1d161000..0x1d169000] fid = 5:117983 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2016-11-01/pj-google/Google Photos/2016/IMG_0638.JPG 2017-04-05 22:16:26 26275.26276 crawl: dst 1.828M [0x0..0x1d4000] (0x45191829000->0x6160e42000) /media/backup/*****/2016-12-01/pj-google/Google Photos/2016/IMG_0638.JPG 2017-04-05 22:16:26 26275.26276 crawl: scan: 1.828M 0x0 [Dddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd] 0x1d4000 /media/backup/*****/2016-12-01/pj-google/Google Photos/2016/IMG_0638.JPG 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2016-06-10/pj-google/Google Photos/2015/20151004_184325.mp4 2017-04-05 22:16:26 26275.26276 crawl: dst 512K [0x3e81000..0x3f01000] (0x43f85a81000->0x124c71a000) /media/backup/*****/2017-01-20/pj-keep/photos/Camera Uploads/2015-10-04 18.45.14.mp4 2017-04-05 22:16:26 26275.26276 crawl: scan: 512K 0x3e81000 [DDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDdddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd] 0x3f01000 /media/backup/*****/2017-01-20/pj-keep/photos/Camera Uploads/2015-10-04 18.45.14.mp4 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2016-12-01/linux/var/lib/mysql/RealEstate/Valuation.ibd 2017-04-05 22:16:26 26275.26276 crawl: dst 36K [0x1bbfca000..0x1bbfd3000] (0xfbcbb17000->0x57d4868000z0) /media/backup/*****/2017-02-01/linux/var/lib/mysql/RealEstate/Valuation.ibd 2017-04-05 22:16:26 26275.26276 crawl: scan: 36K 0x1bbfca000 [Ddddddddd] 0x1bbfd3000 /media/backup/*****/2017-02-01/linux/var/lib/mysql/RealEstate/Valuation.ibd 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2017-03-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: dst 512K [0x1380000..0x1400000] (0x1056af9000->0x3c4826e000) /media/backup/*****/2017-04-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: scan: 512K 0x1380000 [Dddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd] 0x1400000 /media/backup/*****/2017-04-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: No FD in /media/backup/ for 8K [0x1d169000..0x1d16b000] fid = 5:117983 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2016-11-01/pj-google/Google Photos/2016/IMG_0638.JPG 2017-04-05 22:16:26 26275.26276 crawl: dst 1.644K [0x1d4000..0x1d4693] (0x451919fd000u->0x4a57bc2000u) /media/backup/*****/2016-12-01/pj-google/Google Photos/2016/IMG_0638.JPG 2017-04-05 22:16:26 26275.26276 crawl: scan: 1.644K 0x1d4000 [D] 0x1d4693 /media/backup/*****/2016-12-01/pj-google/Google Photos/2016/IMG_0638.JPG 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2016-12-01/linux/var/lib/mysql/RealEstate/Valuation.ibd 2017-04-05 22:16:26 26275.26276 crawl: dst 12K [0x1bbfd3000..0x1bbfd6000] (0xfbcbb20000->0x57d4868000z9000) /media/backup/*****/2017-02-01/linux/var/lib/mysql/RealEstate/Valuation.ibd 2017-04-05 22:16:26 26275.26276 crawl: scan: 12K 0x1bbfd3000 [Ddd] 0x1bbfd6000 /media/backup/*****/2017-02-01/linux/var/lib/mysql/RealEstate/Valuation.ibd 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2017-04-01/pj-keep/** Archive/Firmware/Irrigation/Main Workspace/.metadata/.plugins/org.eclipse.core.resources/.projects/**.Controller/.markers 2017-04-05 22:16:26 26275.26276 crawl: dst 1.265K [0x2000..0x250f] (0x9670dd7000u->0x1d6d1f1000u) /media/backup/*****/2017-03-20/pj-keep/** Archive/Firmware/Irrigation/Main Workspace/.metadata/.plugins/org.eclipse.core.resources/.projects/**.Controller/.markers 2017-04-05 22:16:26 26275.26276 crawl: scan: 1.265K 0x2000 [D] 0x250f /media/backup/*****/2017-03-20/pj-keep/** Archive/Firmware/Irrigation/Main Workspace/.metadata/.plugins/org.eclipse.core.resources/.projects/**.Controller/.markers 2017-04-05 22:16:26 26275.26276 crawl: dedup: src /media/backup/*****/2017-03-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: dst 512K [0x1400000..0x1480000] (0x1056b79000->0x3c482ee000) /media/backup/*****/2017-04-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: scan: 512K 0x1400000 [Dddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd] 0x1480000 /media/backup/*****/2017-04-01/*****/Personal Pictures/DV-Tapes/Horizontal Falls - Penticost river/2006-06-04 11_02_22.mov.mp4 2017-04-05 22:16:26 26275.26276 crawl: No FD in /media/backup/ for 8K [0x1d16b000..0x1d16d000] fid = 5:117983

Compile issue (-Werror=unused-result)

Hi,

I just tried to build debian packages for bees, and I'm running into the following
compile issue. Yes, I know the warning could be ignored, but most build services
apply very restrictive compiler options to force the best code quality, so it'd be
nice to have this warning/error fixed:

<...>
[ 132s] g++ -Wall -Wextra -Werror -O3 -I../include -ggdb -fpic -std=c++11 -Wold-style-cast -o execpipe.o -c execpipe.cc
[ 133s] execpipe.cc: In function 'crucible::Fd crucible::popen(std::function<int()>, std::function<void(const crucible::ResourceHandle<int, crucible::IOHandle>&)>)':
[ 133s] execpipe.cc:81:38: error: ignoring return value of 'int system(const char*)', declared with attribute warn_unused_result [-Werror=unused-result]
[ 133s] system("ls -l /proc/$$/task/ >&2");
[ 133s] ^
[ 133s] cc1plus: all warnings being treated as errors
[ 133s] Makefile:34: recipe for target 'execpipe.o' failed
[ 133s] make[2]: *** [execpipe.o] Error 1
[ 133s] make[2]: Leaving directory '/usr/src/packages/BUILD/lib'

Thanx,
Marcel

std::invalid_argument - (core dumped) "$bees_bin" "${ARGUMENTS[@]}

All was working fine with: bees version v0.5-130-ge564d27
After upgrade to bees version v0.6-6-g14b35e3
Can't get it working due to below error (UUID is changed but matches what is in the config).

INFO: Find 61aaaa24-a25f-aad5-b3aa-d3ec97b9e5cd in /etc/bees//bees.conf, use as conf
INFO: Check: Disk exists
INFO: Check: Disk with btrfs
INFO: WORK DIR: /run/bees/
INFO: MOUNT DIR: /run/bees//mnt/61aaaa24-a25f-aad5-b3aa-d3ec97b9e5cd
bees version v0.6-6-g14b35e3
2018-10-15 01:25:24 10251.10251<3> bees:
2018-10-15 01:25:24 10251.10251<3> bees:
2018-10-15 01:25:24 10251.10251<3> bees: *** EXCEPTION ***
2018-10-15 01:25:24 10251.10251<3> bees: exception type std::invalid_argument: stoul
2018-10-15 01:25:24 10251.10251<3> bees: ***
terminate called after throwing an instance of 'std::invalid_argument'
what(): stoul
/usr/sbin/beesd: line 145: 10251 Aborted (core dumped) "$bees_bin" "${ARGUMENTS[@]}" $OPTIONS "$MNT_DIR"

equal physical addresses in dedup

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 ---

Invalid argument exception

I'm not sure if this is a bug or something I've done wrong.

Linux vm-server 4.8.12-gentoo #1 SMP Sun Dec 4 18:06:37 AEDT 2016 x86_64 AMD Phenom(tm) II X6 1055T Processor AuthenticAMD GNU/Linux
btrfs-progs v4.8.5

2016-12-09 12:21:00 10600.10600 main: set_root_path /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10600 main: set_root_fd /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10600 main: Filesystem UUID is 63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10600 main: BeesStringFile /root/dedupe/beescrawl.dat max size 1M 2016-12-09 12:21:00 10600.10600 main: BeesThread exec crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10600 main: returning from set_root_fd in /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10600 main: BeesThread construct status 2016-12-09 12:21:00 10600.10600 main: BeesThread exec status 2016-12-09 12:21:00 10600.10601 bees: Starting thread crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: loading crawl state 2016-12-09 12:21:00 10600.10602 bees: Starting thread status 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Read line: root 5 objectid 60438 offset 5898241 min_transid 0 max_transid 221817 started 1481245828 start_ts 2016-12-09-12-10-28 2016-12-09 12:21:00 10600.10602 status: Exiting thread status, 0.001 sec 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: loaded_state BeesCrawlState 5:60438 offset 0x5a0001 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Read line: root 14677 objectid 0 offset 0 min_transid 0 max_transid 221817 started 1481245828 start_ts 2016-12-09-12-10-28 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: loaded_state BeesCrawlState 14677:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Read line: root 14720 objectid 0 offset 0 min_transid 0 max_transid 221817 started 1481245828 start_ts 2016-12-09-12-10-28 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: loaded_state BeesCrawlState 14720:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Read line: root 14796 objectid 0 offset 0 min_transid 0 max_transid 221817 started 1481245828 start_ts 2016-12-09-12-10-28 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: loaded_state BeesCrawlState 14796:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: BeesThread exec crawl_writeback /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10603 bees: Starting thread crawl_writeback /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling BeesCrawlState 5:60438 offset 0x5a0001 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling 4096 results from BeesCrawlState 5:60438 offset 0x5a0001 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10603 crawl_writeback /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: open_root_nocache 14677: /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902/peejay/*******/****** 2016-12-09 12:21:00 10600.10603 crawl_writeback /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Saving crawl state 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawled inline 0 data 3338 other 758 unknown 0 gen_low 0 gen_high 0 BeesCrawlState 5:60634 offset 0x800001 transid 0..221817 started 2016-12-09-12$ 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling BeesCrawlState 14677:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling 2 results from BeesCrawlState 14677:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawled inline 0 data 0 other 2 unknown 0 gen_low 0 gen_high 0 BeesCrawlState 14677:256 offset 0x101 transid 0..221817 started 2016-12-09-12-10-28$ 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling BeesCrawlState 14677:256 offset 0x101 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawl empty BeesCrawlState 14677:256 offset 0x101 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Deferring next transid in BeesCrawlState 14677:256 offset 0x101 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling BeesCrawlState 14720:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling 4096 results from BeesCrawlState 14720:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10603 crawl_writeback /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Saved crawl state in 0.004s 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawled inline 5 data 1011 other 3080 unknown 0 gen_low 0 gen_high 0 BeesCrawlState 14720:591 offset 0x1260001 transid 0..221817 started 2016-12-0$ 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawling BeesCrawlState 14796:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Crawl empty BeesCrawlState 14796:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Deferring next transid in BeesCrawlState 14796:0 offset 0x0 transid 0..221817 started 2016-12-09-12-10-28 (632s ago) 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: BeesStringFile /root/dedupe/beesstats.txt max size 1M 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: opened hash table filename 'beeshash.dat' length 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: cells 335544320, buckets 1310720, extents 320 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: flush rate limit 1.19305e+06 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mapping hash table size 5368709120 with flags MAP_PRIVATE|MAP_ANONYMOUS 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mmap done in 0.001 sec 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table extent size 16777216 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table bucket size 4096 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table size 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_prefetch /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_writeback no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: scan extent Extent { begin = 0x0, end = 0x2000, physical = 0xc53cf105000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x2000, logical_len = 0x20$ 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: *** EXCEPTION *** 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: exception type std::system_error: madvise(m_byte_ptr, m_size, MADV_HUGEPAGE | MADV_DONTFORK): Invalid argument 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: *** 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: BeesStringFile /root/dedupe/beesstats.txt max size 1M 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: opened hash table filename 'beeshash.dat' length 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: cells 335544320, buckets 1310720, extents 320 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: flush rate limit 1.19305e+06 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mapping hash table size 5368709120 with flags MAP_PRIVATE|MAP_ANONYMOUS 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mmap done in 0.001 sec 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table extent size 16777216 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table bucket size 4096 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table size 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_prefetch /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_writeback no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: scan extent Extent { begin = 0xe000, end = 0xf000, physical = 0xc5468993000, flags = , physical_len = 0x1000, logical_len = 0x1000 } 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: *** EXCEPTION *** 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: exception type std::system_error: madvise(m_byte_ptr, m_size, MADV_HUGEPAGE | MADV_DONTFORK): Invalid argument 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: *** 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: BeesStringFile /root/dedupe/beesstats.txt max size 1M 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: opened hash table filename 'beeshash.dat' length 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: cells 335544320, buckets 1310720, extents 320 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: flush rate limit 1.19305e+06 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mapping hash table size 5368709120 with flags MAP_PRIVATE|MAP_ANONYMOUS 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mmap done in 0.001 sec 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table extent size 16777216 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table bucket size 4096 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table size 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_prefetch /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_writeback no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: scan extent Extent { begin = 0xf000, end = 0x11000, physical = 0xc53d197d000, flags = Extent::OBSCURED|FIEMAP_EXTENT_ENCODED, physical_len = 0x160$ 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: *** EXCEPTION *** 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: exception type std::system_error: madvise(m_byte_ptr, m_size, MADV_HUGEPAGE | MADV_DONTFORK): Invalid argument 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: *** 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: BeesStringFile /root/dedupe/beesstats.txt max size 1M 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: opened hash table filename 'beeshash.dat' length 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: cells 335544320, buckets 1310720, extents 320 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: flush rate limit 1.19305e+06 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mapping hash table size 5368709120 with flags MAP_PRIVATE|MAP_ANONYMOUS 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: mmap done in 0.001 sec 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table extent size 16777216 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table bucket size 4096 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: hash table size 5368709120 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_prefetch /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902 no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: Thread hash_writeback no thread ptr 2016-12-09 12:21:00 10600.10601 crawl /var/lib/bees/63ec312b-5f7a-4137-a8f0-e877d5a85902: scan extent Extent { begin = 0x11000, end = 0x15000, physical = 0xc5468994000, flags = FIEMAP_EXTENT_ENCODED, physical_len = 0x4000, logical_len =$
...and so on.

[RFC] May be add some default sh wrapper?

What's about do something like, by default:

  1. Store binary and table at /var/lib/bees
  2. Have a config at /etc/bees.conf
  3. Add a sh/bash file at bin/bees for wrap default config

May be add some options to config for automount FS based on UUID and run bees in background?
(I think, it's can work pretty well with systemd restriction and private mount points)

Or you want write all of this stuff in code?

Thanks for any comments.
P.S.
Patch are welcomed?

Option to ignore snapshots

Background:
When incremental backup is used, changing layout of snapshot partition causes that send fails because of changed extents.
example error: Send: inconsistent snapshot, found updated extent for inode 20930799 without updated inode item, send root is 3024, parent root is 3007
full send/receive is working without any errors.
(bees was disabled before backup started)

Solution:
Option to disable/enable deduplication for specific subvolumes. (make some subvolumes immutable)
This would case that disk space isn't freed until snapshot is removed, but in this case we only keeping single (daily) snapshot to be able to do incremental backup to different hard drive. So it is still beneficial to wait one day for extra space, and after initial deduplication process, it shouldn't gain much more free space.

Other observations:
After initial deduplication was made and full backup was performed, next incremental backup also failed with the same reason. -> bees seams to sometimes replace old data with new duplicated ones.

can't compile on archlinux on ARM

Getting this, which translates to constant not defined:

In file included from fd.cc:4:0:
fd.cc:177:25: Fehler: »MAP_32BIT« wurde in diesem Gültigkeitsbereich nicht definiert
NTOA_TABLE_ENTRY_BITS(MAP_32BIT),

gcc 7.2.1+20180116-1
gcc-libs 7.2.1+20180116-1

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.