[tip:timers/core] [timekeeping] 5aa6c43eca: BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow

[tip:timers/core] [timekeeping] 5aa6c43eca: BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow

[kernel test robot]

Hello,


this is another report about BUG:KCSAN, the change does not introduce new KCSAN
issue, but causes stats changes as below.


1d72d7b5fd535923 5aa6c43eca21a929ace6a8e31ab
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
          6:6          -83%            :6     dmesg.BUG:KCSAN:data-race_in_timekeeping_advance/timekeeping_debug_get_ns
           :6          100%           6:6     dmesg.BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow


again, this report is just FYI what's the possible issue in related code.
and if you need more tests or want us to test some patches, please let us know.

thanks!


kernel test robot noticed "BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow" on:

commit: 5aa6c43eca21a929ace6a8e31ab3520ddc50dfa9 ("timekeeping: Split out timekeeper update of timekeeping_advanced()")
https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git timers/core

[test failed on linux-next/master 6fb2fa9805c501d9ade047fc511961f3273cdcb5]

in testcase: boot

config: x86_64-randconfig-073-20241025
compiler: gcc-12
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

(please refer to attached dmesg/kmsg for entire log/backtrace)



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 <oliver.sang@intel.com>
| Closes: https://lore.kernel.org/oe-lkp/202410301316.e51421de-lkp@intel.com


