Message-ID: <667bea49-f772-4093-93cd-c590b666330b@paulmck-laptop>
Date: Sun, 25 Aug 2024 12:36:50 -0700
From: "Paul E. McKenney" <paulmck@...nel.org>
To: Peter Zijlstra <peterz@...radead.org>, vschneid@...hat.com,
	linux-kernel@...r.kernel.org, sfr@...b.auug.org.au,
	linux-next@...r.kernel.org, kernel-team@...a.com
Subject: Re: [BUG almost bisected] Splat in dequeue_rt_stack() and build error

On Sat, Aug 24, 2024 at 07:10:21PM -0700, Paul E. McKenney wrote:
> On Sat, Aug 24, 2024 at 08:26:57AM -0700, Paul E. McKenney wrote:
> > On Sat, Aug 24, 2024 at 08:54:34AM +0200, Peter Zijlstra wrote:
> > > On Fri, Aug 23, 2024 at 02:51:03PM -0700, Paul E. McKenney wrote:
> > > 
> > > > > > Does the below help any? That's more or less what it was before Valentin
> > > > > > asked me why it was weird like that :-)
> > > > > > 
> > > > > > diff --git a/kernel/sched/fair.c b/kernel/sched/fair.c
> > > > > > index 6be618110885..5757dd50b02f 100644
> > > > > > --- a/kernel/sched/fair.c
> > > > > > +++ b/kernel/sched/fair.c
> > > > > > @@ -13107,7 +13107,6 @@ static void switched_from_fair(struct rq *rq, struct task_struct *p)
> > > > > >  	 * and we cannot use DEQUEUE_DELAYED.
> > > > > >  	 */
> > > > > >  	if (p->se.sched_delayed) {
> > > > > > -		dequeue_task(rq, p, DEQUEUE_NOCLOCK | DEQUEUE_SLEEP);
> > > > > >  		p->se.sched_delayed = 0;
> > > > > >  		p->se.rel_deadline = 0;
> > > > > >  		if (sched_feat(DELAY_ZERO) && p->se.vlag > 0)
> > > > > 
> > > > > Removing that line from 2e0199df252a still gets me the complaint about
> > > > > __SCHED_FEAT_DELAY_ZERO being undefined.  To my naive eyes, it appears
> > > > > that this commit:
> > > > > 
> > > > > 54a58a787791 ("sched/fair: Implement DELAY_ZERO")
> > > > > 
> > > > > Need to be placed before 2e0199df252a.  Of course, when I try it, I
> > > > > get conflicts.  So I took just this hunk:
> > > > > 
> > > > > ------------------------------------------------------------------------
> > > > > 
> > > > > diff --git a/kernel/sched/features.h b/kernel/sched/features.h
> > > > > index 97fb2d4920898..6c5f5424614d4 100644
> > > > > --- a/kernel/sched/features.h
> > > > > +++ b/kernel/sched/features.h
> > > > > @@ -28,6 +28,11 @@ SCHED_FEAT(NEXT_BUDDY, false)
> > > > >   */
> > > > >  SCHED_FEAT(CACHE_HOT_BUDDY, true)
> > > > >  
> > > > > +/*
> > > > > + * DELAY_ZERO clips the lag on dequeue (or wakeup) to 0.
> > > > > + */
> > > > > +SCHED_FEAT(DELAY_ZERO, true)
> > > > > +
> > > > >  /*
> > > > >   * Allow wakeup-time preemption of the current task:
> > > > >   */
> > > > > 
> > > > > ------------------------------------------------------------------------
> > > > > 
> > > > > That makes the build error go away.  Maybe even legitimately?
> > > 
> > > Yep.
> > > 
> > > > > Just to pick on the easy one, I took a look at the complaint about
> > > > > cfs_rq being unused and the complaint about __SCHED_FEAT_DELAY_ZERO
> > > > > being undefined.  This variable was added here:
> > > > > 
> > > > > 781773e3b680 ("sched/fair: Implement ENQUEUE_DELAYED")
> > > > > 
> > > > > And its first use was added here:
> > > > > 
> > > > > 54a58a787791 ("sched/fair: Implement DELAY_ZERO")
> > > > > 
> > > > > Which matches my experience.
> > > > > 
> > > > > So left to myself, I would run on these commits with the above hunk:
> > > > > 
> > > > > 54a58a7877916 sched/fair: Implement DELAY_ZERO
> > > > > 152e11f6df293 sched/fair: Implement delayed dequeue
> > > > > e1459a50ba318 sched: Teach dequeue_task() about special task states
> > > > > a1c446611e31c sched,freezer: Mark TASK_FROZEN special
> > > > > 781773e3b6803 sched/fair: Implement ENQUEUE_DELAYED
> > > > > f12e148892ede sched/fair: Prepare pick_next_task() for delayed dequeue
> > > > > 2e0199df252a5 sched/fair: Prepare exit/cleanup paths for delayed_dequeue
> > > > > e28b5f8bda017 sched/fair: Assert {set_next,put_prev}_entity() are properly balanced
> > > > > 
> > > > > And where needed, remove the unused cfs_rq local variable.
> > > > > 
> > > > > Would that likely work?
> > > 
> > > Sounds about right.
> > > 
> > > > > 
> > > > > In the meantime, SIGFOOD!
> > > > 
> > > > Hearing no objections...
> > > 
> > > Yeah, sorry, I'm on holidays with the kids and not glued to the screen
> > > as per usual :-)
> > 
> > No worries, and have a great holiday!!!
> > 
> > > > Given two patches each of which might or might not need to be applied to a
> > > > given commit, I chose to rebase as follows:
> > > > 
> > > > e28b5f8bda017 sched/fair: Assert {set_next,put_prev}_entity() are properly balanced
> > > > 8aed87410a695 EXP sched/fair: Provide DELAY_ZERO definition
> > > > 	I took this from 54a58a7877916 sched/fair: Implement DELAY_ZERO.
> > > > 49575c0087bc0 sched/fair: Prepare exit/cleanup paths for delayed_dequeue
> > > > 14c3207fd2456 sched/fair: Prepare pick_next_task() for delayed dequeue
> > > > be567af45dd04 sched/fair: Implement ENQUEUE_DELAYED
> > > > 	I dropped the unused cfs_rq local variable from requeue_delayed_entity()
> > > > ed28f7b3ac3f4 sched,freezer: Mark TASK_FROZEN special
> > > > 48d541847b4a6 sched: Teach dequeue_task() about special task states
> > > > ef3b9c5d038dc sched/fair: Implement delayed dequeue
> > > > 	--- First bad commit with dequeue_rt_stack() failures.
> > > > 876c99c058219 sched/fair: Implement DELAY_ZERO
> > > > 	I added the cfs_rq local variable to requeue_delayed_entity()
> > > > 
> > > > This is on -rcu branch peterz.2024.08.23b.
> > > > 
> > > > I ran 50*TREE05 in a bisection, which converged on be567af45dd04, but only
> > > > one run of the 50 had a complaint, and that was in enqueue_dl_entry(),
> > > 
> > > Hmm, I have one other report about that. Hasn't made much sense yet --
> > > then again, as per the above mentioned reason, I'm not able to put real
> > > time in atm.
> > 
> > I ran 1000*TREE03 on that same commit, no failures.  Just started
> > 5000*TREE03, and will let you know what happens.  This will likely take
> > better part of a day to complete.
> > 
> > > > not the dequeue_rt_stack() that I have been chasing.  I ran three
> > > > additional 50*TREE05 runs on its predecessor (14c3207fd2456) with no
> > > > failures.  I then ran 50*TREE03 on each of ed28f7b3ac3f4, 48d541847b4a6,
> > > > and ef3b9c5d038dc.  Only this last ("ef3b9c5d038dc sched/fair: Implement
> > > > delayed dequeue") had failure, and they were all the dequeue_rt_stack()
> > > > failures I am chasing.  One of the runs also hung.
> > > 
> > > I'm a little confused now though; this is with the dequeue removed from
> > > switched_from_fair() ?
> > 
> > Ah!!!  I thought that change was for the build issue, which I will
> > admit puzzled me a bit.
> > 
> > > Looking at your tree, 49575c0087bc0 still has that dequeue. Does the
> > > dequeue_rt_stack() issue go away with that line removed?
> > 
> > I will try it and let you know.  Thank you for reminding me!
> 
> Preliminary results show that removing the dequeue from that commit or
> just from next-20240823 at the very least greatly reduces the probability
> of the problem occurring.  I am doing an overnight run with that dequeue
> removed from next-20240823 and will let you know how it goes.

No dequeue_rt_stack() or enqueue_dl_entry() issues in 5000*TREE03 runs, so
I think we can declare the first to be fixed and the second to be rather
low probability.  I also searched for "enqueue_dl_entry" in my employer's
full fleet's worth of console output from the past week, and saw no hits.
(Not too surprising, given that we don't do much RT here, but still...)

I did get what appears to me to be an unrelated one-off shown below.  I am
including this not as a bug report, but just for completeness.  I didn't
find anything like this from the fleet over the past week, either.

Unicorns!!!  ;-)

							Thanx, Paul

------------------------------------------------------------------------

[   66.315476] smpboot: CPU 2 is now offline
[   67.245115] rcu-torture: rcu_torture_read_exit: Start of episode
[   69.232773] rcu-torture: Stopping rcu_torture_boost task
[   70.290610] rcu-torture: rcu_torture_boost is stopping
[   70.295436] BUG: kernel NULL pointer dereference, address: 0000000000000000
[   70.295444] smpboot: CPU 3 is now offline
[   70.296343] #PF: supervisor write access in kernel mode
[   70.296343] #PF: error_code(0x0002) - not-present page
[   70.296343] PGD 0 P4D 0
[   70.296343] Oops: Oops: 0002 [#1] PREEMPT SMP NOPTI
[   70.296343] CPU: 14 UID: 0 PID: 414 Comm: kworker/u67:1 Not tainted 6.11.0-rc4-next-20240823-dirty #53827
[   70.296343] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
[   70.296343] RIP: 0010:_raw_spin_lock_irq+0x13/0x30
[   70.303668] Code: 1f 84 00 00 00 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa fa 65 ff 05 7c c9 0e 6e 31 c0 ba 01 00 00 00 <f0> 0f b1 17 75 05 c3 cc cc cc cc 89 c6 e9 1b 00 00 00 66 2e 0f 1f
[   70.303668] RSP: 0018:ffffa13840cafec0 EFLAGS: 00010046
[   70.322799] rcu-torture: rcu_torture_read_exit: End of episode
[   70.323615] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff9fb682c0ac40
[   70.323615] RDX: 0000000000000001 RSI: ffffa13840cafe60 RDI: 0000000000000000
[   70.323615] RBP: ffff9fb68294c300 R08: 000000000000041e R09: 0000000000000001
[   70.323615] R10: 0000000000000003 R11: 00000000002dc6c0 R12: ffff9fb682b2ba80
[   70.323615] R13: ffff9fb682c120c0 R14: ffff9fb682c120c0 R15: ffff9fb682c0ac40
[   70.323615] FS:  0000000000000000(0000) GS:ffff9fb69f580000(0000) knlGS:0000000000000000
[   70.323615] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   70.323615] CR2: 0000000000000000 CR3: 000000001ac2e000 CR4: 00000000000006f0
[   70.323615] Call Trace:
[   70.323615]  <TASK>
[   70.323615]  ? __die+0x1f/0x70
[   70.323615]  ? page_fault_oops+0x155/0x440
[   70.323615]  ? _raw_spin_lock_irq+0x15/0x30
[   70.323615]  ? is_prefetch.constprop.0+0xed/0x1b0
[   70.323615]  ? exc_page_fault+0x69/0x150
[   70.323615]  ? asm_exc_page_fault+0x26/0x30
[   70.323615]  ? _raw_spin_lock_irq+0x13/0x30
[   70.323615]  worker_thread+0x41/0x3a0
[   70.323615]  ? __pfx_worker_thread+0x10/0x10
[   70.323615]  kthread+0xd1/0x100
[   70.323615]  ? __pfx_kthread+0x10/0x10
[   70.323615]  ret_from_fork+0x2f/0x50
[   70.323615]  ? __pfx_kthread+0x10/0x10
[   70.323615]  ret_from_fork_asm+0x1a/0x30
[   70.323615]  </TASK>
[   70.323615] Modules linked in:
[   70.323615] CR2: 0000000000000000
[   70.323615] ---[ end trace 0000000000000000 ]---

Powered by blists - more mailing lists