bcachefs: Log more messages in the journal

This patch

 - Adds a mechanism for queuing up journal entries prior to the journal
   being started, which will be used for early journal log messages

 - Adds bch2_fs_log_msg() and improves bch2_trans_log_msg(), which now
   take format strings. bch2_fs_log_msg() can be used before or after
   the journal has been started, and will use the appropriate mechanism.

 - Deletes the now obsolete bch2_journal_log_msg()

 - And adds more log messages to the recovery path - messages for
   journal/filesystem started, journal entries being blacklisted, and
   journal replay starting/finishing.

Signed-off-by: Kent Overstreet <kent.overstreet@linux.dev>

diff --git a/fs/bcachefs/btree_types.h b/fs/bcachefs/btree_types.h
index 390cfe63fbe87b1387de86d2ce74a855b2437ac5..3cf10b3f37881fc13391e72a33657b835cc128b3 100644 (file)
--- a/fs/bcachefs/btree_types.h
+++ b/fs/bcachefs/btree_types.h
@@ -433,7 +433,7 @@ struct btree_trans {
 
        /* update path: */
        struct btree_trans_commit_hook *hooks;
-       DARRAY(u64)             extra_journal_entries;
+       darray_u64              extra_journal_entries;
        struct journal_entry_pin *journal_pin;
 
        struct journal_res      journal_res;

diff --git a/fs/bcachefs/btree_update.h b/fs/bcachefs/btree_update.h
index 1c2e7b2b4ed5b01b00b9e61d6bdaf0802bc69c48..7e9f1f170d5f6bdcedd0585f7263cc053e69b78b 100644 (file)
--- a/fs/bcachefs/btree_update.h
+++ b/fs/bcachefs/btree_update.h
@@ -82,7 +82,8 @@ void bch2_trans_commit_hook(struct btree_trans *,
                            struct btree_trans_commit_hook *);
 int __bch2_trans_commit(struct btree_trans *);
 
-int bch2_trans_log_msg(struct btree_trans *, const char *);
+int bch2_trans_log_msg(struct btree_trans *, const char *, ...);
+int bch2_fs_log_msg(struct bch_fs *, const char *, ...);
 
 /**
  * bch2_trans_commit - insert keys at given iterator positions

diff --git a/fs/bcachefs/btree_update_leaf.c b/fs/bcachefs/btree_update_leaf.c
index ca15ed33a2041e627f37a8c646ccab4294ccbd7f..d333d0e46d0d8a544ebaabf726c32396466d9a41 100644 (file)
--- a/fs/bcachefs/btree_update_leaf.c
+++ b/fs/bcachefs/btree_update_leaf.c
@@ -1772,18 +1772,25 @@ int bch2_btree_delete_range(struct bch_fs *c, enum btree_id id,
        return ret;
 }
 
-int bch2_trans_log_msg(struct btree_trans *trans, const char *msg)
+static int __bch2_trans_log_msg(darray_u64 *entries, const char *fmt, va_list args)
 {
-       unsigned len = strlen(msg);
-       unsigned u64s = DIV_ROUND_UP(len, sizeof(u64));
+       struct printbuf buf = PRINTBUF;
        struct jset_entry_log *l;
+       unsigned u64s;
        int ret;
 
-       ret = darray_make_room(&trans->extra_journal_entries, jset_u64s(u64s));
+       prt_vprintf(&buf, fmt, args);
+       ret = buf.allocation_failure ? -ENOMEM : 0;
        if (ret)
-               return ret;
+               goto err;
+
+       u64s = DIV_ROUND_UP(buf.pos, sizeof(u64));
+
+       ret = darray_make_room(entries, jset_u64s(u64s));
+       if (ret)
+               goto err;
 
-       l = (void *) &darray_top(trans->extra_journal_entries);
+       l = (void *) &darray_top(*entries);
        l->entry.u64s           = cpu_to_le16(u64s);
        l->entry.btree_id       = 0;
        l->entry.level          = 1;
@@ -1791,10 +1798,44 @@ int bch2_trans_log_msg(struct btree_trans *trans, const char *msg)
        l->entry.pad[0]         = 0;
        l->entry.pad[1]         = 0;
        l->entry.pad[2]         = 0;
-       memcpy(l->d, msg, len);
-       while (len & 7)
-               l->d[len++] = '\0';
+       memcpy(l->d, buf.buf, buf.pos);
+       while (buf.pos & 7)
+               l->d[buf.pos++] = '\0';
+
+       entries->nr += jset_u64s(u64s);
+err:
+       printbuf_exit(&buf);
+       return ret;
+}
+
+int bch2_trans_log_msg(struct btree_trans *trans, const char *fmt, ...)
+{
+       va_list args;
+       int ret;
+
+       va_start(args, fmt);
+       ret = __bch2_trans_log_msg(&trans->extra_journal_entries, fmt, args);
+       va_end(args);
+
+       return ret;
+}
+
+int bch2_fs_log_msg(struct bch_fs *c, const char *fmt, ...)
+{
+       va_list args;
+       int ret;
+
+       va_start(args, fmt);
+
+       if (!test_bit(JOURNAL_STARTED, &c->journal.flags)) {
+               ret = __bch2_trans_log_msg(&c->journal.early_journal_entries, fmt, args);
+       } else {
+               ret = bch2_trans_do(c, NULL, NULL, BTREE_INSERT_LAZY_RW,
+                       __bch2_trans_log_msg(&trans.extra_journal_entries, fmt, args));
+       }
+
+       va_end(args);
+
+       return ret;
 
-       trans->extra_journal_entries.nr += jset_u64s(u64s);
-       return 0;
 }

diff --git a/fs/bcachefs/journal.c b/fs/bcachefs/journal.c
index ed3ed3072db1ee91fb9f3172d2fdfb99a2cfc679..c7a7b9cd20f0603171d13d6b75f70eccb5df0cdc 100644 (file)
--- a/fs/bcachefs/journal.c
+++ b/fs/bcachefs/journal.c
@@ -249,7 +249,7 @@ static int journal_entry_open(struct journal *j)
                journal_entry_overhead(j);
        u64s = clamp_t(int, u64s, 0, JOURNAL_ENTRY_CLOSED_VAL - 1);
 
-       if (u64s <= 0)
+       if (u64s <= (ssize_t) j->early_journal_entries.nr)
                return JOURNAL_ERR_journal_full;
 
        if (fifo_empty(&j->pin) && j->reclaim_thread)
@@ -274,6 +274,12 @@ static int journal_entry_open(struct journal *j)
        buf->data->seq  = cpu_to_le64(journal_cur_seq(j));
        buf->data->u64s = 0;
 
+       if (j->early_journal_entries.nr) {
+               memcpy(buf->data->_data, j->early_journal_entries.data,
+                      j->early_journal_entries.nr * sizeof(u64));
+               le32_add_cpu(&buf->data->u64s, j->early_journal_entries.nr);
+       }
+
        /*
         * Must be set before marking the journal entry as open:
         */
@@ -290,7 +296,9 @@ static int journal_entry_open(struct journal *j)
                BUG_ON(new.idx != (journal_cur_seq(j) & JOURNAL_BUF_MASK));
 
                journal_state_inc(&new);
-               new.cur_entry_offset = 0;
+
+               /* Handle any already added entries */
+               new.cur_entry_offset = le32_to_cpu(buf->data->u64s);
        } while ((v = atomic64_cmpxchg(&j->reservations.counter,
                                       old.v, new.v)) != old.v);
 
