[PATCH] btrfs: track current commit duration in commit_stats

[PATCH] btrfs: track current commit duration in commit_stats

[Boris Burkov]

When debugging/detecting outlier commit stalls, having an indicator that
we are currently in a long commit critical section can be very useful.
Extend the commit_stats sysfs file to also include the current commit
critical section duration.

Since this requires storing the last commit start time, use that rather
than a separate stack variable for storing the finished commit durations
as well.

Signed-off-by: Boris Burkov <boris@bur.io>
---
 fs/btrfs/fs.h          |  2 ++
 fs/btrfs/sysfs.c       |  8 ++++++++
 fs/btrfs/transaction.c | 17 +++++++++--------
 3 files changed, 19 insertions(+), 8 deletions(-)

diff --git a/fs/btrfs/fs.h b/fs/btrfs/fs.h
index bcca43046064..1f375170cdcb 100644
--- a/fs/btrfs/fs.h
+++ b/fs/btrfs/fs.h
@@ -419,6 +419,8 @@ struct btrfs_commit_stats {
 	u64 last_commit_dur;
 	/* The total commit duration in ns */
 	u64 total_commit_dur;
+	/* Start of the last critical section in ns. */
+	u64 start_time;
 };
 
 struct btrfs_fs_info {
diff --git a/fs/btrfs/sysfs.c b/fs/btrfs/sysfs.c
index b9af74498b0c..4e35b4bfffaa 100644
--- a/fs/btrfs/sysfs.c
+++ b/fs/btrfs/sysfs.c
@@ -1138,13 +1138,21 @@ static ssize_t btrfs_commit_stats_show(struct kobject *kobj,
 				       struct kobj_attribute *a, char *buf)
 {
 	struct btrfs_fs_info *fs_info = to_fs_info(kobj);
+	u64 now = ktime_get_ns();
+	u64 start_time = fs_info->commit_stats.start_time;
+	u64 pending = 0;
+
+	if (start_time)
+		pending = now - start_time;
 
 	return sysfs_emit(buf,
 		"commits %llu\n"
+		"cur_commit_ms %llu\n"
 		"last_commit_ms %llu\n"
 		"max_commit_ms %llu\n"
 		"total_commit_ms %llu\n",
 		fs_info->commit_stats.commit_count,
+		div_u64(pending, NSEC_PER_MSEC),
 		div_u64(fs_info->commit_stats.last_commit_dur, NSEC_PER_MSEC),
 		div_u64(fs_info->commit_stats.max_commit_dur, NSEC_PER_MSEC),
 		div_u64(fs_info->commit_stats.total_commit_dur, NSEC_PER_MSEC));
diff --git a/fs/btrfs/transaction.c b/fs/btrfs/transaction.c
index 39e48bf610a1..02e6926d53bd 100644
--- a/fs/btrfs/transaction.c
+++ b/fs/btrfs/transaction.c
@@ -2164,13 +2164,19 @@ static void add_pending_snapshot(struct btrfs_trans_handle *trans)
 	list_add(&trans->pending_snapshot->list, &cur_trans->pending_snapshots);
 }
 
-static void update_commit_stats(struct btrfs_fs_info *fs_info, ktime_t interval)
+static void update_commit_stats(struct btrfs_fs_info *fs_info)
 {
+	ktime_t now = ktime_get_ns();
+	ktime_t interval = now - fs_info->commit_stats.start_time;
+
+	ASSERT(fs_info->commit_stats.start_time);
+
 	fs_info->commit_stats.commit_count++;
 	fs_info->commit_stats.last_commit_dur = interval;
 	fs_info->commit_stats.max_commit_dur =
 			max_t(u64, fs_info->commit_stats.max_commit_dur, interval);
 	fs_info->commit_stats.total_commit_dur += interval;
+	fs_info->commit_stats.start_time = 0;
 }
 
 int btrfs_commit_transaction(struct btrfs_trans_handle *trans)
@@ -2179,8 +2185,6 @@ int btrfs_commit_transaction(struct btrfs_trans_handle *trans)
 	struct btrfs_transaction *cur_trans = trans->transaction;
 	struct btrfs_transaction *prev_trans = NULL;
 	int ret;
-	ktime_t start_time;
-	ktime_t interval;
 
 	ASSERT(refcount_read(&trans->use_count) == 1);
 	btrfs_trans_state_lockdep_acquire(fs_info, BTRFS_LOCKDEP_TRANS_COMMIT_PREP);
@@ -2314,7 +2318,7 @@ int btrfs_commit_transaction(struct btrfs_trans_handle *trans)
 	 * Get the time spent on the work done by the commit thread and not
 	 * the time spent waiting on a previous commit
 	 */
-	start_time = ktime_get_ns();
+	fs_info->commit_stats.start_time = ktime_get_ns();
 
 	extwriter_counter_dec(cur_trans, trans->type);
 
@@ -2568,6 +2572,7 @@ int btrfs_commit_transaction(struct btrfs_trans_handle *trans)
 	cur_trans->state = TRANS_STATE_COMPLETED;
 	wake_up(&cur_trans->commit_wait);
 	btrfs_trans_state_lockdep_release(fs_info, BTRFS_LOCKDEP_TRANS_COMPLETED);
+	update_commit_stats(fs_info);
 
 	spin_lock(&fs_info->trans_lock);
 	list_del_init(&cur_trans->list);
@@ -2581,8 +2586,6 @@ int btrfs_commit_transaction(struct btrfs_trans_handle *trans)
 
 	trace_btrfs_transaction_commit(fs_info);
 
-	interval = ktime_get_ns() - start_time;
-
 	btrfs_scrub_continue(fs_info);
 
 	if (current->journal_info == trans)
@@ -2590,8 +2593,6 @@ int btrfs_commit_transaction(struct btrfs_trans_handle *trans)
 
 	kmem_cache_free(btrfs_trans_handle_cachep, trans);
 
-	update_commit_stats(fs_info, interval);
-
 	return ret;
 
 unlock_reloc:
-- 
2.49.0

Re: [PATCH] btrfs: track current commit duration in commit_stats

[David Sterba]

On Thu, Apr 24, 2025 at 04:56:34PM -0700, Boris Burkov wrote:
> When debugging/detecting outlier commit stalls, having an indicator that
> we are currently in a long commit critical section can be very useful.
> Extend the commit_stats sysfs file to also include the current commit
> critical section duration.
> 
> Since this requires storing the last commit start time, use that rather
> than a separate stack variable for storing the finished commit durations
> as well.
> 
> Signed-off-by: Boris Burkov <boris@bur.io>

Reviewed-by: David Sterba <dsterba@suse.com>

> --- a/fs/btrfs/sysfs.c
> +++ b/fs/btrfs/sysfs.c
> @@ -1138,13 +1138,21 @@ static ssize_t btrfs_commit_stats_show(struct kobject *kobj,
>  				       struct kobj_attribute *a, char *buf)
>  {
>  	struct btrfs_fs_info *fs_info = to_fs_info(kobj);
> +	u64 now = ktime_get_ns();
> +	u64 start_time = fs_info->commit_stats.start_time;
> +	u64 pending = 0;
> +
> +	if (start_time)
> +		pending = now - start_time;
>  
>  	return sysfs_emit(buf,
>  		"commits %llu\n"
> +		"cur_commit_ms %llu\n"
>  		"last_commit_ms %llu\n"
>  		"max_commit_ms %llu\n"
>  		"total_commit_ms %llu\n",

This ordering looks logical, the presence of order should not be assumed
by applications, this is line oriented so a grep should always work.

>  		fs_info->commit_stats.commit_count,
> +		div_u64(pending, NSEC_PER_MSEC),
>  		div_u64(fs_info->commit_stats.last_commit_dur, NSEC_PER_MSEC),
>  		div_u64(fs_info->commit_stats.max_commit_dur, NSEC_PER_MSEC),
>  		div_u64(fs_info->commit_stats.total_commit_dur, NSEC_PER_MSEC));

Re: [PATCH] btrfs: track current commit duration in commit_stats

[David Sterba]

On Thu, Apr 24, 2025 at 04:56:34PM -0700, Boris Burkov wrote:
> When debugging/detecting outlier commit stalls, having an indicator that
> we are currently in a long commit critical section can be very useful.
> Extend the commit_stats sysfs file to also include the current commit
> critical section duration.
> 
> Since this requires storing the last commit start time, use that rather
> than a separate stack variable for storing the finished commit durations
> as well.
> 
> Signed-off-by: Boris Burkov <boris@bur.io>
> ---
>  fs/btrfs/fs.h          |  2 ++
>  fs/btrfs/sysfs.c       |  8 ++++++++
>  fs/btrfs/transaction.c | 17 +++++++++--------
>  3 files changed, 19 insertions(+), 8 deletions(-)
> 
> diff --git a/fs/btrfs/fs.h b/fs/btrfs/fs.h
> index bcca43046064..1f375170cdcb 100644
> --- a/fs/btrfs/fs.h
> +++ b/fs/btrfs/fs.h
> @@ -419,6 +419,8 @@ struct btrfs_commit_stats {
>  	u64 last_commit_dur;
>  	/* The total commit duration in ns */
>  	u64 total_commit_dur;
> +	/* Start of the last critical section in ns. */
> +	u64 start_time;
>  };
>  
>  struct btrfs_fs_info {
> diff --git a/fs/btrfs/sysfs.c b/fs/btrfs/sysfs.c
> index b9af74498b0c..4e35b4bfffaa 100644
> --- a/fs/btrfs/sysfs.c
> +++ b/fs/btrfs/sysfs.c
> @@ -1138,13 +1138,21 @@ static ssize_t btrfs_commit_stats_show(struct kobject *kobj,
>  				       struct kobj_attribute *a, char *buf)
>  {
>  	struct btrfs_fs_info *fs_info = to_fs_info(kobj);
> +	u64 now = ktime_get_ns();
> +	u64 start_time = fs_info->commit_stats.start_time;
> +	u64 pending = 0;
> +
> +	if (start_time)
> +		pending = now - start_time;
>  
>  	return sysfs_emit(buf,
>  		"commits %llu\n"
> +		"cur_commit_ms %llu\n"
>  		"last_commit_ms %llu\n"
>  		"max_commit_ms %llu\n"
>  		"total_commit_ms %llu\n",
>  		fs_info->commit_stats.commit_count,
> +		div_u64(pending, NSEC_PER_MSEC),
>  		div_u64(fs_info->commit_stats.last_commit_dur, NSEC_PER_MSEC),
>  		div_u64(fs_info->commit_stats.max_commit_dur, NSEC_PER_MSEC),
>  		div_u64(fs_info->commit_stats.total_commit_dur, NSEC_PER_MSEC));
> diff --git a/fs/btrfs/transaction.c b/fs/btrfs/transaction.c
> index 39e48bf610a1..02e6926d53bd 100644
> --- a/fs/btrfs/transaction.c
> +++ b/fs/btrfs/transaction.c
> @@ -2164,13 +2164,19 @@ static void add_pending_snapshot(struct btrfs_trans_handle *trans)
>  	list_add(&trans->pending_snapshot->list, &cur_trans->pending_snapshots);
>  }
>  
> -static void update_commit_stats(struct btrfs_fs_info *fs_info, ktime_t interval)
> +static void update_commit_stats(struct btrfs_fs_info *fs_info)
>  {
> +	ktime_t now = ktime_get_ns();
> +	ktime_t interval = now - fs_info->commit_stats.start_time;
> +
> +	ASSERT(fs_info->commit_stats.start_time);

[ 2469.533069] assertion failed: fs_info->commit_stats.start_time :: 0, in fs/btrfs/transaction.c:2172
[ 2469.536071] ------------[ cut here ]------------
[ 2469.537543] kernel BUG at fs/btrfs/transaction.c:2172!
[ 2469.539158] Oops: invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC KASAN
[ 2469.541112] CPU: 11 UID: 0 PID: 4140 Comm: fsstress Not tainted 6.15.0-rc4-default+ #109 PREEMPT(full) 
[ 2469.543907] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.2-3-gd478f380-rebuilt.opensuse.org 04/01/2014
[ 2469.547238] RIP: 0010:btrfs_commit_transaction.cold+0x126/0x1dd [btrfs]
[ 2469.554618] RSP: 0018:ffff8880059dfc58 EFLAGS: 00010282
[ 2469.556210] RAX: 0000000000000057 RBX: ffff888006414000 RCX: 0000000000000000
[ 2469.558319] RDX: 0000000000000057 RSI: 0000000000000004 RDI: ffffed1000b3bf7e
[ 2469.560427] RBP: 0000000000000000 R08: 0000000000000000 R09: fffffbfff54e5f34
[ 2469.562575] R10: 0000000000000003 R11: 0000000000000001 R12: ffff88800374e800
[ 2469.564682] R13: 0000023eedb59554 R14: ffff88800374e8f8 R15: ffff88800b01a948
[ 2469.566788] FS:  00007f590f740180(0000) GS:ffff8880bab98000(0000) knlGS:0000000000000000
[ 2469.569219] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2469.570971] CR2: 00007f416fd9e038 CR3: 000000001f3ee000 CR4: 00000000000006b0
[ 2469.573076] Call Trace:
[ 2469.573954]  <TASK>
[ 2469.574737]  ? cleanup_transaction+0x1a0/0x1a0 [btrfs]
[ 2469.576421]  ? __lock_release.isra.0+0xc1/0x2e0
[ 2469.577847]  ? preempt_count_add+0x79/0x150
[ 2469.579171]  ? __up_write+0x1b3/0x520
[ 2469.580377]  ? btrfs_sync_file+0xb4b/0xd30 [btrfs]
[ 2469.581961]  btrfs_sync_file+0x740/0xd30 [btrfs]
[ 2469.583507]  ? start_ordered_ops.constprop.0+0x100/0x100 [btrfs]
[ 2469.585406]  do_fsync+0x39/0x70
[ 2469.586475]  __x64_sys_fsync+0x2e/0x40
[ 2469.587693]  do_syscall_64+0x6d/0x140
[ 2469.588894]  entry_SYSCALL_64_after_hwframe+0x4b/0x53
[ 2469.590461] RIP: 0033:0x7f590f853874
[ 2469.591626] Code: 00 e9 a0 5b f1 ff 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 90 90 80 3d 35 81 0f 00 00 74 13 b8 4a 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 44 c3 0f 1f 00 48 83 ec 18 89 7c 24 0c e8 b1
[ 2469.596956] RSP: 002b:00007fffe09524d8 EFLAGS: 00000202 ORIG_RAX: 000000000000004a
[ 2469.599242] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007f590f853874
[ 2469.601341] RDX: 0000000000000103 RSI: 0000000000411059 RDI: 0000000000000004
[ 2469.603429] RBP: 0000000000001049 R08: fefefefefefefeff R09: 00007fffe09524ec
[ 2469.605525] R10: 0000000000000000 R11: 0000000000000202 R12: 00007fffe09524f0
[ 2469.607631] R13: 0000000000000000 R14: 00007fffe0952590 R15: 000000000040cdc0
[ 2469.609742]  </TASK>
[ 2469.610552] Modules linked in: btrfs blake2b_generic xor lzo_compress lzo_decompress raid6_pq zstd_decompress zstd_compress zstd_common xxhash loop
[ 2469.614356] ---[ end trace 0000000000000000 ]---
[ 2469.615800] RIP: 0010:btrfs_commit_transaction.cold+0x126/0x1dd [btrfs]
[ 2469.623202] RSP: 0018:ffff8880059dfc58 EFLAGS: 00010282
[ 2469.624798] RAX: 0000000000000057 RBX: ffff888006414000 RCX: 0000000000000000
[ 2469.626912] RDX: 0000000000000057 RSI: 0000000000000004 RDI: ffffed1000b3bf7e
[ 2469.629000] RBP: 0000000000000000 R08: 0000000000000000 R09: fffffbfff54e5f34
[ 2469.631125] R10: 0000000000000003 R11: 0000000000000001 R12: ffff88800374e800
[ 2469.633231] R13: 0000023eedb59554 R14: ffff88800374e8f8 R15: ffff88800b01a948
[ 2469.635350] FS:  00007f590f740180(0000) GS:ffff8880bab98000(0000) knlGS:0000000000000000
[ 2469.637818] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2469.639568] CR2: 00007f416fd9e038 CR3: 000000001f3ee000 CR4: 00000000000006b0

Re: [PATCH] btrfs: track current commit duration in commit_stats

[David Sterba]

On Tue, Apr 29, 2025 at 10:27:11AM +0200, David Sterba wrote:
> On Thu, Apr 24, 2025 at 04:56:34PM -0700, Boris Burkov wrote:
> > When debugging/detecting outlier commit stalls, having an indicator that
> > we are currently in a long commit critical section can be very useful.
> > Extend the commit_stats sysfs file to also include the current commit
> > critical section duration.
> > 
> > Since this requires storing the last commit start time, use that rather
> > than a separate stack variable for storing the finished commit durations
> > as well.
> > 
> > Signed-off-by: Boris Burkov <boris@bur.io>
> > ---
> >  fs/btrfs/fs.h          |  2 ++
> >  fs/btrfs/sysfs.c       |  8 ++++++++
> >  fs/btrfs/transaction.c | 17 +++++++++--------
> >  3 files changed, 19 insertions(+), 8 deletions(-)
> > 
> > diff --git a/fs/btrfs/fs.h b/fs/btrfs/fs.h
> > index bcca43046064..1f375170cdcb 100644
> > --- a/fs/btrfs/fs.h
> > +++ b/fs/btrfs/fs.h
> > @@ -419,6 +419,8 @@ struct btrfs_commit_stats {
> >  	u64 last_commit_dur;
> >  	/* The total commit duration in ns */
> >  	u64 total_commit_dur;
> > +	/* Start of the last critical section in ns. */
> > +	u64 start_time;
> >  };
> >  
> >  struct btrfs_fs_info {
> > diff --git a/fs/btrfs/sysfs.c b/fs/btrfs/sysfs.c
> > index b9af74498b0c..4e35b4bfffaa 100644
> > --- a/fs/btrfs/sysfs.c
> > +++ b/fs/btrfs/sysfs.c
> > @@ -1138,13 +1138,21 @@ static ssize_t btrfs_commit_stats_show(struct kobject *kobj,
> >  				       struct kobj_attribute *a, char *buf)
> >  {
> >  	struct btrfs_fs_info *fs_info = to_fs_info(kobj);
> > +	u64 now = ktime_get_ns();
> > +	u64 start_time = fs_info->commit_stats.start_time;
> > +	u64 pending = 0;
> > +
> > +	if (start_time)
> > +		pending = now - start_time;
> >  
> >  	return sysfs_emit(buf,
> >  		"commits %llu\n"
> > +		"cur_commit_ms %llu\n"
> >  		"last_commit_ms %llu\n"
> >  		"max_commit_ms %llu\n"
> >  		"total_commit_ms %llu\n",
> >  		fs_info->commit_stats.commit_count,
> > +		div_u64(pending, NSEC_PER_MSEC),
> >  		div_u64(fs_info->commit_stats.last_commit_dur, NSEC_PER_MSEC),
> >  		div_u64(fs_info->commit_stats.max_commit_dur, NSEC_PER_MSEC),
> >  		div_u64(fs_info->commit_stats.total_commit_dur, NSEC_PER_MSEC));
> > diff --git a/fs/btrfs/transaction.c b/fs/btrfs/transaction.c
> > index 39e48bf610a1..02e6926d53bd 100644
> > --- a/fs/btrfs/transaction.c
> > +++ b/fs/btrfs/transaction.c
> > @@ -2164,13 +2164,19 @@ static void add_pending_snapshot(struct btrfs_trans_handle *trans)
> >  	list_add(&trans->pending_snapshot->list, &cur_trans->pending_snapshots);
> >  }
> >  
> > -static void update_commit_stats(struct btrfs_fs_info *fs_info, ktime_t interval)
> > +static void update_commit_stats(struct btrfs_fs_info *fs_info)
> >  {
> > +	ktime_t now = ktime_get_ns();
> > +	ktime_t interval = now - fs_info->commit_stats.start_time;
> > +
> > +	ASSERT(fs_info->commit_stats.start_time);
> 
> [ 2469.533069] assertion failed: fs_info->commit_stats.start_time :: 0, in fs/btrfs/transaction.c:2172

Quite reliably (2/2) in btrfs/028 so I'll remove the patch from
for-next for now.