On Wed, May 14, 2025 at 10:47:30AM +0800, kernel test robot wrote:
>
> hi, Paul,
>
> for this commit we tested before, now we found it causes issues in linux-next
> master branch.
Good catch as always!!! Yes, using HRTIMER_MODE_HARD means that this
ircutorture_one_extend_check() function must check for hardirq as well
as softirq. Which, oddly enough, permits simplifying the code, though
a larger patch.
I could reproduce this, and the patch at the end of this email fixes it
for me. Does it work for you as well?
Thanx, Paul
> =========================================================================================
> tbox_group/testcase/rootfs/kconfig/compiler/runtime/test/torture_type:
>
> vm-snb/rcutorture/debian-11.1-i386-20220923.cgz/i386-randconfig-141-20250508/clang-20/300s/cpuhotplug/srcud
>
> c795676b5c0a4ab7 c27d0d38f2cafb70a68ca42c410
> ---------------- ---------------------------
> fail:runs %reproduction fail:runs
> | | |
> :50 2% 1:50 dmesg.EIP:__kernel_text_address
> :50 4% 2:50
> dmesg.EIP:__srcu_check_read_flavor
> :50 2% 1:50 dmesg.EIP:_raw_spin_unlock_irq
> :50 14% 7:50
> dmesg.EIP:_raw_spin_unlock_irqrestore
> :50 30% 15:50 dmesg.EIP:console_flush_all
> :50 4% 2:50
> dmesg.EIP:console_trylock_spinning
> :50 2% 1:50 dmesg.EIP:delay_tsc
> :50 2% 1:50 dmesg.EIP:finish_lock_switch
> :50 2% 1:50 dmesg.EIP:kernel_text_address
> :50 2% 1:50 dmesg.EIP:lock_acquire
> :50 36% 18:50 dmesg.EIP:pv_native_safe_halt
> 1:50 -2% :50
> dmesg.EIP:rcu_torture_fwd_prog_cr
> 7:50 -14% :50 dmesg.EIP:rcu_torture_writer
> :50 100% 50:50
> dmesg.EIP:rcutorture_one_extend_check
> 48:50 0% 48:50
> dmesg.INFO:task_blocked_for_more_than#seconds
> 48:50 0% 48:50
> dmesg.Kernel_panic-not_syncing:hung_task:blocked_tasks
> 50:50 0% 50:50
> dmesg.UBSAN:negation-overflow_in_lib/sort.c
> 1:50 -2% :50
> dmesg.WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_fwd_prog_cr[rcutorture]
> 7:50 -14% :50
> dmesg.WARNING:at_kernel/rcu/rcutorture.c:#rcu_torture_writer[rcutorture]
> :50 100% 50:50
> dmesg.WARNING:at_kernel/rcu/rcutorture.c:#rcutorture_one_extend_check[rcutorture]
> <--- (1)
> 7:50 -14% :50 dmesg.calltrace:__do_softirq
> 1:50 -2% :50
> dmesg.calltrace:rcu_torture_pipe_update
>
> though both c27d0d38f2/parent have various issues, it seems (1) is persistent
> on c27d0d38f2 and clean on parent.
>
>
> Hello,
>
> kernel test robot noticed
> "WARNING:at_kernel/rcu/rcutorture.c:#rcutorture_one_extend_check[rcutorture]"
> on:
>
> commit: c27d0d38f2cafb70a68ca42c4105e170862aaf77 ("rcutorture: Complain if an
> ->up_read() is delayed more than 10 seconds")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
>
> [test failed on linux-next/master f48887a98b78880b7711aca311fbbbcaad6c4e3b]
>
> in testcase: rcutorture
> version:
> with following parameters:
>
> runtime: 300s
> test: cpuhotplug
> torture_type: srcud
>
>
>
> config: i386-randconfig-141-20250508
> compiler: clang-20
> 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 <[email protected]>
> | Closes: https://lore.kernel.org/oe-lkp/[email protected]
>
>
> The kernel config and materials to reproduce are available at:
> https://download.01.org/0day-ci/archive/20250514/[email protected]
>
>
> [ 76.027193][ C1] ------------[ cut here ]------------
> [ 76.027652][ T661] srcud-torture: rcu_torture_stats task started
> [ 76.027754][ C1] rcutorture_one_extend_check before change: Current
> 0x80 To add 0x0 To remove 0x80 preempt_count() 0x10001
> [ 76.029893][ C1] WARNING: CPU: 1 PID: 2 at kernel/rcu/rcutorture.c:1976
> rcutorture_one_extend_check+0x5b/0x300 [rcutorture]
> [ 76.031093][ C1] Modules linked in: rcutorture(+) torture
> [ 76.031736][ C1] CPU: 1 UID: 0 PID: 2 Comm: kthreadd Tainted: G
> T 6.15.0-rc1-00008-gc27d0d38f2ca #1 PREEMPT(full)
> 4c3e2c742772c0895467dcaa42b0aab115cc2926
> [ 76.033194][ C1] Tainted: [T]=RANDSTRUCT
> [ 76.033728][ C1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
> BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> [ 76.034602][ C1] EIP: rcutorture_one_extend_check+0x5b/0x300
> [rcutorture]
> [ 76.035319][ C1] Code: 05 68 e2 69 f0 01 64 a1 0c f0 b4 c3 25 ff ff ff
> 7f 50 ff 75 0c 57 53 56 68 e3 c9 6a f0 68 19 b5 6a f0 e8 b8 c8 96 d0 83 c4 1c
> <0f> 0b f6 c3 09 75 1d eb 35 9c 8f 45 ec f7 45 ec 00 02 00 00 74 09
> [ 76.037024][ C1] EAX: 0000006c EBX: 00000080 ECX: 00000027 EDX: 00000000
> [ 76.037760][ C1] ESI: f06ad951 EDI: 00000000 EBP: c7f19da0 ESP: c7f19d8c
> [ 76.038490][ C1] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS:
> 00010082
> [ 76.039252][ C1] CR0: 80050033 CR2: b7e17eb0 CR3: 08be7000 CR4: 00040690
> [ 76.039989][ C1] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 76.040713][ C1] DR6: fffe0ff0 DR7: 00000400
> [ 76.041313][ C1] Call Trace:
> [ 76.041825][ C1] rcutorture_one_extend+0x54/0x4b0 [rcutorture
> 4a4a34e515cdd0c53b2c18de8a71945278e82895]
> [ 76.042705][ C1] ? lock_acquire+0xa8/0x1c0
> [ 76.043299][ C1] rcu_torture_one_read_end+0x1b7/0x350 [rcutorture
> 4a4a34e515cdd0c53b2c18de8a71945278e82895]
> [ 76.044196][ C1] ? local_bh_enable+0x20/0x20 [rcutorture
> 4a4a34e515cdd0c53b2c18de8a71945278e82895]
> [ 76.045049][ C1] rcu_torture_updown_hrt+0x18/0x30 [rcutorture
> 4a4a34e515cdd0c53b2c18de8a71945278e82895]
> [ 76.045935][ C1] __hrtimer_run_queues+0x18a/0x3b0
> [ 76.046555][ C1] ? ktime_get_update_offsets_now+0x52/0x200
> [ 76.047309][ C1] hrtimer_run_queues+0xf7/0x130
> [ 76.048063][ C1] update_process_times+0x25/0xb0
> [ 76.048680][ C1] tick_periodic+0xc4/0xe0
> [ 76.049272][ C1] tick_handle_periodic+0x23/0x70
> [ 76.049875][ C1] __sysvec_apic_timer_interrupt+0x73/0x190
> [ 76.050528][ C1] ? sysvec_call_function_single+0x30/0x30
> [ 76.051175][ C1] sysvec_apic_timer_interrupt+0x1a/0x34
> [ 76.051812][ C1] handle_exception+0x150/0x150
> [ 76.052405][ C1] EIP: lock_acquire+0xda/0x1c0
> [ 76.052998][ C1] Code: 64 0f c1 05 8c 0e b5 c3 83 f8 01 0f 85 a5 00 00
> 00 9c 8f 45 d4 f7 45 d4 00 02 00 00 0f 85 a6 00 00 00 85 f6 74 01 fb 83 c4 20
> <5e> 5f 5b 5d 2e e9 30 3d 3c 01 89 ce 89 55 f0 8b 55 f0 ff 75 14 ff
> [ 76.054753][ C1] EAX: 00000001 EBX: c345d894 ECX: b4a771ac EDX: 00000000
> [ 76.055499][ C1] ESI: 00000001 EDI: 00000000 EBP: c7f19f50 ESP: c7f19f44
> [ 76.056248][ C1] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS:
> 00000286
> [ 76.057032][ C1] ? try_to_wake_up+0x248/0x850
> [ 76.057690][ C1] ? sysvec_call_function_single+0x30/0x30
> [ 76.058377][ C1] ? try_to_wake_up+0x248/0x850
> [ 76.059009][ C1] ? sysvec_call_function_single+0x30/0x30
> [ 76.059693][ C1] ? lock_acquire+0xda/0x1c0
> [ 76.060312][ C1] _raw_spin_lock+0x2a/0x3c
> [ 76.060927][ C1] ? kthreadd+0xda/0x160
> [ 76.061549][ C1] kthreadd+0xda/0x160
> [ 76.062126][ C1] ? schedule_tail+0xd4/0x120
> [ 76.062729][ C1] ? kthread_stop_put+0x30/0x30
> [ 76.063335][ C1] ? kthread_stop_put+0x30/0x30
> [ 76.063933][ C1] ret_from_fork+0x35/0x40
> [ 76.064505][ C1] ret_from_fork_asm+0x12/0x1c
> [ 76.065091][ C1] entry_INT80_32+0x10d/0x10d
> [ 76.065693][ C1] irq event stamp: 4386
> [ 76.066236][ C1] hardirqs last enabled at (4385): [<c10f858d>]
> finish_lock_switch+0x9d/0xe0
> [ 76.067037][ C1] hardirqs last disabled at (4386): [<c24e7ab0>]
> sysvec_apic_timer_interrupt+0xc/0x34
> [ 76.067873][ C1] softirqs last enabled at (2260): [<c10bb5d2>]
> handle_softirqs+0x372/0x3b0
> [ 76.068659][ C1] softirqs last disabled at (2255): [<c24f627f>]
> __do_softirq+0xf/0x16
> [ 76.069635][ C1] ---[ end trace 0000000000000000 ]---
> [ 76.099825][ T636] srcud-torture: Creating torture_stutter task
> [ 76.099831][ T667] srcud-torture: torture_shuffle task started
> [ 76.101418][ T636] srcud-torture: Creating torture_onoff task
>
>
> --
> 0-DAY CI Kernel Test Service
> https://github.com/intel/lkp-tests/wiki
------------------------------------------------------------------------
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 373c65a6e1031..0840153c90d18 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -1975,14 +1975,14 @@ static void rcu_torture_reader_do_mbchk(long myid,
struct rcu_torture *rtp,
// Verify the specified RCUTORTURE_RDR* state.
#define ROEC_ARGS "%s %s: Current %#x To add %#x To remove %#x
preempt_count() %#x\n", __func__, s, curstate, new, old, preempt_count()
-static void rcutorture_one_extend_check(char *s, int curstate, int new, int
old, bool insoftirq)
+static void rcutorture_one_extend_check(char *s, int curstate, int new, int
old)
{
int mask;
- if (!IS_ENABLED(CONFIG_RCU_TORTURE_TEST_CHK_RDR_STATE))
+ if (!IS_ENABLED(CONFIG_RCU_TORTURE_TEST_CHK_RDR_STATE) || in_nmi())
return;
- WARN_ONCE(!(curstate & RCUTORTURE_RDR_IRQ) && irqs_disabled(),
ROEC_ARGS);
+ WARN_ONCE(!(curstate & RCUTORTURE_RDR_IRQ) && irqs_disabled() &&
!in_hardirq(), ROEC_ARGS);
WARN_ONCE((curstate & RCUTORTURE_RDR_IRQ) && !irqs_disabled(),
ROEC_ARGS);
// If CONFIG_PREEMPT_COUNT=n, further checks are unreliable.
@@ -1997,9 +1997,9 @@ static void rcutorture_one_extend_check(char *s, int
curstate, int new, int old,
(curstate & (RCUTORTURE_RDR_RCU_1 | RCUTORTURE_RDR_RCU_2)) &&
cur_ops->readlock_nesting() == 0, ROEC_ARGS);
- // Timer handlers have all sorts of stuff disabled, so ignore
+ // Interrupt handlers have all sorts of stuff disabled, so ignore
// unintended disabling.
- if (insoftirq)
+ if (in_serving_softirq() || in_hardirq())
return;
WARN_ONCE(cur_ops->extendables &&
@@ -2038,8 +2038,7 @@ static void rcutorture_one_extend_check(char *s, int
curstate, int new, int old,
* beginning or end of the critical section and if there was actually a
* change, do a ->read_delay().
*/
-static void rcutorture_one_extend(int *readstate, int newstate, bool insoftirq,
- struct torture_random_state *trsp,
+static void rcutorture_one_extend(int *readstate, int newstate, struct
torture_random_state *trsp,
struct rt_read_seg *rtrsp)
{
bool first;
@@ -2054,7 +2053,7 @@ static void rcutorture_one_extend(int *readstate, int
newstate, bool insoftirq,
first = idxold1 == 0;
WARN_ON_ONCE(idxold2 < 0);
WARN_ON_ONCE(idxold2 & ~(RCUTORTURE_RDR_ALLBITS |
RCUTORTURE_RDR_UPDOWN));
- rcutorture_one_extend_check("before change", idxold1, statesnew,
statesold, insoftirq);
+ rcutorture_one_extend_check("before change", idxold1, statesnew,
statesold);
rtrsp->rt_readstate = newstate;
/* First, put new protection in place to avoid critical-section gap. */
@@ -2074,8 +2073,7 @@ static void rcutorture_one_extend(int *readstate, int
newstate, bool insoftirq,
idxnew2 = (cur_ops->readlock() << RCUTORTURE_RDR_SHIFT_2) &
RCUTORTURE_RDR_MASK_2;
// Complain unless both the old and the new protection is in place.
- rcutorture_one_extend_check("during change",
- idxold1 | statesnew, statesnew, statesold,
insoftirq);
+ rcutorture_one_extend_check("during change", idxold1 | statesnew,
statesnew, statesold);
// Sample CPU under both sets of protections to reduce confusion.
if (IS_ENABLED(CONFIG_RCU_TORTURE_TEST_LOG_CPU)) {
@@ -2150,7 +2148,7 @@ static void rcutorture_one_extend(int *readstate, int
newstate, bool insoftirq,
WARN_ON_ONCE(*readstate < 0);
if (WARN_ON_ONCE(*readstate & ~RCUTORTURE_RDR_ALLBITS))
pr_info("Unexpected readstate value of %#x\n", *readstate);
- rcutorture_one_extend_check("after change", *readstate, statesnew,
statesold, insoftirq);
+ rcutorture_one_extend_check("after change", *readstate, statesnew,
statesold);
}
/* Return the biggest extendables mask given current RCU and boot parameters.
*/
@@ -2217,8 +2215,7 @@ rcutorture_extend_mask(int oldmask, struct
torture_random_state *trsp)
* critical section.
*/
static struct rt_read_seg *
-rcutorture_loop_extend(int *readstate, bool insoftirq, struct
torture_random_state *trsp,
- struct rt_read_seg *rtrsp)
+rcutorture_loop_extend(int *readstate, struct torture_random_state *trsp,
struct rt_read_seg *rtrsp)
{
int i;
int j;
@@ -2233,7 +2230,7 @@ rcutorture_loop_extend(int *readstate, bool insoftirq,
struct torture_random_sta
for (j = 0; j < i; j++) {
mask = rcutorture_extend_mask(*readstate, trsp);
WARN_ON_ONCE(mask & RCUTORTURE_RDR_UPDOWN);
- rcutorture_one_extend(readstate, mask, insoftirq, trsp,
&rtrsp[j]);
+ rcutorture_one_extend(readstate, mask, trsp, &rtrsp[j]);
}
return &rtrsp[j];
}
@@ -2279,7 +2276,7 @@ static bool rcu_torture_one_read_start(struct
rcu_torture_one_read_state *rtorsp
(rtorsp->readstate &
RCUTORTURE_RDR_UPDOWN));
if (rtorsp->p == NULL) {
/* Wait for rcu_torture_writer to get underway */
- rcutorture_one_extend(&rtorsp->readstate, 0, myid < 0, trsp,
rtorsp->rtrsp);
+ rcutorture_one_extend(&rtorsp->readstate, 0, trsp,
rtorsp->rtrsp);
return false;
}
if (rtorsp->p->rtort_mbtest == 0)
@@ -2293,7 +2290,7 @@ static bool rcu_torture_one_read_start(struct
rcu_torture_one_read_state *rtorsp
* critical sections and check for errors.
*/
static void rcu_torture_one_read_end(struct rcu_torture_one_read_state *rtorsp,
- struct torture_random_state *trsp, long
myid)
+ struct torture_random_state *trsp)
{
int i;
unsigned long completed;
@@ -2340,7 +2337,7 @@ static void rcu_torture_one_read_end(struct
rcu_torture_one_read_state *rtorsp,
}
if (cur_ops->reader_blocked)
preempted = cur_ops->reader_blocked();
- rcutorture_one_extend(&rtorsp->readstate, 0, myid < 0, trsp,
rtorsp->rtrsp);
+ rcutorture_one_extend(&rtorsp->readstate, 0, trsp, rtorsp->rtrsp);
WARN_ON_ONCE(rtorsp->readstate);
// This next splat is expected behavior if leakpointer, especially
// for CONFIG_RCU_STRICT_GRACE_PERIOD=y kernels.
@@ -2370,13 +2367,13 @@ static bool rcu_torture_one_read(struct
torture_random_state *trsp, long myid)
init_rcu_torture_one_read_state(&rtors, trsp);
newstate = rcutorture_extend_mask(rtors.readstate, trsp);
WARN_ON_ONCE(newstate & RCUTORTURE_RDR_UPDOWN);
- rcutorture_one_extend(&rtors.readstate, newstate, myid < 0, trsp,
rtors.rtrsp++);
+ rcutorture_one_extend(&rtors.readstate, newstate, trsp, rtors.rtrsp++);
if (!rcu_torture_one_read_start(&rtors, trsp, myid)) {
- rcutorture_one_extend(&rtors.readstate, 0, myid < 0, trsp,
rtors.rtrsp);
+ rcutorture_one_extend(&rtors.readstate, 0, trsp, rtors.rtrsp);
return false;
}
- rtors.rtrsp = rcutorture_loop_extend(&rtors.readstate, myid < 0, trsp,
rtors.rtrsp);
- rcu_torture_one_read_end(&rtors, trsp, myid);
+ rtors.rtrsp = rcutorture_loop_extend(&rtors.readstate, trsp,
rtors.rtrsp);
+ rcu_torture_one_read_end(&rtors, trsp);
return true;
}
@@ -2469,7 +2466,7 @@ static enum hrtimer_restart rcu_torture_updown_hrt(struct
hrtimer *hrtp)
struct rcu_torture_one_read_state_updown *rtorsup;
rtorsup = container_of(hrtp, struct rcu_torture_one_read_state_updown,
rtorsu_hrt);
- rcu_torture_one_read_end(&rtorsup->rtorsu_rtors, &rtorsup->rtorsu_trs,
-1);
+ rcu_torture_one_read_end(&rtorsup->rtorsu_rtors, &rtorsup->rtorsu_trs);
WARN_ONCE(rtorsup->rtorsu_nups >= rtorsup->rtorsu_ndowns, "%s: Up
without matching down #%zu.\n", __func__, rtorsup - updownreaders);
WRITE_ONCE(rtorsup->rtorsu_nups, rtorsup->rtorsu_nups + 1);
WRITE_ONCE(rtorsup->rtorsu_nmigrates,
@@ -2519,7 +2516,7 @@ static void rcu_torture_updown_cleanup(void)
if (!smp_load_acquire(&rtorsup->rtorsu_inuse))
continue;
if (hrtimer_cancel(&rtorsup->rtorsu_hrt) ||
WARN_ON_ONCE(rtorsup->rtorsu_inuse)) {
- rcu_torture_one_read_end(&rtorsup->rtorsu_rtors,
&rtorsup->rtorsu_trs, -1);
+ rcu_torture_one_read_end(&rtorsup->rtorsu_rtors,
&rtorsup->rtorsu_trs);
WARN_ONCE(rtorsup->rtorsu_nups >=
rtorsup->rtorsu_ndowns, "%s: Up without matching down #%zu.\n", __func__,
rtorsup - updownreaders);
WRITE_ONCE(rtorsup->rtorsu_nups, rtorsup->rtorsu_nups +
1);
smp_store_release(&rtorsup->rtorsu_inuse, false);
