]> git.hungrycats.org Git - bees/commitdiff
hash: report progress while loading and resizing the table
authorZygo Blaxell <bees@furryterror.org>
Sat, 22 Aug 2026 23:04:31 +0000 (19:04 -0400)
committerZygo Blaxell <bees@furryterror.org>
Sat, 5 Sep 2026 04:03:58 +0000 (00:03 -0400)
Loading or resizing a multi-gigabyte hash table happens in the main
thread at startup, before the status file exists and before any worker
runs.  On an 8G-to-16G resize that is over half an hour during which the
log shows a single line at the start and nothing else, so an operator
has no way to distinguish slow progress from a hang.

Add BeesProgressLogger, a rate-limited reporter that emits one debug
line every BEES_HASH_PROGRESS_INTERVAL (15) seconds with the completed unit
count, the percentage, elapsed time, and a linear estimate of the time
remaining, plus one summary line when the operation ends.  The interval
timer starts at construction, so short operations stay silent.

Report progress from the three loops that dominate startup:

  - the per-extent load in prepare()
  - the cell-pass scan of the old table in resize_file(), whose unit
    count is cells-per-bucket times old extents, all units equal cost
  - the write of the new table in resize_file()

Also time the zero-filled allocation of the new table and the fsync of
the temp file, both of which are single blocking calls with no interior
progress to report.

Write the new table one Extent at a time, matching the unit prepare()
reads it in, and view the staging buffer through an Extent alias the way
the mmap'd table is viewed through m_extent_ptr.  Writing it in one call
is not an option any more: pwrite_or_die() rejects a request above
max_transfer_size(), which any table worth resizing exceeds.  Extents
are also what gives the write something to report, one update per Extent
rather than one for the whole table.  open_file() already requires the
table size to be an exact multiple of one Extent, so the loop needs no
partial tail case; assert that invariant where the buffer is allocated.

Durability is unchanged: it comes from the fsync and rename, not from
the size of any one write.  Record why that fsync, unlike the writeback
and close ones, is not gated by a config knob.

The constant is named for the hash table rather than progress in
general: an unrelated BEES_PROGRESS_INTERVAL used to pace the hourly
show_progress dump before that moved into [report.*], and branches
that still carry the old one must not collide with this.

Assisted-by: Claude-Code:claude-opus-5
Signed-off-by: Zygo Blaxell <bees@furryterror.org>
src/bees-hash.cc
src/bees.h

index c7acf124f5c3ee9d5e599da1833066d3b47168f8..7122642286a5045ea8f8dd4e40e1492b1f8f137e 100644 (file)
@@ -7,12 +7,68 @@
 #include "crucible/uname.h"
 
 #include <algorithm>
+#include <sstream>
 
 #include <sys/mman.h>
 
 using namespace crucible;
 using namespace std;
 
+namespace {
+
+/// Rate-limited progress reporter for the long single-threaded hash table
+/// operations that run before the daemon's status file and worker threads
+/// exist.  Loading or resizing a multi-gigabyte table takes minutes to
+/// tens of minutes, and BEESNOTE alone is invisible to an operator who is
+/// only watching the log.  Emits at most one line per
+/// BEES_HASH_PROGRESS_INTERVAL seconds, plus one summary line at the end.
+class BeesProgressLogger {
+       const string    m_what;
+       Timer           m_start;
+       Timer           m_since_log;
+
+public:
+       explicit BeesProgressLogger(const string &what) : m_what(what) { }
+
+       /// Log progress if the reporting interval has elapsed.  Cheap enough
+       /// to call from the innermost loop: the common case is one Timer::age().
+       void update(uint64_t done, uint64_t total);
+
+       /// Log the total elapsed time, unconditionally.
+       void finish() const;
+};
+
+void
+BeesProgressLogger::update(const uint64_t done, const uint64_t total)
+{
+       if (m_since_log.age() < BEES_HASH_PROGRESS_INTERVAL) {
+               return;
+       }
+       m_since_log.reset();
+       const double elapsed = m_start.age();
+       ostringstream oss;
+       oss << m_what << ": " << done << "/" << total;
+       if (total > 0) {
+               oss << " (" << (done * 100 / total) << "%)";
+       }
+       oss << ", " << m_start << " sec elapsed";
+       // Extrapolate from the average rate so far.  The resize passes are
+       // uniform in cost, and the load is a linear scan, so a plain linear
+       // estimate is honest enough to be worth printing.
+       if (done > 0 && done < total && elapsed > 0) {
+               oss << ", " << static_cast<uint64_t>(elapsed / done * (total - done)) << " sec remaining";
+       }
+       BEESLOGDEBUG(oss.str());
+}
+
+void
+BeesProgressLogger::finish() const
+{
+       BEESLOGDEBUG(m_what << ": done in " << m_start << " sec");
+}
+
+}
+
 // Process-global hash function selection.
 // Defaults to CRC-64 so BeesHash(ptr, len) works correctly even before
 // BeesContext calls set_hash_function at startup.