@@ -303,6 +311,9 @@ static int journal_entry_open(struct journal *j)
                         &j->write_work,
                         msecs_to_jiffies(c->opts.journal_flush_delay));
        journal_wake(j);
+
+       if (j->early_journal_entries.nr)
+               darray_exit(&j->early_journal_entries);
        return 0;
 }
 
@@ -719,39 +730,6 @@ int bch2_journal_meta(struct journal *j)
        return bch2_journal_flush_seq(j, res.seq);
 }
 
-int bch2_journal_log_msg(struct journal *j, const char *fmt, ...)
-{
-       struct jset_entry_log *entry;
-       struct journal_res res = { 0 };
-       unsigned msglen, u64s;
-       va_list args;
-       int ret;
-
-       va_start(args, fmt);
-       msglen = vsnprintf(NULL, 0, fmt, args) + 1;
-       va_end(args);
-
-       u64s = jset_u64s(DIV_ROUND_UP(msglen, sizeof(u64)));
-
-       ret = bch2_journal_res_get(j, &res, u64s, 0);
-       if (ret)
-               return ret;
-
-       entry = container_of(journal_res_entry(j, &res),
-                            struct jset_entry_log, entry);
-       memset(entry, 0, u64s * sizeof(u64));
-       entry->entry.type = BCH_JSET_ENTRY_log;
-       entry->entry.u64s = u64s - 1;
-
-       va_start(args, fmt);
-       vsnprintf(entry->d, INT_MAX, fmt, args);
-       va_end(args);
-
-       bch2_journal_res_put(j, &res);
-
-       return bch2_journal_flush_seq(j, res.seq);
-}
-
 /* block/unlock the journal: */
 
 void bch2_journal_unblock(struct journal *j)
