linux-kernel - Re: [PATCH] printk: Print cpu number along with time

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite for Android: free password hash cracker in your pocket

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Message-Id: <20140910142627.fcbf8c2fd7a8e6e5a8f5a69d@linux-foundation.org>
Date:	Wed, 10 Sep 2014 14:26:27 -0700
From:	Andrew Morton <akpm@...ux-foundation.org>
To:	Jörn Engel <joern@...fs.org>
Cc:	Jiri Kosina <jkosina@...e.cz>, Rik van Riel <riel@...hat.com>,
	linux-kernel@...r.kernel.org, peterz@...radead.org,
	cxie@...hat.com, Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
	Jiri Slaby <jslaby@...e.cz>
Subject: Re: [PATCH] printk: Print cpu number along with time

On Tue, 9 Sep 2014 13:16:58 -0400 J__rn Engel <joern@...fs.org> wrote:

> On Wed, 4 June 2014 19:15:06 -0400, J__rn Engel wrote:
> > On Mon, 28 April 2014 17:22:19 -0700, Andrew Morton wrote:
> > > On Mon, 28 Apr 2014 19:40:39 -0400 J__rn Engel <joern@...fs.org> wrote:
> > > > On Thu, 24 April 2014 15:40:24 -0400, J__rn Engel wrote:
> > > > > On Wed, 23 April 2014 20:52:47 -0400, J__rn Engel wrote:
> > > > > > 
> > > > > > I use the patch below for some time now.  While it doesn't avoid the
> > > > > > log pollution in the first place, it lessens the impact somewhat.
> > > > > 
> > > > > Added a config option and ported it to current -linus.  Andrew, would
> > > > > you take this patch?
> > > > 
> > > > Andrew?  Did you dislike this patch for some reason or just miss it in
> > > > the thread?
> > > 
> > > Neither ;) I try to respond in some way to all patches unless I think it's clear
> > > to the originator why I took no action.  And I think I'm pretty good at
> > > not losing stuff.
> > > 
> > > otoh, it has only been four days, three of which I spent offline...
> > 
> > Ping.
> 
> Ping.

It needs a resend please.

A few thoughts:

On Thu, 24 Apr 2014 15:40:24 -0400 J__rn Engel <joern@...fs.org> wrote:
> 
> Sometimes the printk log is heavily interleaving between different cpus.
> This is particularly bad when you have two backtraces at the same time,
> but can be annoying in other cases as well.  With an explicit cpu
> number, a simple grep can disentangle the mess for you.
> 
> Signed-off-by: Joern Engel <joern@...fs.org>
> ---
>  kernel/printk/printk.c | 19 ++++++++++++++++---
>  lib/Kconfig.debug      |  9 +++++++++
>  2 files changed, 25 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index a45b50962295..b9e464924825 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -200,6 +200,7 @@ struct printk_log {
>  	u16 len;		/* length of entire record */
>  	u16 text_len;		/* length of text buffer */
>  	u16 dict_len;		/* length of dictionary buffer */
> +	u16 cpu;		/* cpu the message was generated on */
>  	u8 facility;		/* syslog facility */
>  	u8 flags:5;		/* internal record flags */
>  	u8 level:3;		/* syslog level */
> @@ -346,6 +347,7 @@ static void log_store(int facility, int level,
>  	msg->facility = facility;
>  	msg->level = level & 7;
>  	msg->flags = flags & 0x1f;
> +	msg->cpu = smp_processor_id();

Are you sure this won't generate smp_processor_id-in-preemptible
warnings?  log_store has several callers..

>  	if (ts_nsec > 0)
>  		msg->ts_nsec = ts_nsec;
>  	else
> @@ -859,7 +861,7 @@ static bool printk_time;
>  #endif
>  module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
>  
> -static size_t print_time(u64 ts, char *buf)
> +static size_t print_time(u64 ts, u16 cpu, char *buf)

The name is now wrong - it prints cpu number as well as time.

>  {
>  	unsigned long rem_nsec;
>  
> @@ -868,11 +870,20 @@ static size_t print_time(u64 ts, char *buf)
>  
>  	rem_nsec = do_div(ts, 1000000000);
>  
> +#ifdef CONFIG_PRINTK_CPU

This is regrettable.  If someone wants the CPU number they have to
compile and install a new kernel?  That's often impractical so we have
to hope that everyone enables the feature.  And if they do that, why
did we need the Kconfigurability?

We have a printk.time boot parameter, so adding printk.cpu seems natural?

+		return snprintf(NULL, 0, "[%5lu.000000,%02x] ",

Printing hex numbers without 0x is just nasty.  "11" = 17, surprise!
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/