[PATCH v2 0/4] btrfs: output more info for -ENOSPC caused transaction abort and other enhancement

[PATCH v2 0/4] btrfs: output more info for -ENOSPC caused transaction abort and other enhancement

[Qu Wenruo]

[Changelog]
v2:
- Add a new line to show the meaning of the metadata dump.
  Previous output only includes the reserved bytes and size bytes,
  but not showing which is which, thus still need to check the code

We have some internal reports of transaction abort with -ENOSPC.

Unfortunately it's really hard to debug, since we really got nothing
other than the error message for most cases.

Also we have helpers like __btrfs_dump_space_info(), it needs enospc_debug
mount option which only makes sense if the user can reproduce the bug
and retry with that mount option.

Considering ENOSPC should not happen for critical paths which failure
means transaction abort, we should dump all space info for debug purpose
if the transaction arbot is caused by -ENOSPC.

And since we're here, also enhance the output of
__btrfs_dump_space_info().

Now it should be more human readable, the exmaple would look like this:

 BTRFS info (device dm-1: state A): dumpping space info:
 BTRFS info (device dm-1: state A): space_info DATA has 1175552 free, is not full
 BTRFS info (device dm-1: state A):   total:         8388608
 BTRFS info (device dm-1: state A):   used:          7163904
 BTRFS info (device dm-1: state A):   pinned:        49152
 BTRFS info (device dm-1: state A):   reserved:      0
 BTRFS info (device dm-1: state A):   may_use:       0
 BTRFS info (device dm-1: state A):   read_only:     0
 BTRFS info (device dm-1: state A): space_info META has 263798784 free, is not full
 BTRFS info (device dm-1: state A):   total:         268435456
 BTRFS info (device dm-1: state A):   used:          180224
 BTRFS info (device dm-1: state A):   pinned:        196608
 BTRFS info (device dm-1: state A):   reserved:      0
 BTRFS info (device dm-1: state A):   may_use:       4194304
 BTRFS info (device dm-1: state A):   read_only:     65536
 BTRFS info (device dm-1: state A): space_info SYS has 8372224 free, is not full
 BTRFS info (device dm-1: state A):   total:         8388608
 BTRFS info (device dm-1: state A):   used:          16384
 BTRFS info (device dm-1: state A):   pinned:        0
 BTRFS info (device dm-1: state A):   reserved:      0
 BTRFS info (device dm-1: state A):   may_use:       0
 BTRFS info (device dm-1: state A):   read_only:     0
 BTRFS info (device dm-1: state A): dumpping metadata reservation:
 BTRFS info (device dm-1: state A):   global:          (3670016/3670016)
 BTRFS info (device dm-1: state A):   trans:           (0/0)
 BTRFS info (device dm-1: state A):   chuunk:          (0/0)
 BTRFS info (device dm-1: state A):   delayed_inode:   (0/0)
 BTRFS info (device dm-1: state A):   delayed_refs:    (524288/524288)
 BTRFS: error (device dm-1: state A) in cleanup_transaction:1971: errno=-28 No space left
 BTRFS info (device dm-1: state EA): forced readonly


Qu Wenruo (4):
  btrfs: output human readable space info flag
  btrfs: make __btrfs_dump_space_info() output better formatted
  btrfs: make DUMP_BLOCK_RSV() to have better output
  btrfs: dump all space infos if we abort transaction due to ENOSPC

 fs/btrfs/ctree.h      |  6 ++--
 fs/btrfs/space-info.c | 72 +++++++++++++++++++++++++++++++++----------
 fs/btrfs/space-info.h |  2 ++
 fs/btrfs/super.c      |  4 ++-
 4 files changed, 64 insertions(+), 20 deletions(-)

-- 
2.37.0

[PATCH v2 1/4] btrfs: output human readable space info flag

[Qu Wenruo]

For btrfs_space_info, its flags has only 4 possible values:
- BTRFS_BLOCK_GROUP_SYSTEM
- BTRFS_BLOCK_GROUP_METADATA | BTRFS_BLOCK_GROUP_DATA
- BTRFS_BLOCK_GROUP_METADATA
- BTRFS_BLOCK_GROUP_DATA

Thus do debuggers a favor by output a human readable flags in
__btrfs_dump_space_info().

Now the summary line of __btrfs_dump_space_info() looks like:

 BTRFS info (device dm-1: state A): space_info META has 251494400 free, is not full

Signed-off-by: Qu Wenruo <wqu@suse.com>
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
---
 fs/btrfs/space-info.c | 19 +++++++++++++++++--
 1 file changed, 17 insertions(+), 2 deletions(-)

diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
index 62d25112310d..36b466525318 100644
--- a/fs/btrfs/space-info.c
+++ b/fs/btrfs/space-info.c
@@ -450,14 +450,29 @@ do {									\
 	spin_unlock(&__rsv->lock);					\
 } while (0)
 
