Received: by 2002:a05:6a10:af89:0:0:0:0 with SMTP id iu9csp4023956pxb; Tue, 25 Jan 2022 01:39:11 -0800 (PST) X-Google-Smtp-Source: ABdhPJz9UOgs4LLS2j53G5oAFtQqCMGYMgIy9C6CSUa+LNEPsg55y+EZKm1k5hSalDmd324khbms X-Received: by 2002:a17:90a:fe2:: with SMTP id 89mr2613215pjz.162.1643103551040; Tue, 25 Jan 2022 01:39:11 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1643103551; cv=none; d=google.com; s=arc-20160816; b=0i0jcX2+cVO1mTDEd6ekJmmjEcXUFOamHnmdu5AbHseN8ijZulD4EEr22ZkbGkChOm SOzT4RnVlG3svRj6t2aodi9NiYZWwILGuE5eMCJP+MY6trXDNUZVcfg+cLNccbcP5PeU hJfQrQgJD1sUFdmO1h7q7YKFKInUt7C3QoIZnMM8mKUZEAh8vxtnPoCf72KSAV9hTovm gwmBzrdZFCMb6xASvLFCE97nE6HvcpSvvOH7DSstvF/ked2zZphX4UQneosNEvHHYiia oVrc1g/0f13PVZu+m0db6V6CGalE2C/z2QaoLml3Y10fK4yAYg8pyTn2KVyxktgeRUyK spBg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:in-reply-to:content-disposition:mime-version :references:message-id:subject:cc:to:from:date:dkim-signature; bh=bXSEp2XleIcO4xphn/mhCtpq46oflmZEb9NkcmEhGJc=; b=zOyQF2WxmVcVMk+njj3Xf1Ped8RM3kNZJO65m+DqGPEXqk6zTRMqedu81iP33tJSdg kZonT5KeWMZQNyuGMpPoQh9G2V9x4gMeMVHqXr8RUIYW3A+Ui/efsAOp1A29sDLGvWlL lxr3GFtBrkSAerZBQUDbQ/w33++FbHVz3f9Ukt8/gtgU0tStxkHn6yfgLO+0Qo/BMXJL DmK0T8qBuA+F8mDLaX63TuVKe/vrB95Ztrwk/1mNNb/Airukh2HRRmLzNGTpi0IHDgNs se4UinKJ9doEHm8K+1GKrZBrjPIlMY2nnStvlnPposAVdSGj6CMt8aM+9mIVT2l9Iaxg Wl6A== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@suse.com header.s=susede1 header.b=lM8bWip5; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=QUARANTINE sp=NONE dis=NONE) header.from=suse.com Return-Path: Received: from vger.kernel.org (vger.kernel.org. [23.128.96.18]) by mx.google.com with ESMTP id u15si20876pjr.84.2022.01.25.01.38.58; Tue, 25 Jan 2022 01:39:11 -0800 (PST) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18; Authentication-Results: mx.google.com; dkim=pass header.i=@suse.com header.s=susede1 header.b=lM8bWip5; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=QUARANTINE sp=NONE dis=NONE) header.from=suse.com Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1453884AbiAYI4R (ORCPT + 99 others); Tue, 25 Jan 2022 03:56:17 -0500 Received: from smtp-out1.suse.de ([195.135.220.28]:42574 "EHLO smtp-out1.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1453141AbiAYIwk (ORCPT ); Tue, 25 Jan 2022 03:52:40 -0500 Received: from relay2.suse.de (relay2.suse.de [149.44.160.134]) by smtp-out1.suse.de (Postfix) with ESMTP id 067522199F; Tue, 25 Jan 2022 08:52:31 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.com; s=susede1; t=1643100751; h=from:from:reply-to:date:date:message-id:message-id:to:to:cc:cc: mime-version:mime-version:content-type:content-type: in-reply-to:in-reply-to:references:references; bh=bXSEp2XleIcO4xphn/mhCtpq46oflmZEb9NkcmEhGJc=; b=lM8bWip5ZAIwddDfEpaQ0+9RtSe4juKsVAUpy0pnoWhyzKIviWEJLTdbne8sHgFQAcjG3n c6k9BH2w7cdFamFgFZpkezS38qa1Fecx45KLLQu6ICBiaFjd10qymZlU4IOweEs6tdwZtC Kl+TchZQPYqJRtZstKiAc3nrrvQu9Ec= Received: from suse.cz (unknown [10.100.224.162]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by relay2.suse.de (Postfix) with ESMTPS id 91BEBA3B83; Tue, 25 Jan 2022 08:52:30 +0000 (UTC) Date: Tue, 25 Jan 2022 09:52:27 +0100 From: Petr Mladek To: John Sperbeck Cc: Steven Rostedt , John Ogness , Andrew Morton , linux-kernel@vger.kernel.org Subject: Re: [PATCH] kernel: count warnings and make count accessible to userspace Message-ID: References: <20220118060431.1368538-1-jsperbeck@google.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 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 > > > --- > > > 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): [] vprintk_emit+0x21e/0x2b0 > > [ 1871.489803] softirqs last enabled at (9096): [] __do_softirq+0x364/0x4ab > > [ 1871.489805] softirqs last disabled at (9083): [] 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