@@ -1197,6 +1175,8 @@ void bch2_fs_journal_exit(struct journal *j)
 {
        unsigned i;
 
+       darray_exit(&j->early_journal_entries);
+
        for (i = 0; i < ARRAY_SIZE(j->buf); i++)
                kvpfree(j->buf[i].data, j->buf[i].buf_size);
        free_fifo(&j->pin);

diff --git a/fs/bcachefs/journal.h b/fs/bcachefs/journal.h
index 3e93f0d67c09c5b0f06445006f781c32c59603a3..1c750833343208ba7c40494c7c56901efc38708e 100644 (file)
--- a/fs/bcachefs/journal.h
+++ b/fs/bcachefs/journal.h
@@ -478,7 +478,6 @@ int bch2_journal_flush_seq(struct journal *, u64);
 int bch2_journal_flush(struct journal *);
 bool bch2_journal_noflush_seq(struct journal *, u64);
 int bch2_journal_meta(struct journal *);
-int bch2_journal_log_msg(struct journal *, const char *, ...);
 
 void bch2_journal_halt(struct journal *);
 

diff --git a/fs/bcachefs/journal_io.c b/fs/bcachefs/journal_io.c
index dbbf2a03bd3879d4030a549a46afffe761f3e920..a9744924d619501deb3eab7e5369cdb012931018 100644 (file)
--- a/fs/bcachefs/journal_io.c
+++ b/fs/bcachefs/journal_io.c
@@ -1079,7 +1079,10 @@ void bch2_journal_ptrs_to_text(struct printbuf *out, struct bch_fs *c,
        }
 }
 
-int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
+int bch2_journal_read(struct bch_fs *c,
+                     u64 *last_seq,
+                     u64 *blacklist_seq,
+                     u64 *start_seq)
 {
        struct journal_list jlist;
        struct journal_replay *i, **_i, *prev = NULL;
@@ -1088,7 +1091,7 @@ int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
        unsigned iter;
        struct printbuf buf = PRINTBUF;
        bool degraded = false, last_write_torn = false;
-       u64 seq, last_seq = 0;
+       u64 seq;
        int ret = 0;
 
        closure_init_stack(&jlist.cl);
@@ -1117,6 +1120,7 @@ int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
        if (jlist.ret)
                return jlist.ret;
 
+       *last_seq       = 0;
        *start_seq      = 0;
        *blacklist_seq  = 0;
 
@@ -1153,7 +1157,7 @@ int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
                                         le64_to_cpu(i->j.seq)))
                        i->j.last_seq = i->j.seq;
 
-               last_seq        = le64_to_cpu(i->j.last_seq);
+               *last_seq       = le64_to_cpu(i->j.last_seq);
                *blacklist_seq  = le64_to_cpu(i->j.seq) + 1;
                break;
        }
