bcachefs: Add more time_stats

This adds more latency/event measurements and breaks some apart into
more events. Journal writes are broken apart into flush writes and
noflush writes, btree compactions are broken out from btree splits,
btree mergers are added, as well as btree_interior_updates - foreground
and total.

Signed-off-by: Kent Overstreet <kent.overstreet@gmail.com>

10 files changed, 52 insertions, 14 deletions

diff --git a/fs/bcachefs/bcachefs.h b/fs/bcachefs/bcachefs.h
index 5e9378843476..dde919a95585 100644
--- a/fs/bcachefs/bcachefs.h
+++ b/fs/bcachefs/bcachefs.h
@@ -321,8 +321,12 @@ BCH_DEBUG_PARAMS_DEBUG()
 #define BCH_TIME_STATS()			\
 	x(btree_node_mem_alloc)			\
 	x(btree_node_split)			\
+	x(btree_node_compact)			\
+	x(btree_node_merge)			\
 	x(btree_node_sort)			\
 	x(btree_node_read)			\
+	x(btree_interior_update_foreground)	\
+	x(btree_interior_update_total)		\
 	x(btree_gc)				\
 	x(btree_lock_contended_read)		\
 	x(btree_lock_contended_intent)		\
@@ -330,8 +334,8 @@ BCH_DEBUG_PARAMS_DEBUG()
 	x(data_write)				\
 	x(data_read)				\
 	x(data_promote)				\
-	x(journal_write)			\
-	x(journal_delay)			\
+	x(journal_flush_write)			\
+	x(journal_noflush_write)		\
 	x(journal_flush_seq)			\
 	x(blocked_journal)			\
 	x(blocked_allocate)			\
diff --git a/fs/bcachefs/btree_gc.c b/fs/bcachefs/btree_gc.c
index dc4562a1e122..ccb85850080b 100644
--- a/fs/bcachefs/btree_gc.c
+++ b/fs/bcachefs/btree_gc.c
@@ -1849,6 +1849,7 @@ int bch2_gc_gens(struct bch_fs *c)
 	struct bch_dev *ca;
 	struct bucket_array *buckets;
 	struct bucket *g;
+	u64 start_time = local_clock();
 	unsigned i;
 	int ret;
 
@@ -1892,6 +1893,8 @@ int bch2_gc_gens(struct bch_fs *c)
 	c->gc_gens_pos		= POS_MIN;
 
 	c->gc_count++;
+
+	bch2_time_stats_update(&c->times[BCH_TIME_btree_gc], start_time);
 err:
 	up_read(&c->gc_lock);
 	return ret;
diff --git a/fs/bcachefs/btree_update_interior.c b/fs/bcachefs/btree_update_interior.c
index a28c7cf381ce..8865ab7d087b 100644
--- a/fs/bcachefs/btree_update_interior.c
+++ b/fs/bcachefs/btree_update_interior.c
@@ -455,15 +455,23 @@ static void bch2_btree_update_free(struct btree_update *as)
 	bch2_disk_reservation_put(c, &as->disk_res);
 	bch2_btree_reserve_put(as);
 
+	bch2_time_stats_update(&c->times[BCH_TIME_btree_interior_update_total],
+			       as->start_time);
+
 	mutex_lock(&c->btree_interior_update_lock);
 	list_del(&as->unwritten_list);
 	list_del(&as->list);
-	mutex_unlock(&c->btree_interior_update_lock);
 
 	closure_debug_destroy(&as->cl);
 	mempool_free(as, &c->btree_interior_update_pool);
 
+	/*
+	 * Have to do the wakeup with btree_interior_update_lock still held,
+	 * since being on btree_interior_update_list is our ref on @c:
+	 */
 	closure_wake_up(&c->btree_interior_update_wait);