+static const char *space_info_flag_to_str(struct btrfs_space_info *space_info)
+{
+	if (space_info->flags == BTRFS_BLOCK_GROUP_SYSTEM)
+		return "SYS";
+
+	/* Handle mixed data+metadata first. */
+	if (space_info->flags == (BTRFS_BLOCK_GROUP_METADATA |
+				  BTRFS_BLOCK_GROUP_DATA))
+		return "DATA+META";
+	if (space_info->flags == BTRFS_BLOCK_GROUP_DATA)
+		return "DATA";
+	return "META";
+}
+
 static void __btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
 				    struct btrfs_space_info *info)
 {
+	const char *flag_str = space_info_flag_to_str(info);
 	lockdep_assert_held(&info->lock);
 
 	/* The free space could be negative in case of overcommit */
-	btrfs_info(fs_info, "space_info %llu has %lld free, is %sfull",
-		   info->flags,
+	btrfs_info(fs_info, "space_info %s has %lld free, is %sfull",
+		   flag_str,
 		   (s64)(info->total_bytes - btrfs_space_info_used(info, true)),
 		   info->full ? "" : "not ");
 	btrfs_info(fs_info,
-- 
2.37.0

Re: [PATCH v2 1/4] btrfs: output human readable space info flag

[Sweet Tea Dorminy]

On 7/19/22 01:11, Qu Wenruo wrote:
> For btrfs_space_info, its flags has only 4 possible values:
> - BTRFS_BLOCK_GROUP_SYSTEM
> - BTRFS_BLOCK_GROUP_METADATA | BTRFS_BLOCK_GROUP_DATA
> - BTRFS_BLOCK_GROUP_METADATA
> - BTRFS_BLOCK_GROUP_DATA
> 
> Thus do debuggers a favor by output a human readable flags in
> __btrfs_dump_space_info().
> 
> Now the summary line of __btrfs_dump_space_info() looks like:
> 
>   BTRFS info (device dm-1: state A): space_info META has 251494400 free, is not full
> 
> Signed-off-by: Qu Wenruo <wqu@suse.com>
> Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
> ---
>   fs/btrfs/space-info.c | 19 +++++++++++++++++--
>   1 file changed, 17 insertions(+), 2 deletions(-)
> 
> diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
> index 62d25112310d..36b466525318 100644
> --- a/fs/btrfs/space-info.c
> +++ b/fs/btrfs/space-info.c
> @@ -450,14 +450,29 @@ do {									\
>   	spin_unlock(&__rsv->lock);					\
>   } while (0)
>   
> +static const char *space_info_flag_to_str(struct btrfs_space_info *space_info)
> +{
> +	if (space_info->flags == BTRFS_BLOCK_GROUP_SYSTEM)
> +		return "SYS";
> +
> +	/* Handle mixed data+metadata first. */
> +	if (space_info->flags == (BTRFS_BLOCK_GROUP_METADATA |
> +				  BTRFS_BLOCK_GROUP_DATA))
> +		return "DATA+META";
> +	if (space_info->flags == BTRFS_BLOCK_GROUP_DATA)
> +		return "DATA";
> +	return "META";
> +}

I think this would be more elegant as a switch statement; and would 
prefer the default to be "UNKNOWN" just in case there were a flag 
bitflip.   +
>   static void __btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
>   				    struct btrfs_space_info *info)
>   {
> +	const char *flag_str = space_info_flag_to_str(info);
>   	lockdep_assert_held(&info->lock);
>   
>   	/* The free space could be negative in case of overcommit */
> -	btrfs_info(fs_info, "space_info %llu has %lld free, is %sfull",
> -		   info->flags,
> +	btrfs_info(fs_info, "space_info %s has %lld free, is %sfull",
> +		   flag_str,
>   		   (s64)(info->total_bytes - btrfs_space_info_used(info, true)),
>   		   info->full ? "" : "not ");
>   	btrfs_info(fs_info,

[PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Qu Wenruo]

The format change includes:

- Output each bytes_* in a separate line

- All bytes_* output starts at the same vertical position
  Do human a favor reading the numbers

- Skip zone specific numbers if zone is not enabled

Now one example of __btrfs_dump_space_info() looks like this for its
bytes_* members.

 BTRFS info (device dm-1: state A): space_info META has 251494400 free, is not full
 BTRFS info (device dm-1: state A):   total:         268435456
 BTRFS info (device dm-1: state A):   used:          376832
 BTRFS info (device dm-1: state A):   pinned:        229376
 BTRFS info (device dm-1: state A):   reserved:      0
 BTRFS info (device dm-1: state A):   may_use:       16269312
 BTRFS info (device dm-1: state A):   read_only:     65536

Signed-off-by: Qu Wenruo <wqu@suse.com>
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
---
 fs/btrfs/space-info.c | 14 +++++++++-----
 1 file changed, 9 insertions(+), 5 deletions(-)

diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
index 36b466525318..623fa0488545 100644
--- a/fs/btrfs/space-info.c
+++ b/fs/btrfs/space-info.c
@@ -475,11 +475,15 @@ static void __btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
 		   flag_str,
 		   (s64)(info->total_bytes - btrfs_space_info_used(info, true)),
 		   info->full ? "" : "not ");
-	btrfs_info(fs_info,
-		"space_info total=%llu, used=%llu, pinned=%llu, reserved=%llu, may_use=%llu, readonly=%llu zone_unusable=%llu",
-		info->total_bytes, info->bytes_used, info->bytes_pinned,
-		info->bytes_reserved, info->bytes_may_use,
-		info->bytes_readonly, info->bytes_zone_unusable);
+	btrfs_info(fs_info, "  total:         %llu", info->total_bytes);
+	btrfs_info(fs_info, "  used:          %llu", info->bytes_used);
+	btrfs_info(fs_info, "  pinned:        %llu", info->bytes_pinned);
+	btrfs_info(fs_info, "  reserved:      %llu", info->bytes_reserved);
+	btrfs_info(fs_info, "  may_use:       %llu", info->bytes_may_use);
+	btrfs_info(fs_info, "  read_only:     %llu", info->bytes_readonly);
+	if (btrfs_is_zoned(fs_info))
+		btrfs_info(fs_info,
+			    "  zone_unusable: %llu", info->bytes_zone_unusable);
 
 	DUMP_BLOCK_RSV(fs_info, global_block_rsv);
 	DUMP_BLOCK_RSV(fs_info, trans_block_rsv);
-- 
2.37.0

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Sweet Tea Dorminy]

On 7/19/22 01:11, Qu Wenruo wrote:
> The format change includes:
> 
> - Output each bytes_* in a separate line
> 
> - All bytes_* output starts at the same vertical position
>    Do human a favor reading the numbers
> 
> - Skip zone specific numbers if zone is not enabled
> 
> Now one example of __btrfs_dump_space_info() looks like this for its
> bytes_* members.
> 
>   BTRFS info (device dm-1: state A): space_info META has 251494400 free, is not full
>   BTRFS info (device dm-1: state A):   total:         268435456
>   BTRFS info (device dm-1: state A):   used:          376832
>   BTRFS info (device dm-1: state A):   pinned:        229376
>   BTRFS info (device dm-1: state A):   reserved:      0
>   BTRFS info (device dm-1: state A):   may_use:       16269312
>   BTRFS info (device dm-1: state A):   read_only:     65536
> 
> Signed-off-by: Qu Wenruo <wqu@suse.com>
> Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
> ---
>   fs/btrfs/space-info.c | 14 +++++++++-----
>   1 file changed, 9 insertions(+), 5 deletions(-)
> 
> diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
> index 36b466525318..623fa0488545 100644
> --- a/fs/btrfs/space-info.c
> +++ b/fs/btrfs/space-info.c
> @@ -475,11 +475,15 @@ static void __btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
>   		   flag_str,
>   		   (s64)(info->total_bytes - btrfs_space_info_used(info, true)),
>   		   info->full ? "" : "not ");
> -	btrfs_info(fs_info,
> -		"space_info total=%llu, used=%llu, pinned=%llu, reserved=%llu, may_use=%llu, readonly=%llu zone_unusable=%llu",
> -		info->total_bytes, info->bytes_used, info->bytes_pinned,
> -		info->bytes_reserved, info->bytes_may_use,
> -		info->bytes_readonly, info->bytes_zone_unusable);
> +	btrfs_info(fs_info, "  total:         %llu", info->total_bytes);
> +	btrfs_info(fs_info, "  used:          %llu", info->bytes_used);
> +	btrfs_info(fs_info, "  pinned:        %llu", info->bytes_pinned);
> +	btrfs_info(fs_info, "  reserved:      %llu", info->bytes_reserved);
> +	btrfs_info(fs_info, "  may_use:       %llu", info->bytes_may_use);
> +	btrfs_info(fs_info, "  read_only:     %llu", info->bytes_readonly);
> +	if (btrfs_is_zoned(fs_info))
> +		btrfs_info(fs_info,
> +			    "  zone_unusable: %llu", info->bytes_zone_unusable);

I'm (perhaps needlessly) worried about splitting this up into six/seven 
messages, because of the ratelimiting rolled into btrfs_printk. The 
ratelimit is 100 messages per 5 * HZ, and it seems like it would be 
unfortunate if it kicked in during the middle of this dump and prevented 
later info from being dumped.

Maybe we should add a btrfs_dump_printk() helper that doesn't have a 
ratelimit built in, for exceptional cases like this where we really, 
really don't want anything ratelimited?


>   
>   	DUMP_BLOCK_RSV(fs_info, global_block_rsv);
>   	DUMP_BLOCK_RSV(fs_info, trans_block_rsv);

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[David Sterba]

On Tue, Jul 19, 2022 at 04:56:00PM -0400, Sweet Tea Dorminy wrote:
> On 7/19/22 01:11, Qu Wenruo wrote:
> > 
> > diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
> > index 36b466525318..623fa0488545 100644
> > --- a/fs/btrfs/space-info.c
> > +++ b/fs/btrfs/space-info.c
> > @@ -475,11 +475,15 @@ static void __btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
> >   		   flag_str,
> >   		   (s64)(info->total_bytes - btrfs_space_info_used(info, true)),
> >   		   info->full ? "" : "not ");
> > -	btrfs_info(fs_info,
> > -		"space_info total=%llu, used=%llu, pinned=%llu, reserved=%llu, may_use=%llu, readonly=%llu zone_unusable=%llu",
> > -		info->total_bytes, info->bytes_used, info->bytes_pinned,
> > -		info->bytes_reserved, info->bytes_may_use,
> > -		info->bytes_readonly, info->bytes_zone_unusable);
> > +	btrfs_info(fs_info, "  total:         %llu", info->total_bytes);
> > +	btrfs_info(fs_info, "  used:          %llu", info->bytes_used);
> > +	btrfs_info(fs_info, "  pinned:        %llu", info->bytes_pinned);
> > +	btrfs_info(fs_info, "  reserved:      %llu", info->bytes_reserved);
> > +	btrfs_info(fs_info, "  may_use:       %llu", info->bytes_may_use);
> > +	btrfs_info(fs_info, "  read_only:     %llu", info->bytes_readonly);
> > +	if (btrfs_is_zoned(fs_info))
> > +		btrfs_info(fs_info,
> > +			    "  zone_unusable: %llu", info->bytes_zone_unusable);
> 
> I'm (perhaps needlessly) worried about splitting this up into six/seven 
> messages, because of the ratelimiting rolled into btrfs_printk. The 
> ratelimit is 100 messages per 5 * HZ, and it seems like it would be 
> unfortunate if it kicked in during the middle of this dump and prevented 
> later info from being dumped.
> 
> Maybe we should add a btrfs_dump_printk() helper that doesn't have a 
> ratelimit built in, for exceptional cases like this where we really, 
> really don't want anything ratelimited?

Splitting the message is IMHO wrong thing, there are other subysystems
writing to the log so the lines can become scattered or interleaved with
the same message from other threads.

We should prefer single line messages if possible, if not only for
better grep-ability, pretty printing can be done by any utility that
parses the logs.

I did not think about the rate limiting, but you're right that it could
be problematic.

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Qu Wenruo]

