All of lore.kernel.org
 help / color / mirror / Atom feed
* [QUESTION] printk: time namespaces and printk timestamps
@ 2026-05-23 15:20 Thomas Weißschuh
  2026-05-25  8:37 ` Petr Mladek
  0 siblings, 1 reply; 8+ messages in thread
From: Thomas Weißschuh @ 2026-05-23 15:20 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, John Ogness, Sergey Senozhatsky; +Cc: linux-kernel

Hi everyone,

It looks like the monotonic timestamps of printk records do not take the
callers time namespace into account when emitted through /dev/kmsg,
/proc/kmsg and syslog(2).

To me this looks like a bug. What do you think? Should it be changed?


Thomas

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [QUESTION] printk: time namespaces and printk timestamps
  2026-05-23 15:20 [QUESTION] printk: time namespaces and printk timestamps Thomas Weißschuh
@ 2026-05-25  8:37 ` Petr Mladek
  2026-05-25  8:47   ` Thomas Weißschuh
  0 siblings, 1 reply; 8+ messages in thread
From: Petr Mladek @ 2026-05-25  8:37 UTC (permalink / raw)
  To: Thomas Weißschuh
  Cc: Steven Rostedt, John Ogness, Sergey Senozhatsky, linux-kernel

On Sat 2026-05-23 17:20:45, Thomas Weißschuh wrote:
> Hi everyone,
> 
> It looks like the monotonic timestamps of printk records do not take the
> callers time namespace into account when emitted through /dev/kmsg,
> /proc/kmsg and syslog(2).
> 
> To me this looks like a bug. What do you think? Should it be changed?

To be honest, I have never heard about time namespaces before ;-)

So, you propose to use the timestamp with the namespace-specific
offset when a message is added from the given namespace, e.g. via:

   echo "This message is from another time space" > /dev/kmsg

Do I get it correctly?

I see two potential problems:

1. printk() historically used a monotonic clock. I am not sure if any
   usespace application depends on it but there is a risk of breaking
   something.

   Anyway, the printk messages are used to debug kernel problems.
   And the order of events might be important. IMHO, messages with
   random offsets might create confusion.


2. printk() has to work in any context, including NMI. It requires
   a lockless way to get the timestamps. I am not sure if the
   namespace timestamps might be read a lockless way and if
   it would be worth the effort.


Best Regards,
Petr

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [QUESTION] printk: time namespaces and printk timestamps
  2026-05-25  8:37 ` Petr Mladek
@ 2026-05-25  8:47   ` Thomas Weißschuh
  2026-05-25  9:30     ` Petr Mladek
  0 siblings, 1 reply; 8+ messages in thread
From: Thomas Weißschuh @ 2026-05-25  8:47 UTC (permalink / raw)
  To: Petr Mladek; +Cc: Steven Rostedt, John Ogness, Sergey Senozhatsky, linux-kernel

On 2026-05-25 10:37:40+0200, Petr Mladek wrote:
> On Sat 2026-05-23 17:20:45, Thomas Weißschuh wrote:
> > It looks like the monotonic timestamps of printk records do not take the
> > callers time namespace into account when emitted through /dev/kmsg,
> > /proc/kmsg and syslog(2).
> > 
> > To me this looks like a bug. What do you think? Should it be changed?
> 
> To be honest, I have never heard about time namespaces before ;-)
> 
> So, you propose to use the timestamp with the namespace-specific
> offset when a message is added from the given namespace, e.g. via:
> 
>    echo "This message is from another time space" > /dev/kmsg
> 
> Do I get it correctly?

My idea was rather to do the conversion when *reading* the message from
a time namespaced user process.

> I see two potential problems:
> 
> 1. printk() historically used a monotonic clock. I am not sure if any
>    usespace application depends on it but there is a risk of breaking
>    something.

From the perspective of the namespaced process currently the timestamps
from printk may in fact not be CLOCK_MONOTONIC.

>    Anyway, the printk messages are used to debug kernel problems.
>    And the order of events might be important. IMHO, messages with
>    random offsets might create confusion.

That would not be an issue when doing the conversion during read.
Each process sees the same order of events with the same relative
time increments between them. Only the absolute values would change.

Note: The offsets can never change for a given namespace or process.

> 2. printk() has to work in any context, including NMI. It requires
>    a lockless way to get the timestamps. I am not sure if the
>    namespace timestamps might be read a lockless way and if
>    it would be worth the effort.

