Re: [PATCH] printk: add KERN_NOTIME to skip the timestamp

[xiang xiao]

On Wed, Feb 13, 2019 at 9:19 PM Petr Mladek <pmladek@xxxxxxxx> wrote:
>
> On Wed 2019-02-13 14:19:01, xiang xiao wrote:
> > On Wed, Feb 13, 2019 at 3:46 AM Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> > >
> > > On Wed, 13 Feb 2019 02:11:05 +0800
> > > Xiang Xiao <xiaoxiang781216@xxxxxxxxx> wrote:
> > >
> > > > Because log may already add the timestamp sometime
> > >
> > > Can you be a bit more detailed on this. When and where does this
> > > happen?
> >
> > Here is my case:
> > 1.A small MCU(Cortex M4) in SoC run RTOS
> > 2.RTOS append timestamp to log for the accurate timing
> > 3.RTOS send log to Linux kernel when buffer exceed the threshold
>
> What do you exactly mean by the threshold, please?

The current algorithm is:
1.the free space is less than 25% or
2.the idle time is large than 100ms

> Does it mean
> that you use the kernel buffer when there are too many messages
> and they do not fit into the MCU local buffer?

The buffering just happen in MCU side, kernel don't do any buffering
except waiting for '\n' before printk.

>
> How exactly the kernel gets the messages, please?
> Via a kernel driver or from userspace (via /dev/kmsg)?
>

It's a kernel rpmsg driver:
https://github.com/thesofproject/linux/pull/177/commits/a0b7009fede5552dc98733f2996a8140bff62455

>
> > 4.Kernel call printk to dump the received buffer
> > So I want that printk skip the timestamp here.
>
> If the messages are printed by a kernel driver then
> a better solution would be to create a printk() API
> where you could pass the time stamp as a parameter.

Yes, this is a better approach and could fix all issues you list below.

>
> The aim is to store the precise time stamp in ts_nsec, struct
> printk_log. Then it will get handled correctly by any
> output, e.g. consoles, syslog, /dev/kmsg.
>
>
> There are several problems with your approach:
>
> 1. The time stamp is still duplicated in the output via /dev/kmsg,
>    see msg_print_ext_header(). We could not change this
>    because the time stamp is part of the format.
>    Any change could break userspace (systemd).
>
>
> 2. The time stamp stays part of the message:
>
>      + It might have different format than the normal
>        time stamp. Therefore it might be hard to filter
>
>      + dmesg might be unable to parse it and show in
>        the other formats.
>
>      + Kernel-5.1 will allow to print information
>        about the caller. It is supposed to be between
>        the time stamp and the message text, see
>        http://lkml.kernel.org/r/93f19e57-5051-c67d-9af4-b17624062d44@xxxxxxxxxxxxxxxxxxx
>
>
> Best Regards,
> Petr