On 2022/7/20 05:38, David Sterba wrote:
> On Tue, Jul 19, 2022 at 04:56:00PM -0400, Sweet Tea Dorminy wrote:
>> On 7/19/22 01:11, Qu Wenruo wrote:
>>>
>>> diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
>>> index 36b466525318..623fa0488545 100644
>>> --- a/fs/btrfs/space-info.c
>>> +++ b/fs/btrfs/space-info.c
>>> @@ -475,11 +475,15 @@ static void __btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
>>>    		   flag_str,
>>>    		   (s64)(info->total_bytes - btrfs_space_info_used(info, true)),
>>>    		   info->full ? "" : "not ");
>>> -	btrfs_info(fs_info,
>>> -		"space_info total=%llu, used=%llu, pinned=%llu, reserved=%llu, may_use=%llu, readonly=%llu zone_unusable=%llu",
>>> -		info->total_bytes, info->bytes_used, info->bytes_pinned,
>>> -		info->bytes_reserved, info->bytes_may_use,
>>> -		info->bytes_readonly, info->bytes_zone_unusable);
>>> +	btrfs_info(fs_info, "  total:         %llu", info->total_bytes);
>>> +	btrfs_info(fs_info, "  used:          %llu", info->bytes_used);
>>> +	btrfs_info(fs_info, "  pinned:        %llu", info->bytes_pinned);
>>> +	btrfs_info(fs_info, "  reserved:      %llu", info->bytes_reserved);
>>> +	btrfs_info(fs_info, "  may_use:       %llu", info->bytes_may_use);
>>> +	btrfs_info(fs_info, "  read_only:     %llu", info->bytes_readonly);
>>> +	if (btrfs_is_zoned(fs_info))
>>> +		btrfs_info(fs_info,
>>> +			    "  zone_unusable: %llu", info->bytes_zone_unusable);
>>
>> I'm (perhaps needlessly) worried about splitting this up into six/seven
>> messages, because of the ratelimiting rolled into btrfs_printk. The
>> ratelimit is 100 messages per 5 * HZ, and it seems like it would be
>> unfortunate if it kicked in during the middle of this dump and prevented
>> later info from being dumped.
>>
>> Maybe we should add a btrfs_dump_printk() helper that doesn't have a
>> ratelimit built in, for exceptional cases like this where we really,
>> really don't want anything ratelimited?
>
> Splitting the message is IMHO wrong thing, there are other subysystems
> writing to the log so the lines can become scattered or interleaved with
> the same message from other threads.

But that one line output is really hard to read for human beings.

Or do you mean that, as long as it's debug info, we should not care
about readability at all?

Thanks,
Qu
>
> We should prefer single line messages if possible, if not only for
> better grep-ability, pretty printing can be done by any utility that
> parses the logs.
>
> I did not think about the rate limiting, but you're right that it could
> be problematic.

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[David Sterba]

On Wed, Jul 20, 2022 at 06:58:16AM +0800, Qu Wenruo wrote:
> >>> +	btrfs_info(fs_info, "  reserved:      %llu", info->bytes_reserved);
> >>> +	btrfs_info(fs_info, "  may_use:       %llu", info->bytes_may_use);
> >>> +	btrfs_info(fs_info, "  read_only:     %llu", info->bytes_readonly);
> >>> +	if (btrfs_is_zoned(fs_info))
> >>> +		btrfs_info(fs_info,
> >>> +			    "  zone_unusable: %llu", info->bytes_zone_unusable);
> >>
> >> I'm (perhaps needlessly) worried about splitting this up into six/seven
> >> messages, because of the ratelimiting rolled into btrfs_printk. The
> >> ratelimit is 100 messages per 5 * HZ, and it seems like it would be
> >> unfortunate if it kicked in during the middle of this dump and prevented
> >> later info from being dumped.
> >>
> >> Maybe we should add a btrfs_dump_printk() helper that doesn't have a
> >> ratelimit built in, for exceptional cases like this where we really,
> >> really don't want anything ratelimited?
> >
> > Splitting the message is IMHO wrong thing, there are other subysystems
> > writing to the log so the lines can become scattered or interleaved with
> > the same message from other threads.
> 
> But that one line output is really hard to read for human beings.
> 
> Or do you mean that, as long as it's debug info, we should not care
> about readability at all?

Yes we shold care about readability but kernel printk output lines can
be interleaved, single line is much easier to grep for and all the
values are from one event. The format where it's a series of "key=value"
is common and I think we're used to it from tracepoints too. There are
lines that do not put "=" between keys and values we could unify that
eventually.

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Boris Burkov]

On Tue, Jul 26, 2022 at 08:13:53PM +0200, David Sterba wrote:
> On Wed, Jul 20, 2022 at 06:58:16AM +0800, Qu Wenruo wrote:
> > >>> +	btrfs_info(fs_info, "  reserved:      %llu", info->bytes_reserved);
> > >>> +	btrfs_info(fs_info, "  may_use:       %llu", info->bytes_may_use);
> > >>> +	btrfs_info(fs_info, "  read_only:     %llu", info->bytes_readonly);
> > >>> +	if (btrfs_is_zoned(fs_info))
> > >>> +		btrfs_info(fs_info,
> > >>> +			    "  zone_unusable: %llu", info->bytes_zone_unusable);
> > >>
> > >> I'm (perhaps needlessly) worried about splitting this up into six/seven
> > >> messages, because of the ratelimiting rolled into btrfs_printk. The
> > >> ratelimit is 100 messages per 5 * HZ, and it seems like it would be
> > >> unfortunate if it kicked in during the middle of this dump and prevented
> > >> later info from being dumped.
> > >>
> > >> Maybe we should add a btrfs_dump_printk() helper that doesn't have a
> > >> ratelimit built in, for exceptional cases like this where we really,
> > >> really don't want anything ratelimited?
> > >
> > > Splitting the message is IMHO wrong thing, there are other subysystems
> > > writing to the log so the lines can become scattered or interleaved with
> > > the same message from other threads.
> > 
> > But that one line output is really hard to read for human beings.
> > 
> > Or do you mean that, as long as it's debug info, we should not care
> > about readability at all?
> 
> Yes we shold care about readability but kernel printk output lines can
> be interleaved, single line is much easier to grep for and all the
> values are from one event. The format where it's a series of "key=value"
> is common and I think we're used to it from tracepoints too. There are
> lines that do not put "=" between keys and values we could unify that
> eventually.

Agreed that a long line is OK, and preferable to full on splitting.

What about making some btrfs printing macros that use KERN_CONT? I think
that would do what Qu wants without splitting the lines or being bad for
ratelimiting.

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[David Sterba]

On Tue, Jul 26, 2022 at 01:53:33PM -0700, Boris Burkov wrote:
> > Yes we shold care about readability but kernel printk output lines can
> > be interleaved, single line is much easier to grep for and all the
> > values are from one event. The format where it's a series of "key=value"
> > is common and I think we're used to it from tracepoints too. There are
> > lines that do not put "=" between keys and values we could unify that
> > eventually.
> 
> Agreed that a long line is OK, and preferable to full on splitting.
> 
> What about making some btrfs printing macros that use KERN_CONT? I think
> that would do what Qu wants without splitting the lines or being bad for
> ratelimiting.

IIRC I've read some discussions about KERN_CONT suggesting not to use
it, I'll ask what's the status.

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Boris Burkov]

On Tue, Jul 26, 2022 at 11:39:28PM +0200, David Sterba wrote:
> On Tue, Jul 26, 2022 at 01:53:33PM -0700, Boris Burkov wrote:
> > > Yes we shold care about readability but kernel printk output lines can
> > > be interleaved, single line is much easier to grep for and all the
> > > values are from one event. The format where it's a series of "key=value"
> > > is common and I think we're used to it from tracepoints too. There are
> > > lines that do not put "=" between keys and values we could unify that
> > > eventually.
> > 
> > Agreed that a long line is OK, and preferable to full on splitting.
> > 
> > What about making some btrfs printing macros that use KERN_CONT? I think
> > that would do what Qu wants without splitting the lines or being bad for
> > ratelimiting.
> 
> IIRC I've read some discussions about KERN_CONT suggesting not to use
> it, I'll ask what's the status.

I just saw a comment at its definition that reads:

/*
 * Annotation for a "continued" line of log printout (only done after a
 * line that had no enclosing \n). Only to be used by core/arch code
 * during early bootup (a continued line is not SMP-safe otherwise).
 */
#define KERN_CONT       KERN_SOH "c"

So that's not an encouraging sign. OTOH, I found some code in
ext4/super.c that prints its errors with KERN_CONT here:
'ext4: super.c: Update logging style using KERN_CONT'

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Sweet Tea Dorminy]

On 7/26/22 19:21, Boris Burkov wrote:
> On Tue, Jul 26, 2022 at 11:39:28PM +0200, David Sterba wrote:
>> On Tue, Jul 26, 2022 at 01:53:33PM -0700, Boris Burkov wrote:
>>>> Yes we shold care about readability but kernel printk output lines can
>>>> be interleaved, single line is much easier to grep for and all the
>>>> values are from one event. The format where it's a series of "key=value"
>>>> is common and I think we're used to it from tracepoints too. There are
>>>> lines that do not put "=" between keys and values we could unify that
>>>> eventually.
>>>
>>> Agreed that a long line is OK, and preferable to full on splitting.
>>>
>>> What about making some btrfs printing macros that use KERN_CONT? I think
>>> that would do what Qu wants without splitting the lines or being bad for
>>> ratelimiting.
>>
>> IIRC I've read some discussions about KERN_CONT suggesting not to use
>> it, I'll ask what's the status.
> 
> I just saw a comment at its definition that reads:
> 
> /*
>   * Annotation for a "continued" line of log printout (only done after a
>   * line that had no enclosing \n). Only to be used by core/arch code
>   * during early bootup (a continued line is not SMP-safe otherwise).
>   */
> #define KERN_CONT       KERN_SOH "c"
> 
> So that's not an encouraging sign. OTOH, I found some code in
> ext4/super.c that prints its errors with KERN_CONT here:
> 'ext4: super.c: Update logging style using KERN_CONT

