Messages in this thread | | | Date | Wed, 10 Sep 2014 14:26:27 -0700 | From | Andrew Morton <> | Subject | Re: [PATCH] printk: Print cpu number along with time |
| |
On Tue, 9 Sep 2014 13:16:58 -0400 J__rn Engel <joern@logfs.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@logfs.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@logfs.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@logfs.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!
| |