public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed
* [PATCH v4 0/1] printk: fix zero-valued printk timestamps
@ 2026-04-10 20:37 Tim Bird
  2026-04-10 20:37 ` [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot Tim Bird
  0 siblings, 1 reply; 11+ messages in thread
From: Tim Bird @ 2026-04-10 20:37 UTC (permalink / raw)
  To: pmladek, rostedt, john.ogness, senozhatsky
  Cc: francesco, geert, tglx, shashankbalaji02, linux-embedded,
	linux-kernel, Tim Bird

Some kernel messages emitted before kernel timekeeping is started
have a timestamp value of zero.  However, some platforms
have a cycle counter or timer register that is initialized
before the kernel starts (either in hardware or pre-kernel
firmware), and it can be accessed to provide uncalibrated
values before any other kernel initialization.  I refer
to this period where kernel timestamps are zero as the
printk timing "blind spot".

The following patch allows developers to set a config value
CONFIG_EARLY_CYCLES_KHZ, that will be used to provide
useful timestamps on early printk messages.
This calibration value is set as a static configuration
variable, since it must be available from the very first kernel
instruction.  Since this value is machine-specific, it cannot
be used in the .config for a generic distribution kernel.
The feature is presented here as something useful for
kernel developers working on boot-time optimization
(ie, as something that can be used temporarily during boot
time research and development work, and not necessarily
a runtime option for the average user).

Different platforms have different blind spot durations.
On an x86_64 platform, due to early tsc initialization, the
blind spot may be as small at 16 milliseconds.  On a
Raspberry Pi 4 board, it is approximately 180 milliseconds.
On a RISC V BeagleV Fire board, it can be up to 1700
milliseconds (1.7 seconds).  On some platforms, the blind spot
duration is a significant percentage of the time before user-space
initialization in the kernel (greater than 20%).

This feature uses a different mechanism to gather timestamp values.
When kernel timekeeping starts, the printk timestamps change
to a new timebase based on local_clock(), and timestamp values
reset to the baseline used for kernel timekeeping. This results in a
one-time discontinuity in timestamps between early printks and later
printks. The discontinuity should be obvious to humans, but could
possibly confuse tools.

Here is before and after dmesg output for a Raspberry PI 4 board:

before:
[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[    0.000000] Linux version 7.0.0-rc3-v8+ (tbird@timdesk) (aarch64-linux-gnu-gcc (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #5 SMP PREEMPT Wed Mar 11 18:30:18 MDT 2026
[    0.000000] KASLR enabled
[    0.000000] random: crng init done
[    0.000000] Machine model: Raspberry Pi 4 Model B Rev 1.5
[    0.000000] efi: UEFI not found.
...
[    0.000000] Root IRQ handler: gic_handle_irq
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.000000] arch_timer: cp15 timer running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000000] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000161] Console: colour dummy device 80x25
[    0.000170] printk: legacy console [tty1] enabled

after:
[    0.002975] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[    0.002998] Linux version 7.0.0-rc6-v8+ (tbird@timdesk) (aarch64-linux-gnu-gcc (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #20 SMP PREEMPT Fri Apr 10 11:57:48 MDT 2026
[    0.003002] KASLR enabled
[    0.003338] random: crng init done
[    0.003866] Machine model: Raspberry Pi 4 Model B Rev 1.5
[    0.004495] efi: UEFI not found.
...
[    0.183552] Root IRQ handler: gic_handle_irq
[    0.183561] GIC: Using split EOI/Deactivate mode
[    0.183699] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.183958] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.183952] arch_timer: cp15 timer running at 54.00MHz (phys).
[    0.000000] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000157] Console: colour dummy device 80x25
[    0.000165] printk: legacy console [tty1] enabled


Tim Bird (1):
  printk: fix zero-valued printk timestamps in early boot

 include/linux/early_times.h | 55 +++++++++++++++++++++++++++++++++++++
 init/Kconfig                | 30 ++++++++++++++++++++
 kernel/printk/printk.c      |  3 ++
 3 files changed, 88 insertions(+)
 create mode 100644 include/linux/early_times.h

-- 
2.43.0


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

* [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-10 20:37 [PATCH v4 0/1] printk: fix zero-valued printk timestamps Tim Bird
@ 2026-04-10 20:37 ` Tim Bird
  2026-04-12 10:10   ` kernel test robot
                     ` (4 more replies)
  0 siblings, 5 replies; 11+ messages in thread
From: Tim Bird @ 2026-04-10 20:37 UTC (permalink / raw)
  To: pmladek, rostedt, john.ogness, senozhatsky
  Cc: francesco, geert, tglx, shashankbalaji02, linux-embedded,
	linux-kernel, Tim Bird