Some other log message from somewhere else could be emitted to the 
printk ringbuffer between the original and the continued message. In 
such a case, the continued message instead gets treated as its own 
message of loglevel default. (kernel/printk/printk.c:2173ish) Using 
KERN_CONT seems like it has a lot of potential for confusion, especially 
if the default message level has been changed to be different from the 
original messages' level.

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Qu Wenruo]

On 2022/7/27 09:21, Sweet Tea Dorminy wrote:
>
>
> On 7/26/22 19:21, Boris Burkov wrote:
>> On Tue, Jul 26, 2022 at 11:39:28PM +0200, David Sterba wrote:
>>> On Tue, Jul 26, 2022 at 01:53:33PM -0700, Boris Burkov wrote:
>>>>> Yes we shold care about readability but kernel printk output lines can
>>>>> be interleaved, single line is much easier to grep for and all the
>>>>> values are from one event. The format where it's a series of
>>>>> "key=value"
>>>>> is common and I think we're used to it from tracepoints too. There are
>>>>> lines that do not put "=" between keys and values we could unify that
>>>>> eventually.
>>>>
>>>> Agreed that a long line is OK, and preferable to full on splitting.
>>>>
>>>> What about making some btrfs printing macros that use KERN_CONT? I
>>>> think
>>>> that would do what Qu wants without splitting the lines or being bad
>>>> for
>>>> ratelimiting.
>>>
>>> IIRC I've read some discussions about KERN_CONT suggesting not to use
>>> it, I'll ask what's the status.
>>
>> I just saw a comment at its definition that reads:
>>
>> /*
>>   * Annotation for a "continued" line of log printout (only done after a
>>   * line that had no enclosing \n). Only to be used by core/arch code
>>   * during early bootup (a continued line is not SMP-safe otherwise).
>>   */
>> #define KERN_CONT       KERN_SOH "c"
>>
>> So that's not an encouraging sign. OTOH, I found some code in
>> ext4/super.c that prints its errors with KERN_CONT here:
>> 'ext4: super.c: Update logging style using KERN_CONT
>
> Some other log message from somewhere else could be emitted to the
> printk ringbuffer between the original and the continued message. In
> such a case, the continued message instead gets treated as its own
> message of loglevel default. (kernel/printk/printk.c:2173ish) Using
> KERN_CONT seems like it has a lot of potential for confusion, especially
> if the default message level has been changed to be different from the
> original messages' level.

Thanks for all the discussion, it looks like the current long single
line is the way to go (in fact, the space info dumping itself is still
two lines, and we may want to fix it).

Although it's not that human readable, the racy nature of message output
is indeed a concern.
This also means the old DUMP_BLOCK_RSV() function calls are not safe either.


But on the other hand, what if we output one line with multiple '\n'?
Would it keep things readable while still count as one single line?

If so, I'd prefer multiple line split.

Thanks,
Qu

Re: [PATCH v2 2/4] btrfs: make __btrfs_dump_space_info() output better formatted

[Sweet Tea Dorminy]

On 7/26/22 21:44, Qu Wenruo wrote:
> 
> 
> On 2022/7/27 09:21, Sweet Tea Dorminy wrote:
>>
>>
>> On 7/26/22 19:21, Boris Burkov wrote:
>>> On Tue, Jul 26, 2022 at 11:39:28PM +0200, David Sterba wrote:
>>>> On Tue, Jul 26, 2022 at 01:53:33PM -0700, Boris Burkov wrote:
>>>>>> Yes we shold care about readability but kernel printk output lines 
>>>>>> can
>>>>>> be interleaved, single line is much easier to grep for and all the
>>>>>> values are from one event. The format where it's a series of
>>>>>> "key=value"
>>>>>> is common and I think we're used to it from tracepoints too. There 
>>>>>> are
>>>>>> lines that do not put "=" between keys and values we could unify that
>>>>>> eventually.
>>>>>
>>>>> Agreed that a long line is OK, and preferable to full on splitting.
>>>>>
>>>>> What about making some btrfs printing macros that use KERN_CONT? I
>>>>> think
>>>>> that would do what Qu wants without splitting the lines or being bad
>>>>> for
>>>>> ratelimiting.
>>>>
>>>> IIRC I've read some discussions about KERN_CONT suggesting not to use
>>>> it, I'll ask what's the status.
>>>
>>> I just saw a comment at its definition that reads:
>>>
>>> /*
>>>   * Annotation for a "continued" line of log printout (only done after a
>>>   * line that had no enclosing \n). Only to be used by core/arch code
>>>   * during early bootup (a continued line is not SMP-safe otherwise).
>>>   */
>>> #define KERN_CONT       KERN_SOH "c"
>>>
>>> So that's not an encouraging sign. OTOH, I found some code in
>>> ext4/super.c that prints its errors with KERN_CONT here:
>>> 'ext4: super.c: Update logging style using KERN_CONT
>>
>> Some other log message from somewhere else could be emitted to the
>> printk ringbuffer between the original and the continued message. In
>> such a case, the continued message instead gets treated as its own
>> message of loglevel default. (kernel/printk/printk.c:2173ish) Using
>> KERN_CONT seems like it has a lot of potential for confusion, especially
>> if the default message level has been changed to be different from the
>> original messages' level.
> 
> Thanks for all the discussion, it looks like the current long single
> line is the way to go (in fact, the space info dumping itself is still
> two lines, and we may want to fix it).
> 
> Although it's not that human readable, the racy nature of message output
> is indeed a concern.
> This also means the old DUMP_BLOCK_RSV() function calls are not safe 
> either.
> 
> 
> But on the other hand, what if we output one line with multiple '\n'?
> Would it keep things readable while still count as one single line?

Yes, it would count as only one message, but it would break scripts that 
assume dmesg etc outputs a timestamp for every line; I think many kernel 
log scrapers make that assumption.

sample dmesg -T

[Wed Jul 27 10:59:54 2022] test three
                            line message

[Wed Jul 27 11:03:50 2022] next message.

sample journalctl:

Jul 27 10:59:54 vmcentral unknown: test three
                            line message
Jul 27 11:03:50 vmcentral unknown: next message.

[PATCH v2 3/4] btrfs: make DUMP_BLOCK_RSV() to have better output

[Qu Wenruo]

This involves the following change:

- Remove "_block_rsv" suffix

- Better alignment for the numbers

- Better naming distinguish for delayed refs and delayed inode

- Skip "size" and "reserved" output
  Just output the numbers directly

Before:

  BTRFS info (device dm-1: state A): global_block_rsv: size 3670016 reserved 3653632
  BTRFS info (device dm-1: state A): trans_block_rsv: size 0 reserved 0
  BTRFS info (device dm-1: state A): chunk_block_rsv: size 0 reserved 0
  BTRFS info (device dm-1: state A): delayed_block_rsv: size 0 reserved 0
  BTRFS info (device dm-1: state A): delayed_refs_rsv: size 524288 reserved 360448

After:

 BTRFS info (device dm-1: state A): dumping metadata reservation: (reserved/size)
 BTRFS info (device dm-1: state A):   global:          (3670016/3670016)
 BTRFS info (device dm-1: state A):   trans:           (0/0)
 BTRFS info (device dm-1: state A):   chunk:           (0/0)
 BTRFS info (device dm-1: state A):   delayed_inode:   (0/0)
 BTRFS info (device dm-1: state A):   delayed_refs:    (524288/524288)

Also, this patch will separate the metadata reservation dumping into a
separate function for later usage.

Signed-off-by: Qu Wenruo <wqu@suse.com>
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
---
 fs/btrfs/space-info.c | 25 +++++++++++++++----------
 1 file changed, 15 insertions(+), 10 deletions(-)

diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
index 623fa0488545..81457049816e 100644
--- a/fs/btrfs/space-info.c
+++ b/fs/btrfs/space-info.c
@@ -441,12 +441,12 @@ void btrfs_try_granting_tickets(struct btrfs_fs_info *fs_info,
 	}
 }
 
-#define DUMP_BLOCK_RSV(fs_info, rsv_name)				\
+#define DUMP_BLOCK_RSV(fs_info, member, name)				\
 do {									\
-	struct btrfs_block_rsv *__rsv = &(fs_info)->rsv_name;		\
+	struct btrfs_block_rsv *__rsv = &(fs_info)->member;		\
 	spin_lock(&__rsv->lock);					\
-	btrfs_info(fs_info, #rsv_name ": size %llu reserved %llu",	\
-		   __rsv->size, __rsv->reserved);			\
+	btrfs_info(fs_info, "  %-16s (%llu/%llu)",			\
+		   name, __rsv->reserved, __rsv->size);			\
 	spin_unlock(&__rsv->lock);					\
 } while (0)
 