As above.


Thomas

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [QUESTION] printk: time namespaces and printk timestamps
  2026-05-25  8:47   ` Thomas Weißschuh
@ 2026-05-25  9:30     ` Petr Mladek
  2026-05-25 10:26       ` Thomas Weißschuh
  0 siblings, 1 reply; 8+ messages in thread
From: Petr Mladek @ 2026-05-25  9:30 UTC (permalink / raw)
  To: Thomas Weißschuh
  Cc: Steven Rostedt, John Ogness, Sergey Senozhatsky, linux-kernel

On Mon 2026-05-25 10:47:46, Thomas Weißschuh wrote:
> On 2026-05-25 10:37:40+0200, Petr Mladek wrote:
> > On Sat 2026-05-23 17:20:45, Thomas Weißschuh wrote:
> > > It looks like the monotonic timestamps of printk records do not take the
> > > callers time namespace into account when emitted through /dev/kmsg,
> > > /proc/kmsg and syslog(2).
> > > 
> > > To me this looks like a bug. What do you think? Should it be changed?
> > 
> > To be honest, I have never heard about time namespaces before ;-)
> > 
> > So, you propose to use the timestamp with the namespace-specific
> > offset when a message is added from the given namespace, e.g. via:
> > 
> >    echo "This message is from another time space" > /dev/kmsg
> > 
> > Do I get it correctly?
> 
> My idea was rather to do the conversion when *reading* the message from
> a time namespaced user process.

I see. But it might produce messages with negative timestamps. I am
not sure if it is a good idea. I guess that many tools might get
confused.

> > I see two potential problems:
> > 
> > 1. printk() historically used a monotonic clock. I am not sure if any
> >    usespace application depends on it but there is a risk of breaking
> >    something.
> 
> >From the perspective of the namespaced process currently the timestamps
> from printk may in fact not be CLOCK_MONOTONIC.

The messages stored in the kernel ring buffer currently always have
monotonic timestamps.

I guess that you talk about matching kernel messages with other
userspace logs. But they might be inconsistent also because
of using different clocks...

There were several discussions in the past about storing more
timestamps from different clocks in the printk ring buffer.
But it never went anywhere.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [QUESTION] printk: time namespaces and printk timestamps
  2026-05-25  9:30     ` Petr Mladek
@ 2026-05-25 10:26       ` Thomas Weißschuh
  2026-05-25 13:29         ` Petr Mladek
  0 siblings, 1 reply; 8+ messages in thread
From: Thomas Weißschuh @ 2026-05-25 10:26 UTC (permalink / raw)
  To: Petr Mladek; +Cc: Steven Rostedt, John Ogness, Sergey Senozhatsky, linux-kernel

On 2026-05-25 11:30:08+0200, Petr Mladek wrote:
> On Mon 2026-05-25 10:47:46, Thomas Weißschuh wrote:
> > On 2026-05-25 10:37:40+0200, Petr Mladek wrote:
> > > On Sat 2026-05-23 17:20:45, Thomas Weißschuh wrote:
> > > > It looks like the monotonic timestamps of printk records do not take the
> > > > callers time namespace into account when emitted through /dev/kmsg,
> > > > /proc/kmsg and syslog(2).
> > > > 
> > > > To me this looks like a bug. What do you think? Should it be changed?
> > > 
> > > To be honest, I have never heard about time namespaces before ;-)
> > > 
> > > So, you propose to use the timestamp with the namespace-specific
> > > offset when a message is added from the given namespace, e.g. via:
> > > 
> > >    echo "This message is from another time space" > /dev/kmsg
> > > 
> > > Do I get it correctly?
> > 
> > My idea was rather to do the conversion when *reading* the message from
> > a time namespaced user process.
> 
> I see. But it might produce messages with negative timestamps. I am
> not sure if it is a good idea. I guess that many tools might get
> confused.

Yeah. While the time namespace core ensures that the observed "now" can
never be negative, messages that were recorded before the creation of
the namespace could result in negative timestamps.
These could be filtered out during formatting, but that is ugly, too.

> > > I see two potential problems:
> > > 
> > > 1. printk() historically used a monotonic clock. I am not sure if any
> > >    usespace application depends on it but there is a risk of breaking
> > >    something.
> > 
> > >From the perspective of the namespaced process currently the timestamps
> > from printk may in fact not be CLOCK_MONOTONIC.
> 
> The messages stored in the kernel ring buffer currently always have
> monotonic timestamps.

