Re: [PATCH] printk: inject caller information into the body of message

[Petr Mladek]

On Thu 2018-05-17 20:21:35, Sergey Senozhatsky wrote:
> On (05/11/18 20:58), Tetsuo Handa wrote:
> > @@ -1820,6 +1860,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
> >  			return text_len;
> >  	}
> >  
> > +	/* Inject caller info. */
> > +	text = printk_inject_caller_info(text, &text_len);
> > +
> >  	/* Store it in the record log */
> >  	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
> >  }
> 
> [..]
> 
> I think this is slightly intrusive. I understand that you want to avoid
> struct printk_log modification, let's try to see if we have any other
> options.

I agree with Sergey that it is intrusive. We should keep the
information separate from the original string and format it
according to the selected output format (syslog, /dev/kmsg,
console) like we do it with the other metadata, e.g. timestamp,
loglevel, dict).


> Dunno...
> For instance, can we store context tracking info as a extended record
> data? We have that dict/dict_len thing. So may we can store tracking
> info there? Extended records will appear on the serial console /* if
> console supports extended data */ or can be read in via devkmsg_read().
> Any other options?

This sounds interesting. Well, we would need to handle different dict
items different ways. I still wonder if we really need these "hacks".

Another option would be to store the metadata into a separate table
indexed by log_seq number. But it still look unnecessarily complicated.

IMHO, we could change struct printk_log if we provide related
patches for crashdump and crash utilities.


Important:

First, we should ask what we expect from this feature. Different
information might be needed in different situations. In general,
people might want to know:

  + CPUid even in task context
  + exact interrupt context (soft, hard, NMI)
  + whether preemption or interrupts are enabled

It still looks bearable. But what if people want more,
e.g. context switch counts, task state, pending signals,
mem usage, cgroup stuff.

Is this information useful for all messages or only
selected ones?

Is it acceptable when message prefix is longer than, let's
say 40 characters?

Is the extended output worth having even on slow consoles?


By other words, I wonder if you wanted similar feature in many
situations in the past and could provide more use cases.


Note:

The proposed patch enabled the extra info with a config option
=> you need to rebuild the kernel => you could just modify
the problematic message. We could just add some printk_ helpers
to make it easier.

Alternatively, I wonder if it might be enough to add a tracepoint
into printk() and get the extra info via
/sys/kernel/debug/tracing/events/. We would need to prevent
recursion when trace buffer is flushed by printk() but...

Best Regards,
Petr