[PATCH] printk: add KERN_NOTIME to skip the timestamp

[PATCH] printk: add KERN_NOTIME to skip the timestamp

[Xiang Xiao]

Because log may already add the timestamp sometime

Signed-off-by: Xiang Xiao <xiaoxiang@xiaomi.com>
---
 include/linux/kern_levels.h | 2 ++
 include/linux/printk.h      | 1 +
 kernel/printk/printk.c      | 7 ++++++-
 3 files changed, 9 insertions(+), 1 deletion(-)

diff --git a/include/linux/kern_levels.h b/include/linux/kern_levels.h
index d237fe8..ed2aec6 100644
--- a/include/linux/kern_levels.h
+++ b/include/linux/kern_levels.h
@@ -23,6 +23,8 @@
  */
 #define KERN_CONT	KERN_SOH "c"
 
+#define KERN_NOTIME	KERN_SOH "t"	/* don't print the timestamp */
+
 /* integer equivalents of KERN_<LEVEL> */
 #define LOGLEVEL_SCHED		-2	/* Deferred messages from sched code
 					 * are set to this special level */
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 77740a5..be12ac4 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -20,6 +20,7 @@ static inline int printk_get_level(const char *buffer)
 		case '0' ... '7':
 		case 'd':	/* KERN_DEFAULT */
 		case 'c':	/* KERN_CONT */
+		case 't':	/* KERN_NOTIME */
 			return buffer[1];
 		}
 	}
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d3d1703..0688cf2 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -346,6 +346,7 @@ enum log_flags {
 	LOG_NEWLINE	= 2,	/* text ended with a newline */
 	LOG_PREFIX	= 4,	/* text started with a prefix */
 	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
+	LOG_NOTIME	= 16,	/* don't print the timestamp */
 };
 
 struct printk_log {
@@ -1247,7 +1248,7 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,
 
 	if (syslog)
 		len = print_syslog((msg->facility << 3) | msg->level, buf);
-	if (time)
+	if (time && !(msg->flags & LOG_NOTIME))
 		len += print_time(msg->ts_nsec, buf + len);
 	return len;
 }
@@ -1873,6 +1874,10 @@ int vprintk_store(int facility, int level,
 				break;
 			case 'c':	/* KERN_CONT */
 				lflags |= LOG_CONT;
+				break;
+			case 't':	/* KERN_NOTIME */
+				lflags |= LOG_NOTIME;
+				break;
 			}
 
 			text_len -= 2;
-- 
2.7.4

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

[Steven Rostedt]

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? If anything, I would probably prefer that we export whether
time is being printed, and have the caller not print time if printk is
doing it already, than to add the complexity into printk itself.

-- Steve

> 
> Signed-off-by: Xiang Xiao <xiaoxiang@xiaomi.com>
> ---
>  include/linux/kern_levels.h | 2 ++
>  include/linux/printk.h      | 1 +
>  kernel/printk/printk.c      | 7 ++++++-
>  3 files changed, 9 insertions(+), 1 deletion(-)
> 
> diff --git a/include/linux/kern_levels.h b/include/linux/kern_levels.h
> index d237fe8..ed2aec6 100644
> --- a/include/linux/kern_levels.h
> +++ b/include/linux/kern_levels.h
> @@ -23,6 +23,8 @@
>   */
>  #define KERN_CONT	KERN_SOH "c"
>  
> +#define KERN_NOTIME	KERN_SOH "t"	/* don't print the timestamp */
> +
>  /* integer equivalents of KERN_<LEVEL> */
>  #define LOGLEVEL_SCHED		-2	/* Deferred messages from sched code
>  					 * are set to this special level */
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 77740a5..be12ac4 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -20,6 +20,7 @@ static inline int printk_get_level(const char *buffer)
>  		case '0' ... '7':
>  		case 'd':	/* KERN_DEFAULT */
>  		case 'c':	/* KERN_CONT */
> +		case 't':	/* KERN_NOTIME */
>  			return buffer[1];
>  		}
>  	}
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index d3d1703..0688cf2 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -346,6 +346,7 @@ enum log_flags {
>  	LOG_NEWLINE	= 2,	/* text ended with a newline */
>  	LOG_PREFIX	= 4,	/* text started with a prefix */
>  	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
> +	LOG_NOTIME	= 16,	/* don't print the timestamp */
>  };
>  
>  struct printk_log {
> @@ -1247,7 +1248,7 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,
>  
>  	if (syslog)
>  		len = print_syslog((msg->facility << 3) | msg->level, buf);
> -	if (time)
> +	if (time && !(msg->flags & LOG_NOTIME))
>  		len += print_time(msg->ts_nsec, buf + len);
>  	return len;
>  }
> @@ -1873,6 +1874,10 @@ int vprintk_store(int facility, int level,
>  				break;
>  			case 'c':	/* KERN_CONT */
>  				lflags |= LOG_CONT;
> +				break;
> +			case 't':	/* KERN_NOTIME */
> +				lflags |= LOG_NOTIME;
> +				break;
>  			}
>  
>  			text_len -= 2;

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

