Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Thu, 21 Jun 2018 17:29:49 +0900
From:   Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
To:     Dmitry Vyukov <dvyukov@google.com>
Cc:     Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>,
        Petr Mladek <pmladek@suse.com>,
        Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp>,
        Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
        syzkaller <syzkaller@googlegroups.com>,
        Steven Rostedt <rostedt@goodmis.org>,
        Fengguang Wu <fengguang.wu@intel.com>,
        LKML <linux-kernel@vger.kernel.org>,
        Linus Torvalds <torvalds@linux-foundation.org>,
        Andrew Morton <akpm@linux-foundation.org>
Subject: Re: [PATCH] printk: inject caller information into the body of
 message
Message-ID: <20180621082949.GB677@jagdpanzerIV>
References: <20180524021451.GA23443@jagdpanzerIV>
 <CACT4Y+brbqfBWntjVaj-Ri2WhBdXpkA_PYs59qgLZ0vtepZEtw@mail.gmail.com>
 <CACT4Y+ZGSefrYL9xtQs=yPMRNFsOUumuJXsShJPhCOBSLySxuw@mail.gmail.com>
 <20180620083126.GA477@jagdpanzerIV>
 <CACT4Y+YMubTm1xduj+XCbQnNwQxYFLjBT33cFKisN1HyeaBpZw@mail.gmail.com>
 <20180620090413.GA444@jagdpanzerIV>
 <20180620091541.GB444@jagdpanzerIV>
 <CACT4Y+bcp4fSBBq3F86T-C4+n-YkeXUGMqpvkJ6vj6mK-TU2EA@mail.gmail.com>
 <20180620110759.GD444@jagdpanzerIV>
 <CACT4Y+aER3O2x2ApM=MVFoFXhp_T_rUeyG9CBx031qyH0voSRg@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <CACT4Y+aER3O2x2ApM=MVFoFXhp_T_rUeyG9CBx031qyH0voSRg@mail.gmail.com>
User-Agent: Mutt/1.10.0 (2018-05-17)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On (06/20/18 13:32), Dmitry Vyukov wrote:
> >>
> >> So this is another reason to get rid of pr_cont entirely, right?
> >
> > Getting rid of pr_cont() from important output would be totally cool.
> > Quoting Linus:
> >
> >     Only acceptable use of continuations is basically boot-time testing,
> >     when you do things like
> >
> >      printk("Testing feature XYZ..");
> >      this_may_blow_up_because_of_hw_bugs();
> >      printk(KERN_CONT " ... ok\n");
> >
> >
> > I can recall at least 4 attempts when people tried to introduce new pr_cont()
> > or some concept with similar functionality to pr_cont(), but SMP safe. We
> > brought the first one - per-CPU pr_cont() buffers - to KS several years ago
> > but Linus didn't like it. Then there was a buffered printk() mode patch from
> > Tetsuo, then a solution from Steven, then I had my second try with a
> > soft-of-pr_cont() replacement.
> >
> > So, if we could get rid of pr_cont() from the most important parts
> > (instruction dumps, etc) then I would just vote to leave pr_cont()
> > alone and avoid any handling of it in printk context tracking. Simply
> > because we wouldn't care about pr_cont(). This also could simplify
> > Tetsuo's patch significantly.
> 
> Sounds good to me.

Another thing about pr_cont() is that as long as pr_cont() does not race
with pr_cont() from another task or from IRQ, the task that is the owner
(see struct cont in printk.c) of the existing continuation line can migrate,
IOW we can have

	CPU0	CPU1	CPU2	CPU3

	task A
	pr_cont()
		task A
		pr_cont()
			task A
			pr_cont()
				task A
				pr_cont("\n") << flush

The line was printed from 4 CPUs, but appears as a single line
in the logbuf. Should we account CPU0 or CPU3 as the line origin?

That's another reason why I don't really want to handle pr_cont in
any special way in context tracking.

So, currently, context tracking looks like this:

---
	char mode = 'T';

	if (in_serving_softirq())
		mode = 'S';
	if (in_irq())
		mode = 'I';
	if (in_nmi())
		mode = 'N';

	ret = snprintf(buf, buf_len, "%c<%d>%c",
			mode,
			raw_smp_processor_id(),
			cont.len ? '+' : ' ');
---

I add a '+' symbol to continuation lines. Which should simply hint
that tracking info for that particular line is not entirely trustworthy.

I also don't add any tracking info for printk_safe output. We get
tracking info for such lines from the printk_safe flush path
(irq work that happens on the same CPU that added printk_safe output).

	-ss