@@ -1163,13 +1167,13 @@ int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
                return 0;
        }
 
-       if (!last_seq) {
+       if (!*last_seq) {
                fsck_err(c, "journal read done, but no entries found after dropping non-flushes");
                return 0;
        }
 
        bch_info(c, "journal read done, replaying entries %llu-%llu",
-                last_seq, *blacklist_seq - 1);
+                *last_seq, *blacklist_seq - 1);
 
        if (*start_seq != *blacklist_seq)
                bch_info(c, "dropped unflushed entries %llu-%llu",
@@ -1183,7 +1187,7 @@ int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
                        continue;
 
                seq = le64_to_cpu(i->j.seq);
-               if (seq < last_seq) {
+               if (seq < *last_seq) {
                        journal_replay_free(c, i);
                        continue;
                }
@@ -1196,7 +1200,7 @@ int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
        }
 
        /* Check for missing entries: */
-       seq = last_seq;
+       seq = *last_seq;
        genradix_for_each(&c->journal_entries, radix_iter, _i) {
                i = *_i;
 
@@ -1234,7 +1238,7 @@ int bch2_journal_read(struct bch_fs *c, u64 *blacklist_seq, u64 *start_seq)
                                 "  prev at %s\n"
                                 "  next at %s",
                                 missing_start, missing_end,
-                                last_seq, *blacklist_seq - 1,
+                                *last_seq, *blacklist_seq - 1,
                                 buf1.buf, buf2.buf);
 
                        printbuf_exit(&buf1);

diff --git a/fs/bcachefs/journal_io.h b/fs/bcachefs/journal_io.h
index 2f8bbf06b28951301d8c0469eed1e0f934adf18b..a32c2876f2a65075e5803ce01c18aa9f29793aec 100644 (file)
--- a/fs/bcachefs/journal_io.h
+++ b/fs/bcachefs/journal_io.h
@@ -52,7 +52,7 @@ void bch2_journal_entry_to_text(struct printbuf *, struct bch_fs *,
 void bch2_journal_ptrs_to_text(struct printbuf *, struct bch_fs *,
                               struct journal_replay *);
 
-int bch2_journal_read(struct bch_fs *, u64 *, u64 *);
+int bch2_journal_read(struct bch_fs *, u64 *, u64 *, u64 *);
 
 void bch2_journal_write(struct closure *);
 

diff --git a/fs/bcachefs/journal_types.h b/fs/bcachefs/journal_types.h
index 4c3065dceeea98a651f2b726ddf44f6fad05cb72..0e6bde669b3e6577b542a4243a11a061693ffc8c 100644 (file)
--- a/fs/bcachefs/journal_types.h
+++ b/fs/bcachefs/journal_types.h
@@ -177,6 +177,8 @@ enum journal_errors {
 #undef x
 };
 
+typedef DARRAY(u64)            darray_u64;
+
 /* Embedded in struct bch_fs */
 struct journal {
        /* Fastpath stuff up front: */
@@ -206,6 +208,12 @@ struct journal {
        enum journal_errors     cur_entry_error;
 
        unsigned                buf_size_want;
+       /*
+        * We may queue up some things to be journalled (log messages) before
+        * the journal has actually started - stash them here:
+        */
+       darray_u64              early_journal_entries;
+
        /*
         * Two journal entries -- one is currently open for new entries, the
         * other is possibly being written out.

diff --git a/fs/bcachefs/recovery.c b/fs/bcachefs/recovery.c
index 55819378fd4ac2d2f5d409da63101f6ed303dedf..d054e83d86efc571c2e6998ca4ecece08559cd6a 100644 (file)
--- a/fs/bcachefs/recovery.c
+++ b/fs/bcachefs/recovery.c
@@ -587,7 +587,7 @@ static int journal_sort_seq_cmp(const void *_l, const void *_r)
        return cmp_int(l->journal_seq, r->journal_seq);
 }
 
-static int bch2_journal_replay(struct bch_fs *c)
+static int bch2_journal_replay(struct bch_fs *c, u64 start_seq, u64 end_seq)
 {
        struct journal_keys *keys = &c->journal_keys;
        struct journal_key **keys_sorted, *k;
@@ -609,6 +609,13 @@ static int bch2_journal_replay(struct bch_fs *c)
             sizeof(keys_sorted[0]),
             journal_sort_seq_cmp, NULL);
 
+       if (keys->nr) {
+               ret = bch2_fs_log_msg(c, "Starting journal replay (%zu keys in entries %llu-%llu)",
+                                     keys->nr, start_seq, end_seq);
+               if (ret)
+                       goto err;
+       }
+
        for (i = 0; i < keys->nr; i++) {
                k = keys_sorted[i];
 
@@ -638,7 +645,7 @@ static int bch2_journal_replay(struct bch_fs *c)
        ret = bch2_journal_error(j);
 
        if (keys->nr && !ret)
-               bch2_journal_log_msg(&c->journal, "journal replay finished");
+               bch2_fs_log_msg(c, "journal replay finished");
 err:
        kvfree(keys_sorted);
        return ret;
@@ -1042,7 +1049,7 @@ int bch2_fs_recovery(struct bch_fs *c)
        const char *err = "cannot allocate memory";
        struct bch_sb_field_clean *clean = NULL;
        struct jset *last_journal_entry = NULL;
-       u64 blacklist_seq, journal_seq;
+       u64 last_seq, blacklist_seq, journal_seq;
        bool write_sb = false;
        int ret = 0;
 
@@ -1109,7 +1116,7 @@ int bch2_fs_recovery(struct bch_fs *c)
                struct journal_replay **i;
 
                bch_verbose(c, "starting journal read");
-               ret = bch2_journal_read(c, &blacklist_seq, &journal_seq);
+               ret = bch2_journal_read(c, &last_seq, &blacklist_seq, &journal_seq);
                if (ret)
                        goto err;
 
@@ -1191,7 +1198,9 @@ use_clean:
                journal_seq += 8;
 
        if (blacklist_seq != journal_seq) {
-               ret = bch2_journal_seq_blacklist_add(c,
+               ret =   bch2_fs_log_msg(c, "blacklisting entries %llu-%llu",
+                                       blacklist_seq, journal_seq) ?:
+                       bch2_journal_seq_blacklist_add(c,
                                        blacklist_seq, journal_seq);
                if (ret) {
                        bch_err(c, "error creating new journal seq blacklist entry");
@@ -1199,12 +1208,14 @@ use_clean:
                }
        }
 
-       ret = bch2_fs_journal_start(&c->journal, journal_seq);
+       ret =   bch2_fs_log_msg(c, "starting journal at entry %llu, replaying %llu-%llu",
+                               journal_seq, last_seq, blacklist_seq - 1) ?:
+               bch2_fs_journal_start(&c->journal, journal_seq);
        if (ret)
                goto err;
 
        if (c->opts.reconstruct_alloc)
-               bch2_journal_log_msg(&c->journal, "dropping alloc info");
+               bch2_fs_log_msg(c, "dropping alloc info");
 
        /*
         * Skip past versions that might have possibly been used (as nonces),
@@ -1260,7 +1271,7 @@ use_clean:
 
                bch_info(c, "starting journal replay, %zu keys", c->journal_keys.nr);
                err = "journal replay failed";
-               ret = bch2_journal_replay(c);
+               ret = bch2_journal_replay(c, last_seq, blacklist_seq - 1);
                if (ret)
                        goto err;
                if (c->opts.verbose || !c->sb.clean)
@@ -1293,7 +1304,7 @@ use_clean:
 
                bch_verbose(c, "starting journal replay, %zu keys", c->journal_keys.nr);
                err = "journal replay failed";
-               ret = bch2_journal_replay(c);
+               ret = bch2_journal_replay(c, last_seq, blacklist_seq - 1);
                if (ret)
                        goto err;
                if (c->opts.verbose || !c->sb.clean)