lkml.org 
[lkml]   [2022]   [Jan]   [26]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Date
SubjectRe: [PATCH] kernel: count warnings and make count accessible to userspace
On Tue, Jan 25, 2022 at 12:52 AM Petr Mladek <pmladek@suse.com> wrote:
>
> Adding Andrew back to Cc :-)
>
> On Sat 2022-01-22 12:58:39, John Sperbeck wrote:
> > On Wed, Jan 19, 2022 at 4:01 AM Petr Mladek <pmladek@suse.com> wrote:
> > >
> > > Adding Andrew into Cc. Most changes in panic.c go via his tree.
> > >
> > > On Tue 2022-01-18 06:04:31, John Sperbeck wrote:
> > > > When testing, it's common to consider a warning to be a test failure,
> > > > but it's currently awkward to determine which of multiple sequential
> > > > tests is responsible for triggering a warning. Scraping dmesg or
> > > > /var/log/messages is somewhat expensive and error-prone. Setting
> > > > panic_on_warn is reliable, but spoils test runs for minor issues.
> > > > Looking at the taint bit is also reliable, but only works for a single
> > > > warning.
> > > >
> > > > We can track the warning count and expose it as a sysfs file. Test
> > > > infrastructures can snapshot the value before and after a test. If
> > > > the value changes, they can do more expensive things like extracting
> > > > logs.
> > >
> > > The counter makes sense. It might be useful even for normal debugging.
> > > It would be nice to show the value in the log.
> > >
> > > > Signed-off-by: John Sperbeck <jsperbeck@google.com>
> > > > ---
> > > > kernel/panic.c | 5 +++++
> > > > 1 file changed, 5 insertions(+)
> > > >
> > > > diff --git a/kernel/panic.c b/kernel/panic.c
> > > > index cefd7d82366f..5262c2a0ebf4 100644
> > > > --- a/kernel/panic.c
> > > > +++ b/kernel/panic.c
> > > > @@ -571,6 +571,8 @@ struct warn_args {
> > > > va_list args;
> > > > };
> > > >
> > > > +static atomic_t __maybe_unused warn_counter;
> > > > +
> > > > void __warn(const char *file, int line, void *caller, unsigned taint,
> > > > struct pt_regs *regs, struct warn_args *args)
> > > > {
> > > > @@ -612,6 +614,8 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
> > > >
> > > > /* Just a warning, don't kill lockdep. */
> > > > add_taint(taint, LOCKDEP_STILL_OK);
> > > > +
> > > > + atomic_inc(&warn_counter);
> > > > }
> > > >
> > > > #ifndef __WARN_FLAGS
> > > > @@ -667,6 +671,7 @@ static __init int register_warn_debugfs(void)
> > > > /* Don't care about failure */
> > > > debugfs_create_file_unsafe("clear_warn_once", 0200, NULL, NULL,
> > > > &clear_warn_once_fops);
> > > > + debugfs_create_atomic_t("warn_count", 0444, NULL, &warn_counter);
> > >
> > > Is the sysfs interface really important for you use case, please?
> > > Would the value in the log be enough?
> > >
> > > Anyway, we already count the number WARN() reports. It is quite hidden
> > > and hashed in init_oops_id()/print_oops_end_marker().
> > >
> > > A solution would be to make this hidden counter more explicit.
> > > Something like:
> > >
> > > diff --git a/kernel/panic.c b/kernel/panic.c
> > > index cefd7d82366f..8ac19124ceb4 100644
> > > --- a/kernel/panic.c
> > > +++ b/kernel/panic.c
> > > @@ -537,13 +537,12 @@ void oops_enter(void)
> > > * 64-bit random ID for oopses:
> > > */
> > > static u64 oops_id;
> > > +static int oops_cnt;
> > >
> > > static int init_oops_id(void)
> > > {
> > > if (!oops_id)
> > > get_random_bytes(&oops_id, sizeof(oops_id));
> > > - else
> > > - oops_id++;
> > >
> > > return 0;
> > > }
> > > @@ -552,7 +551,9 @@ late_initcall(init_oops_id);
> > > static void print_oops_end_marker(void)
> > > {
> > > init_oops_id();
> > > - pr_warn("---[ end trace %016llx ]---\n", (unsigned long long)oops_id);
> > > + oops_cnt++;
> > > + pr_warn("---[ end trace %016llx:%d ]---\n",
> > > + (unsigned long long)oops_id, oops_cnt);
> > > }
> > >
> > > /*
> > >
> > >
> > > The report would like like:
> > >
> > > [ 1871.476204] WARNING: CPU: 2 PID: 2003 at samples/livepatch/livepatch-sample.c:60 livepatch_init+0x11/0x20 [livepatch_sample]
> > > [ 1871.476905] Modules linked in: livepatch_sample(EK+) [last unloaded: livepatch_sample]
> > > [ 1871.477509] CPU: 2 PID: 2003 Comm: modprobe Tainted: G W E K 5.16.0-default+ #312
> > > [ 1871.478175] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014
> > > [ 1871.478858] RIP: 0010:livepatch_init+0x11/0x20 [livepatch_sample]
> > > [...]
> > > [ 1871.489801] hardirqs last disabled at (9188): [<ffffffffb217aa4e>] vprintk_emit+0x21e/0x2b0
> > > [ 1871.489803] softirqs last enabled at (9096): [<ffffffffb3000364>] __do_softirq+0x364/0x4ab
> > > [ 1871.489805] softirqs last disabled at (9083): [<ffffffffb20efb5d>] irq_exit_rcu+0x10d/0x120
> > > [ 1871.489807] ---[ end trace a19f0f55262cfcc8:2 ]---
> > >
> > > Best Regards,
> > > Petr
> >
> > Thanks for adding the CC.
> >
> > The sysfs interface was kind of the main thing I'm after. The intent is
> > to avoid parsing logs unless something interesting is likely to be there.
> >
> > If we were to rely entirely on log parsing, adding a count to the logs
> > doesn't add much, I think. That is, if a warning is parsed, then we
> > already know it occurred, and don't need the counter value in the message
> > that we parsed to tell us what we just discovered.
>
> Fair enough.
>
> > I see some precedent for exposing counts for things like this: lockdep,
> > kfence, DMA-API debug. Warnings, KASAN, and UBSAN are some areas that
> > don't have this convenience.
>
> I see.
>
> > If the sysfs interface isn't palatable, that's okay. Supporting a
> > three-line patch locally isn't a tremendous burden.
>
> I am not against the debugfs interface. The counter might be useful.
>
> Well, I would still combine it with my proposal. The number of
> warnings is already "counted" by the number printed in
> 'end trace XXXXXXXXXXXXXX' line. It does not make sense to
> add yet another counter.
>
> Best Regards,
> Petr

I'm not sure I understand the comment that it doesn't make sense to
add yet another counter? Isn't the alternate proposal to add
'oops_cnt' adding a counter?

Also, is a simple 'int' adequate? Are there any concerns about
multiple CPUs calling warn at the same time?

I'm also wondering about the ramifications of changing the format of a
string that the log-scraping crowd might use for identifying the end
of a warning?

Finally, wouldn't dropping the 'oops_id++' from init_oops_id() lose
the intent of d6624f996ae5 ("oops: increment the oops UUID every time
we oops")?

\
 
 \ /
  Last update: 2022-01-27 01:23    [W:0.477 / U:0.396 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site