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

From: xiang xiao <xiaoxiang781216@gmail.com>
To: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>,
	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
	linux-kernel@vger.kernel.org, Xiang Xiao <xiaoxiang@xiaomi.com>
Subject: Re: [PATCH] printk: add KERN_NOTIME to skip the timestamp
Date: Wed, 13 Feb 2019 21:49:30 +0800	[thread overview]
Message-ID: <CAH2Cfb-5-ZxQPBTx_Gxt9kK3DqwTOS1Z6RVJ-ewMSB2-U0eTRg@mail.gmail.com> (raw)
In-Reply-To: <20190213131912.4w3fonbgwjathpyp@pathway.suse.cz>

On Wed, Feb 13, 2019 at 9:19 PM Petr Mladek <pmladek@suse.com> wrote:
>
> On Wed 2019-02-13 14:19:01, xiang xiao wrote:
> > On Wed, Feb 13, 2019 at 3:46 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > > On Wed, 13 Feb 2019 02:11:05 +0800
> > > Xiang Xiao <xiaoxiang781216@gmail.com> 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@i-love.sakura.ne.jp
>
>
> Best Regards,
> Petr