"monotonic" as in "never decreases" (obious) or "CLOCK_MONOTONIC"?
That is not actually well-documented I think.
dmesg(1) assumes CLOCK_MONOTONIC.

> I guess that you talk about matching kernel messages with other
> userspace logs. But they might be inconsistent also because
> of using different clocks...

Or matching it with clock_gettime().

> There were several discussions in the past about storing more
> timestamps from different clocks in the printk ring buffer.
> But it never went anywhere.

From the perspective of a namespaced process, this *is* the actual
CLOCK_MONOTONIC. It doesn't really know about any other one, and
the time APIs do not expose the un-namespaced clock value to a
namespaced process. So I am not sure this is the same usecase.

As a real-world example, dmesg(1) uses clock_gettime(CLOCK_MONOTONIC) in
its logic to format kmsg timestamps as wallcock/CLOCK_REALTIME ones:

# echo test > /dev/kmsg
# unshare -T --monotonic 5000000 dmesg --time-format iso | tail -1
2026-03-28T14:20:35,366875+01:00 test
# dmesg --time-format iso | tail -1
2026-05-25T12:13:55,366876+02:00 test
# date
Mon May 25 12:13:55 CEST 2026

The timestamp from the namespaced dmesg(1) is wrong.
(CLOCK_REALTIME itself is not namespace-aware)