@@ -711,6 +767,7 @@ BeesHashTable::prepare()
        // faster to steady state and lets the lookup/insert paths assume the
        // table is always resident.  Memory-only mode skips this —
        // the pages are already zero from MAP_ANONYMOUS.
+       BeesProgressLogger load_progress("Loading hash table '" + m_filename + "'");
        for (uint64_t ext = 0; ext < m_extents; ++ext) {
                if (m_persistent) {
                        BEESNOTE("loading hash extent #" << ext << " of " << m_extents);
@@ -718,12 +775,16 @@ BeesHashTable::prepare()
                        uint8_t *const extent_end   = m_extent_ptr[ext + 1].p_byte;
                        pread_or_die(m_fd, extent_begin, extent_end - extent_begin, extent_begin - m_byte_ptr);
                        BEESCOUNT(hash_extent_in);
+                       load_progress.update(ext + 1, m_extents);
                }
                // Seed the occupancy fragment from the just-loaded (or, in
                // memory-only mode, zeroed) extent so the survey has data before
                // the first writeback.
                recompute_extent_fill_histogram_locked(ext);
        }
+       if (m_persistent) {
+               load_progress.finish();
+       }
 
        // Pre-fault and lock now, while we know which size the host has to
        // back.  prefetch_loop() used to do this on its first analyze pass,
@@ -897,8 +958,23 @@ BeesHashTable::resize_file(off_t new_size_signed)
        // reading the old file one extent at a time below.  When the old
        // table fits in the page cache the rereads land in cache; when it
        // does not the resize is slow but does not OOM.
+       //
+       // open_file() guarantees the table size is an exact multiple of one
+       // Extent, so both views below tile the buffer exactly and the write
+       // loop has no partial tail extent to special-case.
+       THROW_CHECK2(invalid_argument, new_size, BLOCK_SIZE_HASHTAB_EXTENT, (new_size % BLOCK_SIZE_HASHTAB_EXTENT) == 0);
+       const uint64_t new_extents = new_size / BLOCK_SIZE_HASHTAB_EXTENT;
+       BEESNOTE("allocating " << pretty(new_size) << " for the resized hash table");
+       Timer alloc_timer;
+       // Raw bytes, not vector<Extent>: Cell has no default constructor by
+       // design, so Bucket and Extent have none either.  Both are union
+       // aliases over the same bytes, exactly as the mmap'd table is viewed
+       // through m_bucket_ptr and m_extent_ptr.
        vector<uint8_t> new_table(new_size, 0);
        Bucket *const new_bucket_ptr = reinterpret_cast<Bucket *>(new_table.data());
+       const Extent *const new_extent_ptr = reinterpret_cast<const Extent *>(new_table.data());
+       BEESLOGDEBUG("Allocated " << pretty(new_size) << " (" << new_extents << " extents)"
+               " for the resized hash table in " << alloc_timer << " sec");
 
        // Cell-position is the OUTER loop, not the inner.  When two old
        // buckets collide on one new bucket (the common case on shrink:
@@ -918,14 +994,23 @@ BeesHashTable::resize_file(off_t new_size_signed)
        // fast; when it does not, every pass after the first reads from
        // disk again.  Resizing a hash table is a rare, slow operation —
        // correctness over speed.
