[linus:master] [timekeeping] fcf190c369: BUG:KCSAN:data-race_in_timekeeping_advance/timekeeping_debug_get_ns

From: kernel test robot
Date: Fri May 31 2024 - 10:41:40 EST

Next message: Shuah Khan: "Re: [PATCH 1/2] selftests/tracing: Fix event filter test to retry up to 10 times"
Previous message: Mukesh Ojha: "Re: [PATCH v2 2/2] arm64: dts: qcom: sa8775p: Add IMEM and PIL info region"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello,

kernel test robot noticed "BUG:KCSAN:data-race_in_timekeeping_advance/timekeeping_debug_get_ns" on:

commit: fcf190c369149c3b04539797cedf28741eb14164 ("timekeeping: Make delta calculation overflow safe")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

[test failed on linus/master 4a4be1ad3a6efea16c56615f31117590fd881358]
[test failed on linux-next/master 9d99040b1bc8dbf385a8aa535e9efcdf94466e19]

in testcase: boot

compiler: gcc-13
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

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

since we don't have enough knowledge to investigate KCSAN issues deeply, we
just run more times to make sure the issue is persistent on the commit and
clean on parent. for this one, below just FYI.

e809a80aa0bcf802 fcf190c369149c3b04539797ced
---------------- ---------------------------
fail:runs %reproduction fail:runs
| | |
17:50 -34% :50 dmesg.BUG:KCSAN:data-race_in_ktime_get/timekeeping_advance
14:50 -28% :50 dmesg.BUG:KCSAN:data-race_in_ktime_get_update_offsets_now/timekeeping_advance
13:50 10% 18:50 dmesg.BUG:KCSAN:data-race_in_rb_get_reader_page/rb_move_tail
50:50 0% 50:50 dmesg.BUG:KCSAN:data-race_in_rb_get_reader_page/ring_buffer_unlock_commit
:50 6% 3:50 dmesg.BUG:KCSAN:data-race_in_rb_move_tail/ring_buffer_read_page
:50 60% 30:50 dmesg.BUG:KCSAN:data-race_in_timekeeping_advance/timekeeping_debug_get_ns

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@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202405312203.a36824e7-lkp@xxxxxxxxx

