hash: log startup progress instead of publishing thread notes

Every BEESNOTE between BeesHashTable construction and the end of
prepare() is write-only.  bees_main() calls start_hash_writeback(),
which runs start_threads() -> prepare() and therefore the whole table
load and any resize, at bees.cc:587.  BeesContext::start(), at
bees.cc:600, is what creates the threads that read thread status:
show_progress() at bees-context.cc:1301 and the reporter at 1305.
Those are the only two readers of BeesNote::get_status(), so until
start() runs a note updates a map nobody reads.  Notes are not part of
the exception trace either; that is BEESTRACE.

Getting reports running earlier is not a cheap fix.  They would have to
be hardened against a hash table that is not yet loaded, which is the
whole reason the notes exist in this path.  A log message costs nothing
and is visible immediately, because the log queue replays once config is
applied.

Drop the notes that duplicate an adjacent log line: creating and
truncating a new table, mlock, allocating the resize buffer, and the
resize fsync.  Drop the per-iteration notes for loading an extent, the
resize cell-pass, and the resize write; BeesProgressLogger already
reports all three at BEES_HASH_PROGRESS_INTERVAL, and one log line per
iteration would be millions of lines on a multi-gigabyte table.

Convert the one note with no log counterpart, the hash table open, to
BEESLOGDEBUG.  It is the last thing to happen before the "does not exist
and state.create = no" throw, so it is worth having on a channel that
something reads.

Keep the notes in the writeback loop, print_occupancy, and the stop
paths.  Those run when the reporter is alive; BeesContext::stop() tears
the reporter down after the hash table, not before.

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

diff --git a/src/bees-hash.cc b/src/bees-hash.cc
index 7122642286a5045ea8f8dd4e40e1492b1f8f137e..c422a8d6e9b9c55f1b9d6cb223e21a40e08b60f3 100644 (file)
--- a/src/bees-hash.cc
+++ b/src/bees-hash.cc
@@ -17,11 +17,13 @@ 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.
+/// operations that run at startup.  Loading or resizing a multi-gigabyte
+/// table takes minutes to tens of minutes, and the log is the only channel
+/// available: bees.cc runs start_hash_writeback() (which loads and resizes)
+/// before BeesContext::start() creates the reporter thread, so BEESNOTE in
+/// this path publishes thread status that nothing will ever render.  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;
@@ -623,8 +625,11 @@ BeesHashTable::try_mmap_flags(int flags)
 void
 BeesHashTable::open_file()
 {
-       // OK open hash table
-       BEESNOTE("opening hash table '" << m_filename << "' target size " << m_size << " (" << pretty(m_size) << ")");
+       // Everything from here to the end of prepare() runs before the
+       // reporter thread exists (bees.cc calls start_hash_writeback() before
+       // BeesContext::start()), so BEESNOTE would publish thread status that
+       // nothing is left to render.  Log instead.
+       BEESLOGDEBUG("Opening hash table '" << m_filename << "' target size " << m_size << " (" << pretty(m_size) << ")");
 
        // Try to open existing hash table
        Fd new_fd = openat(m_ctx->home_fd(), m_filename.c_str(), FLAGS_OPEN_FILE_RW, 0700);
@@ -635,14 +640,11 @@ BeesHashTable::open_file()
                        THROW_ERRNO("hash table '" << m_filename << "' does not exist and state.create = no");
                }
                string tmp_filename = m_filename + ".tmp";
-               BEESNOTE("creating new hash table '" << tmp_filename << "'");
                BEESLOGINFO("Creating new hash table '" << tmp_filename << "'");
                unlinkat(m_ctx->home_fd(), tmp_filename.c_str(), 0);
                new_fd = openat_or_die(m_ctx->home_fd(), tmp_filename, FLAGS_CREATE_FILE, 0700);
-               BEESNOTE("truncating new hash table '" << tmp_filename << "' size " << m_size << " (" << pretty(m_size) << ")");
                BEESLOGINFO("Truncating new hash table '" << tmp_filename << "' size " << m_size << " (" << pretty(m_size) << ")");
                ftruncate_or_die(new_fd, m_size);
-               BEESNOTE("truncating new hash table '" << tmp_filename << "' -> '" << m_filename << "'");
                BEESLOGINFO("Truncating new hash table '" << tmp_filename << "' -> '" << m_filename << "'");
                renameat_or_die(m_ctx->home_fd(), tmp_filename, m_ctx->home_fd(), m_filename);
        }
@@ -770,7 +772,6 @@ BeesHashTable::prepare()
        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);
                        uint8_t *const extent_begin = m_extent_ptr[ext    ].p_byte;
                        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);
@@ -794,7 +795,6 @@ BeesHashTable::prepare()
        // the requested size fails fast and visibly.  catch_all to support
        // users who don't want to use mlock().
        if (m_cell_ptr) {
-               BEESNOTE("mlock " << pretty(m_size));
                BEESLOGINFO("mlock(" << pretty(m_size) << ")...");
                Timer lock_time;
                catch_all([&]() {
@@ -964,7 +964,6 @@ BeesHashTable::resize_file(off_t new_size_signed)
        // 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
@@ -1007,9 +1006,6 @@ BeesHashTable::resize_file(off_t new_size_signed)
                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);
@@ -1043,8 +1039,6 @@ BeesHashTable::resize_file(off_t new_size_signed)
        // 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)));
@@ -1059,7 +1053,6 @@ BeesHashTable::resize_file(off_t new_size_signed)
        // 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");