From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by smtp.lore.kernel.org (Postfix) with ESMTP id 1063AC433F5 for ; Mon, 2 May 2022 08:30:37 +0000 (UTC) Received: by kanga.kvack.org (Postfix) id 4371C6B0072; Mon, 2 May 2022 04:30:37 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 3E6B96B0073; Mon, 2 May 2022 04:30:37 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id 2AE076B0074; Mon, 2 May 2022 04:30:37 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from relay.hostedemail.com (relay.hostedemail.com [64.99.140.27]) by kanga.kvack.org (Postfix) with ESMTP id 182B56B0072 for ; Mon, 2 May 2022 04:30:37 -0400 (EDT) Received: from smtpin05.hostedemail.com (a10.router.float.18 [10.200.18.1]) by unirelay07.hostedemail.com (Postfix) with ESMTP id DD70C21C11 for ; Mon, 2 May 2022 08:30:36 +0000 (UTC) X-FDA: 79420131672.05.CC7D113 Received: from smtp-out2.suse.de (smtp-out2.suse.de [195.135.220.29]) by imf17.hostedemail.com (Postfix) with ESMTP id E61874006D for ; Mon, 2 May 2022 08:30:24 +0000 (UTC) Received: from relay2.suse.de (relay2.suse.de [149.44.160.134]) by smtp-out2.suse.de (Postfix) with ESMTP id E87281F38C; Mon, 2 May 2022 08:30:34 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.com; s=susede1; t=1651480234; 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=m5U9elRICPWSleScnMCrzm3cSvSDZ+t1d2mLrc+xdPA=; b=GrDoFmUIFdZ8y5dGow0KnPTRdoogF2Pvy/witwTizJGhkPqEz16PdCw33yjLy8AXllvUoz uzWsGoopijmEHEFBsKBYR2W1Zv4QyH4mv4Yn8k3oXIhCBGiQyWVw5xjbGfXIgPsnznb8Jh xC0ejVxLrKeflIkvR4VIo4XQqu9s7C0= 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 DDE392C142; Mon, 2 May 2022 08:30:33 +0000 (UTC) Date: Mon, 2 May 2022 10:30:32 +0200 From: Petr Mladek To: Marco Elver Cc: John Ogness , Naresh Kamboju , Linux-Next Mailing List , open list , lkft-triage@lists.linaro.org, linux-mm , Andrew Morton , Alexander Potapenko , Dmitry Vyukov , Stephen Rothwell , Anders Roxell , Andrey Konovalov , Andrey Ryabinin , Catalin Marinas , Evgenii Stepanov , Mark Rutland , Peter Collingbourne , Vincenzo Frascino , Will Deacon Subject: Re: [next] i386: kunit: ASSERTION FAILED at mm/kfence/kfence_test.c:547 Message-ID: References: <87fslup9dx.fsf@jogness.linutronix.de> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: X-Rspamd-Server: rspam04 X-Rspamd-Queue-Id: E61874006D X-Stat-Signature: mgitesij6ex3zrjcyyrbtq4uy18kzmay X-Rspam-User: Authentication-Results: imf17.hostedemail.com; dkim=pass header.d=suse.com header.s=susede1 header.b=GrDoFmUI; spf=pass (imf17.hostedemail.com: domain of pmladek@suse.com designates 195.135.220.29 as permitted sender) smtp.mailfrom=pmladek@suse.com; dmarc=pass (policy=quarantine) header.from=suse.com X-HE-Tag: 1651480224-779936 X-Bogosity: Ham, tests=bogofilter, spamicity=0.000000, version=1.2.4 Sender: owner-linux-mm@kvack.org Precedence: bulk X-Loop: owner-majordomo@kvack.org List-ID: On Mon 2022-05-02 09:51:46, Marco Elver wrote: > On Sat, Apr 30, 2022 at 11:14PM +0206, John Ogness wrote: > [...] > > I am not familiar with how this works. Is the tracepoint getting set on > > call_console_drivers()? Or on call_console_driver()? > > It's at the start of call_console_drivers(). See trace_console_rcuidle() > call. > > > If so, there are a couple problems with that. First off, the prototype > > for that function has changed. Second, that function is called when text > > is printed, but this is not when the text was created. With the > > kthreads, the printing can be significantly delayed. > > > > Since printk() is now lockless and console printing is delayed, it > > becomes a bit tricky to parse the records in the existing code using a > > tracepoint. > > > > I wonder if creating a NOP function for the kfence probe to attach to > > would be more appropriate. In printk_sprint() we get the text after > > space has been reserved, but before the text is committed to the > > ringbuffer. This is guaranteed to be called from within the printk() > > context. > > I think we just need to fix the existing tracepoint, since it has > changed its semantics vs. what it was intended to be: > > | commit 95100358491abaa2e9a5483811370059bbca4645 > | Author: Johannes Berg > | Date: Thu Nov 24 20:03:08 2011 +0100 > | > | printk/tracing: Add console output tracing > | > | Add a printk.console trace point to record any printk > | messages into the trace, regardless of the current > | console loglevel. This can help correlate (existing) > | printk debugging with other tracing. > | > | Link: http://lkml.kernel.org/r/1322161388.5366.54.camel@jlt3.sipsolutions.net > | > | Acked-by: Frederic Weisbecker > | Cc: Christoph Hellwig > | Cc: Ingo Molnar > | Acked-by: Peter Zijlstra > | Acked-by: Thomas Gleixner > | Signed-off-by: Johannes Berg > | Signed-off-by: Steven Rostedt > > Specifically using it to "correlate (existing) printk debugging with > other tracing" is now broken. It is pity that it was done in the console code in the first place. printk() always used console_trylock() and the message was flushed to the console only when the trylock succeeded. And it was always deferred in NMI or when printed via printk_deferred(). > My proposal would be to fix the tracepoint like so: > > | --- a/kernel/printk/printk.c > | +++ b/kernel/printk/printk.c > | @@ -2002,8 +2002,6 @@ static void call_console_driver(struct console *con, const char *text, size_t le > | { > | size_t dropped_len; > | > | - trace_console_rcuidle(text, len); > | - > | if (con->dropped && dropped_text) { > | dropped_len = snprintf(dropped_text, DROPPED_TEXT_MAX, > | "** %lu printk messages dropped **\n", > | @@ -2178,6 +2176,8 @@ static u16 printk_sprint(char *text, u16 size, int facility, > | } > | } > | > | + trace_console_rcuidle(text, text_len); > | + > | return text_len; > | } > > This fixes the KFENCE and KCSAN tests. > > Unless I hear objections, I'll prepare a patch explaining why we need to > fix the tracepoint. It makes perfect sense to me. Note that there is one difference. The original tracepoint stored the string with the console header (loglevel + timestamp), see info_print_prefix(). The new code will store "only" the plain message. But the new code should be more user friendly. The printk() message will be sorted with the other tracing messages out of box. Users will not longer need to use the printk timestamp to find when it was actually printed. Best Regards, Petr