Thomas

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [QUESTION] printk: time namespaces and printk timestamps
  2026-05-25 10:26       ` Thomas Weißschuh
@ 2026-05-25 13:29         ` Petr Mladek
  2026-05-25 15:38           ` Thomas Weißschuh
  0 siblings, 1 reply; 8+ messages in thread
From: Petr Mladek @ 2026-05-25 13:29 UTC (permalink / raw)
  To: Thomas Weißschuh
  Cc: Steven Rostedt, John Ogness, Sergey Senozhatsky,
	Anna-Maria Behnsen, Frederic Weisbecker, Thomas Gleixner,
	linux-kernel

Adding timekeeping maintainers into Cc.

On Mon 2026-05-25 12:26:47, Thomas Weißschuh wrote:
> On 2026-05-25 11:30:08+0200, Petr Mladek wrote:
> > On Mon 2026-05-25 10:47:46, Thomas Weißschuh wrote:
> > > On 2026-05-25 10:37:40+0200, Petr Mladek wrote:
> > > > On Sat 2026-05-23 17:20:45, Thomas Weißschuh wrote:
> > > > > It looks like the monotonic timestamps of printk records do not take the
> > > > > callers time namespace into account when emitted through /dev/kmsg,
> > > > > /proc/kmsg and syslog(2).
> > > > > 
> > > > > To me this looks like a bug. What do you think? Should it be changed?
> > > > 
> > > My idea was rather to do the conversion when *reading* the message from
> > > a time namespaced user process.
> > 
> > I see. But it might produce messages with negative timestamps. I am
> > not sure if it is a good idea. I guess that many tools might get
> > confused.
> 
> Yeah. While the time namespace core ensures that the observed "now" can
> never be negative, messages that were recorded before the creation of
> the namespace could result in negative timestamps.
> These could be filtered out during formatting, but that is ugly, too.

Maybe, I was wrong. It seems that the offset might only be positive,
see below.

> > > > I see two potential problems:
> > > > 
> > > > 1. printk() historically used a monotonic clock. I am not sure if any
> > > >    usespace application depends on it but there is a risk of breaking
> > > >    something.
> > > 
> > > >From the perspective of the namespaced process currently the timestamps
> > > from printk may in fact not be CLOCK_MONOTONIC.
> > 
> > The messages stored in the kernel ring buffer currently always have
> > monotonic timestamps.
> 
> "monotonic" as in "never decreases" (obious) or "CLOCK_MONOTONIC"?
> That is not actually well-documented I think.
> dmesg(1) assumes CLOCK_MONOTONIC.

Honestly, I do not know the details. printk() is calling local_clock()
which is a wrapper over sched_clock(). I think that it is based on
"CLOCK_MONOTONIC" but it is not precise because it is lockless.

> > I guess that you talk about matching kernel messages with other
> > userspace logs. But they might be inconsistent also because
> > of using different clocks...
> 
> Or matching it with clock_gettime().
> 
> > There were several discussions in the past about storing more
> > timestamps from different clocks in the printk ring buffer.
> > But it never went anywhere.
> 
> >From the perspective of a namespaced process, this *is* the actual
> CLOCK_MONOTONIC. It doesn't really know about any other one, and
> the time APIs do not expose the un-namespaced clock value to a
> namespaced process. So I am not sure this is the same usecase.
> 
> As a real-world example, dmesg(1) uses clock_gettime(CLOCK_MONOTONIC) in
> its logic to format kmsg timestamps as wallcock/CLOCK_REALTIME ones:
> 
> # echo test > /dev/kmsg
> # unshare -T --monotonic 5000000 dmesg --time-format iso | tail -1
> 2026-03-28T14:20:35,366875+01:00 test
> # dmesg --time-format iso | tail -1
> 2026-05-25T12:13:55,366876+02:00 test
> # date
> Mon May 25 12:13:55 CEST 2026
> 
> The timestamp from the namespaced dmesg(1) is wrong.
> (CLOCK_REALTIME itself is not namespace-aware)

Note that kernel always gives the same output:

Via syslog, it prints XXX.YYYYYY seconds since boot, see print_time()
in kernel/printk/printk.c. Or see the raw output using dmesg -S -r,
for example:

  # dmesg -S -r
  <6>[    0.037954][    T0] Console: colour dummy device 80x25
  <6>[    0.037956][    T0] printk: legacy console [tty0] enabled
  <6>[    0.037987][    T0] ACPI: Core revision 20251212

Via /dev/kmsg, it prints the number of micro seconds since boot, see
info_print_ext_header() in kernel/printk/printk.c. Or see
the raw output:

  # cat /dev/kmsg
  6,258,37954,-,caller=T0;Console: colour dummy device 80x25
  6,259,37956,-,caller=T0;printk: legacy console [tty0] enabled
  6,260,37987,-,caller=T0;ACPI: Core revision 20251212

All the transformations into other time formats are done by dmesg
internally. See dmesg(1)"

<paste>
	-T, --ctime
	       Print human-readable timestamps.

	       Be aware that the timestamp could be inaccurate! The time
	       source used for the logs is not updated after system
	       SUSPEND/RESUME. Timestamps are adjusted according to
	       current delta between boottime and monotonic clocks,
	       this works only for messages printed after last resume.

       --time-format format
	     The iso format has the same issue as ctime: the time may
	     be inaccurate when a system is suspended and resumed.
</paste>

It means that the "iso" format is broken by definition. But we
probably could do better here.

The big difference of the timestamp in your example is because
the namespace uses so big offset for the monotonic clock.

It should get fixed if we added the name space offset, similar
to commit 3ae700ecfae91331 ("fs/proc: apply the time namespace
offset to /proc/stat btime"). But we should use
timens_add_boottime_ns() which does not exist at the moment.

Something like:

diff --git a/include/linux/time_namespace.h b/include/linux/time_namespace.h
index 58bd9728df58..c34713b657b5 100644
--- a/include/linux/time_namespace.h
+++ b/include/linux/time_namespace.h
@@ -77,6 +77,13 @@ static inline void timens_add_monotonic(struct timespec64 *ts)
 	*ts = timespec64_add(*ts, ns_offsets->monotonic);
 }
 
+static inline u64 timens_add_monotonic_ns(u64 nsec)
+{
+	struct timens_offsets *ns_offsets = &current->nsproxy->time_ns->offsets;
+
+	return nsec + timespec64_to_ns(&ns_offsets->monotonic);
+}
+
 static inline void timens_add_boottime(struct timespec64 *ts)
 {
 	struct timens_offsets *ns_offsets = &current->nsproxy->time_ns->offsets;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0323149548f6..c5dcf544e267 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/time_namespace.h>
 #include <linux/panic.h>
 
 #include <linux/uaccess.h>
@@ -641,7 +642,7 @@ static void append_char(char **pp, char *e, char c)
 static ssize_t info_print_ext_header(char *buf, size_t size,
 				     struct printk_info *info)
 {
-	u64 ts_usec = info->ts_nsec;
+	u64 ts_usec = timens_add_monotonic_ns(info->ts_nsec);
 	char caller[20];
 #ifdef CONFIG_PRINTK_CALLER
 	u32 id = info->caller_id;
@@ -1382,7 +1383,7 @@ static size_t info_print_prefix(const struct printk_info  *info, bool syslog,
 		len = print_syslog((info->facility << 3) | info->level, buf);
 
 	if (time)
-		len += print_time(info->ts_nsec, buf + len);
+		len += print_time(timens_add_monotonic_ns(info->ts_nsec), buf + len);
 
 	len += print_caller(info->caller_id, buf + len);
 

Best Regards,
Petr

^ permalink raw reply related	[flat|nested] 8+ messages in thread

* Re: [QUESTION] printk: time namespaces and printk timestamps
  2026-05-25 13:29         ` Petr Mladek