[Sergey Senozhatsky]

On (02/13/19 02:11), Xiang Xiao wrote:
>
> Because log may already add the timestamp sometime
>

We have module_param(printk_time) which enables/disables
timestamps. And a .config option. And a kernel boot param.
Why would you want KERN_NOTIME?

	-ss

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

[xiang xiao]

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
4.Kernel call printk to dump the received buffer
So I want that printk skip the timestamp here.

> If anything, I would probably prefer that we export whether
> time is being printed, and have the caller not print time if printk is
> doing it already, than to add the complexity into printk itself.

Actually, the timestamp of our initial implementation like your
suggestion come from printk,
but we found that timestamp from kernel isn't accurate as from RTOS
due the buffer and IPC.

>
> -- Steve
>
> >
> > Signed-off-by: Xiang Xiao <xiaoxiang@xiaomi.com>
> > ---
> >  include/linux/kern_levels.h | 2 ++
> >  include/linux/printk.h      | 1 +
> >  kernel/printk/printk.c      | 7 ++++++-
> >  3 files changed, 9 insertions(+), 1 deletion(-)
> >
> > diff --git a/include/linux/kern_levels.h b/include/linux/kern_levels.h
> > index d237fe8..ed2aec6 100644
> > --- a/include/linux/kern_levels.h
> > +++ b/include/linux/kern_levels.h
> > @@ -23,6 +23,8 @@
> >   */
> >  #define KERN_CONT    KERN_SOH "c"
> >
> > +#define KERN_NOTIME  KERN_SOH "t"    /* don't print the timestamp */
> > +
> >  /* integer equivalents of KERN_<LEVEL> */
> >  #define LOGLEVEL_SCHED               -2      /* Deferred messages from sched code
> >                                        * are set to this special level */
> > diff --git a/include/linux/printk.h b/include/linux/printk.h
> > index 77740a5..be12ac4 100644
> > --- a/include/linux/printk.h
> > +++ b/include/linux/printk.h
> > @@ -20,6 +20,7 @@ static inline int printk_get_level(const char *buffer)
> >               case '0' ... '7':
> >               case 'd':       /* KERN_DEFAULT */
> >               case 'c':       /* KERN_CONT */
> > +             case 't':       /* KERN_NOTIME */
> >                       return buffer[1];
> >               }
> >       }
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index d3d1703..0688cf2 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -346,6 +346,7 @@ enum log_flags {
> >       LOG_NEWLINE     = 2,    /* text ended with a newline */
> >       LOG_PREFIX      = 4,    /* text started with a prefix */
> >       LOG_CONT        = 8,    /* text is a fragment of a continuation line */
> > +     LOG_NOTIME      = 16,   /* don't print the timestamp */
> >  };
> >
> >  struct printk_log {
> > @@ -1247,7 +1248,7 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog,
> >
> >       if (syslog)
> >               len = print_syslog((msg->facility << 3) | msg->level, buf);
> > -     if (time)
> > +     if (time && !(msg->flags & LOG_NOTIME))
> >               len += print_time(msg->ts_nsec, buf + len);
> >       return len;
> >  }
> > @@ -1873,6 +1874,10 @@ int vprintk_store(int facility, int level,
> >                               break;
> >                       case 'c':       /* KERN_CONT */
> >                               lflags |= LOG_CONT;
> > +                             break;
> > +                     case 't':       /* KERN_NOTIME */
> > +                             lflags |= LOG_NOTIME;
> > +                             break;
> >                       }
> >
> >                       text_len -= 2;
>

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

