From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-wm1-f48.google.com (mail-wm1-f48.google.com [209.85.128.48]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id A7321383981 for ; Mon, 25 May 2026 13:29:05 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.128.48 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1779715747; cv=none; b=KAp2nkztky1TCKI2CUEEQ1B40OMuEgTrUs84LydNiXStN/uhUQZrgHX96P/pb1Xtjqiiqj0SZWNsvm7Dtb144W+z9eIdj42a4dRdgN2JWIxBnuTcULC/3EzLPRJjIdHmgAaqtbVQXdlAz6xFweP+xThivafVL5AWYwLje2KT0KY= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1779715747; c=relaxed/simple; bh=vd125Lcf/TNUeBUGPs+4uNcSi+Y5oRxDlxrIkDGbv6E=; h=Date:From:To:Cc:Subject:Message-ID:References:MIME-Version: Content-Type:Content-Disposition:In-Reply-To; b=AEWBB9eoE84UrO6gLEKJufBFwfqmOesiu7+9Bds6dpisDvzpHxVHCpuB3qo7+X2Yf+Bd4vE/a9PrOT5r1rVWyXD6zTr6wedjTh4+iqCVjrFDpQbICURy4BPfz8cNoPU/bdA8qzwn/Kap7mSVB1xhcAURu9uf9VktzPq8PwsQ3Ag= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=quarantine dis=none) header.from=suse.com; spf=pass smtp.mailfrom=suse.com; dkim=pass (2048-bit key) header.d=suse.com header.i=@suse.com header.b=JYMP+j0f; arc=none smtp.client-ip=209.85.128.48 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=quarantine dis=none) header.from=suse.com Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=suse.com Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=suse.com header.i=@suse.com header.b="JYMP+j0f" Received: by mail-wm1-f48.google.com with SMTP id 5b1f17b1804b1-490388fd0dbso39690955e9.0 for ; Mon, 25 May 2026 06:29:05 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.com; s=google; t=1779715744; x=1780320544; darn=vger.kernel.org; h=in-reply-to:content-transfer-encoding:content-disposition :mime-version:references:message-id:subject:cc:to:from:date:from:to :cc:subject:date:message-id:reply-to; bh=L5lq5l3mHzRMh4g2BXopS/EJzG0m2BHCz7XcEM7WDUA=; b=JYMP+j0fDu/d9D56S2gcFdeWYZDEfkqcFrwzyoQMiOU3gVaNnqtMmtD6VY6me3497R 7811J2vQDfcZK2HY/27Te6vo9a6zxq9sJYsc5TlZGqJJr6PKWY31cULHzbqidKgYZQYt IL6U7n/yGdWX1fSaoWJu+Mae/YZg+AJqFC9y8FO7upFECYrYQr6NsReePxlEJdf+2jOY +7ftnvBBWk11rf0+2bOlKOhwhE/RMIuJvfcL3HcxnnLTa99GQOZTlHOT9+HP/cwxeiqn rGd1JXXSDOUFp0/+zPeFfcxxetXO6g83uLxK+d5AAuwNcY0DfLHauVttRM4nFZZl9UKa eD8w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20251104; t=1779715744; x=1780320544; h=in-reply-to:content-transfer-encoding:content-disposition :mime-version:references:message-id:subject:cc:to:from:date:x-gm-gg :x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=L5lq5l3mHzRMh4g2BXopS/EJzG0m2BHCz7XcEM7WDUA=; b=SDCWpLfogjpdSzvve79FSP3KblKO3NWPg6CPadygJ7lyQuyjHHgtJhk9cBuCpqAEAv //JeEG/D8SOl2U2gpnbqzFztgyHv/fkp62fyVQzLl8EdvAYoaei7x+uQOtlRslPTzia6 B2KhIeLu3+jzn2YDAwWjOr5gT6DntjfhwoxscS76AjuJSBARfG8PjQYuukByS/h4Hwn5 TistVUMtbzbCAZxDLYxpTJykI0ylspFgZY+fmFffuJeOppFjjc8uT9vvEG7uHdwz+tzu a70rnivv4vYCx2IJhLeyJ3LoqsD2IEAKkw9faa4ht4Yo5OKehDUAfUrbn1ewX4qyVNwN zeSg== X-Forwarded-Encrypted: i=1; AFNElJ+fPJ7TAC2wQEqHjJseIw1386YNDsXJL/TjvF6n3xD2ohgTaLL5Dd8rl7ugA1HJB7TyCRI1pd55VBbYvyc=@vger.kernel.org X-Gm-Message-State: AOJu0Yz6DXe+FIXgLso79mH+C+bLyjHCP+8XMedA2raYZ4hD5hb1AS8R j0GgICHqRbbkvlLBTxn+e/CT9A08w07+hb0/GkxxhPsgDJCiJ1EfxMKDMR17OGHrFUE= X-Gm-Gg: Acq92OFIHyNa1ld5/hQ5A8SIWfyE9OwCq4CCpz4te8Cx9s1XN6BYQ5+DYVevKOhzvCC l1AmQ0p8tJTkkcjRcu/HbXk4LOH8viP/N3slxKOv4ddyw6NV1kqa/Hyo7UWbliahVSEuG/Pm1+h tIH/T4NwloeBFoENIorc3pWk1nklpI24EFYIWQlzvXqQFNe89Zg6IOfDOGLtlqv3rcj1flUPeHr 3bxD4cChWWB1WRXVwTbHv7MIwwU6G01tkjB0M4xLoHj8DLOmXyv/1zVoslvYhd2J5bYlY/7aJMk WR1mhUqj26CAscTDOkHb2SfvZsJarRWUIbDnuL93Gkvdkmpwo2+AtgFVma9Y4cP+HcSWrWyFvmB V3rd1qM1G5H0l7GSzRG1OIfD5pGKAJIJQCu5ipSO41jreJcQcy04NvkE15M1s5Xlx3jruXVV5JY 1Zy7Y8w7LrNIrVzQfuzNIfDuQHKg== X-Received: by 2002:a05:600c:3b20:b0:48e:8741:fd53 with SMTP id 5b1f17b1804b1-490426adc1amr216598205e9.15.1779715743782; Mon, 25 May 2026 06:29:03 -0700 (PDT) Received: from pathway.suse.cz ([176.114.240.130]) by smtp.gmail.com with ESMTPSA id 5b1f17b1804b1-4904527dbf3sm235734995e9.6.2026.05.25.06.29.03 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 25 May 2026 06:29:03 -0700 (PDT) Date: Mon, 25 May 2026 15:29:01 +0200 From: Petr Mladek To: Thomas =?iso-8859-1?Q?Wei=DFschuh?= Cc: Steven Rostedt , John Ogness , Sergey Senozhatsky , Anna-Maria Behnsen , Frederic Weisbecker , Thomas Gleixner , linux-kernel@vger.kernel.org Subject: Re: [QUESTION] printk: time namespaces and printk timestamps Message-ID: References: Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: 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)" -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. 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 #include #include +#include #include #include @@ -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