@ 2026-05-25 15:38           ` Thomas Weißschuh
  2026-05-26 20:08             ` Thomas Gleixner
  0 siblings, 1 reply; 8+ messages in thread
From: Thomas Weißschuh @ 2026-05-25 15:38 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Steven Rostedt, John Ogness, Sergey Senozhatsky,
	Anna-Maria Behnsen, Frederic Weisbecker, Thomas Gleixner,
	linux-kernel

On 2026-05-25 15:29:01+0200, Petr Mladek wrote:
> Adding timekeeping maintainers into Cc.
> 
> On Mon 2026-05-25 12:26:47, Thomas Weißschuh wrote:
> > On 2026-05-25 11:30:08+0200, Petr Mladek wrote:
> > > On Mon 2026-05-25 10:47:46, Thomas Weißschuh wrote:
> > > > On 2026-05-25 10:37:40+0200, Petr Mladek wrote:
> > > > > On Sat 2026-05-23 17:20:45, Thomas Weißschuh wrote:
> > > > > > It looks like the monotonic timestamps of printk records do not take the
> > > > > > callers time namespace into account when emitted through /dev/kmsg,
> > > > > > /proc/kmsg and syslog(2).
> > > > > > 
> > > > > > To me this looks like a bug. What do you think? Should it be changed?
> > > > > 
> > > > My idea was rather to do the conversion when *reading* the message from
> > > > a time namespaced user process.
> > > 
> > > I see. But it might produce messages with negative timestamps. I am
> > > not sure if it is a good idea. I guess that many tools might get
> > > confused.
> > 
> > Yeah. While the time namespace core ensures that the observed "now" can
> > never be negative, messages that were recorded before the creation of
> > the namespace could result in negative timestamps.
> > These could be filtered out during formatting, but that is ugly, too.
> 
> Maybe, I was wrong. It seems that the offset might only be positive,
> see below.

With your patch below (with an added NULL-check as explained below)
I was able to trigger such a negative number, or rather an unsigned
underflow:

	#!/bin/bash

	set -e

	echo test > /dev/kmsg

	sleep 3

	# lsclocks from recent util-linux. I don't know another way to
	# get CLOCK_MONOTONIC from shell.
	mono=$(lsclocks --time monotonic | cut -d. -f1)

	unshare -T --monotonic -$mono lsclocks --time monotonic
	unshare -T --monotonic -$mono dmesg -r | tail -1

Result:
[    2.998937] test		(host console, non-namespaced)
0.873620599			(lsclocks --time monotonic in namespace)
<12>[18446744071.708489] test	(/dev/kmsg in namespace)

> > > > > I see two potential problems:
> > > > > 
> > > > > 1. printk() historically used a monotonic clock. I am not sure if any
> > > > >    usespace application depends on it but there is a risk of breaking
> > > > >    something.
> > > > 
> > > > >From the perspective of the namespaced process currently the timestamps
> > > > from printk may in fact not be CLOCK_MONOTONIC.
> > > 
> > > The messages stored in the kernel ring buffer currently always have
> > > monotonic timestamps.
> > 
> > "monotonic" as in "never decreases" (obious) or "CLOCK_MONOTONIC"?
> > That is not actually well-documented I think.
> > dmesg(1) assumes CLOCK_MONOTONIC.
> 
> Honestly, I do not know the details. printk() is calling local_clock()
> which is a wrapper over sched_clock(). I think that it is based on
> "CLOCK_MONOTONIC" but it is not precise because it is lockless.

We have ktime_get_mono_fast_ns() which is also supposed to do this.
The name would be clearer and it should be guaranteed to be
CLOCK_MONOTONIC. But I don't know the details or history so this is just
guesswork right now.