[xiang xiao]

On Wed, Feb 13, 2019 at 8:48 AM Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
>
> On (02/13/19 02:11), Xiang Xiao wrote:
> >
> > Because log may already add the timestamp sometime
> >
>
> We have module_param(printk_time) which enables/disables
> timestamps. And a .config option. And a kernel boot param.
> Why would you want KERN_NOTIME?
>

Because I need control whether append timestamp per message:
1.message come from kernel add the timestamp
2.message come from remote skip the timestamp
Like my previous reply case.

>         -ss

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

[Sergey Senozhatsky]

On (02/13/19 14:19), xiang xiao wrote:
> 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
> 4.Kernel call printk to dump the received buffer
> So I want that printk skip the timestamp here.
> 
> > If anything, I would probably prefer that we export whether
> > time is being printed, and have the caller not print time if printk is
> > doing it already, than to add the complexity into printk itself.
> 
> Actually, the timestamp of our initial implementation like your
> suggestion come from printk,

cat /sys/module/printk/parameters/time ?

Y - we add time prefix
N - we don't add time prefix

	-ss

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

[Sergey Senozhatsky]

On (02/13/19 15:29), Sergey Senozhatsky wrote:
>
> cat /sys/module/printk/parameters/time ?
 ^^^^^
cat / echo

Works both ways.

	-ss

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

[xiang xiao]

But how can I precisely control timestamp on/off per message through sysfs node?

On Wed, Feb 13, 2019 at 2:38 PM Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
>
> On (02/13/19 15:29), Sergey Senozhatsky wrote:
> >
> > cat /sys/module/printk/parameters/time ?
>  ^^^^^
> cat / echo
>
> Works both ways.
>
>         -ss

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

[Sergey Senozhatsky]

On (02/13/19 15:14), xiang xiao wrote:
>
> But how can I precisely control timestamp on/off per message
> through sysfs node?
>

Hmm. I don't know how many kernel printk-s you have and how often
do you write to kmsg. I was thinking about something like this:

	echo 0 > /...printk.../time
	dump buffer to /dev/kmsg
	echo 1 > /...printk../time

- If you would have several kernel printk-s in the meantime, then
  those would not have timestamps, but you kinda can roughly guess
  it

	write [1243] foo > /dev/kmsg
	write [1244] foo > /dev/kmsg
		<< printk(bar)               <timestamp ~[1244,1245]>
	write [1245] foo > /dev/kmsg

Maybe this won't suffice.

	-ss

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

[xiang xiao]

On Wed, Feb 13, 2019 at 4:08 PM Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
>
> On (02/13/19 15:14), xiang xiao wrote:
> >
> > But how can I precisely control timestamp on/off per message
> > through sysfs node?
> >
>
> Hmm. I don't know how many kernel printk-s you have and how often
> do you write to kmsg.

It depend on use case, but I plan to create a generic driver which
could reuse by all rpmsg based remoteproc.
This is the driver for upstream:
https://github.com/thesofproject/linux/pull/177/commits/a0b7009fede5552dc98733f2996a8140bff62455
so we need more precisely control here.

> I was thinking about something like this:
>

>         echo 0 > /...printk.../time
>         dump buffer to /dev/kmsg
>         echo 1 > /...printk../time
>

Another problem is how to control sysfs node from driver code
naturally, the concurrency and global side effect also need to
address.