During early boot, printk timestamps are reported as zero before
kernel timekeeping starts (i.e. before time_init()).  This
hinders boot-time optimization efforts.  This period ranges from
17 to 1700 milliseconds on different embedded machines running Linux.

Add support for early timestamps based on processor cycle-generators
that need no kernel initialization. Use a statically-configured
frequency value for converting cycles to nanoseconds. This means
that this feature cannot be turned on in generic distro kernels.
It is intended for temporary use during kernel development and
boot-time research and optimization only.

This yields non-zero timestamps for printks from the very start
of kernel execution.  The timestamps are relative to the start of
an architecture-specific counter (e.g. tsc on x86_64 and cntvct_el0
on arm64).  Affected timestamps reflect time from cycle counter
init (usually machine power-on or virtual machine start) instead of
time from the kernel's timekeeping initialization. This results in a
discontinuity in the printk timestamp values, one time, when
kernel timekeeping starts.

Signed-off-by: Tim Bird <tim.bird@sony.com>
---
V3 -> V4
  Replace config vars with single one: CONFIG_EARLY_CYCLES_KHZ
  Replace runtime calibration with static config variable
  Remove reference to get_cycles()
  Add support for RISCV platforms
V2 -> V3
  Default CONFIG option to 'n'
  Move more code into early_times.h (reduce ifdefs in init/main.c)
  Use match64 helper routines
  Use cycles_t instead of u64 type
  Add #defines for EARLY_CYCLES_BIT and EARLY_CYCLES_MASK
  Invert if logic in adjust_early_ts()
