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 fee1fc58e13b..5c01f0564752 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 a36b0e60077e..91c69a9f96ae 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 dfff972551ee..d895d4eff0a9 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 268f3ea4bdd2..ff8b81fa6772 100644
--- a/fs/bcachefs/journal.c
+++ b/fs/bcachefs/journal.c
@@ -626,6 +626,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 37abfb1885a6..80e0dd311ffd 100644
--- a/fs/bcachefs/journal_io.c
+++ b/fs/bcachefs/journal_io.c
@@ -1238,7 +1238,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 66b1707a6697..54cc69bde1bb 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 time_stats	*write_time;
-	struct time_stats	*delay_time;
+	struct time_stats	*flush_write_time;
+	struct time_stats	*noflush_write_time;
 	struct time_stats	*blocked_time;
 	struct time_stats	*flush_seq_time;
 
diff --git a/fs/bcachefs/opts.h b/fs/bcachefs/opts.h
index e2eb9b3fb275..871142778763 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 f673efed2f47..505e559b48a6 100644
--- a/fs/bcachefs/super.c
+++ b/fs/bcachefs/super.c
@@ -722,10 +722,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);