> - If you would have several kernel printk-s in the meantime, then
>   those would not have timestamps, but you kinda can roughly guess
>   it
>
>         write [1243] foo > /dev/kmsg
>         write [1244] foo > /dev/kmsg
>                 << printk(bar)               <timestamp ~[1244,1245]>
>         write [1245] foo > /dev/kmsg
>
> Maybe this won't suffice.
>
>         -ss

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

[Petr Mladek]

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? 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?

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


> 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.

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

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

[Steven Rostedt]

On Wed, 13 Feb 2019 14:19:01 +0800
xiang xiao <xiaoxiang781216@gmail.com> 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
> 4.Kernel call printk to dump the received buffer
> So I want that printk skip the timestamp here.
> 
> > If anything, I would probably prefer that we export whether
> > time is being printed, and have the caller not print time if printk is
> > doing it already, than to add the complexity into printk itself.  
> 
> Actually, the timestamp of our initial implementation like your
> suggestion come from printk,
> but we found that timestamp from kernel isn't accurate as from RTOS
> due the buffer and IPC.
>

If the timestamps are different, then you don't want to remove the
printk one. Otherwise you are going to have a confusion between your
added timestamp mixed in with the kernel's inaccurate timestamps.

-- Steve

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

[xiang xiao]

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

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

[xiang xiao]

On Wed, Feb 13, 2019 at 9:47 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 13 Feb 2019 14:19:01 +0800
> xiang xiao <xiaoxiang781216@gmail.com> 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
> > 4.Kernel call printk to dump the received buffer
> > So I want that printk skip the timestamp here.
> >
> > > If anything, I would probably prefer that we export whether
> > > time is being printed, and have the caller not print time if printk is
> > > doing it already, than to add the complexity into printk itself.
> >
> > Actually, the timestamp of our initial implementation like your
> > suggestion come from printk,
> > but we found that timestamp from kernel isn't accurate as from RTOS
> > due the buffer and IPC.
> >
>
> If the timestamps are different, then you don't want to remove the
> printk one. Otherwise you are going to have a confusion between your
> added timestamp mixed in with the kernel's inaccurate timestamps.
>