@@ -484,13 +484,16 @@ static void __btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
 	if (btrfs_is_zoned(fs_info))
 		btrfs_info(fs_info,
 			    "  zone_unusable: %llu", info->bytes_zone_unusable);
+}
 
-	DUMP_BLOCK_RSV(fs_info, global_block_rsv);
-	DUMP_BLOCK_RSV(fs_info, trans_block_rsv);
-	DUMP_BLOCK_RSV(fs_info, chunk_block_rsv);
-	DUMP_BLOCK_RSV(fs_info, delayed_block_rsv);
-	DUMP_BLOCK_RSV(fs_info, delayed_refs_rsv);
-
+static void dump_metadata_rsv(struct btrfs_fs_info *fs_info)
+{
+	btrfs_info(fs_info, "dumping metadata reservation: (reserved/size)");
+	DUMP_BLOCK_RSV(fs_info, global_block_rsv, "global:");
+	DUMP_BLOCK_RSV(fs_info, trans_block_rsv, "trans:");
+	DUMP_BLOCK_RSV(fs_info, chunk_block_rsv, "chunk:");
+	DUMP_BLOCK_RSV(fs_info, delayed_block_rsv, "delayed_inode:");
+	DUMP_BLOCK_RSV(fs_info, delayed_refs_rsv, "delayed_refs:");
 }
 
 void btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
@@ -502,6 +505,7 @@ void btrfs_dump_space_info(struct btrfs_fs_info *fs_info,
 
 	spin_lock(&info->lock);
 	__btrfs_dump_space_info(fs_info, info);
+	dump_metadata_rsv(fs_info);
 	spin_unlock(&info->lock);
 
 	if (!dump_block_groups)
@@ -957,6 +961,7 @@ static bool maybe_fail_all_tickets(struct btrfs_fs_info *fs_info,
 	if (btrfs_test_opt(fs_info, ENOSPC_DEBUG)) {
 		btrfs_info(fs_info, "cannot satisfy tickets, dumping space info");
 		__btrfs_dump_space_info(fs_info, space_info);
+		dump_metadata_rsv(fs_info);
 	}
 
 	while (!list_empty(&space_info->tickets) &&
-- 
2.37.0

[PATCH v2 4/4] btrfs: dump all space infos if we abort transaction due to ENOSPC

[Qu Wenruo]

We have hit some transaction abort due to -ENOSPC internally.

Normally we should always reserve enough space for metadata for every
transaction, thus hitting -ENOSPC should really indicate some cases we
didn't expect.

But unfrotunately current error reporting will only give a kernel
wanring and backtrace, not really helpful to debug what's causing the
problem.

And debug_enospc can only help when user can reproduce the problem, but
under most cases, such transaction abort by -ENOSPC is really hard to
reproduce.

So this patch will dump all space infos (data, metadata, system) when we
abort the first transaction with -ENOSPC.

This should at least provide some clue to us.

The example of a dump would look like this:

 ------------[ cut here ]------------
 <skip stack dump>
 ---[ end trace 0000000000000000 ]---
 BTRFS info (device dm-4: state A): dumpping space info:
 BTRFS info (device dm-4: state A): space_info DATA has 8388608 free, is not full
 BTRFS info (device dm-4: state A):   total:         8388608
 BTRFS info (device dm-4: state A):   used:          0
 BTRFS info (device dm-4: state A):   pinned:        0
 BTRFS info (device dm-4: state A):   reserved:      0
 BTRFS info (device dm-4: state A):   may_use:       0
 BTRFS info (device dm-4: state A):   read_only:     0
 BTRFS info (device dm-4: state A): space_info META has 263979008 free, is not full
 BTRFS info (device dm-4: state A):   total:         268435456
 BTRFS info (device dm-4: state A):   used:          131072
 BTRFS info (device dm-4: state A):   pinned:        65536
 BTRFS info (device dm-4: state A):   reserved:      0
 BTRFS info (device dm-4: state A):   may_use:       4194304
 BTRFS info (device dm-4: state A):   read_only:     65536
 BTRFS info (device dm-4: state A): space_info SYS has 8372224 free, is not full
 BTRFS info (device dm-4: state A):   total:         8388608
 BTRFS info (device dm-4: state A):   used:          16384
 BTRFS info (device dm-4: state A):   pinned:        0
 BTRFS info (device dm-4: state A):   reserved:      0
 BTRFS info (device dm-4: state A):   may_use:       0
 BTRFS info (device dm-4: state A):   read_only:     0
 BTRFS info (device dm-4: state A): dumping metadata reservation: (reserved/size)
 BTRFS info (device dm-4: state A):   global:          (3670016/3670016)
 BTRFS info (device dm-4: state A):   trans:           (0/0)
 BTRFS info (device dm-4: state A):   chunk:           (0/0)
 BTRFS info (device dm-4: state A):   delayed_inode:   (0/0)
 BTRFS info (device dm-4: state A):   delayed_refs:    (524288/524288)
 BTRFS: error (device dm-1: state A) in cleanup_transaction:1971: errno=-28 No space left
 BTRFS info (device dm-1: state EA): forced readonly

Signed-off-by: Qu Wenruo <wqu@suse.com>
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
---
 fs/btrfs/ctree.h      |  6 ++++--
 fs/btrfs/space-info.c | 14 ++++++++++++++
 fs/btrfs/space-info.h |  2 ++
 fs/btrfs/super.c      |  4 +++-
 4 files changed, 23 insertions(+), 3 deletions(-)

diff --git a/fs/btrfs/ctree.h b/fs/btrfs/ctree.h
index 4e2569f84aab..3d6fd7f6b339 100644
--- a/fs/btrfs/ctree.h
+++ b/fs/btrfs/ctree.h
@@ -3739,7 +3739,7 @@ const char * __attribute_const__ btrfs_decode_error(int errno);
 __cold
 void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
 			       const char *function,
-			       unsigned int line, int errno);
+			       unsigned int line, int errno, bool first_hit);
 
 /*
  * Call btrfs_abort_transaction as early as possible when an error condition is
@@ -3747,9 +3747,11 @@ void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
  */
 #define btrfs_abort_transaction(trans, errno)		\
 do {								\
+	bool first = false;					\
 	/* Report first abort since mount */			\
 	if (!test_and_set_bit(BTRFS_FS_STATE_TRANS_ABORTED,	\
 			&((trans)->fs_info->fs_state))) {	\
+		first = true;					\
 		if ((errno) != -EIO && (errno) != -EROFS) {		\
 			WARN(1, KERN_DEBUG				\
 			"BTRFS: Transaction aborted (error %d)\n",	\
@@ -3761,7 +3763,7 @@ do {								\
 		}						\
 	}							\
 	__btrfs_abort_transaction((trans), __func__,		\
-				  __LINE__, (errno));		\
+				  __LINE__, (errno), first);	\
 } while (0)
 
 #ifdef CONFIG_PRINTK_INDEX
diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
index 81457049816e..af2b3f5ef2b0 100644
--- a/fs/btrfs/space-info.c
+++ b/fs/btrfs/space-info.c
@@ -1717,3 +1717,17 @@ int btrfs_reserve_data_bytes(struct btrfs_fs_info *fs_info, u64 bytes,
 	}
 	return ret;
 }
+
+/* Dump all the space infos when we abort a transaction due to ENOSPC. */
+__cold void btrfs_dump_fs_space_info(struct btrfs_fs_info *fs_info)
+{
+	struct btrfs_space_info *space_info;
+
+	btrfs_info(fs_info, "dumping space info:");
+	list_for_each_entry(space_info, &fs_info->space_info, list) {
+		spin_lock(&space_info->lock);
+		__btrfs_dump_space_info(fs_info, space_info);
+		spin_unlock(&space_info->lock);
+	}
+	dump_metadata_rsv(fs_info);
+}
diff --git a/fs/btrfs/space-info.h b/fs/btrfs/space-info.h
index e7de24a529cf..01287a7a22a4 100644
--- a/fs/btrfs/space-info.h
+++ b/fs/btrfs/space-info.h
@@ -157,4 +157,6 @@ static inline void btrfs_space_info_free_bytes_may_use(
 }
 int btrfs_reserve_data_bytes(struct btrfs_fs_info *fs_info, u64 bytes,
 			     enum btrfs_reserve_flush_enum flush);
+void btrfs_dump_fs_space_info(struct btrfs_fs_info *fs_info);
+
 #endif /* BTRFS_SPACE_INFO_H */
diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
index 4c7089b1681b..f6bc8aa00f44 100644
--- a/fs/btrfs/super.c
+++ b/fs/btrfs/super.c
@@ -346,12 +346,14 @@ void __cold btrfs_err_32bit_limit(struct btrfs_fs_info *fs_info)
 __cold
 void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
 			       const char *function,
-			       unsigned int line, int errno)
+			       unsigned int line, int errno, bool first_hit)
 {
 	struct btrfs_fs_info *fs_info = trans->fs_info;
 
 	WRITE_ONCE(trans->aborted, errno);
 	WRITE_ONCE(trans->transaction->aborted, errno);
+	if (first_hit && errno == -ENOSPC)
+		btrfs_dump_fs_space_info(fs_info);
 	/* Wake up anybody who may be waiting on this transaction */
 	wake_up(&fs_info->transaction_wait);
 	wake_up(&fs_info->transaction_blocked_wait);
-- 
2.37.0

Re: [PATCH v2 4/4] btrfs: dump all space infos if we abort transaction due to ENOSPC

[Sweet Tea Dorminy]

On 7/19/22 01:11, Qu Wenruo wrote:
> We have hit some transaction abort due to -ENOSPC internally.
> 
> Normally we should always reserve enough space for metadata for every
> transaction, thus hitting -ENOSPC should really indicate some cases we
> didn't expect.
> 
> But unfrotunately current error reporting will only give a kernel
> wanring and backtrace, not really helpful to debug what's causing the
> problem.
> 
> And debug_enospc can only help when user can reproduce the problem, but
> under most cases, such transaction abort by -ENOSPC is really hard to
> reproduce.
> 
> So this patch will dump all space infos (data, metadata, system) when we
> abort the first transaction with -ENOSPC.
> 
> This should at least provide some clue to us.
> 
> The example of a dump would look like this:
> 
>   ------------[ cut here ]------------
>   <skip stack dump>
>   ---[ end trace 0000000000000000 ]---
>   BTRFS info (device dm-4: state A): dumpping space info >   BTRFS info (device dm-4: state A): space_info DATA has 8388608 
free, is not full
>   BTRFS info (device dm-4: state A):   total:         8388608
>   BTRFS info (device dm-4: state A):   used:          0
>   BTRFS info (device dm-4: state A):   pinned:        0
>   BTRFS info (device dm-4: state A):   reserved:      0
>   BTRFS info (device dm-4: state A):   may_use:       0
>   BTRFS info (device dm-4: state A):   read_only:     0
>   BTRFS info (device dm-4: state A): space_info META has 263979008 free, is not full
>   BTRFS info (device dm-4: state A):   total:         268435456
>   BTRFS info (device dm-4: state A):   used:          131072
>   BTRFS info (device dm-4: state A):   pinned:        65536
>   BTRFS info (device dm-4: state A):   reserved:      0
>   BTRFS info (device dm-4: state A):   may_use:       4194304
>   BTRFS info (device dm-4: state A):   read_only:     65536
>   BTRFS info (device dm-4: state A): space_info SYS has 8372224 free, is not full
>   BTRFS info (device dm-4: state A):   total:         8388608
>   BTRFS info (device dm-4: state A):   used:          16384
>   BTRFS info (device dm-4: state A):   pinned:        0
>   BTRFS info (device dm-4: state A):   reserved:      0
>   BTRFS info (device dm-4: state A):   may_use:       0
>   BTRFS info (device dm-4: state A):   read_only:     0
>   BTRFS info (device dm-4: state A): dumping metadata reservation: (reserved/size)
>   BTRFS info (device dm-4: state A):   global:          (3670016/3670016)
>   BTRFS info (device dm-4: state A):   trans:           (0/0)
>   BTRFS info (device dm-4: state A):   chunk:           (0/0)
>   BTRFS info (device dm-4: state A):   delayed_inode:   (0/0)
>   BTRFS info (device dm-4: state A):   delayed_refs:    (524288/524288)
>   BTRFS: error (device dm-1: state A) in cleanup_transaction:1971: errno=-28 No space left
>   BTRFS info (device dm-1: state EA): forced readonly
> 
> Signed-off-by: Qu Wenruo <wqu@suse.com>
> Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
> ---
>   fs/btrfs/ctree.h      |  6 ++++--
>   fs/btrfs/space-info.c | 14 ++++++++++++++
>   fs/btrfs/space-info.h |  2 ++
>   fs/btrfs/super.c      |  4 +++-
>   4 files changed, 23 insertions(+), 3 deletions(-)
> 
> diff --git a/fs/btrfs/ctree.h b/fs/btrfs/ctree.h
> index 4e2569f84aab..3d6fd7f6b339 100644
> --- a/fs/btrfs/ctree.h
> +++ b/fs/btrfs/ctree.h
> @@ -3739,7 +3739,7 @@ const char * __attribute_const__ btrfs_decode_error(int errno);
>   __cold
>   void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
>   			       const char *function,
> -			       unsigned int line, int errno);
> +			       unsigned int line, int errno, bool first_hit);
>   
>   /*
>    * Call btrfs_abort_transaction as early as possible when an error condition is
> @@ -3747,9 +3747,11 @@ void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
>    */
>   #define btrfs_abort_transaction(trans, errno)		\
>   do {								\
> +	bool first = false;					\
>   	/* Report first abort since mount */			\
>   	if (!test_and_set_bit(BTRFS_FS_STATE_TRANS_ABORTED,	\
>   			&((trans)->fs_info->fs_state))) {	\
> +		first = true;					\
>   		if ((errno) != -EIO && (errno) != -EROFS) {		\
>   			WARN(1, KERN_DEBUG				\
>   			"BTRFS: Transaction aborted (error %d)\n",	\
> @@ -3761,7 +3763,7 @@ do {								\
>   		}						\
>   	}							\
>   	__btrfs_abort_transaction((trans), __func__,		\
> -				  __LINE__, (errno));		\
> +				  __LINE__, (errno), first);	\
>   } while (0)
>   
>   #ifdef CONFIG_PRINTK_INDEX
> diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
> index 81457049816e..af2b3f5ef2b0 100644
> --- a/fs/btrfs/space-info.c
> +++ b/fs/btrfs/space-info.c
> @@ -1717,3 +1717,17 @@ int btrfs_reserve_data_bytes(struct btrfs_fs_info *fs_info, u64 bytes,
>   	}
>   	return ret;
>   }
> +
> +/* Dump all the space infos when we abort a transaction due to ENOSPC. */
> +__cold void btrfs_dump_fs_space_info(struct btrfs_fs_info *fs_info)
> +{
> +	struct btrfs_space_info *space_info;
> +
> +	btrfs_info(fs_info, "dumping space info:");
> +	list_for_each_entry(space_info, &fs_info->space_info, list) {
> +		spin_lock(&space_info->lock);
> +		__btrfs_dump_space_info(fs_info, space_info);
> +		spin_unlock(&space_info->lock);
> +	}
> +	dump_metadata_rsv(fs_info);
> +}
This function looks similar to btrfs_dump_space_info(), and the name and 
callsite doesn't help distinguish it very much to me. It seems 
potentially useful to print all the space_infos when one space_info 
encounters a problem, and it seems potentially useful to print the block 
group infos when we're dumping all the space infos already, so maybe the
two functions could be combined.