> > > I guess that you talk about matching kernel messages with other
> > > userspace logs. But they might be inconsistent also because
> > > of using different clocks...
> > 
> > Or matching it with clock_gettime().
> > 
> > > There were several discussions in the past about storing more
> > > timestamps from different clocks in the printk ring buffer.
> > > But it never went anywhere.
> > 
> > >From the perspective of a namespaced process, this *is* the actual
> > CLOCK_MONOTONIC. It doesn't really know about any other one, and
> > the time APIs do not expose the un-namespaced clock value to a
> > namespaced process. So I am not sure this is the same usecase.
> > 
> > As a real-world example, dmesg(1) uses clock_gettime(CLOCK_MONOTONIC) in
> > its logic to format kmsg timestamps as wallcock/CLOCK_REALTIME ones:
> > 
> > # echo test > /dev/kmsg
> > # unshare -T --monotonic 5000000 dmesg --time-format iso | tail -1
> > 2026-03-28T14:20:35,366875+01:00 test
> > # dmesg --time-format iso | tail -1
> > 2026-05-25T12:13:55,366876+02:00 test
> > # date
> > Mon May 25 12:13:55 CEST 2026
> > 
> > The timestamp from the namespaced dmesg(1) is wrong.
> > (CLOCK_REALTIME itself is not namespace-aware)
> 
> Note that kernel always gives the same output:

(...)

> All the transformations into other time formats are done by dmesg
> internally. See dmesg(1)"

(...)

> It means that the "iso" format is broken by definition.

ctime and reltime, too.

> But we probably could do better here.
> 
> The big difference of the timestamp in your example is because
> the namespace uses so big offset for the monotonic clock.

I don't see how the size of the offset makes a difference.
Could you explain?