V1 -> V2
  Remove calibration CONFIG vars
  Add 'depends on' to restrict arches (to handle ppc bug)
  Add early_ts_offset to avoid discontinuity
  Save cycles in ts_nsec, and convert on output
  Move conditional code to include file (early_times.h>
---
 include/linux/early_times.h | 55 +++++++++++++++++++++++++++++++++++++
 init/Kconfig                | 30 ++++++++++++++++++++
 kernel/printk/printk.c      |  3 ++
 3 files changed, 88 insertions(+)
 create mode 100644 include/linux/early_times.h

diff --git a/include/linux/early_times.h b/include/linux/early_times.h
new file mode 100644
index 000000000000..82bacfd0e26b
--- /dev/null
+++ b/include/linux/early_times.h
@@ -0,0 +1,55 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _EARLY_TIMES_H
+#define _EARLY_TIMES_H
+
+#include <linux/timekeeping.h>
+#ifdef CONFIG_ARM64
+#include <asm/sysreg.h>
+#endif
+
+#ifdef CONFIG_EARLY_CYCLES_KHZ
+static inline u64 early_unsafe_cycles(void)
+{
+#if defined(CONFIG_X86_64)
+	/*
+	 * This rdtsc may happen before secure TSC is initialized, and
+	 * it is unordered. So please don't use this value for cryptography
+	 * or after SMP is initialized.
+	 */
+	return rdtsc();
+#elif defined(CONFIG_ARM64)
+	return read_sysreg(cntvct_el0);
+#elif defined(CONFIG_RISCV_TIMER)
+	u64 val;
+
+	asm volatile("rdtime %0" : "=r"(val));
+	return val;
+#else
+	return 0;
+#endif
+}
+
+#define NS_PER_KHZ	1000000UL
+
+/* returns a nanosecond value based on early cycles */
+static inline u64 early_times_ns(void)
+{
+	if (CONFIG_EARLY_CYCLES_KHZ)
+		/*
+		 * Note: the multiply must precede the division to avoid
+		 * truncation and loss of resolution
+		 * Don't use fancier MULT/SHIFT math here.  Since this is
+		 * static, the compiler can optimize the math operations.
+		 */
+		return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
+	return 0;
+}
+#else
+static inline u64 early_times_ns(void)
+{
+	return 0;
+}
+#endif
+
+#endif /* _EARLY_TIMES_H */
diff --git a/init/Kconfig b/init/Kconfig
index 7484cd703bc1..40c3123c2c27 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -792,6 +792,36 @@ config IKHEADERS
 	  or similar programs.  If you build the headers as a module, a module called
 	  kheaders.ko is built which can be loaded on-demand to get access to headers.
 
+config EARLY_CYCLES_KHZ
+	int "Frequency of the early times cycle counter, in KHz"
+	default 0
+	depends on PRINTK
+	depends on ARM64 || X86_64 || RISCV_TIMER
+	help
+	  Specifies the frequency value (in KHz) of the cycle counter
+	  used for early times information.
+
+	  Set this to provide timing information for printks in early boot
+	  (before the start of kernel timekeeping), that would otherwise
+	  show as 0.
+
+	  To calculate the value for your system, boot your system, and
+	  use the value expressed on the tsc or cntvct_el0 calibration line
+	  in your kernel message log:
+	  ex x86_64: tsc: Refined TSC clocksource calibration: 2095.057 MHz
+          In that case, use the value 2095057.
+	  ex arm64: arch_timer: cp15 timer running at 54.00MHz (phys).
+	  In that case, use the value of 54000.
+
+	  Note that this causes the kernel to show, for some early printks,
+	  times that are relative to processor power on, instead of
+	  relative to the start of kernel timekeeping.  When kernel
+	  timekeeping starts, the timestamps values reset, causing
+	  a discontinuity in the timestamp values.  If you see
+	  non-monotonic printk timestamps, please don't freak out.
+
+	  Set to 0 to disable this feature.
+
 config LOG_BUF_SHIFT
 	int "Kernel log buffer size (16 => 64KB, 17 => 128KB)"
 	range 12 25
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0323149548f6..ddeab81f04ef 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -46,6 +46,7 @@
 #include <linux/ctype.h>
 #include <linux/uio.h>
 #include <linux/sched/clock.h>
+#include <linux/early_times.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
 #include <linux/panic.h>
@@ -2294,6 +2295,8 @@ int vprintk_store(int facility, int level,
 	 * timestamp with respect to the caller.
 	 */
 	ts_nsec = local_clock();
+	if (unlikely(!ts_nsec))
+		ts_nsec = early_times_ns();
 
 	caller_id = printk_caller_id();
 
-- 
2.43.0


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

* Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-10 20:37 ` [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot Tim Bird
@ 2026-04-12 10:10   ` kernel test robot
  2026-04-13 17:58     ` Bird, Tim
  2026-04-12 11:12   ` kernel test robot
                     ` (3 subsequent siblings)
  4 siblings, 1 reply; 11+ messages in thread
From: kernel test robot @ 2026-04-12 10:10 UTC (permalink / raw)
  To: Tim Bird, pmladek, rostedt, john.ogness, senozhatsky
  Cc: oe-kbuild-all, francesco, geert, tglx, shashankbalaji02,
	linux-embedded, linux-kernel, Tim Bird

Hi Tim,

kernel test robot noticed the following build warnings:

[auto build test WARNING on linus/master]
[also build test WARNING on v7.0-rc7 next-20260410]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Tim-Bird/printk-fix-zero-valued-printk-timestamps-in-early-boot/20260412-134726
base:   linus/master
patch link:    https://lore.kernel.org/r/20260410203741.997410-2-tim.bird%40sony.com
patch subject: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
config: arm64-allnoconfig (https://download.01.org/0day-ci/archive/20260412/202604121822.OvOLcTnO-lkp@intel.com/config)
compiler: aarch64-linux-gcc (GCC) 15.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20260412/202604121822.OvOLcTnO-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202604121822.OvOLcTnO-lkp@intel.com/

All warnings (new ones prefixed by >>):

   In file included from kernel/printk/printk.c:49:
   include/linux/early_times.h: In function 'early_times_ns':
>> include/linux/early_times.h:45:61: warning: division by zero [-Wdiv-by-zero]
      45 |                 return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
         |                                                             ^


vim +45 include/linux/early_times.h

    34	
    35	/* returns a nanosecond value based on early cycles */
    36	static inline u64 early_times_ns(void)
    37	{
    38		if (CONFIG_EARLY_CYCLES_KHZ)
    39			/*
    40			 * Note: the multiply must precede the division to avoid
    41			 * truncation and loss of resolution
    42			 * Don't use fancier MULT/SHIFT math here.  Since this is
    43			 * static, the compiler can optimize the math operations.
    44			 */
  > 45			return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
    46		return 0;
    47	}
    48	#else
    49	static inline u64 early_times_ns(void)
    50	{
    51		return 0;
    52	}
    53	#endif
    54	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

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

* Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-10 20:37 ` [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot Tim Bird
  2026-04-12 10:10   ` kernel test robot
@ 2026-04-12 11:12   ` kernel test robot
  2026-04-12 12:55   ` kernel test robot
                     ` (2 subsequent siblings)
  4 siblings, 0 replies; 11+ messages in thread
From: kernel test robot @ 2026-04-12 11:12 UTC (permalink / raw)
  To: Tim Bird, pmladek, rostedt, john.ogness, senozhatsky
  Cc: llvm, oe-kbuild-all, francesco, geert, tglx, shashankbalaji02,
	linux-embedded, linux-kernel, Tim Bird

Hi Tim,

kernel test robot noticed the following build warnings:

[auto build test WARNING on linus/master]
[also build test WARNING on v7.0-rc7 next-20260410]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Tim-Bird/printk-fix-zero-valued-printk-timestamps-in-early-boot/20260412-134726
base:   linus/master
patch link:    https://lore.kernel.org/r/20260410203741.997410-2-tim.bird%40sony.com
patch subject: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
config: um-defconfig (https://download.01.org/0day-ci/archive/20260412/202604121907.nsngvl5u-lkp@intel.com/config)
compiler: clang version 23.0.0git (https://github.com/llvm/llvm-project ae825cb8cea7f3ac8e5e4096f22713845cf5e501)
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20260412/202604121907.nsngvl5u-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202604121907.nsngvl5u-lkp@intel.com/

All warnings (new ones prefixed by >>):

   In file included from kernel/printk/printk.c:49:
   include/linux/early_times.h:20:9: error: call to undeclared function 'rdtsc'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
      20 |         return rdtsc();
         |                ^
>> include/linux/early_times.h:45:47: warning: division by zero is undefined [-Wdivision-by-zero]
      45 |                 return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
         |                                                             ^ ~~~~~~~~~~~~~~~~~~~~~~~
   1 warning and 1 error generated.


vim +45 include/linux/early_times.h

    34	
    35	/* returns a nanosecond value based on early cycles */
    36	static inline u64 early_times_ns(void)
    37	{
    38		if (CONFIG_EARLY_CYCLES_KHZ)
    39			/*
    40			 * Note: the multiply must precede the division to avoid
    41			 * truncation and loss of resolution
    42			 * Don't use fancier MULT/SHIFT math here.  Since this is
    43			 * static, the compiler can optimize the math operations.
    44			 */
  > 45			return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
    46		return 0;
    47	}
    48	#else
    49	static inline u64 early_times_ns(void)
    50	{
    51		return 0;
    52	}
    53	#endif
    54	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

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

* Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-10 20:37 ` [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot Tim Bird
  2026-04-12 10:10   ` kernel test robot
  2026-04-12 11:12   ` kernel test robot
@ 2026-04-12 12:55   ` kernel test robot
  2026-04-14  7:03   ` Geert Uytterhoeven
  2026-04-14 22:38   ` Thomas Gleixner
  4 siblings, 0 replies; 11+ messages in thread
From: kernel test robot @ 2026-04-12 12:55 UTC (permalink / raw)
  To: Tim Bird, pmladek, rostedt, john.ogness, senozhatsky
  Cc: llvm, oe-kbuild-all, francesco, geert, tglx, shashankbalaji02,
	linux-embedded, linux-kernel, Tim Bird

Hi Tim,

kernel test robot noticed the following build errors:

[auto build test ERROR on linus/master]
[also build test ERROR on v7.0-rc7 next-20260410]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Tim-Bird/printk-fix-zero-valued-printk-timestamps-in-early-boot/20260412-134726
base:   linus/master
patch link:    https://lore.kernel.org/r/20260410203741.997410-2-tim.bird%40sony.com
patch subject: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
config: um-defconfig (https://download.01.org/0day-ci/archive/20260412/202604122037.R14cnXpl-lkp@intel.com/config)
compiler: clang version 23.0.0git (https://github.com/llvm/llvm-project ae825cb8cea7f3ac8e5e4096f22713845cf5e501)
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20260412/202604122037.R14cnXpl-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202604122037.R14cnXpl-lkp@intel.com/

All errors (new ones prefixed by >>):

   In file included from kernel/printk/printk.c:49:
>> include/linux/early_times.h:20:9: error: call to undeclared function 'rdtsc'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
      20 |         return rdtsc();
         |                ^
   include/linux/early_times.h:45:47: warning: division by zero is undefined [-Wdivision-by-zero]
      45 |                 return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
         |                                                             ^ ~~~~~~~~~~~~~~~~~~~~~~~
   1 warning and 1 error generated.


vim +/rdtsc +20 include/linux/early_times.h

    10	
    11	#ifdef CONFIG_EARLY_CYCLES_KHZ
    12	static inline u64 early_unsafe_cycles(void)
    13	{
    14	#if defined(CONFIG_X86_64)
    15		/*
    16		 * This rdtsc may happen before secure TSC is initialized, and
    17		 * it is unordered. So please don't use this value for cryptography
    18		 * or after SMP is initialized.
    19		 */
  > 20		return rdtsc();
    21	#elif defined(CONFIG_ARM64)
    22		return read_sysreg(cntvct_el0);
    23	#elif defined(CONFIG_RISCV_TIMER)
    24		u64 val;
    25	
    26		asm volatile("rdtime %0" : "=r"(val));
    27		return val;
    28	#else
    29		return 0;
    30	#endif
    31	}
    32	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

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

* RE: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-12 10:10   ` kernel test robot
@ 2026-04-13 17:58     ` Bird, Tim
  2026-04-13 20:17       ` David Laight
  2026-04-14 22:48       ` Thomas Gleixner
  0 siblings, 2 replies; 11+ messages in thread
From: Bird, Tim @ 2026-04-13 17:58 UTC (permalink / raw)
  To: kernel test robot, pmladek@suse.com, rostedt@goodmis.org,
	john.ogness@linutronix.de, senozhatsky@chromium.org
  Cc: oe-kbuild-all@lists.linux.dev, francesco@valla.it,
	geert@linux-m68k.org, tglx@kernel.org, shashankbalaji02@gmail.com,
	linux-embedded@vger.kernel.org, linux-kernel@vger.kernel.org

Hmmm,

This is a false positive warning from the compiler (see below).

I apologize for not catching it.   I did test with CONFIG_EARLY_CYCLES=0
and I'm not sure why I didn't see the warning.

I'll see if I can silence this warning.

> -----Original Message-----
> From: kernel test robot <lkp@intel.com>
> Sent: Sunday, April 12, 2026 4:11 AM
> Hi Tim,
> 
> kernel test robot noticed the following build warnings:
> 
> [auto build test WARNING on linus/master]
> [also build test WARNING on v7.0-rc7 next-20260410]
> [If your patch is applied to the wrong git tree, kindly drop us a note.
> And when submitting patch, we suggest to use '--base' as documented in
> https://git-scm.com/docs/git-format-patch#_base_tree_information]
> 
> url:    https://github.com/intel-lab-lkp/linux/commits/Tim-Bird/printk-fix-zero-valued-printk-timestamps-in-early-boot/20260412-134726
> base:   linus/master
> patch link:    https://lore.kernel.org/r/20260410203741.997410-2-tim.bird%40sony.com
> patch subject: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
> config: arm64-allnoconfig (https://download.01.org/0day-ci/archive/20260412/202604121822.OvOLcTnO-lkp@intel.com/config)
> compiler: aarch64-linux-gcc (GCC) 15.2.0
> reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20260412/202604121822.OvOLcTnO-lkp@intel.com/reproduce)
> 
> If you fix the issue in a separate patch/commit (i.e. not just a new version of
> the same patch/commit), kindly add following tags
> | Reported-by: kernel test robot <lkp@intel.com>
> | Closes: https://lore.kernel.org/oe-kbuild-all/202604121822.OvOLcTnO-lkp@intel.com/
> 
> All warnings (new ones prefixed by >>):
> 
>    In file included from kernel/printk/printk.c:49:
>    include/linux/early_times.h: In function 'early_times_ns':
> >> include/linux/early_times.h:45:61: warning: division by zero [-Wdiv-by-zero]
>       45 |                 return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
>          |                                                             ^
> 
> 
> vim +45 include/linux/early_times.h
> 
>     34
>     35	/* returns a nanosecond value based on early cycles */
>     36	static inline u64 early_times_ns(void)
>     37	{
>     38		if (CONFIG_EARLY_CYCLES_KHZ)
>     39			/*
>     40			 * Note: the multiply must precede the division to avoid
>     41			 * truncation and loss of resolution
>     42			 * Don't use fancier MULT/SHIFT math here.  Since this is
>     43			 * static, the compiler can optimize the math operations.
>     44			 */
>   > 45			return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
Based on this conditional, it's not possible for CONFIG_EARLY_CYCLES_KHZ to be zero
on this line of code.  Does GCC not catch this?
if (0)
   x = <some expression>/0;

So this is a false positive.

>     46		return 0;
>     47	}
>     48	#else
>     49	static inline u64 early_times_ns(void)
>     50	{
>     51		return 0;
>     52	}
>     53	#endif
>     54
> 
> --
> 0-DAY CI Kernel Test Service
> https://github.com/intel/lkp-tests/wiki

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

* Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-13 17:58     ` Bird, Tim
@ 2026-04-13 20:17       ` David Laight
  2026-04-14 22:48       ` Thomas Gleixner
  1 sibling, 0 replies; 11+ messages in thread
From: David Laight @ 2026-04-13 20:17 UTC (permalink / raw)
  To: Bird, Tim
  Cc: kernel test robot, pmladek@suse.com, rostedt@goodmis.org,
	john.ogness@linutronix.de, senozhatsky@chromium.org,
	oe-kbuild-all@lists.linux.dev, francesco@valla.it,
	geert@linux-m68k.org, tglx@kernel.org, shashankbalaji02@gmail.com,
	linux-embedded@vger.kernel.org, linux-kernel@vger.kernel.org

On Mon, 13 Apr 2026 17:58:34 +0000
"Bird, Tim" <Tim.Bird@sony.com> wrote:

> Hmmm,
> 
> This is a false positive warning from the compiler (see below).
> 
> I apologize for not catching it.   I did test with CONFIG_EARLY_CYCLES=0
> and I'm not sure why I didn't see the warning.
> 
> I'll see if I can silence this warning.
> 
> > -----Original Message-----
> > From: kernel test robot <lkp@intel.com>
> > Sent: Sunday, April 12, 2026 4:11 AM
> > Hi Tim,
> > 
> > kernel test robot noticed the following build warnings:
> > 
> > [auto build test WARNING on linus/master]
> > [also build test WARNING on v7.0-rc7 next-20260410]
> > [If your patch is applied to the wrong git tree, kindly drop us a note.
> > And when submitting patch, we suggest to use '--base' as documented in
> > https://git-scm.com/docs/git-format-patch#_base_tree_information]
> > 
> > url:    https://github.com/intel-lab-lkp/linux/commits/Tim-Bird/printk-fix-zero-valued-printk-timestamps-in-early-boot/20260412-134726
> > base:   linus/master
> > patch link:    https://lore.kernel.org/r/20260410203741.997410-2-tim.bird%40sony.com
> > patch subject: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
> > config: arm64-allnoconfig (https://download.01.org/0day-ci/archive/20260412/202604121822.OvOLcTnO-lkp@intel.com/config)
> > compiler: aarch64-linux-gcc (GCC) 15.2.0
> > reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20260412/202604121822.OvOLcTnO-lkp@intel.com/reproduce)
> > 
> > If you fix the issue in a separate patch/commit (i.e. not just a new version of
> > the same patch/commit), kindly add following tags
> > | Reported-by: kernel test robot <lkp@intel.com>
> > | Closes: https://lore.kernel.org/oe-kbuild-all/202604121822.OvOLcTnO-lkp@intel.com/
> > 
> > All warnings (new ones prefixed by >>):
> > 
> >    In file included from kernel/printk/printk.c:49:
> >    include/linux/early_times.h: In function 'early_times_ns':  
> > >> include/linux/early_times.h:45:61: warning: division by zero [-Wdiv-by-zero]  
> >       45 |                 return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
> >          |                                                             ^
> > 
> > 
> > vim +45 include/linux/early_times.h
> > 
> >     34
> >     35	/* returns a nanosecond value based on early cycles */
> >     36	static inline u64 early_times_ns(void)
> >     37	{
> >     38		if (CONFIG_EARLY_CYCLES_KHZ)
> >     39			/*
> >     40			 * Note: the multiply must precede the division to avoid
> >     41			 * truncation and loss of resolution
> >     42			 * Don't use fancier MULT/SHIFT math here.  Since this is
> >     43			 * static, the compiler can optimize the math operations.
> >     44			 */  
> >   > 45			return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;  
> Based on this conditional, it's not possible for CONFIG_EARLY_CYCLES_KHZ to be zero
> on this line of code.  Does GCC not catch this?
> if (0)
>    x = <some expression>/0;
> 
> So this is a false positive.

I suspect the warning is being generated before the optimiser throws
the code away as unreachable.
You might have to do:
	return (early_unsafe_cycles() * NS_PER_KHZ) / (CONFIG_EARLY_CYCLES_KHZ ?: 1);

David

> 
> >     46		return 0;
> >     47	}
> >     48	#else
> >     49	static inline u64 early_times_ns(void)
> >     50	{
> >     51		return 0;
> >     52	}
> >     53	#endif
> >     54
> > 
> > --
> > 0-DAY CI Kernel Test Service
> > https://github.com/intel/lkp-tests/wiki  


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

* Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-10 20:37 ` [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot Tim Bird
                     ` (2 preceding siblings ...)
  2026-04-12 12:55   ` kernel test robot
@ 2026-04-14  7:03   ` Geert Uytterhoeven
  2026-04-14  9:51     ` Roberto A. Foglietta
  2026-04-14 22:38   ` Thomas Gleixner
  4 siblings, 1 reply; 11+ messages in thread
From: Geert Uytterhoeven @ 2026-04-14  7:03 UTC (permalink / raw)
  To: Tim Bird
  Cc: pmladek, rostedt, john.ogness, senozhatsky, francesco, tglx,
	shashankbalaji02, linux-embedded, linux-kernel

Hi Tim,

Thanks for your patch!

On Fri, 10 Apr 2026 at 22:38, Tim Bird <tim.bird@sony.com> wrote:
> During early boot, printk timestamps are reported as zero before
> kernel timekeeping starts (i.e. before time_init()).  This
> hinders boot-time optimization efforts.  This period ranges from
> 17 to 1700 milliseconds on different embedded machines running Linux.
>
> Add support for early timestamps based on processor cycle-generators
> that need no kernel initialization. Use a statically-configured
> frequency value for converting cycles to nanoseconds. This means
> that this feature cannot be turned on in generic distro kernels.
> It is intended for temporary use during kernel development and
> boot-time research and optimization only.
>
> This yields non-zero timestamps for printks from the very start
> of kernel execution.  The timestamps are relative to the start of
> an architecture-specific counter (e.g. tsc on x86_64 and cntvct_el0
> on arm64).  Affected timestamps reflect time from cycle counter
> init (usually machine power-on or virtual machine start) instead of
> time from the kernel's timekeeping initialization. This results in a
> discontinuity in the printk timestamp values, one time, when
> kernel timekeeping starts.

Won't it be hard to see where the discontinuity happens in some cases?
Perhaps this can be made more obvious by not doing the time conversion
in kernelspace, like in your first version?

> Signed-off-by: Tim Bird <tim.bird@sony.com>

> --- /dev/null
> +++ b/include/linux/early_times.h

> +/* returns a nanosecond value based on early cycles */
> +static inline u64 early_times_ns(void)
> +{
> +       if (CONFIG_EARLY_CYCLES_KHZ)
> +               /*
> +                * Note: the multiply must precede the division to avoid
> +                * truncation and loss of resolution
> +                * Don't use fancier MULT/SHIFT math here.  Since this is
> +                * static, the compiler can optimize the math operations.
> +                */
> +               return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;

Still, this contains a 64-by-32 division, so let's see how this works
out on 32-bit (RISCV_TIMER is set on rv32!).  If the compiler would
generate a function call to a libgcc helper, you will have to switch
to the mul_u64_u32_div() helper...

> +       return 0;
> +}
> +#else
> +static inline u64 early_times_ns(void)
> +{
> +       return 0;
> +}
> +#endif
> +
> +#endif /* _EARLY_TIMES_H */

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

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

* Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-14  7:03   ` Geert Uytterhoeven
@ 2026-04-14  9:51     ` Roberto A. Foglietta
  0 siblings, 0 replies; 11+ messages in thread
From: Roberto A. Foglietta @ 2026-04-14  9:51 UTC (permalink / raw)
  To: Geert Uytterhoeven
  Cc: Tim Bird, pmladek, rostedt, john.ogness, senozhatsky, francesco,
	tglx, shashankbalaji02, linux-embedded, linux-kernel

On Tue, 14 Apr 2026 at 09:03, Geert Uytterhoeven <geert@linux-m68k.org> wrote:
>
> Hi Tim,
>
> Thanks for your patch!
>
> On Fri, 10 Apr 2026 at 22:38, Tim Bird <tim.bird@sony.com> wrote:
> > During early boot, printk timestamps are reported as zero before
> > kernel timekeeping starts (i.e. before time_init()).  This
...
> Won't it be hard to see where the discontinuity happens in some cases?
> Perhaps this can be made more obvious by not doing the time conversion
> in kernelspace, like in your first version?
>
> > Signed-off-by: Tim Bird <tim.bird@sony.com>
>
> > --- /dev/null
> > +++ b/include/linux/early_times.h
>
> > +/* returns a nanosecond value based on early cycles */
> > +static inline u64 early_times_ns(void)
> > +{
> > +       if (CONFIG_EARLY_CYCLES_KHZ)
> > +               /*
> > +                * Note: the multiply must precede the division to avoid
> > +                * truncation and loss of resolution
> > +                * Don't use fancier MULT/SHIFT math here.  Since this is
> > +                * static, the compiler can optimize the math operations.
> > +                */
> > +               return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
>
> Still, this contains a 64-by-32 division, so let's see how this works
> out on 32-bit (RISCV_TIMER is set on rv32!).  If the compiler would
> generate a function call to a libgcc helper, you will have to switch
> to the mul_u64_u32_div() helper...

Interesting.

https://github.com/robang74/uchaosys/blob/53e72d169/cnfg/printk-fix-early-boot-timestamps-patch-v4.txt#L92

Elvis the King (A?:), R-

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

* Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-10 20:37 ` [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot Tim Bird
                     ` (3 preceding siblings ...)
  2026-04-14  7:03   ` Geert Uytterhoeven
@ 2026-04-14 22:38   ` Thomas Gleixner
  4 siblings, 0 replies; 11+ messages in thread
From: Thomas Gleixner @ 2026-04-14 22:38 UTC (permalink / raw)
  To: Tim Bird, pmladek, rostedt, john.ogness, senozhatsky
  Cc: francesco, geert, shashankbalaji02, linux-embedded, linux-kernel,
	Tim Bird

On Fri, Apr 10 2026 at 14:37, Tim Bird wrote:
> +
> +#include <linux/timekeeping.h>
> +#ifdef CONFIG_ARM64
> +#include <asm/sysreg.h>
> +#endif
> +
> +#ifdef CONFIG_EARLY_CYCLES_KHZ
> +static inline u64 early_unsafe_cycles(void)
> +{
> +#if defined(CONFIG_X86_64)
> +	/*
> +	 * This rdtsc may happen before secure TSC is initialized, and
> +	 * it is unordered. So please don't use this value for cryptography
> +	 * or after SMP is initialized.
> +	 */
> +	return rdtsc();
> +#elif defined(CONFIG_ARM64)
> +	return read_sysreg(cntvct_el0);
> +#elif defined(CONFIG_RISCV_TIMER)
> +	u64 val;
> +
> +	asm volatile("rdtime %0" : "=r"(val));
> +	return val;
> +#else
> +	return 0;
> +#endif
> +}

No. Generic code and generic headers have no business to implement any
architecture specific code and there is zero justification for
architecture specific #ifdefs in generic code.

Ask your favourite AI assistant for an opinion.

> +#define NS_PER_KHZ	1000000UL

The existing nomenclature for nanosecond related constants is NSEC_* 

> +
> +/* returns a nanosecond value based on early cycles */
> +static inline u64 early_times_ns(void)
> +{
> +	if (CONFIG_EARLY_CYCLES_KHZ)
> +		/*
> +		 * Note: the multiply must precede the division to avoid
> +		 * truncation and loss of resolution
> +		 * Don't use fancier MULT/SHIFT math here.  Since this is
> +		 * static, the compiler can optimize the math operations.
> +		 */
> +		return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;

This code will result in a division by zero warning from any reasonable
compiler because this is evaluated _before_ it is eliminated.

> @@ -2294,6 +2295,8 @@ int vprintk_store(int facility, int level,
>  	 * timestamp with respect to the caller.
>  	 */
>  	ts_nsec = local_clock();
> +	if (unlikely(!ts_nsec))
> +		ts_nsec = early_times_ns();

I explained to you how this wants to be implemented to be useful and you
declared that you are unwilling to put the effort in.

My NAK for this disgusting and tasteless hack still applies.

Either you are willing to work with the community and the relevant
maintainers or you can keep your hackery maintained out of tree for
those who care about it and are willing to ignore the fallout. 

Thanks,

        tglx

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

* RE: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
  2026-04-13 17:58     ` Bird, Tim
  2026-04-13 20:17       ` David Laight
@ 2026-04-14 22:48       ` Thomas Gleixner
  1 sibling, 0 replies; 11+ messages in thread
From: Thomas Gleixner @ 2026-04-14 22:48 UTC (permalink / raw)
  To: Bird, Tim, kernel test robot, pmladek@suse.com,
	rostedt@goodmis.org, john.ogness@linutronix.de,
	senozhatsky@chromium.org
  Cc: oe-kbuild-all@lists.linux.dev, francesco@valla.it,
	geert@linux-m68k.org, shashankbalaji02@gmail.com,
	linux-embedded@vger.kernel.org, linux-kernel@vger.kernel.org

On Mon, Apr 13 2026 at 17:58, Tim Bird wrote:
> This is a false positive warning from the compiler (see below).

This is _NOT_ a false positive warning. The compiler is absolutely
correct.

>>     34
>>     35	/* returns a nanosecond value based on early cycles */
>>     36	static inline u64 early_times_ns(void)
>>     37	{
>>     38		if (CONFIG_EARLY_CYCLES_KHZ)
>>     39			/*
>>     40			 * Note: the multiply must precede the division to avoid
>>     41			 * truncation and loss of resolution
>>     42			 * Don't use fancier MULT/SHIFT math here.  Since this is
>>     43			 * static, the compiler can optimize the math operations.
>>     44			 */
>>   > 45			return (early_unsafe_cycles() * NS_PER_KHZ) / CONFIG_EARLY_CYCLES_KHZ;
> Based on this conditional, it's not possible for CONFIG_EARLY_CYCLES_KHZ to be zero
> on this line of code.  Does GCC not catch this?
> if (0)
>    x = <some expression>/0;
>
> So this is a false positive.

You clearly fail to understand how compilers work. The dead code
elimination happens _after_ the evaluation of the code and the compiler
does not care whether your initial condition evaluated to false or
not. That's documented compiler behaviour,

Whether GCC complains about it or not is completely irrelevant.

> I'll see if I can silence this warning.

Don't put much effort into it. This whole hack is going nowhere.

Thanks,

        tglx


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

end of thread, other threads:[~2026-04-14 22:48 UTC | newest]

Thread overview: 11+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2026-04-10 20:37 [PATCH v4 0/1] printk: fix zero-valued printk timestamps Tim Bird
2026-04-10 20:37 ` [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot Tim Bird
2026-04-12 10:10   ` kernel test robot
2026-04-13 17:58     ` Bird, Tim
2026-04-13 20:17       ` David Laight
2026-04-14 22:48       ` Thomas Gleixner
2026-04-12 11:12   ` kernel test robot
2026-04-12 12:55   ` kernel test robot
2026-04-14  7:03   ` Geert Uytterhoeven
2026-04-14  9:51     ` Roberto A. Foglietta
2026-04-14 22:38   ` Thomas Gleixner

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox