Re: [PATCH] RFC: sched: Rework task_sched_runtime to avoid calling update_rq_clock

[Johannes Weiner <hannes@cmpxchg.org>]

On Tue, Jun 18, 2024 at 10:12:36AM +0200, Peter Zijlstra wrote:
> On Mon, Jun 17, 2024 at 05:42:25PM -0700, John Stultz wrote:
> > On Fri, Jun 14, 2024 at 2:48 AM Peter Zijlstra <peterz@infradead.org> wrote:
> > > Which then gets me something like the (completely untested) below..
> > >
> > > Hmm?
> > >
> > > diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> > > index 0935f9d4bb7b..36aed99d6a6c 100644
> > > --- a/kernel/sched/core.c
> > > +++ b/kernel/sched/core.c
> > > @@ -724,7 +724,6 @@ static void update_rq_clock_task(struct rq *rq, s64 delta)
> > >
> > >         rq->prev_irq_time += irq_delta;
> > >         delta -= irq_delta;
> > > -       psi_account_irqtime(rq->curr, irq_delta);
> > >         delayacct_irq(rq->curr, irq_delta);
> > >  #endif
> > >  #ifdef CONFIG_PARAVIRT_TIME_ACCOUNTING
> > > @@ -5459,6 +5458,8 @@ void sched_tick(void)
> > >
> > >         sched_clock_tick();
> > >
> > > +       psi_account_irqtime(curr, NULL, &rq->psi_irq_time);
> > > +
> > >         rq_lock(rq, &rf);
> > >
> > >         update_rq_clock(rq);
> > > @@ -6521,6 +6524,7 @@ static void __sched notrace __schedule(unsigned int sched_mode)
> > >                 ++*switch_count;
> > >
> > >                 migrate_disable_switch(rq, prev);
> > > +               psi_account_irqtime(prev, next, &rq->psi_irq_time);
> > 
> > FYI: These references to psi_irq_time hit build issues if
> > CONFIG_IRQ_TIME_ACCOUNTING is disabled.
> 
> Ah, well, I did say it was untested...
> 
> > Also, separately, while I didn't see this earlier testing on physical
> > devices, when running virtualized, I can pretty easily trip over the
> > following:
> > 
> > [   65.207340] watchdog: BUG: soft lockup - CPU#0 stuck for 26s!
> > [kworker/0:3:374]
> > [   65.211107] irq event stamp: 118664
> > [   65.212786] hardirqs last  enabled at (118663):
> > [<ffffffff97a00e46>] asm_sysvec_apic_timer_interrupt+0x16/0x20
> > [   65.218440] hardirqs last disabled at (118664):
> > [<ffffffff977fdeca>] sysvec_apic_timer_interrupt+0xa/0xc0
> > [   65.223074] softirqs last  enabled at (118546):
> > [<ffffffff9676db78>] __irq_exit_rcu+0x88/0xe0
> > [   65.227118] softirqs last disabled at (118541):
> > [<ffffffff9676db78>] __irq_exit_rcu+0x88/0xe0
> > [   65.231137] CPU: 0 PID: 374 Comm: kworker/0:3 Not tainted
> > 6.10.0-rc4-dirty #4393
> > [   65.234625] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
> > BIOS 1.16.3-debian-1.16.3-2 04/01/2014
> > [   65.239089] Workqueue: events psi_avgs_work
> > [   65.241122] RIP: 0010:collect_percpu_times+0xff/0x310
> > [   65.243525] Code: b9 02 00 00 00 48 89 df e8 8e a4 01 00 48 8b b4
> > 24 d0 00 00 00 48 89 df e8 5e 9e 01 00 58 45 8b 34 24 41 f6 c6 01 74
> > 0c f3 0
> > [   65.252926] RSP: 0018:ffff958501263d50 EFLAGS: 00000202
> > [   65.255433] RAX: 0000000000017b61 RBX: ffff9585b901d848 RCX: 0000000000000006
> > [   65.258755] RDX: ffffffff967eb6ac RSI: ffffffff9819e305 RDI: ffffffff98177748
> > [   65.262113] RBP: ffff958501263db0 R08: 0000000000000001 R09: 0000000000000000
> > [   65.265475] R10: 0000000000000001 R11: 0000000000000001 R12: ffff9585b901d840
> > [   65.268785] R13: ffff9585b901d884 R14: 0000000000033d8b R15: 0000000000000000
> > [   65.272146] FS:  0000000000000000(0000) GS:ffff9585b9000000(0000)
> > knlGS:0000000000000000
> > [   65.275908] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [   65.278629] CR2: 00005631aee8b000 CR3: 0000000116c0e001 CR4: 0000000000370ef0
> > [   65.282002] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [   65.285386] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > [   65.288730] Call Trace:
> > [   65.289958]  <IRQ>
> > [   65.290965]  ? watchdog_timer_fn+0x275/0x310
> > [   65.293185]  ? __pfx_watchdog_timer_fn+0x10/0x10
> > [   65.295379]  ? __hrtimer_run_queues+0x190/0x3b0
> > [   65.297795]  ? hrtimer_interrupt+0xf9/0x230
> > [   65.299782]  ? __sysvec_apic_timer_interrupt+0x82/0x210
> > [   65.302243]  ? sysvec_apic_timer_interrupt+0x98/0xc0
> > [   65.304590]  </IRQ>
> > [   65.305658]  <TASK>
> > [   65.306708]  ? asm_sysvec_apic_timer_interrupt+0x16/0x20
> > [   65.309206]  ? psi_avgs_work+0x3c/0xb0
> > [   65.311001]  ? collect_percpu_times+0xff/0x310
> > [   65.313153]  psi_avgs_work+0x3c/0xb0
> > [   65.314864]  process_one_work+0x1fe/0x700
> > [   65.316782]  ? lock_is_held_type+0xcd/0x120
> > [   65.318782]  worker_thread+0x1c7/0x3b0
> > [   65.320571]  ? __pfx_worker_thread+0x10/0x10
> > [   65.322626]  kthread+0xe0/0x110
> > [   65.324103]  ? __pfx_kthread+0x10/0x10
> > [   65.325853]  ret_from_fork+0x28/0x40
> > [   65.327512]  ? __pfx_kthread+0x10/0x10
> > [   65.329255]  ret_from_fork_asm+0x1a/0x30
> > [   65.331073]  </TASK>
> > [   65.332119] Kernel panic - not syncing: softlockup: hung tasks
> > 
> > Where collect_percpu_times+0xff/0x310:
> > __seqprop_sequence at include/linux/seqlock.h:211 (discriminator 2)
> > (inlined by) get_recent_times at kernel/sched/psi.c:261 (discriminator 2)
> > (inlined by) collect_percpu_times at kernel/sched/psi.c:359 (discriminator 2)
> > 
> > Which looks like its getting stuck in the seqlock loop, and the only
> > way I can see that catching right off, is if we're in some sort of
> > livelock where the calls to psi_account_irqtime(curr, NULL,
> > &rq->psi_irq_time) is coming in frequently enough to change the seqno
> > each iteration through the reader.  But from my initial trace_printk
> > debugging, it seems like from a kworker we enter the loop in
> > get_recent_times(), hit an irq and somehow never really come back out
> > of irq context. Though we continue to get ticks on the task and
> > continue to call psi_account_irqtime().  I was worried we were somehow
> > getting stuck in the 'while ((group = group->parent));' loop in
> > psi_account_irqtime(), but that doesn't seem to be the case.
> > 
> > [  238.297094] kworker/-798       0..... 200647713us :
> > collect_percpu_times: JDB: get_recent_times at top of loop 0!
> > [  238.301705] kworker/-798       0..... 200647767us :
> > collect_percpu_times: JDB: get_recent_times done with read (looped:
> > 1)!
> > [  238.306689] kworker/-798       0..... 200647768us :
> > collect_percpu_times: JDB: get_recent_times at top of loop 0!
> > [  238.311313] kworker/-798       0..... 200647769us :
> > collect_percpu_times: JDB: get_recent_times done with read (looped:
> > 1)!
> > [  238.316318] kworker/-798       0d..2. 200647786us :
> > psi_group_change: JDB: psi_group_change seqwrite
> > <normal behavior above>
> > [  238.320460] kworker/-10        0..... 200647790us :
> > collect_percpu_times: JDB: get_recent_times at top of loop 0!
> > [  238.325131] kworker/-10        0d.h.. 200648408us :
> > psi_account_irqtime: JDB: psi_account_irqtime seqwrite (loop count: 0)
> > [  238.330149] kworker/-10        0d.h.. 200649406us :
> > psi_account_irqtime: JDB: psi_account_irqtime seqwrite (loop count: 0)
> > [  238.335140] kworker/-10        0d.h.. 200650405us :
> > psi_account_irqtime: JDB: psi_account_irqtime seqwrite (loop count: 0)
> > ...
> > With the psi_account_irqtime just repeating there each ms/tick.
> > 
> > I'm still digging a bit here to understand what's going on. But I
> > wanted to share.
> 
> Urgh, that's not making any sense to me either. Johannes, considering:
> 
>  https://lkml.kernel.org/20240614094833.GM8774@noisy.programming.kicks-ass.net

This might be the culprit:

@@ -5459,6 +5458,8 @@ void sched_tick(void)
 
 	sched_clock_tick();
 
+	psi_account_irqtime(curr, NULL, &rq->psi_irq_time);
+
 	rq_lock(rq, &rf);
 
 	update_rq_clock(rq);

rq->lock is required for these state updates because it also
serializes against tasks moving between cgroups. If another CPU
changes the task->cgroup association during the update, AFAICS it
could call write_seqcount_begin() one group 1 and _end() on group 2,
leaving both groups' seqcounters odd.

Can you try moving the accounting call below rq_lock()?