> It should get fixed if we added the name space offset, similar
> to commit 3ae700ecfae91331 ("fs/proc: apply the time namespace
> offset to /proc/stat btime"). But we should use
> timens_add_boottime_ns() which does not exist at the moment.
> 
> Something like:
> 
> diff --git a/include/linux/time_namespace.h b/include/linux/time_namespace.h
> index 58bd9728df58..c34713b657b5 100644
> --- a/include/linux/time_namespace.h
> +++ b/include/linux/time_namespace.h
> @@ -77,6 +77,13 @@ static inline void timens_add_monotonic(struct timespec64 *ts)
>  	*ts = timespec64_add(*ts, ns_offsets->monotonic);
>  }
>  
> +static inline u64 timens_add_monotonic_ns(u64 nsec)
> +{
> +	struct timens_offsets *ns_offsets = &current->nsproxy->time_ns->offsets;
> +
> +	return nsec + timespec64_to_ns(&ns_offsets->monotonic);
> +}
> +
>  static inline void timens_add_boottime(struct timespec64 *ts)
>  {
>  	struct timens_offsets *ns_offsets = &current->nsproxy->time_ns->offsets;
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 0323149548f6..c5dcf544e267 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -48,6 +48,7 @@
>  #include <linux/sched/clock.h>
>  #include <linux/sched/debug.h>
>  #include <linux/sched/task_stack.h>
> +#include <linux/time_namespace.h>
>  #include <linux/panic.h>
>  
>  #include <linux/uaccess.h>
> @@ -641,7 +642,7 @@ static void append_char(char **pp, char *e, char c)
>  static ssize_t info_print_ext_header(char *buf, size_t size,
>  				     struct printk_info *info)
>  {
> -	u64 ts_usec = info->ts_nsec;
> +	u64 ts_usec = timens_add_monotonic_ns(info->ts_nsec);
>  	char caller[20];
>  #ifdef CONFIG_PRINTK_CALLER
>  	u32 id = info->caller_id;
> @@ -1382,7 +1383,7 @@ static size_t info_print_prefix(const struct printk_info  *info, bool syslog,
>  		len = print_syslog((info->facility << 3) | info->level, buf);
>  
>  	if (time)
> -		len += print_time(info->ts_nsec, buf + len);
> +		len += print_time(timens_add_monotonic_ns(info->ts_nsec), buf + len);
>  
>  	len += print_caller(info->caller_id, buf + len);

I tried something like this before. There are some notes:

In some contexts where this is called from, current->nsproxy can be NULL
(maybe when printing to the console) and the kernel will crash.
So either we add a NULL check or explicitly pass through a parameter
which enables timens handling when called from the right entrypoints.

This would require to make it clear that the timestamp is
CLOCK_MONOTONIC. Not that outlandish given that userspace already relies
on it.

Given that nobody has complained so far, maybe it is not a real issue.


Thomas

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [QUESTION] printk: time namespaces and printk timestamps
  2026-05-25 15:38           ` Thomas Weißschuh
@ 2026-05-26 20:08             ` Thomas Gleixner
  0 siblings, 0 replies; 8+ messages in thread
From: Thomas Gleixner @ 2026-05-26 20:08 UTC (permalink / raw)
  To: Thomas Weißschuh, Petr Mladek
  Cc: Steven Rostedt, John Ogness, Sergey Senozhatsky,
	Anna-Maria Behnsen, Frederic Weisbecker, linux-kernel

On Mon, May 25 2026 at 17:38, Thomas Weißschuh wrote:
> On 2026-05-25 15:29:01+0200, Petr Mladek wrote:
>
> Result:
> [    2.998937] test		(host console, non-namespaced)
> 0.873620599			(lsclocks --time monotonic in namespace)
> <12>[18446744071.708489] test	(/dev/kmsg in namespace)

Of course :)

>> > > > > I see two potential problems:
>> > > > > 
>> > > > > 1. printk() historically used a monotonic clock. I am not sure if any
>> > > > >    usespace application depends on it but there is a risk of breaking
>> > > > >    something.
>> > > > 
>> > > > >From the perspective of the namespaced process currently the timestamps
>> > > > from printk may in fact not be CLOCK_MONOTONIC.
>> > > 
>> > > The messages stored in the kernel ring buffer currently always have
>> > > monotonic timestamps.
>> > 
>> > "monotonic" as in "never decreases" (obious) or "CLOCK_MONOTONIC"?
>> > That is not actually well-documented I think.
>> > dmesg(1) assumes CLOCK_MONOTONIC.
>> 
>> Honestly, I do not know the details. printk() is calling local_clock()
>> which is a wrapper over sched_clock(). I think that it is based on
>> "CLOCK_MONOTONIC" but it is not precise because it is lockless.
>
> We have ktime_get_mono_fast_ns() which is also supposed to do this.
> The name would be clearer and it should be guaranteed to be
> CLOCK_MONOTONIC. But I don't know the details or history so this is just
> guesswork right now.

local_clock() is available slightly earlier than CLOCK_MONOTONIC and
contrary to CLOCK_MONOTONIC it is not NTP adjusted. So they drift apart,
which makes it actually annoying to correlate dmesg with actual time.

We had this discussion before:

  https://lore.kernel.org/lkml/20171115182657.383713029@linutronix.de/

Tracing allows to select time, which _is_ very useful for correlation.

>> > As a real-world example, dmesg(1) uses clock_gettime(CLOCK_MONOTONIC) in
>> > its logic to format kmsg timestamps as wallcock/CLOCK_REALTIME ones:

That's absurd. There is no way dmesg(1) can map local_clock() to
REALTIME via MONOTONIC. Wishful thinking at best.

>> It should get fixed if we added the name space offset, similar
>> to commit 3ae700ecfae91331 ("fs/proc: apply the time namespace
>> offset to /proc/stat btime"). But we should use
>> timens_add_boottime_ns() which does not exist at the moment.

As long as printk uses local_clock() trying to apply a namespace offset is
completely moot.

local_clock() is basically CLOCK_MONOTONIC_RAW plus an offset, which is
something between 30-100ms. But it's actually not exact as the
calculation is slightly different and therefore drifts apart over time
slightly.

CLOCK_MONOTONIC on the other hand is diverging completely when the
system has NTP enabled. A very small frequency adjustment of 12ppm sums
up to ~one second per day.

Thanks,

        tglx

^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2026-05-26 20:08 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2026-05-23 15:20 [QUESTION] printk: time namespaces and printk timestamps Thomas Weißschuh
2026-05-25  8:37 ` Petr Mladek
2026-05-25  8:47   ` Thomas Weißschuh
2026-05-25  9:30     ` Petr Mladek
2026-05-25 10:26       ` Thomas Weißschuh
2026-05-25 13:29         ` Petr Mladek
2026-05-25 15:38           ` Thomas Weißschuh
2026-05-26 20:08             ` Thomas Gleixner

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.