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>

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;

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

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

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

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 *);
 

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

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 *);
 

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.

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 @@ int bch2_fs_recovery(struct bch_fs *c)
 		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 @@ int bch2_fs_recovery(struct bch_fs *c)
 		}
 	}
 
-	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 @@ int bch2_fs_recovery(struct bch_fs *c)
 
 		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 @@ int bch2_fs_recovery(struct bch_fs *c)
 
 		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)