Re: [QUESTION] printk: time namespaces and printk timestamps
From: Petr Mladek
Date: Mon May 25 2026 - 09:33:31 EST
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 = ¤t->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 = ¤t->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