Maybe you could adjust btrfs_dump_space_info() to print all the space 
infos, starting with the one passed in (potentially NULL), and call it 
instead of this new function?

> diff --git a/fs/btrfs/space-info.h b/fs/btrfs/space-info.h
> index e7de24a529cf..01287a7a22a4 100644
> --- a/fs/btrfs/space-info.h
> +++ b/fs/btrfs/space-info.h
> @@ -157,4 +157,6 @@ static inline void btrfs_space_info_free_bytes_may_use(
>   }
>   int btrfs_reserve_data_bytes(struct btrfs_fs_info *fs_info, u64 bytes,
>   			     enum btrfs_reserve_flush_enum flush);
> +void btrfs_dump_fs_space_info(struct btrfs_fs_info *fs_info);
> +
>   #endif /* BTRFS_SPACE_INFO_H */
> diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
> index 4c7089b1681b..f6bc8aa00f44 100644
> --- a/fs/btrfs/super.c
> +++ b/fs/btrfs/super.c
> @@ -346,12 +346,14 @@ void __cold btrfs_err_32bit_limit(struct btrfs_fs_info *fs_info)
>   __cold
>   void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
>   			       const char *function,
> -			       unsigned int line, int errno)
> +			       unsigned int line, int errno, bool first_hit)
>   {
>   	struct btrfs_fs_info *fs_info = trans->fs_info;
>   
>   	WRITE_ONCE(trans->aborted, errno);
>   	WRITE_ONCE(trans->transaction->aborted, errno);
> +	if (first_hit && errno == -ENOSPC)
> +		btrfs_dump_fs_space_info(fs_info);
>   	/* Wake up anybody who may be waiting on this transaction */
>   	wake_up(&fs_info->transaction_wait);
>   	wake_up(&fs_info->transaction_blocked_wait);
DO_ONCE_LITE(btrfs_dump_fs_space_info, fs_info) from <linux/once_lite.h> 
seems like a more lightweight way to dump the space infos once upon 
first transaction abort. Then you don't have to plumb through the 
'first_hit' parameter from btrfs_abort_transaction(), and this change 
becomes even more minimal than it already is.

Re: [PATCH v2 4/4] btrfs: dump all space infos if we abort transaction due to ENOSPC

[Qu Wenruo]

On 2022/7/20 08:42, Sweet Tea Dorminy wrote:
>
>
> On 7/19/22 01:11, Qu Wenruo wrote:
>> We have hit some transaction abort due to -ENOSPC internally.
>>
>> Normally we should always reserve enough space for metadata for every
>> transaction, thus hitting -ENOSPC should really indicate some cases we
>> didn't expect.
>>
>> But unfrotunately current error reporting will only give a kernel
>> wanring and backtrace, not really helpful to debug what's causing the
>> problem.
>>
>> And debug_enospc can only help when user can reproduce the problem, but
>> under most cases, such transaction abort by -ENOSPC is really hard to
>> reproduce.
>>
>> So this patch will dump all space infos (data, metadata, system) when we
>> abort the first transaction with -ENOSPC.
>>
>> This should at least provide some clue to us.
>>
>> The example of a dump would look like this:
>>
>>   ------------[ cut here ]------------
>>   <skip stack dump>
>>   ---[ end trace 0000000000000000 ]---
>>   BTRFS info (device dm-4: state A): dumpping space info >   BTRFS
>> info (device dm-4: state A): space_info DATA has 8388608
> free, is not full
>>   BTRFS info (device dm-4: state A):   total:         8388608
>>   BTRFS info (device dm-4: state A):   used:          0
>>   BTRFS info (device dm-4: state A):   pinned:        0
>>   BTRFS info (device dm-4: state A):   reserved:      0
>>   BTRFS info (device dm-4: state A):   may_use:       0
>>   BTRFS info (device dm-4: state A):   read_only:     0
>>   BTRFS info (device dm-4: state A): space_info META has 263979008
>> free, is not full
>>   BTRFS info (device dm-4: state A):   total:         268435456
>>   BTRFS info (device dm-4: state A):   used:          131072
>>   BTRFS info (device dm-4: state A):   pinned:        65536
>>   BTRFS info (device dm-4: state A):   reserved:      0
>>   BTRFS info (device dm-4: state A):   may_use:       4194304
>>   BTRFS info (device dm-4: state A):   read_only:     65536
>>   BTRFS info (device dm-4: state A): space_info SYS has 8372224 free,
>> is not full
>>   BTRFS info (device dm-4: state A):   total:         8388608
>>   BTRFS info (device dm-4: state A):   used:          16384
>>   BTRFS info (device dm-4: state A):   pinned:        0
>>   BTRFS info (device dm-4: state A):   reserved:      0
>>   BTRFS info (device dm-4: state A):   may_use:       0
>>   BTRFS info (device dm-4: state A):   read_only:     0
>>   BTRFS info (device dm-4: state A): dumping metadata reservation:
>> (reserved/size)
>>   BTRFS info (device dm-4: state A):   global:          (3670016/3670016)
>>   BTRFS info (device dm-4: state A):   trans:           (0/0)
>>   BTRFS info (device dm-4: state A):   chunk:           (0/0)
>>   BTRFS info (device dm-4: state A):   delayed_inode:   (0/0)
>>   BTRFS info (device dm-4: state A):   delayed_refs:    (524288/524288)
>>   BTRFS: error (device dm-1: state A) in cleanup_transaction:1971:
>> errno=-28 No space left
>>   BTRFS info (device dm-1: state EA): forced readonly
>>
>> Signed-off-by: Qu Wenruo <wqu@suse.com>
>> Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
>> ---
>>   fs/btrfs/ctree.h      |  6 ++++--
>>   fs/btrfs/space-info.c | 14 ++++++++++++++
>>   fs/btrfs/space-info.h |  2 ++
>>   fs/btrfs/super.c      |  4 +++-
>>   4 files changed, 23 insertions(+), 3 deletions(-)
>>
>> diff --git a/fs/btrfs/ctree.h b/fs/btrfs/ctree.h
>> index 4e2569f84aab..3d6fd7f6b339 100644
>> --- a/fs/btrfs/ctree.h
>> +++ b/fs/btrfs/ctree.h
>> @@ -3739,7 +3739,7 @@ const char * __attribute_const__
>> btrfs_decode_error(int errno);
>>   __cold
>>   void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
>>                      const char *function,
>> -                   unsigned int line, int errno);
>> +                   unsigned int line, int errno, bool first_hit);
>>   /*
>>    * Call btrfs_abort_transaction as early as possible when an error
>> condition is
>> @@ -3747,9 +3747,11 @@ void __btrfs_abort_transaction(struct
>> btrfs_trans_handle *trans,
>>    */
>>   #define btrfs_abort_transaction(trans, errno)        \
>>   do {                                \
>> +    bool first = false;                    \
>>       /* Report first abort since mount */            \
>>       if (!test_and_set_bit(BTRFS_FS_STATE_TRANS_ABORTED,    \
>>               &((trans)->fs_info->fs_state))) {    \
>> +        first = true;                    \
>>           if ((errno) != -EIO && (errno) != -EROFS) {        \
>>               WARN(1, KERN_DEBUG                \
>>               "BTRFS: Transaction aborted (error %d)\n",    \
>> @@ -3761,7 +3763,7 @@ do {                                \
>>           }                        \
>>       }                            \
>>       __btrfs_abort_transaction((trans), __func__,        \
>> -                  __LINE__, (errno));        \
>> +                  __LINE__, (errno), first);    \
>>   } while (0)
>>   #ifdef CONFIG_PRINTK_INDEX
>> diff --git a/fs/btrfs/space-info.c b/fs/btrfs/space-info.c
>> index 81457049816e..af2b3f5ef2b0 100644
>> --- a/fs/btrfs/space-info.c
>> +++ b/fs/btrfs/space-info.c
>> @@ -1717,3 +1717,17 @@ int btrfs_reserve_data_bytes(struct
>> btrfs_fs_info *fs_info, u64 bytes,
>>       }
>>       return ret;
>>   }
>> +
>> +/* Dump all the space infos when we abort a transaction due to
>> ENOSPC. */
>> +__cold void btrfs_dump_fs_space_info(struct btrfs_fs_info *fs_info)
>> +{
>> +    struct btrfs_space_info *space_info;
>> +
>> +    btrfs_info(fs_info, "dumping space info:");
>> +    list_for_each_entry(space_info, &fs_info->space_info, list) {
>> +        spin_lock(&space_info->lock);
>> +        __btrfs_dump_space_info(fs_info, space_info);
>> +        spin_unlock(&space_info->lock);
>> +    }
>> +    dump_metadata_rsv(fs_info);
>> +}
> This function looks similar to btrfs_dump_space_info(), and the name and
> callsite doesn't help distinguish it very much to me. It seems
> potentially useful to print all the space_infos when one space_info
> encounters a problem,