[ 7.317452][ C1] BUG: KCSAN: data-race in timekeeping_advance / timekeeping_debug_get_ns
[ 7.319202][ C1]
[ 7.319379][ C1] write to 0xffffffffaaa638b8 of 296 bytes by interrupt on cpu 0:
[ 7.320781][ C1] timekeeping_advance (kernel/time/timekeeping.c:2224 (discriminator 1))
[ 7.320781][ C1] update_wall_time (kernel/time/timekeeping.c:2239 (discriminator 1))
[ 7.320781][ C1] tick_periodic (kernel/time/tick-common.c:97)
[ 7.320781][ C1] tick_handle_periodic (include/linux/clockchips.h:152 kernel/time/tick-common.c:122)
[ 7.324712][ C1] __sysvec_apic_timer_interrupt (arch/x86/include/asm/jump_label.h:27 include/linux/jump_label.h:207 arch/x86/include/asm/trace/irq_vectors.h:41 arch/x86/kernel/apic/apic.c:1050)
[ 7.324712][ C1] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1043 (discriminator 47) arch/x86/kernel/apic/apic.c:1043 (discriminator 47))
[ 7.324712][ C1] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:702)
[ 7.328793][ C1] _raw_spin_unlock_irqrestore (arch/x86/include/asm/paravirt.h:699 arch/x86/include/asm/irqflags.h:135 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
[ 7.328793][ C1] prepare_to_swait_event (kernel/sched/swait.c:122)
[ 7.328793][ C1] rcu_gp_fqs_loop (kernel/rcu/tree.c:1577 kernel/rcu/tree.c:1663)
[ 7.328793][ C1] rcu_gp_kthread (kernel/rcu/tree.c:1865 (discriminator 2))
[ 7.332714][ C1] kthread (kernel/kthread.c:388)
[ 7.332714][ C1] ret_from_fork (arch/x86/kernel/process.c:153)
[ 7.332714][ C1] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 7.332714][ C1]
[ 7.336781][ C1] read to 0xffffffffaaa638d8 of 8 bytes by interrupt on cpu 1:
[ 7.336781][ C1] timekeeping_debug_get_ns (kernel/time/timekeeping.c:389 (discriminator 1) kernel/time/timekeeping.c:372 (discriminator 1) kernel/time/timekeeping.c:280 (discriminator 1))
[ 7.340722][ C1] ktime_get (kernel/time/timekeeping.c:406 kernel/time/timekeeping.c:855)
[ 7.340722][ C1] sched_clock_tick (kernel/sched/clock.c:98 (discriminator 1) kernel/sched/clock.c:424 (discriminator 1) kernel/sched/clock.c:412 (discriminator 1))
[ 7.340722][ C1] scheduler_tick (kernel/sched/sched.h:1385 kernel/sched/sched.h:1699 kernel/sched/core.c:5679)
[ 7.344805][ C1] update_process_times (kernel/time/timer.c:2493)
[ 7.344805][ C1] tick_periodic (kernel/time/tick-common.c:101)
[ 7.344805][ C1] tick_handle_periodic (kernel/time/tick-common.c:129)
[ 7.344805][ C1] __sysvec_apic_timer_interrupt (arch/x86/include/asm/jump_label.h:27 include/linux/jump_label.h:207 arch/x86/include/asm/trace/irq_vectors.h:41 arch/x86/kernel/apic/apic.c:1050)
[ 7.348718][ C1] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1043 (discriminator 2) arch/x86/kernel/apic/apic.c:1043 (discriminator 2))
[ 7.348718][ C1] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:702)
[ 7.348718][ C1] _raw_spin_unlock_irqrestore (arch/x86/include/asm/paravirt.h:699 arch/x86/include/asm/irqflags.h:135 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
[ 7.352782][ C1] swake_up_one_online (kernel/rcu/tree.c:1046)
[ 7.352782][ C1] rcu_gp_kthread_wake (kernel/rcu/tree.c:1073)
[ 7.352782][ C1] rcu_report_qs_rsp (kernel/rcu/tree.c:1889)
[ 7.352782][ C1] rcu_report_qs_rnp (kernel/rcu/tree.c:1960)
[ 7.356725][ C1] rcu_report_qs_rdp (kernel/rcu/tree.c:2062)
[ 7.356725][ C1] rcu_core (kernel/rcu/rcu.h:138 (discriminator 2) kernel/rcu/tree.c:227 (discriminator 2) kernel/rcu/tree.c:2458 (discriminator 2))
[ 7.356725][ C1] rcu_core_si (kernel/rcu/tree.c:2489)
[ 7.356725][ C1] __do_softirq (arch/x86/include/asm/jump_label.h:27 include/linux/jump_label.h:207 include/trace/events/irq.h:142 kernel/softirq.c:555)
[ 7.360772][ C1] irq_exit_rcu (kernel/softirq.c:647 (discriminator 38))
[ 7.360772][ C1] sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1043 (discriminator 47) arch/x86/kernel/apic/apic.c:1043 (discriminator 47))
[ 7.360772][ C1] asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:702)
[ 7.364706][ C1] _raw_spin_unlock_irqrestore (arch/x86/include/asm/paravirt.h:699 arch/x86/include/asm/irqflags.h:135 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
[ 7.364706][ C1] __delete_object (mm/kmemleak.c:798)
[ 7.364706][ C1] kmem_cache_free (include/linux/kmemleak.h:48 mm/slub.c:2072 mm/slub.c:4280 mm/slub.c:4344)
[ 7.364706][ C1] putname (fs/namei.c:274)
[ 7.368775][ C1] kern_path (fs/namei.c:2627)
[ 7.368775][ C1] init_stat (fs/init.c:133)
[ 7.368775][ C1] clean_path (init/initramfs.c:334 (discriminator 1))
[ 7.368775][ C1] do_name (init/initramfs.c:367)
[ 7.368775][ C1] flush_buffer (init/initramfs.c:452 (discriminator 1) init/initramfs.c:464 (discriminator 1))
[ 7.372705][ C1] __gunzip+0x36d/0x4d0
[ 7.372705][ C1] gunzip (lib/decompress_inflate.c:207 (discriminator 1))
[ 7.372705][ C1] unpack_to_rootfs (init/initramfs.c:522)
[ 7.372705][ C1] do_populate_rootfs (init/initramfs.c:714)
[ 7.376757][ C1] async_run_entry_fn (kernel/async.c:136 (discriminator 1))
[ 7.376757][ C1] process_one_work (kernel/workqueue.c:3259)
[ 7.376757][ C1] worker_thread (kernel/workqueue.c:3329 (discriminator 2) kernel/workqueue.c:3416 (discriminator 2))
[ 7.376757][ C1] kthread (kernel/kthread.c:388)
[ 7.380720][ C1] ret_from_fork (arch/x86/kernel/process.c:153)
[ 7.380720][ C1] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 7.380720][ C1]
[ 7.380720][ C1] value changed: 0x000a914d14000000 -> 0x000ace5614000000
[ 7.384767][ C1]
[ 7.384767][ C1] Reported by Kernel Concurrency Sanitizer on:
[ 7.384767][ C1] CPU: 1 PID: 30 Comm: kworker/u9:1 Not tainted 6.9.0-rc3-00018-gfcf190c36914 #2
[ 7.388715][ C1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 7.388715][ C1] Workqueue: async async_run_entry_fn
[ 7.388715][ C1] ==================================================================
[ 46.680358][ T30] Freeing initrd memory: 107964K
[ 46.682005][ T1] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[ 46.683699][ T1] software IO TLB: mapped [mem 0x00000000b5671000-0x00000000b9671000] (64MB)
[ 46.705499][ T1] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x1fa3704c1a9, max_idle_ns: 440795296692 ns
[ 46.711289][ T1] AVX2 or AES-NI instructions are not detected.
[ 46.750407][ T1] Initialise system trusted keyrings
[ 46.752155][ T1] Key type blacklist registered
[ 46.754665][ T1] workingset: timestamp_bits=62 max_order=22 bucket_order=0
[ 46.772327][ T1] debugfs: Directory 'file_lock_cache' with parent 'slab' already present!
[ 46.818173][ T1] ntfs3: Max link count 4000
[ 46.819226][ T1] ntfs3: Warning: Activated 64 bits per cluster. Windows does not support this
[ 46.821239][ T1] ntfs3: Read-only LZX/Xpress compression included
[ 46.827627][ T1] efs: 1.0a - http://aeschi.ch.eu.org/efs/
[ 46.830338][ T1] JFS: nTxBlock = 8192, nTxLock = 65536
[ 46.848621][ T1] NILFS version 2 loaded
[ 46.849689][ T1] befs: version: 0.9.3
[ 46.855836][ T1] gfs2: GFS2 installed
[ 46.860723][ T1] Key type asymmetric registered
[ 46.861970][ T1] Asymmetric key parser 'x509' registered
[ 46.864644][ T1] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[ 46.867540][ T1] io scheduler mq-deadline registered
[ 46.868771][ T1] io scheduler kyber registered
[ 46.870314][ T1] io scheduler bfq registered
[ 47.359071][ T49] ==================================================================
[ 47.360665][ T49] BUG: KCSAN: data-race in rb_get_reader_page / ring_buffer_unlock_commit
[ 47.360665][ T49]
[ 47.360665][ T49] write to 0xffff8881093584a8 of 8 bytes by task 48 on cpu 0:
[ 47.360665][ T49] rb_get_reader_page (kernel/trace/ring_buffer.c:4598)
[ 47.360665][ T49] rb_buffer_peek (kernel/trace/ring_buffer.c:4729)
[ 47.360665][ T49] ring_buffer_consume (kernel/trace/ring_buffer.c:5013)
[ 47.360665][ T49] ring_buffer_consumer (kernel/trace/ring_buffer_benchmark.c:91 kernel/trace/ring_buffer_benchmark.c:205)
[ 47.360665][ T49] ring_buffer_consumer_thread (kernel/trace/ring_buffer_benchmark.c:390 (discriminator 3))
[ 47.360665][ T49] kthread (kernel/kthread.c:388)
[ 47.360665][ T49] ret_from_fork (arch/x86/kernel/process.c:153)
[ 47.360665][ T49] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 47.372689][ T49]
[ 47.372689][ T49] read to 0xffff8881093584a8 of 8 bytes by task 49 on cpu 1:
[ 47.372689][ T49] ring_buffer_unlock_commit (kernel/trace/ring_buffer.c:3067 kernel/trace/ring_buffer.c:3253)
[ 47.372689][ T49] ring_buffer_producer (kernel/trace/ring_buffer_benchmark.c:255 (discriminator 1))
[ 47.372689][ T49] ring_buffer_producer_thread (kernel/trace/ring_buffer_benchmark.c:82 kernel/trace/ring_buffer_benchmark.c:414)
[ 47.372689][ T49] kthread (kernel/kthread.c:388)
[ 47.372689][ T49] ret_from_fork (arch/x86/kernel/process.c:153)
[ 47.372689][ T49] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 47.372689][ T49]
[ 47.372689][ T49] value changed: 0xffff888141aa3c40 -> 0xffff888141aa3b40
[ 47.372689][ T49]
[ 47.372689][ T49] Reported by Kernel Concurrency Sanitizer on:
[ 47.372689][ T49] CPU: 1 PID: 49 Comm: rb_producer Not tainted 6.9.0-rc3-00018-gfcf190c36914 #2
[ 47.372689][ T49] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 47.372689][ T49] ==================================================================
[ 51.025622][ T49] ==================================================================
[ 51.027409][ T49] BUG: KCSAN: data-race in rb_get_reader_page / ring_buffer_unlock_commit
[ 51.028657][ T49]
[ 51.028657][ T49] write to 0xffff8881093584a8 of 8 bytes by task 48 on cpu 0:
[ 51.028657][ T49] rb_get_reader_page (kernel/trace/ring_buffer.c:4598)
[ 51.028657][ T49] rb_buffer_peek (kernel/trace/ring_buffer.c:4729)
[ 51.028657][ T49] ring_buffer_consume (kernel/trace/ring_buffer.c:5013)
[ 51.028657][ T49] ring_buffer_consumer (kernel/trace/ring_buffer_benchmark.c:91 kernel/trace/ring_buffer_benchmark.c:205)
[ 51.028657][ T49] ring_buffer_consumer_thread (kernel/trace/ring_buffer_benchmark.c:390 (discriminator 3))
[ 51.028657][ T49] kthread (kernel/kthread.c:388)
[ 51.028657][ T49] ret_from_fork (arch/x86/kernel/process.c:153)
[ 51.028657][ T49] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 51.028657][ T49]
[ 51.028657][ T49] read to 0xffff8881093584a8 of 8 bytes by task 49 on cpu 1:
[ 51.028657][ T49] ring_buffer_unlock_commit (kernel/trace/ring_buffer.c:3067 kernel/trace/ring_buffer.c:3253)
[ 51.028657][ T49] ring_buffer_producer (kernel/trace/ring_buffer_benchmark.c:255 (discriminator 1))
[ 51.028657][ T49] ring_buffer_producer_thread (kernel/trace/ring_buffer_benchmark.c:82 kernel/trace/ring_buffer_benchmark.c:414)
[ 51.028657][ T49] kthread (kernel/kthread.c:388)
[ 51.028657][ T49] ret_from_fork (arch/x86/kernel/process.c:153)
[ 51.028657][ T49] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 51.028657][ T49]
[ 51.028657][ T49] value changed: 0xffff888141aa3b40 -> 0xffff888141aa3d40
[ 51.028657][ T49]
[ 51.028657][ T49] Reported by Kernel Concurrency Sanitizer on:
[ 51.028657][ T49] CPU: 1 PID: 49 Comm: rb_producer Not tainted 6.9.0-rc3-00018-gfcf190c36914 #2
[ 51.028657][ T49] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 51.028657][ T49] ==================================================================
[ 54.411601][ T49] ==================================================================
[ 54.412673][ T49] BUG: KCSAN: data-race in rb_get_reader_page / ring_buffer_unlock_commit
[ 54.412673][ T49]
[ 54.412673][ T49] write to 0xffff8881093584a8 of 8 bytes by task 48 on cpu 0:
[ 54.412673][ T49] rb_get_reader_page (kernel/trace/ring_buffer.c:4598)
[ 54.412673][ T49] rb_buffer_peek (kernel/trace/ring_buffer.c:4729)
[ 54.412673][ T49] ring_buffer_consume (kernel/trace/ring_buffer.c:5013)
[ 54.412673][ T49] ring_buffer_consumer (kernel/trace/ring_buffer_benchmark.c:91 kernel/trace/ring_buffer_benchmark.c:205)
[ 54.412673][ T49] ring_buffer_consumer_thread (kernel/trace/ring_buffer_benchmark.c:390 (discriminator 3))
[ 54.412673][ T49] kthread (kernel/kthread.c:388)
[ 54.412673][ T49] ret_from_fork (arch/x86/kernel/process.c:153)
[ 54.412673][ T49] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 54.412673][ T49]
[ 54.412673][ T49] read to 0xffff8881093584a8 of 8 bytes by task 49 on cpu 1:
[ 54.412673][ T49] ring_buffer_unlock_commit (kernel/trace/ring_buffer.c:3067 kernel/trace/ring_buffer.c:3253)
[ 54.412673][ T49] ring_buffer_producer (kernel/trace/ring_buffer_benchmark.c:255 (discriminator 1))
[ 54.412673][ T49] ring_buffer_producer_thread (kernel/trace/ring_buffer_benchmark.c:82 kernel/trace/ring_buffer_benchmark.c:414)
[ 54.412673][ T49] kthread (kernel/kthread.c:388)
[ 54.412673][ T49] ret_from_fork (arch/x86/kernel/process.c:153)
[ 54.412673][ T49] ret_from_fork_asm (arch/x86/entry/entry_64.S:256)
[ 54.412673][ T49]
[ 54.412673][ T49] value changed: 0xffff888141a4ed40 -> 0xffff888141a5f340
[ 54.412673][ T49]
[ 54.412673][ T49] Reported by Kernel Concurrency Sanitizer on:
[ 54.412673][ T49] CPU: 1 PID: 49 Comm: rb_producer Not tainted 6.9.0-rc3-00018-gfcf190c36914 #2
[ 54.412673][ T49] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 54.412673][ T49] ==================================================================

The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240531/202405312203.a36824e7-lkp@xxxxxxxxx

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

Next message: Shuah Khan: "Re: [PATCH 1/2] selftests/tracing: Fix event filter test to retry up to 10 times"
Previous message: Mukesh Ojha: "Re: [PATCH v2 2/2] arm64: dts: qcom: sa8775p: Add IMEM and PIL info region"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]