Here is a sample output with this patch:
[   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
[   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
[   10.991450] remoteproc remoteproc1: remote processor
f9210000.toppwr:sen-rproc is now up
[   10.993715] virtio_rpmsg_bus virtio1: creating channel
rpmsg-ttySENSOR addr 0x1
[   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
[   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
[   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
[   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
[   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
[   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
[     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12 2019 16:53:49
arm song/banks
^^^^^^^^^^^^^
[   11.918177] random: crng init done
[   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)

Without this patch:
[   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
[   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
[   10.991450] remoteproc remoteproc1: remote processor
f9210000.toppwr:sen-rproc is now up
[   10.993715] virtio_rpmsg_bus virtio1: creating channel
rpmsg-ttySENSOR addr 0x1
[   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
[   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
[   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
[   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
[   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
[   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
[   11.105345][     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12
2019 16:53:49 arm song/banks
^^^^^^^^^^^^^^^^^^^^^^^^^^
[   11.918177] random: crng init done
[   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)

Which one do you think better?

> -- Steve

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

[Steven Rostedt]

On Wed, 13 Feb 2019 22:00:04 +0800
xiang xiao <xiaoxiang781216@gmail.com> wrote:

> On Wed, Feb 13, 2019 at 9:47 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Wed, 13 Feb 2019 14:19:01 +0800
> > xiang xiao <xiaoxiang781216@gmail.com> 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
> > > 4.Kernel call printk to dump the received buffer
> > > So I want that printk skip the timestamp here.
> > >  
> > > > If anything, I would probably prefer that we export whether
> > > > time is being printed, and have the caller not print time if printk is
> > > > doing it already, than to add the complexity into printk itself.  
> > >
> > > Actually, the timestamp of our initial implementation like your
> > > suggestion come from printk,
> > > but we found that timestamp from kernel isn't accurate as from RTOS
> > > due the buffer and IPC.
> > >  
> >
> > If the timestamps are different, then you don't want to remove the
> > printk one. Otherwise you are going to have a confusion between your
> > added timestamp mixed in with the kernel's inaccurate timestamps.
> >  
> 
> Here is a sample output with this patch:
> [   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
> [   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
> [   10.991450] remoteproc remoteproc1: remote processor
> f9210000.toppwr:sen-rproc is now up
> [   10.993715] virtio_rpmsg_bus virtio1: creating channel
> rpmsg-ttySENSOR addr 0x1
> [   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
> [   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
> [   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
> [   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
> [   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
> [   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
> [     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12 2019 16:53:49
> arm song/banks
> ^^^^^^^^^^^^^
> [   11.918177] random: crng init done
> [   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)
> 
> Without this patch:
> [   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
> [   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
> [   10.991450] remoteproc remoteproc1: remote processor
> f9210000.toppwr:sen-rproc is now up
> [   10.993715] virtio_rpmsg_bus virtio1: creating channel
> rpmsg-ttySENSOR addr 0x1
> [   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
> [   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
> [   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
> [   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
> [   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
> [   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
> [   11.105345][     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12
> 2019 16:53:49 arm song/banks
> ^^^^^^^^^^^^^^^^^^^^^^^^^^
> [   11.918177] random: crng init done
> [   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)
> 
> Which one do you think better?

Honestly, the one without the patch.

Seriously, it also makes it easy to see where that message happened
with respect to the other printks. With your patch, we would have no
idea, and if I was a normal user, unaware of this patch, I would
probably submit a bug report claiming that something is wrong with the
timestamps.

-- Steve

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

[xiang xiao]

On Wed, Feb 13, 2019 at 10:31 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 13 Feb 2019 22:00:04 +0800
> xiang xiao <xiaoxiang781216@gmail.com> wrote:
>
> > On Wed, Feb 13, 2019 at 9:47 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > > On Wed, 13 Feb 2019 14:19:01 +0800
> > > xiang xiao <xiaoxiang781216@gmail.com> 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
> > > > 4.Kernel call printk to dump the received buffer
> > > > So I want that printk skip the timestamp here.
> > > >
> > > > > If anything, I would probably prefer that we export whether
> > > > > time is being printed, and have the caller not print time if printk is
> > > > > doing it already, than to add the complexity into printk itself.
> > > >
> > > > Actually, the timestamp of our initial implementation like your
> > > > suggestion come from printk,
> > > > but we found that timestamp from kernel isn't accurate as from RTOS
> > > > due the buffer and IPC.
> > > >
> > >
> > > If the timestamps are different, then you don't want to remove the
> > > printk one. Otherwise you are going to have a confusion between your
> > > added timestamp mixed in with the kernel's inaccurate timestamps.
> > >
> >
> > Here is a sample output with this patch:
> > [   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
> > [   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
> > [   10.991450] remoteproc remoteproc1: remote processor
> > f9210000.toppwr:sen-rproc is now up
> > [   10.993715] virtio_rpmsg_bus virtio1: creating channel
> > rpmsg-ttySENSOR addr 0x1
> > [   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
> > [   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
> > [   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
> > [   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
> > [   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
> > [   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
> > [     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12 2019 16:53:49
> > arm song/banks
> > ^^^^^^^^^^^^^
> > [   11.918177] random: crng init done
> > [   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)
> >
> > Without this patch:
> > [   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
> > [   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
> > [   10.991450] remoteproc remoteproc1: remote processor
> > f9210000.toppwr:sen-rproc is now up
> > [   10.993715] virtio_rpmsg_bus virtio1: creating channel
> > rpmsg-ttySENSOR addr 0x1
> > [   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
> > [   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
> > [   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
> > [   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
> > [   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
> > [   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
> > [   11.105345][     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12
> > 2019 16:53:49 arm song/banks
> > ^^^^^^^^^^^^^^^^^^^^^^^^^^
> > [   11.918177] random: crng init done
> > [   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)
> >
> > Which one do you think better?
>
> Honestly, the one without the patch.
>
> Seriously, it also makes it easy to see where that message happened
> with respect to the other printks. With your patch, we would have no
> idea, and if I was a normal user, unaware of this patch, I would
> probably submit a bug report claiming that something is wrong with the
> timestamps.
>

Ok, I will remove KERN_NOTIME from rpmsg-syslog driver.

> -- Steve

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

[Sergey Senozhatsky]

On (02/13/19 09:31), Steven Rostedt wrote:
> > Without this patch:
> > [   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
> > [   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
> > [   10.991450] remoteproc remoteproc1: remote processor
> > f9210000.toppwr:sen-rproc is now up
> > [   10.993715] virtio_rpmsg_bus virtio1: creating channel
> > rpmsg-ttySENSOR addr 0x1
> > [   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
> > [   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
> > [   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
> > [   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
> > [   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
> > [   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
> > [   11.105345][     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12
> > 2019 16:53:49 arm song/banks
> > ^^^^^^^^^^^^^^^^^^^^^^^^^^
> > [   11.918177] random: crng init done
> > [   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)
> > 
> > Which one do you think better?
> 
> Honestly, the one without the patch.

+1

> Seriously, it also makes it easy to see where that message happened
> with respect to the other printks. With your patch, we would have no
> idea, and if I was a normal user, unaware of this patch, I would
> probably submit a bug report claiming that something is wrong with the
> timestamps.

+1

	-ss

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

[Petr Mladek]

On Wed 2019-02-13 09:31:54, Steven Rostedt wrote:
> On Wed, 13 Feb 2019 22:00:04 +0800
> xiang xiao <xiaoxiang781216@gmail.com> wrote:
> > Here is a sample output with this patch:
> > [   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
> > [   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
> > [   10.991450] remoteproc remoteproc1: remote processor
> > f9210000.toppwr:sen-rproc is now up
> > [   10.993715] virtio_rpmsg_bus virtio1: creating channel
> > rpmsg-ttySENSOR addr 0x1
> > [   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
> > [   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
> > [   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
> > [   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
> > [   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
> > [   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
> > [     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12 2019 16:53:49
> > arm song/banks
> > ^^^^^^^^^^^^^
> > [   11.918177] random: crng init done
> > [   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)
> > 
> > Without this patch:
> > [   10.991426] virtio_rpmsg_bus virtio1: rpmsg host is online
> > [   10.991443] remoteproc remoteproc1: registered virtio1 (type 7)
> > [   10.991450] remoteproc remoteproc1: remote processor
> > f9210000.toppwr:sen-rproc is now up
> > [   10.993715] virtio_rpmsg_bus virtio1: creating channel
> > rpmsg-ttySENSOR addr 0x1
> > [   10.994606] virtio_rpmsg_bus virtio1: creating channel rpmsg-ttyGPS addr 0x2
> > [   10.995236] virtio_rpmsg_bus virtio1: creating channel rpmsg-clk addr 0x3
> > [   10.995702] virtio_rpmsg_bus virtio1: creating channel rpmsg-syslog addr 0x4
> > [   10.996197] virtio_rpmsg_bus virtio1: creating channel rpmsg-rtc addr 0x5
> > [   10.997297] virtio_rpmsg_bus virtio1: creating channel rpmsg-hostfs addr 0x6
> > [   10.999842] virtio_rpmsg_bus virtio1: creating channel rpmsg-usrsock addr 0x7
> > [   11.105345][     0.007680] sensor: NuttX sensor 7.28 e3c2ecb Feb 12
> > 2019 16:53:49 arm song/banks
> > ^^^^^^^^^^^^^^^^^^^^^^^^^^
> > [   11.918177] random: crng init done
> > [   12.567362] e2fsck: e2fsck 1.42.9 (28-Dec-2013)
> > 
> > Which one do you think better?
> 
> Honestly, the one without the patch.
> 
> Seriously, it also makes it easy to see where that message happened
> with respect to the other printks. With your patch, we would have no
> idea, and if I was a normal user, unaware of this patch, I would
> probably submit a bug report claiming that something is wrong with the
> timestamps.

Just for record. I agree with Steven and Sergey here. The two clocks
are too out of sync. "Randomly" and quietly replacing one with
the other would cause more harm than good from my point of view.

Best Regards,
Petr