| Message ID | dc40ddc78b7173d757065dcdde910bcf593d3a5c.1658207325.git.wqu@suse.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | btrfs: output more info for -ENOSPC caused transaction abort and other enhancement | expand |
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);
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.
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.
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.
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.
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.
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'
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.
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
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.
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);