[   70.265411][    C1] BUG: KCSAN: data-race in timekeeping_debug_get_ns / timekeeping_update_from_shadow
[   70.265430][    C1]
[   70.265433][    C1] write to 0xffffffff8483fef8 of 296 bytes by interrupt on cpu 0:
[ 70.265440][ C1] timekeeping_update_from_shadow+0x8e/0x140 
[ 70.265452][ C1] timekeeping_advance (kernel/time/timekeeping.c:2394) 
[ 70.265462][ C1] update_wall_time (kernel/time/timekeeping.c:2403) 
[ 70.265472][ C1] tick_do_update_jiffies64 (kernel/time/tick-sched.c:150) 
[ 70.265485][ C1] tick_nohz_lowres_handler (kernel/time/tick-sched.c:232 kernel/time/tick-sched.c:290 kernel/time/tick-sched.c:1486) 
[ 70.265498][ C1] __sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1044) 
[ 70.265515][ C1] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1037 arch/x86/kernel/apic/apic.c:1037) 
[ 70.265526][ C1] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:702) 
[ 70.265539][ C1] __tsan_read8 (kernel/kcsan/core.c:280 kernel/kcsan/core.c:752 kernel/kcsan/core.c:1025) 
[ 70.265548][ C1] rcu_lockdep_current_cpu_online (kernel/rcu/tree.c:4740 kernel/rcu/tree.c:4781) 
[ 70.265562][ C1] rcu_read_lock_held (kernel/rcu/update.c:113 kernel/rcu/update.c:349) 
[ 70.265573][ C1] mtree_range_walk (lib/maple_tree.c:789 lib/maple_tree.c:2789) 
[ 70.265584][ C1] mas_walk (lib/maple_tree.c:265 lib/maple_tree.c:4949) 
[ 70.265594][ C1] lock_vma_under_rcu (mm/memory.c:6225) 
[ 70.265606][ C1] do_user_addr_fault (arch/x86/mm/fault.c:1330) 
[ 70.265617][ C1] exc_page_fault (arch/x86/include/asm/irqflags.h:26 arch/x86/include/asm/irqflags.h:87 arch/x86/include/asm/irqflags.h:147 arch/x86/mm/fault.c:1489 arch/x86/mm/fault.c:1539) 
[ 70.265624][ C1] asm_exc_page_fault (arch/x86/include/asm/idtentry.h:623) 
[   70.265634][    C1]
[   70.265636][    C1] read to 0xffffffff8483ff18 of 8 bytes by interrupt on cpu 1:
[ 70.265642][ C1] timekeeping_debug_get_ns (kernel/time/timekeeping.c:415 kernel/time/timekeeping.c:399 kernel/time/timekeeping.c:307) 
[ 70.265653][ C1] ktime_get (kernel/time/timekeeping.c:431 (discriminator 4) kernel/time/timekeeping.c:897 (discriminator 4)) 
[ 70.265660][ C1] tick_nohz_lowres_handler (kernel/time/tick-sched.c:220 kernel/time/tick-sched.c:290 kernel/time/tick-sched.c:1486) 
[ 70.265671][ C1] __sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1044) 
[ 70.265683][ C1] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1037 arch/x86/kernel/apic/apic.c:1037) 
[ 70.265690][ C1] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:702) 
[ 70.265701][ C1] __tsan_unaligned_write8 (arch/x86/include/asm/current.h:49 kernel/kcsan/core.c:206 kernel/kcsan/core.c:750 kernel/kcsan/core.c:1025) 
[ 70.265711][ C1] mntput_no_expire (fs/namespace.c:1396) 
[ 70.265719][ C1] mntput (fs/namespace.c:1471 (discriminator 3)) 
[ 70.265728][ C1] path_openat (fs/namei.c:3910) 
[ 70.265738][ C1] do_filp_open (fs/namei.c:3961) 
[ 70.265749][ C1] do_sys_openat2 (fs/open.c:1416) 
[ 70.265760][ C1] __ia32_compat_sys_openat (fs/open.c:1488) 
[ 70.265772][ C1] ia32_sys_call (arch/x86/entry/syscall_32.c:44) 
[ 70.265781][ C1] __do_fast_syscall_32 (arch/x86/entry/common.c:165 arch/x86/entry/common.c:386) 
[ 70.265792][ C1] do_fast_syscall_32 (arch/x86/entry/common.c:411) 
[ 70.265803][ C1] do_SYSENTER_32 (arch/x86/entry/common.c:450) 
[ 70.265814][ C1] entry_SYSENTER_compat_after_hwframe (arch/x86/entry/entry_64_compat.S:127) 
[   70.265827][    C1]
[   70.265829][    C1] value changed: 0x000bfafab0800000 -> 0x000c197f30800000
[   70.265834][    C1]
[   70.265837][    C1] Reported by Kernel Concurrency Sanitizer on:
[   70.265841][    C1] CPU: 1 UID: 0 PID: 135 Comm: systemd-udevd Not tainted 6.12.0-rc1-00057-g5aa6c43eca21 #1 dac0ad7371e68d11ebb5ff151a0b0e46d35a6ac0
[   70.265853][    C1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[   70.265858][    C1] ==================================================================
[  OK  ] Started Regular background program processing daemon.
[  OK  ] Started D-Bus System Message Bus.
Starting Helper to synchronize boot up for ifupdown...
Starting LSB: OpenIPMI Driver init script...
Starting System Logging Service...
Starting User Login Management...
[  OK  ] Finished Helper to synchronize boot up for ifupdown.
Starting Raise network interfaces...
Starting LSB: Load kernel image with kexec...
[   70.813962][  T196] IPMI message handler: version 39.2
[  OK  ] Finished Raise network interfaces.
[  OK  ] Reached target Network.
[   71.021971][  T208] ipmi_si: IPMI System Interface driver
Starting LKP bootstrap...
[   71.073697][  T208] ipmi_si: Unable to find any System Interface(s)
Starting /etc/rc.local Compatibility...
Starting OpenBSD Secure Shell server...
Starting Permit User Sessions...
[  OK  ] Started LSB: Load kernel image with kexec.
[  OK  ] Started User Login Management.
[   71.125252] rc.local[223]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/lkp/lkp/src/bin
[  OK  ] Started /etc/rc.local Compatibility.
[  OK  ] Finished Permit User Sessions.
LKP: ttyS0: 223: skip deploy intel ucode as no ucode is specified
[   71.266778] rc.local[223]: LKP: stdout: 223: skip deploy intel ucode as no ucode is specified
[  OK  ] Started Getty on tty1.
[  OK  ] Reached target Login Prompts.
[FAILED] Failed to start LSB: OpenIPMI Driver init script.
See 'systemctl status openipmi.service' for details.
[  OK  ] Started OpenBSD Secure Shell server.
LKP: ttyS0: 223: Kernel tests: Boot OK!
LKP: ttyS0: 223: HOSTNAME vm-snb, MAC 52:54:00:12:34:56, kernel 6.12.0-rc1-00057-g5aa6c43eca21 1
LKP: ttyS0: 223:  /lkp/lkp/src/bin/run-lkp /lkp/jobs/scheduled/vm-meta-135/boot-1-debian-11.1-i386-20220923.cgz-x86_64-randconfig-073-20241025-5aa6c43eca21-20241030-925541-jrgvjy-5.yaml
[   80.243928][  T241] is_virt=true
[   80.243958][  T241]
[   80.596747][    C0] ==================================================================
[   80.597444][    C0] BUG: KCSAN: data-race in timekeeping_debug_get_ns / timekeeping_update_from_shadow
[   80.598259][    C0]
[   80.598445][    C0] write to 0xffffffff8483fef8 of 296 bytes by interrupt on cpu 1:
[ 80.599035][ C0] timekeeping_update_from_shadow+0x8e/0x140 
[ 80.599730][ C0] timekeeping_advance (kernel/time/timekeeping.c:2394) 
[ 80.600108][ C0] update_wall_time (kernel/time/timekeeping.c:2403) 
[ 80.600452][ C0] tick_do_update_jiffies64 (kernel/time/tick-sched.c:150) 
[ 80.600881][ C0] tick_nohz_lowres_handler (kernel/time/tick-sched.c:232 kernel/time/tick-sched.c:290 kernel/time/tick-sched.c:1486) 
[ 80.601309][ C0] __sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1044) 
[ 80.601767][ C0] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1037 arch/x86/kernel/apic/apic.c:1037) 
[ 80.602211][ C0] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:702) 
[   80.602705][    C0]
[   80.602997][    C0] read to 0xffffffff8483ff18 of 8 bytes by interrupt on cpu 0:
[ 80.603583][ C0] timekeeping_debug_get_ns (kernel/time/timekeeping.c:415 kernel/time/timekeeping.c:399 kernel/time/timekeeping.c:307) 
[ 80.604050][ C0] ktime_get_update_offsets_now (kernel/time/timekeeping.c:2583 (discriminator 4)) 
[ 80.604545][ C0] hrtimer_run_queues (kernel/time/hrtimer.c:637 kernel/time/hrtimer.c:1904) 
[ 80.604974][ C0] update_process_times (kernel/time/timer.c:2465 kernel/time/timer.c:2517) 
[ 80.605404][ C0] tick_nohz_lowres_handler (kernel/time/tick-sched.c:277 kernel/time/tick-sched.c:297 kernel/time/tick-sched.c:1486) 
[ 80.605866][ C0] __sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1044) 
[ 80.606508][ C0] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1037 arch/x86/kernel/apic/apic.c:1037) 
[ 80.606958][ C0] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:702) 
[   80.607450][    C0]
[   80.607656][    C0] value changed: 0x0015dff030800000 -> 0x0015fe74b0800000
[   80.608228][    C0]
[   80.608442][    C0] Reported by Kernel Concurrency Sanitizer on:
[   80.608945][    C0] CPU: 0 UID: 0 PID: 241 Comm: sed Not tainted 6.12.0-rc1-00057-g5aa6c43eca21 #1 dac0ad7371e68d11ebb5ff151a0b0e46d35a6ac0
[   80.610047][    C0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[   80.610868][    C0] ==================================================================



The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20241030/202410301316.e51421de-lkp@intel.com



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

Re: [tip:timers/core] [timekeeping] 5aa6c43eca: BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow

[Thomas Gleixner]

On Wed, Oct 30 2024 at 13:47, kernel test robot wrote:
> this is another report about BUG:KCSAN, the change does not introduce new KCSAN
> issue, but causes stats changes as below.
>
> [   70.265411][    C1] BUG: KCSAN: data-race in timekeeping_debug_get_ns / timekeeping_update_from_shadow
> [   70.265430][    C1]
> [   70.265433][    C1] write to 0xffffffff8483fef8 of 296 bytes by interrupt on cpu 0:
> [ 70.265440][ C1] timekeeping_update_from_shadow+0x8e/0x140 
> [ 70.265452][ C1] timekeeping_advance (kernel/time/timekeeping.c:2394) 
> [ 70.265462][ C1] update_wall_time (kernel/time/timekeeping.c:2403)

timekeeping_update_from_shadow() holds the sequence count write.

> [ 70.265642][ C1] timekeeping_debug_get_ns (kernel/time/timekeeping.c:415 kernel/time/timekeeping.c:399 kernel/time/timekeeping.c:307) 
> [ 70.265653][ C1] ktime_get (kernel/time/timekeeping.c:431 (discriminator 4) kernel/time/timekeeping.c:897 (discriminator 4)) 
> [ 70.265660][ C1] tick_nohz_lowres_handler (kernel/time/tick-sched.c:220 kernel/time/tick-sched.c:290 kernel/time/tick-sched.c:1486) 

ktime_get()

        do {
           seq = read_seqcount_begin(&tk_core.seq);
           timekeeping_debug_get_ns();
        } while (read_seqcount_retry(&tk_core.seq, seq));

So this should be safe against concurreny. I assume the issue here is
that timekeeping_debug_get_ns() has a nested

        do {
           seq = read_seqcount_begin(&tk_core.seq);
           ....
        } while (read_seqcount_retry(&tk_core.seq, seq));

inside. Which is still correct, but confuses KCSAN. Marco?

But that aside, since 135225a363ae timekeeping_cycles_to_ns() is fully
overflow protected and unconditionally handles negative motion (before
it was x86 only), the value of timekeeping_debug_get_ns() becomes
questionable.

I'm leaning towards removing it completely.

John?

Thanks,

        tglx
---
 include/linux/timekeeper_internal.h |   16 ------
 kernel/time/timekeeping.c           |   87 ++----------------------------------
 2 files changed, 5 insertions(+), 98 deletions(-)

--- a/include/linux/timekeeper_internal.h
+++ b/include/linux/timekeeper_internal.h
@@ -76,9 +76,6 @@ struct tk_read_base {
  *				ntp shifted nano seconds.
  * @ntp_err_mult:		Multiplication factor for scaled math conversion
  * @skip_second_overflow:	Flag used to avoid updating NTP twice with same second
- * @last_warning:		Warning ratelimiter (DEBUG_TIMEKEEPING)
- * @underflow_seen:		Underflow warning flag (DEBUG_TIMEKEEPING)
- * @overflow_seen:		Overflow warning flag (DEBUG_TIMEKEEPING)
  *
  * Note: For timespec(64) based interfaces wall_to_monotonic is what
  * we need to add to xtime (or xtime corrected for sub jiffy times)
@@ -147,19 +144,6 @@ struct timekeeper {
 	u32			ntp_error_shift;
 	u32			ntp_err_mult;
 	u32			skip_second_overflow;
-
-#ifdef CONFIG_DEBUG_TIMEKEEPING
-	long			last_warning;
-	/*
-	 * These simple flag variables are managed
-	 * without locks, which is racy, but they are
-	 * ok since we don't really care about being
-	 * super precise about how many events were
-	 * seen, just that a problem was observed.
-	 */
-	int			underflow_seen;
-	int			overflow_seen;
-#endif
 };
 
 #ifdef CONFIG_GENERIC_TIME_VSYSCALL
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -227,8 +227,6 @@ static inline u64 tk_clock_read(const st
 }
 
 #ifdef CONFIG_DEBUG_TIMEKEEPING
-#define WARNING_FREQ (HZ*300) /* 5 minute rate-limiting */
-
 static void timekeeping_check_update(struct timekeeper *tk, u64 offset)
 {
 
@@ -239,82 +237,15 @@ static void timekeeping_check_update(str
 		printk_deferred("WARNING: timekeeping: Cycle offset (%lld) is larger than allowed by the '%s' clock's max_cycles value (%lld): time overflow danger\n",
 				offset, name, max_cycles);
 		printk_deferred("         timekeeping: Your kernel is sick, but tries to cope by capping time updates\n");
-	} else {
-		if (offset > (max_cycles >> 1)) {
+	} else if (offset > (max_cycles >> 1)) {
 			printk_deferred("INFO: timekeeping: Cycle offset (%lld) is larger than the '%s' clock's 50%% safety margin (%lld)\n",
 					offset, name, max_cycles >> 1);
 			printk_deferred("      timekeeping: Your kernel is still fine, but is feeling a bit nervous\n");
-		}
-	}
-
-	if (tk->underflow_seen) {
-		if (jiffies - tk->last_warning > WARNING_FREQ) {
-			printk_deferred("WARNING: Underflow in clocksource '%s' observed, time update ignored.\n", name);
-			printk_deferred("         Please report this, consider using a different clocksource, if possible.\n");
-			printk_deferred("         Your kernel is probably still fine.\n");
-			tk->last_warning = jiffies;
-		}
-		tk->underflow_seen = 0;
-	}
-
-	if (tk->overflow_seen) {
-		if (jiffies - tk->last_warning > WARNING_FREQ) {
-			printk_deferred("WARNING: Overflow in clocksource '%s' observed, time update capped.\n", name);
-			printk_deferred("         Please report this, consider using a different clocksource, if possible.\n");
-			printk_deferred("         Your kernel is probably still fine.\n");
-			tk->last_warning = jiffies;
-		}
-		tk->overflow_seen = 0;
 	}
 }
 
-static inline u64 timekeeping_cycles_to_ns(const struct tk_read_base *tkr, u64 cycles);
-
-static inline u64 timekeeping_debug_get_ns(const struct tk_read_base *tkr)
-{
-	struct timekeeper *tk = &tk_core.timekeeper;
-	u64 now, last, mask, max, delta;
-	unsigned int seq;
-
-	/*
-	 * Since we're called holding a seqcount, the data may shift
-	 * under us while we're doing the calculation. This can cause
-	 * false positives, since we'd note a problem but throw the
-	 * results away. So nest another seqcount here to atomically
-	 * grab the points we are checking with.
-	 */
-	do {
-		seq = read_seqcount_begin(&tk_core.seq);
-		now = tk_clock_read(tkr);
-		last = tkr->cycle_last;
-		mask = tkr->mask;
-		max = tkr->clock->max_cycles;
-	} while (read_seqcount_retry(&tk_core.seq, seq));
-
-	delta = clocksource_delta(now, last, mask);
-
-	/*
-	 * Try to catch underflows by checking if we are seeing small
-	 * mask-relative negative values.
-	 */
-	if (unlikely((~delta & mask) < (mask >> 3)))
-		tk->underflow_seen = 1;
-
-	/* Check for multiplication overflows */
-	if (unlikely(delta > max))
-		tk->overflow_seen = 1;
-
-	/* timekeeping_cycles_to_ns() handles both under and overflow */
-	return timekeeping_cycles_to_ns(tkr, now);
-}
 #else
-static inline void timekeeping_check_update(struct timekeeper *tk, u64 offset)
-{
-}
-static inline u64 timekeeping_debug_get_ns(const struct tk_read_base *tkr)
-{
-	BUG();
-}
+static inline void timekeeping_check_update(struct timekeeper *tk, u64 offset) { }
 #endif
 
 /**
@@ -421,19 +352,11 @@ static inline u64 timekeeping_cycles_to_
 	return ((delta * tkr->mult) + tkr->xtime_nsec) >> tkr->shift;
 }
 
-static __always_inline u64 __timekeeping_get_ns(const struct tk_read_base *tkr)
+static __always_inline u64 timekeeping_get_ns(const struct tk_read_base *tkr)
 {
 	return timekeeping_cycles_to_ns(tkr, tk_clock_read(tkr));
 }
 
-static inline u64 timekeeping_get_ns(const struct tk_read_base *tkr)
-{
-	if (IS_ENABLED(CONFIG_DEBUG_TIMEKEEPING))
-		return timekeeping_debug_get_ns(tkr);
-
-	return __timekeeping_get_ns(tkr);
-}
-
 /**
  * update_fast_timekeeper - Update the fast and NMI safe monotonic timekeeper.
  * @tkr: Timekeeping readout base from which we take the update
@@ -477,7 +400,7 @@ static __always_inline u64 __ktime_get_f
 		seq = raw_read_seqcount_latch(&tkf->seq);
 		tkr = tkf->base + (seq & 0x01);
 		now = ktime_to_ns(tkr->base);
-		now += __timekeeping_get_ns(tkr);
+		now += timekeeping_get_ns(tkr);
 	} while (raw_read_seqcount_latch_retry(&tkf->seq, seq));
 
 	return now;
@@ -593,7 +516,7 @@ static __always_inline u64 __ktime_get_r
 		tkr = tkf->base + (seq & 0x01);
 		basem = ktime_to_ns(tkr->base);
 		baser = ktime_to_ns(tkr->base_real);
-		delta = __timekeeping_get_ns(tkr);
+		delta = timekeeping_get_ns(tkr);
 	} while (raw_read_seqcount_latch_retry(&tkf->seq, seq));
 
 	if (mono)

Re: [tip:timers/core] [timekeeping] 5aa6c43eca: BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow

[Marco Elver]

On Wed, 30 Oct 2024 at 09:50, Thomas Gleixner <tglx@linutronix.de> wrote:
>
> On Wed, Oct 30 2024 at 13:47, kernel test robot wrote:
> > this is another report about BUG:KCSAN, the change does not introduce new KCSAN
> > issue, but causes stats changes as below.
> >
> > [   70.265411][    C1] BUG: KCSAN: data-race in timekeeping_debug_get_ns / timekeeping_update_from_shadow
> > [   70.265430][    C1]
> > [   70.265433][    C1] write to 0xffffffff8483fef8 of 296 bytes by interrupt on cpu 0:
> > [ 70.265440][ C1] timekeeping_update_from_shadow+0x8e/0x140
> > [ 70.265452][ C1] timekeeping_advance (kernel/time/timekeeping.c:2394)
> > [ 70.265462][ C1] update_wall_time (kernel/time/timekeeping.c:2403)
>
> timekeeping_update_from_shadow() holds the sequence count write.
>
> > [ 70.265642][ C1] timekeeping_debug_get_ns (kernel/time/timekeeping.c:415 kernel/time/timekeeping.c:399 kernel/time/timekeeping.c:307)
> > [ 70.265653][ C1] ktime_get (kernel/time/timekeeping.c:431 (discriminator 4) kernel/time/timekeeping.c:897 (discriminator 4))
> > [ 70.265660][ C1] tick_nohz_lowres_handler (kernel/time/tick-sched.c:220 kernel/time/tick-sched.c:290 kernel/time/tick-sched.c:1486)
>
> ktime_get()
>
>         do {
>            seq = read_seqcount_begin(&tk_core.seq);
>            timekeeping_debug_get_ns();
>         } while (read_seqcount_retry(&tk_core.seq, seq));
>
> So this should be safe against concurreny. I assume the issue here is
> that timekeeping_debug_get_ns() has a nested
>
>         do {
>            seq = read_seqcount_begin(&tk_core.seq);
>            ....
>         } while (read_seqcount_retry(&tk_core.seq, seq));
>
> inside. Which is still correct, but confuses KCSAN. Marco?

Right... Nested seqlocks have always been tricky for KCSAN, because
any racing access (vs. writer) after the inner read_seqcount_retry()
(after the loop) may end up being reported as a data race. The inner
read_seqcount_retry() will tell KCSAN "kcsan_atomic_next(0)", ending
the critical section, but at this point it's also forgotten the outer
one. The main problem with seqlocks has always been that there's no
requirement to cleanly denote a critical section with one
read_seqcount_begin() and a matching read_seqcount_retry(). Which is
why we opted for the kcsan_atomic_next(..) approach for seqlocks, so
that it can recover if the begin/retry calls are imbalanced. If the
seqlock interface were to change to require balanced
read_seqcount_begin/retry, then we could use
kcsan_nestable_atomic_begin/end().

I think for the few seqlock anomalies which KCSAN cannot deal with
today, it would be fair to mark such functions as __no_kcsan (or
surround with kcsan_disable_current()/kcsan_enable_current() to
include callees).

I'm also trying to figure out the seqcount_latch thing right now,
which is causing similar headaches:
https://lore.kernel.org/all/20241029083658.1096492-1-elver@google.com/T/#u

Re: [tip:timers/core] [timekeeping] 5aa6c43eca: BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow

[John Stultz]

On Wed, Oct 30, 2024 at 1:50 AM Thomas Gleixner <tglx@linutronix.de> wrote:
>
> On Wed, Oct 30 2024 at 13:47, kernel test robot wrote:
> > this is another report about BUG:KCSAN, the change does not introduce new KCSAN
> > issue, but causes stats changes as below.
> >
> > [   70.265411][    C1] BUG: KCSAN: data-race in timekeeping_debug_get_ns / timekeeping_update_from_shadow
> > [   70.265430][    C1]
> > [   70.265433][    C1] write to 0xffffffff8483fef8 of 296 bytes by interrupt on cpu 0:
> > [ 70.265440][ C1] timekeeping_update_from_shadow+0x8e/0x140
> > [ 70.265452][ C1] timekeeping_advance (kernel/time/timekeeping.c:2394)
> > [ 70.265462][ C1] update_wall_time (kernel/time/timekeeping.c:2403)
>
> timekeeping_update_from_shadow() holds the sequence count write.
>
> > [ 70.265642][ C1] timekeeping_debug_get_ns (kernel/time/timekeeping.c:415 kernel/time/timekeeping.c:399 kernel/time/timekeeping.c:307)
> > [ 70.265653][ C1] ktime_get (kernel/time/timekeeping.c:431 (discriminator 4) kernel/time/timekeeping.c:897 (discriminator 4))
> > [ 70.265660][ C1] tick_nohz_lowres_handler (kernel/time/tick-sched.c:220 kernel/time/tick-sched.c:290 kernel/time/tick-sched.c:1486)
>
> ktime_get()
>
>         do {
>            seq = read_seqcount_begin(&tk_core.seq);
>            timekeeping_debug_get_ns();
>         } while (read_seqcount_retry(&tk_core.seq, seq));
>
> So this should be safe against concurreny. I assume the issue here is
> that timekeeping_debug_get_ns() has a nested
>
>         do {
>            seq = read_seqcount_begin(&tk_core.seq);
>            ....
>         } while (read_seqcount_retry(&tk_core.seq, seq));
>
> inside. Which is still correct, but confuses KCSAN. Marco?
>
> But that aside, since 135225a363ae timekeeping_cycles_to_ns() is fully
> overflow protected and unconditionally handles negative motion (before
> it was x86 only), the value of timekeeping_debug_get_ns() becomes
> questionable.
>
> I'm leaning towards removing it completely.
>
> John?

Yeah. I could be wrong, but I'm not sure of anyone beyond myself that
has really utilized the TIMEKEEPING_DEBUG logic (and I've not enabled
it myself in a few years). I don't think we've had any problem reports
from it either.

So no objection from me.

thanks
-john

Re: [tip:timers/core] [timekeeping] 5aa6c43eca: BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow

[Thomas Gleixner]

On Wed, Oct 30 2024 at 15:16, John Stultz wrote:
> On Wed, Oct 30, 2024 at 1:50 AM Thomas Gleixner <tglx@linutronix.de> wrote:
>> But that aside, since 135225a363ae timekeeping_cycles_to_ns() is fully
>> overflow protected and unconditionally handles negative motion (before
>> it was x86 only), the value of timekeeping_debug_get_ns() becomes
>> questionable.
>>
>> I'm leaning towards removing it completely.
>>
>> John?
>
> Yeah. I could be wrong, but I'm not sure of anyone beyond myself that
> has really utilized the TIMEKEEPING_DEBUG logic (and I've not enabled
> it myself in a few years). I don't think we've had any problem reports
> from it either.
>
> So no objection from me.

The question is whether we want to preserve the remaining 'offset'
check.  I.e. either discard it or make it unconditional? It's cheep now.

Thanks,

        tglx

Re: [tip:timers/core] [timekeeping] 5aa6c43eca: BUG:KCSAN:data-race_in_timekeeping_debug_get_ns/timekeeping_update_from_shadow

[Thomas Gleixner]

On Thu, Oct 31 2024 at 00:35, Thomas Gleixner wrote:

> On Wed, Oct 30 2024 at 15:16, John Stultz wrote:
>> On Wed, Oct 30, 2024 at 1:50 AM Thomas Gleixner <tglx@linutronix.de> wrote:
>>> But that aside, since 135225a363ae timekeeping_cycles_to_ns() is fully
>>> overflow protected and unconditionally handles negative motion (before
>>> it was x86 only), the value of timekeeping_debug_get_ns() becomes
>>> questionable.
>>>
>>> I'm leaning towards removing it completely.
>>>
>>> John?
>>
>> Yeah. I could be wrong, but I'm not sure of anyone beyond myself that
>> has really utilized the TIMEKEEPING_DEBUG logic (and I've not enabled
>> it myself in a few years). I don't think we've had any problem reports
>> from it either.
>>
>> So no objection from me.
>
> The question is whether we want to preserve the remaining 'offset'
> check.  I.e. either discard it or make it unconditional? It's cheep now.

Nah. It's irrelevant now too. Before the time getters gained the math
overflow handling this definitely was a problem, but now it's just
noise. timekeeping_advance() can handle that case correctly.

Thanks,

        tglx