+       //
+       // One "read" here is one old extent on one cell-pass, so the total
+       // unit count is the product.  Every unit costs the same one pread
+       // plus a fixed amount of bucket walking, which makes the linear ETA
+       // in BeesProgressLogger meaningful.
+       const uint64_t total_reads = c_cells_per_bucket * old_extents;
+       BeesProgressLogger resize_progress("Resizing hash table");
        ByteVector extent_buf(BLOCK_SIZE_HASHTAB_EXTENT);
        for (uint64_t ci = c_cells_per_bucket; ci > 0; --ci) {
                const uint64_t cell_idx = ci - 1;
+               const uint64_t reads_before = (c_cells_per_bucket - ci) * old_extents;
                for (uint64_t pass = 0; pass < old_extents; ++pass) {
                        const uint64_t ei = old_extents - 1 - pass;
                        BEESNOTE("resizing hash table: cell-pass " << (c_cells_per_bucket - cell_idx)
                                << "/" << c_cells_per_bucket
                                << ", reading old extent " << (pass + 1) << "/" << old_extents);
+                       resize_progress.update(reads_before + pass + 1, total_reads);
                        const off_t offset = ranged_cast<off_t>(ei) * BLOCK_SIZE_HASHTAB_EXTENT;
                        pread_or_die(m_fd, extent_buf, offset);
 
@@ -939,16 +1024,45 @@ BeesHashTable::resize_file(off_t new_size_signed)
                }
        }
 
+       resize_progress.finish();
+
        // Write the populated new table to a temp file, fsync, rename over
        // the original.  Crash-safety relies on the rename being atomic.
        const string tmp_filename = m_filename + ".tmp";
-       BEESNOTE("writing resized hash table to '" << tmp_filename << "'");
        BEESLOGINFO("Writing resized hash table to '" << tmp_filename << "'");
        unlinkat(m_ctx->home_fd(), tmp_filename.c_str(), 0);
        Fd tmp_fd = openat_or_die(m_ctx->home_fd(), tmp_filename, FLAGS_CREATE_FILE, 0700);
        ftruncate_or_die(tmp_fd, new_size);
-       pwrite_or_die(tmp_fd, new_table.data(), new_size, 0);
+
+       // Write one Extent at a time, the same unit prepare() reads the table
+       // in.  Handing the kernel the whole table in one call is not an option:
+       // pwrite_or_die() rejects any request above BLOCK_SIZE_MAX_TRANSFER,
+       // which a table this size is far past.  Extents are also the unit
+       // progress is reportable in — writing 16 GiB to a slow device is
+       // minutes of otherwise silent time.  Durability comes from the fsync
+       // and rename below, not from the size of any one write.
+       BeesProgressLogger write_progress("Writing resized hash table to '" + tmp_filename + "'");
+       for (uint64_t ext = 0; ext < new_extents; ++ext) {
+               BEESNOTE("writing resized hash table to '" << tmp_filename << "': extent "
+                       << (ext + 1) << "/" << new_extents);
+               const Extent &extent = new_extent_ptr[ext];
+               pwrite_or_die(tmp_fd, extent.p_byte, sizeof(extent.p_byte),
+                       ranged_cast<off_t>(ext * sizeof(Extent)));
+               write_progress.update(ext + 1, new_extents);
+       }
+       write_progress.finish();
+
+       // Unconditional, unlike the writeback and close fsyncs, which are
+       // gated by state.hash.writeback-fsync and state.hash.close-fsync.
+       // Skipping either of those only risks losing recently learned hashes;
+       // skipping this one risks renaming a partially written table over a
+       // good one.  bees_fsync() decides whether the syscall is needed at
+       // all: on btrfs before 5.16 the rename already flushes, and fsync
+       // there caused ghost dirents in $BEESHOME.
+       BEESNOTE("syncing resized hash table '" << tmp_filename << "'");
+       Timer fsync_timer;
        bees_fsync(tmp_fd);
+       BEESLOGDEBUG("bees_fsync of resized hash table returned in " << fsync_timer << " sec");
        tmp_fd = Fd();
        renameat_or_die(m_ctx->home_fd(), tmp_filename, m_ctx->home_fd(), m_filename);
 
index a2531e6666b4543c6e51ace8ab8578e2fb8c21b3..8c067be0f0ae7e92f795a47624762b71c760ef73 100644 (file)
@@ -104,6 +104,12 @@ const int BEES_PROGRESS_INTERVAL = 3600;
 /// Seconds between writing the status output file (BEESSTATUS).
 const int BEES_STATUS_INTERVAL = 1;
 
+/// Seconds between progress log messages during long single-threaded
+/// startup operations (hash table load, hash table resize).  These run
+/// before the status file exists, so the log is the only feedback the
+/// operator gets, and they can take tens of minutes on a large table.
+const double BEES_HASH_PROGRESS_INTERVAL = 15.0;
+
 /// Maximum number of file file descriptors to keep open in the FD cache.
 const size_t BEES_FILE_FD_CACHE_SIZE = 524288;