This is fine for trans abort dump, but may not be a good idea for
enospc_debug output.

enospc_debug can be triggered way more frequent than trans abort, and
the extra info of unrelated space info may just be noise.

> and it seems potentially useful to print the block
> group infos when we're dumping all the space infos already, so maybe the
> two functions could be combined.

You mean block group infos? That can be very large for large fses.
Thus it's avoided for most call sites other than btrfs_reserve_extent().

>
> Maybe you could adjust btrfs_dump_space_info() to print all the space
> infos, starting with the one passed in (potentially NULL), and call it
> instead of this new function?
>
>> diff --git a/fs/btrfs/space-info.h b/fs/btrfs/space-info.h
>> index e7de24a529cf..01287a7a22a4 100644
>> --- a/fs/btrfs/space-info.h
>> +++ b/fs/btrfs/space-info.h
>> @@ -157,4 +157,6 @@ static inline void
>> btrfs_space_info_free_bytes_may_use(
>>   }
>>   int btrfs_reserve_data_bytes(struct btrfs_fs_info *fs_info, u64 bytes,
>>                    enum btrfs_reserve_flush_enum flush);
>> +void btrfs_dump_fs_space_info(struct btrfs_fs_info *fs_info);
>> +
>>   #endif /* BTRFS_SPACE_INFO_H */
>> diff --git a/fs/btrfs/super.c b/fs/btrfs/super.c
>> index 4c7089b1681b..f6bc8aa00f44 100644
>> --- a/fs/btrfs/super.c
>> +++ b/fs/btrfs/super.c
>> @@ -346,12 +346,14 @@ void __cold btrfs_err_32bit_limit(struct
>> btrfs_fs_info *fs_info)
>>   __cold
>>   void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
>>                      const char *function,
>> -                   unsigned int line, int errno)
>> +                   unsigned int line, int errno, bool first_hit)
>>   {
>>       struct btrfs_fs_info *fs_info = trans->fs_info;
>>       WRITE_ONCE(trans->aborted, errno);
>>       WRITE_ONCE(trans->transaction->aborted, errno);
>> +    if (first_hit && errno == -ENOSPC)
>> +        btrfs_dump_fs_space_info(fs_info);
>>       /* Wake up anybody who may be waiting on this transaction */
>>       wake_up(&fs_info->transaction_wait);
>>       wake_up(&fs_info->transaction_blocked_wait);
> DO_ONCE_LITE(btrfs_dump_fs_space_info, fs_info) from <linux/once_lite.h>
> seems like a more lightweight way to dump the space infos once upon
> first transaction abort. Then you don't have to plumb through the
> 'first_hit' parameter from btrfs_abort_transaction(), and this change
> becomes even more minimal than it already is.

Sounds pretty awesome!

Thanks,
Qu

Re: [PATCH v2 4/4] btrfs: dump all space infos if we abort transaction due to ENOSPC

[Sweet Tea Dorminy]

>>> +}
>> This function looks similar to btrfs_dump_space_info(), and the name and
>> callsite doesn't help distinguish it very much to me. It seems
>> potentially useful to print all the space_infos when one space_info
>> encounters a problem,
> 
> This is fine for trans abort dump, but may not be a good idea for
> enospc_debug output.
> 
> enospc_debug can be triggered way more frequent than trans abort, and
> the extra info of unrelated space info may just be noise.
>> and it seems potentially useful to print the block
>> group infos when we're dumping all the space infos already, so maybe the
>> two functions could be combined.
> 
> You mean block group infos? That can be very large for large fses.
> Thus it's avoided for most call sites other than btrfs_reserve_extent().