+
+	mutex_unlock(&c->btree_interior_update_lock);
 }
 
 static void btree_update_will_delete_key(struct btree_update *as,
@@ -902,6 +910,9 @@ static void bch2_btree_interior_update_will_free_node(struct btree_update *as,
 
 static void bch2_btree_update_done(struct btree_update *as)
 {
+	struct bch_fs *c = as->c;
+	u64 start_time = as->start_time;
+
 	BUG_ON(as->mode == BTREE_INTERIOR_NO_UPDATE);
 
 	if (as->took_gc_lock)
@@ -912,6 +923,9 @@ static void bch2_btree_update_done(struct btree_update *as)
 
 	continue_at(&as->cl, btree_update_set_nodes_written,
 		    as->c->btree_interior_update_worker);
+
+	bch2_time_stats_update(&c->times[BCH_TIME_btree_interior_update_foreground],
+			       start_time);
 }
 
 static struct btree_update *
@@ -921,6 +935,7 @@ bch2_btree_update_start(struct btree_trans *trans, struct btree_path *path,
 	struct bch_fs *c = trans->c;
 	struct btree_update *as;
 	struct closure cl;
+	u64 start_time = local_clock();
 	int disk_res_flags = (flags & BTREE_INSERT_NOFAIL)
 		? BCH_DISK_RESERVATION_NOFAIL : 0;
 	int journal_flags = 0;
@@ -960,6 +975,7 @@ retry:
 	memset(as, 0, sizeof(*as));
 	closure_init(&as->cl, NULL);
 	as->c		= c;
+	as->start_time	= start_time;
 	as->mode	= BTREE_INTERIOR_NO_UPDATE;
 	as->took_gc_lock = !(flags & BTREE_INSERT_GC_LOCK_HELD);
 	as->btree_id	= path->btree_id;
@@ -1452,7 +1468,9 @@ static void btree_split(struct btree_update *as, struct btree_trans *trans,
 
 	bch2_trans_verify_locks(trans);
 
-	bch2_time_stats_update(&c->times[BCH_TIME_btree_node_split],
+	bch2_time_stats_update(&c->times[n2
+			       ? BCH_TIME_btree_node_split
+			       : BCH_TIME_btree_node_compact],
 			       start_time);
 }
 
@@ -1573,6 +1591,7 @@ int __bch2_foreground_maybe_merge(struct btree_trans *trans,
 	struct btree *b, *m, *n, *prev, *next, *parent;
 	struct bpos sib_pos;
 	size_t sib_u64s;
+	u64 start_time = local_clock();
 	int ret = 0;
 
 	BUG_ON(!path->should_be_locked);
@@ -1710,6 +1729,8 @@ int __bch2_foreground_maybe_merge(struct btree_trans *trans,
 	six_unlock_intent(&n->c.lock);
 
 	bch2_btree_update_done(as);
+
+	bch2_time_stats_update(&c->times[BCH_TIME_btree_node_merge], start_time);
 out:
 err:
 	bch2_path_put(trans, sib_path, true);
diff --git a/fs/bcachefs/btree_update_interior.h b/fs/bcachefs/btree_update_interior.h
index 8e03bd987d6d..d4574161a733 100644
--- a/fs/bcachefs/btree_update_interior.h
+++ b/fs/bcachefs/btree_update_interior.h
@@ -35,6 +35,7 @@ bool bch2_btree_node_format_fits(struct bch_fs *c, struct btree *,
 struct btree_update {
 	struct closure			cl;
 	struct bch_fs			*c;
+	u64				start_time;
 
 	struct list_head		list;
 	struct list_head		unwritten_list;
diff --git a/fs/bcachefs/fs-common.c b/fs/bcachefs/fs-common.c
index 5f3429e99115..d543480be111 100644
--- a/fs/bcachefs/fs-common.c
+++ b/fs/bcachefs/fs-common.c
@@ -329,6 +329,7 @@ bool bch2_reinherit_attrs(struct bch_inode_unpacked *dst_u,
 	bool ret = false;
 
 	for (id = 0; id < Inode_opt_nr; id++) {
+		/* Skip attributes that were explicitly set on this inode */
 		if (dst_u->bi_fields_set & (1 << id))
 			continue;
 
diff --git a/fs/bcachefs/journal.c b/fs/bcachefs/journal.c
index 3ce6a78263ba..f15d265ef1b6 100644
--- a/fs/bcachefs/journal.c
+++ b/fs/bcachefs/journal.c
@@ -625,6 +625,12 @@ int bch2_journal_flush_seq(struct journal *j, u64 seq)
 	u64 start_time = local_clock();
 	int ret, ret2;
 
+	/*
+	 * Don't update time_stats when @seq is already flushed:
+	 */
+	if (seq <= j->flushed_seq_ondisk)
+		return 0;
+
 	ret = wait_event_interruptible(j->wait, (ret2 = bch2_journal_flush_seq_async(j, seq, NULL)));
 
 	if (!ret)
diff --git a/fs/bcachefs/journal_io.c b/fs/bcachefs/journal_io.c
index 680ddba1889d..1a8c0a7eaca7 100644
--- a/fs/bcachefs/journal_io.c
+++ b/fs/bcachefs/journal_io.c
@@ -1237,7 +1237,9 @@ static void journal_write_done(struct closure *cl)
 	u64 v, seq;
 	int err = 0;
 
-	bch2_time_stats_update(j->write_time, j->write_start_time);
+	bch2_time_stats_update(!JSET_NO_FLUSH(w->data)
+			       ? j->flush_write_time
+			       : j->noflush_write_time, j->write_start_time);
 
 	if (!w->devs_written.nr) {
 		bch_err(c, "unable to write journal to sufficient devices");
diff --git a/fs/bcachefs/journal_types.h b/fs/bcachefs/journal_types.h
index 9f59e4889f52..0c4df603280d 100644
--- a/fs/bcachefs/journal_types.h
+++ b/fs/bcachefs/journal_types.h
@@ -271,8 +271,8 @@ struct journal {
 	u64			nr_flush_writes;
 	u64			nr_noflush_writes;
 
-	struct bch2_time_stats	*write_time;
-	struct bch2_time_stats	*delay_time;
+	struct bch2_time_stats	*flush_write_time;
+	struct bch2_time_stats	*noflush_write_time;
 	struct bch2_time_stats	*blocked_time;
 	struct bch2_time_stats	*flush_seq_time;
 
diff --git a/fs/bcachefs/opts.h b/fs/bcachefs/opts.h
index aad57a82e5fd..bb2ecc778a8c 100644
--- a/fs/bcachefs/opts.h
+++ b/fs/bcachefs/opts.h
@@ -81,9 +81,9 @@ enum opt_type {
  */
 
 #ifdef __KERNEL__
-#define RATELIMIT_ERRORS true
+#define RATELIMIT_ERRORS_DEFAULT true
 #else
-#define RATELIMIT_ERRORS false
+#define RATELIMIT_ERRORS_DEFAULT false
 #endif
 
 #define BCH_OPTS()							\
@@ -288,7 +288,7 @@ enum opt_type {
 	x(ratelimit_errors,		u8,				\
 	  OPT_FS|OPT_MOUNT,						\
 	  OPT_BOOL(),							\
-	  NO_SB_OPT,			RATELIMIT_ERRORS,		\
+	  NO_SB_OPT,			RATELIMIT_ERRORS_DEFAULT,	\
 	  NULL,		"Ratelimit error messages during fsck")		\
 	x(nochanges,			u8,				\
 	  OPT_FS|OPT_MOUNT,						\
diff --git a/fs/bcachefs/super.c b/fs/bcachefs/super.c
index 22dbbf77d687..afa1a8fa493b 100644
--- a/fs/bcachefs/super.c
+++ b/fs/bcachefs/super.c
@@ -730,10 +730,10 @@ static struct bch_fs *bch2_fs_alloc(struct bch_sb *sb, struct bch_opts opts)
 	c->rebalance.enabled		= 1;
 	c->promote_whole_extents	= true;
 
-	c->journal.write_time	= &c->times[BCH_TIME_journal_write];
-	c->journal.delay_time	= &c->times[BCH_TIME_journal_delay];
-	c->journal.blocked_time	= &c->times[BCH_TIME_blocked_journal];
-	c->journal.flush_seq_time = &c->times[BCH_TIME_journal_flush_seq];
+	c->journal.flush_write_time	= &c->times[BCH_TIME_journal_flush_write];
+	c->journal.noflush_write_time	= &c->times[BCH_TIME_journal_noflush_write];
+	c->journal.blocked_time		= &c->times[BCH_TIME_blocked_journal];
+	c->journal.flush_seq_time	= &c->times[BCH_TIME_journal_flush_seq];
 
 	bch2_fs_btree_cache_init_early(&c->btree_cache);