I appreciate the explanation, I now agree it makes sense to keep the 
dump-all function separate.
Maybe you could move the new dump-all function up beside the dump-one 
function, and name it btrfs_dump_all_space_infos()? I still find the 
name btrfs_dump_fs_space_info() a little hard to distinguish from the 
others, and prefer 'all' being in the function name, but it's only a 
mild preference.

Re: [PATCH v2 4/4] btrfs: dump all space infos if we abort transaction due to ENOSPC

[Qu Wenruo]

On 2022/7/20 09:43, Sweet Tea Dorminy wrote:
> 
>>>> +}
>>> This function looks similar to btrfs_dump_space_info(), and the name and
>>> callsite doesn't help distinguish it very much to me. It seems
>>> potentially useful to print all the space_infos when one space_info
>>> encounters a problem,
>>
>> This is fine for trans abort dump, but may not be a good idea for
>> enospc_debug output.
>>
>> enospc_debug can be triggered way more frequent than trans abort, and
>> the extra info of unrelated space info may just be noise.
>>> and it seems potentially useful to print the block
>>> group infos when we're dumping all the space infos already, so maybe the
>>> two functions could be combined.
>>
>> You mean block group infos? That can be very large for large fses.
>> Thus it's avoided for most call sites other than btrfs_reserve_extent().
> 
> I appreciate the explanation, I now agree it makes sense to keep the 
> dump-all function separate.

Although I'm considering extra dumping, not the level of each block 
groups, but each device (including used, unallocated, and the max hole 
size).

That info can be important for metadata over-reserve cases, but that can 
be done later.

> Maybe you could move the new dump-all function up beside the dump-one 
> function, and name it btrfs_dump_all_space_infos()?

That indeed looks like a much better name, would go that solution, after 
determining if the split lines are to stay or not.

Thanks,
Qu

> I still find the 
> name btrfs_dump_fs_space_info() a little hard to distinguish from the 
> others, and prefer 'all' being in the function name, but it's only a 
> mild preference.

Re: [PATCH v2 4/4] btrfs: dump all space infos if we abort transaction due to ENOSPC

[David Sterba]

On Wed, Jul 20, 2022 at 09:03:33AM +0800, Qu Wenruo wrote:
> >> @@ -346,12 +346,14 @@ void __cold btrfs_err_32bit_limit(struct
> >> btrfs_fs_info *fs_info)
> >>   __cold
> >>   void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
> >>                      const char *function,
> >> -                   unsigned int line, int errno)
> >> +                   unsigned int line, int errno, bool first_hit)
> >>   {
> >>       struct btrfs_fs_info *fs_info = trans->fs_info;
> >>       WRITE_ONCE(trans->aborted, errno);
> >>       WRITE_ONCE(trans->transaction->aborted, errno);
> >> +    if (first_hit && errno == -ENOSPC)
> >> +        btrfs_dump_fs_space_info(fs_info);
> >>       /* Wake up anybody who may be waiting on this transaction */
> >>       wake_up(&fs_info->transaction_wait);
> >>       wake_up(&fs_info->transaction_blocked_wait);
> > DO_ONCE_LITE(btrfs_dump_fs_space_info, fs_info) from <linux/once_lite.h>
> > seems like a more lightweight way to dump the space infos once upon
> > first transaction abort. Then you don't have to plumb through the
> > 'first_hit' parameter from btrfs_abort_transaction(), and this change
> > becomes even more minimal than it already is.
> 
> Sounds pretty awesome!

But DO_ONCE_LITE stores the status in one static variable, this cant' be
used because we want to track the status per filesystem, and also per
mount. Ie. repeated ENOSPC after umount/mount cycle won't be reported,
also another filesystem hitting abort due to ENOSPC.

The first_hit logic as you have it now that passes the first transaction
abort to the report is correct.

Re: [PATCH v2 4/4] btrfs: dump all space infos if we abort transaction due to ENOSPC

[Sweet Tea Dorminy]

On 7/26/22 14:20, David Sterba wrote:
> On Wed, Jul 20, 2022 at 09:03:33AM +0800, Qu Wenruo wrote:
>>>> @@ -346,12 +346,14 @@ void __cold btrfs_err_32bit_limit(struct
>>>> btrfs_fs_info *fs_info)
>>>>    __cold
>>>>    void __btrfs_abort_transaction(struct btrfs_trans_handle *trans,
>>>>                       const char *function,
>>>> -                   unsigned int line, int errno)
>>>> +                   unsigned int line, int errno, bool first_hit)
>>>>    {
>>>>        struct btrfs_fs_info *fs_info = trans->fs_info;
>>>>        WRITE_ONCE(trans->aborted, errno);
>>>>        WRITE_ONCE(trans->transaction->aborted, errno);
>>>> +    if (first_hit && errno == -ENOSPC)
>>>> +        btrfs_dump_fs_space_info(fs_info);
>>>>        /* Wake up anybody who may be waiting on this transaction */
>>>>        wake_up(&fs_info->transaction_wait);
>>>>        wake_up(&fs_info->transaction_blocked_wait);
>>> DO_ONCE_LITE(btrfs_dump_fs_space_info, fs_info) from <linux/once_lite.h>
>>> seems like a more lightweight way to dump the space infos once upon
>>> first transaction abort. Then you don't have to plumb through the
>>> 'first_hit' parameter from btrfs_abort_transaction(), and this change
>>> becomes even more minimal than it already is.
>>
>> Sounds pretty awesome!
> 
> But DO_ONCE_LITE stores the status in one static variable, this cant' be
> used because we want to track the status per filesystem, and also per
> mount. Ie. repeated ENOSPC after umount/mount cycle won't be reported,
> also another filesystem hitting abort due to ENOSPC.

That's a great point, I agree it would be better to print the first 
abort per filesystem/mount instead of only once per reboot now that it's 
noted.

Re: [PATCH v2 0/4] btrfs: output more info for -ENOSPC caused transaction abort and other enhancement

[David Sterba]

On Tue, Jul 19, 2022 at 01:11:14PM +0800, Qu Wenruo wrote:
> [Changelog]
> v2:
> - Add a new line to show the meaning of the metadata dump.
>   Previous output only includes the reserved bytes and size bytes,
>   but not showing which is which, thus still need to check the code

There are some nontrivial pending changes for this patchset, so I can't
merge it to for-next. Please send v3.

Re: [PATCH v2 0/4] btrfs: output more info for -ENOSPC caused transaction abort and other enhancement

[Qu Wenruo]

On 2022/8/24 23:53, David Sterba wrote:
> On Tue, Jul 19, 2022 at 01:11:14PM +0800, Qu Wenruo wrote:
>> [Changelog]
>> v2:
>> - Add a new line to show the meaning of the metadata dump.
>>    Previous output only includes the reserved bytes and size bytes,
>>    but not showing which is which, thus still need to check the code
>
> There are some nontrivial pending changes for this patchset, so I can't
> merge it to for-next. Please send v3.

Thanks for reminding me of this series, I'll update them to address the
comments on the multi-line output format (aka, drop all the re-format
patches) and refresh them soon.

Thanks,
Qu