Re: [PATCH v2 3/2] sched/deadline: Check bandwidth overflow earlier for hotplug

[Juri Lelli]

On 07/02/25 10:38, Jon Hunter wrote:
> 
> On 06/02/2025 09:29, Juri Lelli wrote:
> > On 05/02/25 16:56, Jon Hunter wrote:
> > 
> > ...
> > 
> > > Thanks! That did make it easier :-)
> > > 
> > > Here is what I see ...
> > 
> > Thanks!
> > 
> > Still different from what I can repro over here, so, unfortunately, I
> > had to add additional debug printks. Pushed to the same branch/repo.
> > 
> > Could I ask for another run with it? Please also share the complete
> > dmesg from boot, as I would need to check debug output when CPUs are
> > first onlined.
> 
> 
> Yes no problem. Attached is the complete log.

Great, thanks!

...

> [    0.000000] rq_attach_root: cpu=0 old_span=NULL new_span=
> [    0.000000] rq_attach_root: cpu=1 old_span=NULL new_span=0
> [    0.000000] rq_attach_root: cpu=2 old_span=NULL new_span=0-1
> [    0.000000] rq_attach_root: cpu=3 old_span=NULL new_span=0-2
> [    0.000000] rq_attach_root: cpu=4 old_span=NULL new_span=0-3
> [    0.000000] rq_attach_root: cpu=5 old_span=NULL new_span=0-4

...

> [    0.000000] rq_attach_root: cpu=0 old_span=NULL new_span=
> [    0.000000] rq_attach_root: cpu=1 old_span=NULL new_span=0
> [    0.000000] rq_attach_root: cpu=2 old_span=NULL new_span=0-1
> [    0.000000] rq_attach_root: cpu=3 old_span=NULL new_span=0-2
> [    0.000000] rq_attach_root: cpu=4 old_span=NULL new_span=0-3
> [    0.000000] rq_attach_root: cpu=5 old_span=NULL new_span=0-4

...

> [    0.040366] smp: Bringing up secondary CPUs ...
> [    0.048932] CPU features: detected: Kernel page table isolation (KPTI)
> [    0.048969] Detected PIPT I-cache on CPU1
> [    0.048985] CPU features: SANITY CHECK: Unexpected variation in SYS_CTR_EL0. Boot CPU: 0x0000008444c004, CPU1: 0x0000009444c004
> [    0.049006] CPU features: SANITY CHECK: Unexpected variation in SYS_ID_AA64DFR0_EL1. Boot CPU: 0x00000010305106, CPU1: 0x00000010305116
> [    0.049037] CPU features: SANITY CHECK: Unexpected variation in SYS_ID_DFR0_EL1. Boot CPU: 0x00000003010066, CPU1: 0x00000003001066
> [    0.049074] CPU features: Unsupported CPU feature variation detected.
> [    0.049264] CPU1: Booted secondary processor 0x0000000000 [0x4e0f0030]
> [    0.049331] __dl_add: cpus=1 tsk_bw=52428 total_bw=104856 span=0-5 type=DEF
> [    0.052684] Detected PIPT I-cache on CPU2
> [    0.052705] CPU features: SANITY CHECK: Unexpected variation in SYS_CTR_EL0. Boot CPU: 0x0000008444c004, CPU2: 0x0000009444c004
> [    0.052726] CPU features: SANITY CHECK: Unexpected variation in SYS_ID_AA64DFR0_EL1. Boot CPU: 0x00000010305106, CPU2: 0x00000010305116
> [    0.052754] CPU features: SANITY CHECK: Unexpected variation in SYS_ID_DFR0_EL1. Boot CPU: 0x00000003010066, CPU2: 0x00000003001066
> [    0.052922] CPU2: Booted secondary processor 0x0000000001 [0x4e0f0030]
> [    0.052982] __dl_add: cpus=2 tsk_bw=52428 total_bw=157284 span=0-5 type=DEF
> [    0.060457] Detected PIPT I-cache on CPU3
> [    0.060554] CPU3: Booted secondary processor 0x0000000101 [0x411fd073]
> [    0.060579] __dl_add: cpus=3 tsk_bw=52428 total_bw=209712 span=0-5 type=DEF
> [    0.068476] Detected PIPT I-cache on CPU4
> [    0.068539] CPU4: Booted secondary processor 0x0000000102 [0x411fd073]
> [    0.068560] __dl_add: cpus=4 tsk_bw=52428 total_bw=262140 span=0-5 type=DEF
> [    0.069093] Detected PIPT I-cache on CPU5
> [    0.069154] CPU5: Booted secondary processor 0x0000000103 [0x411fd073]
> [    0.069177] __dl_add: cpus=5 tsk_bw=52428 total_bw=314568 span=0-5 type=DEF
> [    0.069254] smp: Brought up 1 node, 6 CPUs
> [    0.069289] SMP: Total of 6 processors activated.
> [    0.069296] CPU: All CPU(s) started at EL2
> [    0.069308] CPU features: detected: 32-bit EL0 Support
> [    0.069315] CPU features: detected: 32-bit EL1 Support
> [    0.069323] CPU features: detected: CRC32 instructions
> [    0.069432] alternatives: applying system-wide alternatives
> [    0.077906] CPU0 attaching sched-domain(s):
> [    0.077926]  domain-0: span=0,3-5 level=MC
> [    0.077940]   groups: 0:{ span=0 cap=1020 }, 3:{ span=3 }, 4:{ span=4 }, 5:{ span=5 }
> [    0.077982] __dl_sub: cpus=6 tsk_bw=52428 total_bw=262140 span=0-5 type=DEF
> [    0.077988] __dl_server_detach_root: cpu=0 rd_span=0-5 total_bw=262140
> [    0.077996] rq_attach_root: cpu=0 old_span=NULL new_span=
> [    0.078000] __dl_add: cpus=1 tsk_bw=52428 total_bw=52428 span=0 type=DYN
> [    0.078004] __dl_server_attach_root: cpu=0 rd_span=0 total_bw=52428
> [    0.078009] CPU3 attaching sched-domain(s):
> [    0.078036]  domain-0: span=0,3-5 level=MC
> [    0.078046]   groups: 3:{ span=3 }, 4:{ span=4 }, 5:{ span=5 }, 0:{ span=0 cap=1020 }
> [    0.078084] __dl_sub: cpus=5 tsk_bw=52428 total_bw=209712 span=1-5 type=DEF
> [    0.078088] __dl_server_detach_root: cpu=3 rd_span=1-5 total_bw=209712
> [    0.078093] rq_attach_root: cpu=3 old_span=NULL new_span=0
> [    0.078096] __dl_add: cpus=2 tsk_bw=52428 total_bw=104856 span=0,3 type=DYN
> [    0.078100] __dl_server_attach_root: cpu=3 rd_span=0,3 total_bw=104856
> [    0.078104] CPU4 attaching sched-domain(s):
> [    0.078130]  domain-0: span=0,3-5 level=MC
> [    0.078140]   groups: 4:{ span=4 }, 5:{ span=5 }, 0:{ span=0 cap=1020 }, 3:{ span=3 }
> [    0.078177] __dl_sub: cpus=4 tsk_bw=52428 total_bw=157284 span=1-2,4-5 type=DEF
> [    0.078181] __dl_server_detach_root: cpu=4 rd_span=1-2,4-5 total_bw=157284
> [    0.078186] rq_attach_root: cpu=4 old_span=NULL new_span=0,3
> [    0.078189] __dl_add: cpus=3 tsk_bw=52428 total_bw=157284 span=0,3-4 type=DYN
> [    0.078193] __dl_server_attach_root: cpu=4 rd_span=0,3-4 total_bw=157284
> [    0.078197] CPU5 attaching sched-domain(s):
> [    0.078224]  domain-0: span=0,3-5 level=MC
> [    0.078234]   groups: 5:{ span=5 }, 0:{ span=0 cap=1020 }, 3:{ span=3 }, 4:{ span=4 }
> [    0.078271] __dl_sub: cpus=3 tsk_bw=52428 total_bw=104856 span=1-2,5 type=DEF
> [    0.078276] __dl_server_detach_root: cpu=5 rd_span=1-2,5 total_bw=104856
> [    0.078280] rq_attach_root: cpu=5 old_span=NULL new_span=0,3-4
> [    0.078283] __dl_add: cpus=4 tsk_bw=52428 total_bw=209712 span=0,3-5 type=DYN
> [    0.078287] __dl_server_attach_root: cpu=5 rd_span=0,3-5 total_bw=209712
> [    0.078291] root domain span: 0,3-5
> [    0.078317] default domain span: 1-2

Up until here it looks alright: 1,2 are left on DEF root domain since
they are isolated; the rest on a single dynamic domain. Also dl server
bandwidth sums up correctly.

...

> [    4.694391] cpufreq: cpufreq_online: CPU0: Running at unlisted initial frequency: 1344000 kHz, changing to: 1382400 kHz

I didn't of course have cpufreq in my virt env! :)

> [    4.705324] dl_clear_root_domain: span=0,3-5 type=DYN
> [    4.705332] __dl_add: cpus=4 tsk_bw=52428 total_bw=52428 span=0,3-5 type=DYN
> [    4.705338] __dl_add: cpus=4 tsk_bw=52428 total_bw=104856 span=0,3-5 type=DYN
> [    4.705343] __dl_add: cpus=4 tsk_bw=52428 total_bw=157284 span=0,3-5 type=DYN
> [    4.705347] __dl_add: cpus=4 tsk_bw=52428 total_bw=209712 span=0,3-5 type=DYN
> [    4.705351] rd 0,3-5: Checking EAS, CPUs do not have asymmetric capacities
> [    4.745754] dl_clear_root_domain: span=1-2 type=DEF
> [    4.745760] __dl_add: cpus=2 tsk_bw=52428 total_bw=52428 span=1-2 type=DEF
> [    4.745765] __dl_add: cpus=2 tsk_bw=52428 total_bw=104856 span=1-2 type=DEF
> [    4.745823] __dl_add: cpus=4 tsk_bw=104857 total_bw=314569 span=0,3-5 type=DYN
> [    4.745845] __dl_sub: cpus=4 tsk_bw=104857 total_bw=209712 span=0,3-5 type=DYN

This above doesn't already make much sense to me and I still need to
understand what is going on. The rest is actually also not that easy to
follow, so...

I thought maybe we could try switching to use ftrace.

Pushed yet additional debug changes to the repo (please update).

The idea would be to boot with something like "ftrace=nop
trace_buf_size=50K" added to kernel cmdline, then, right after boot
collect the trace buffer with

# cat /sys/kernel/debug/tracing/trace > trace.out

and also collect dmesg as you did already. Going over the two side by
side should hopefully provide more information on what is actually
triggering the total_bw add/sub calls (as I enabled stack traces). I
don't think it's necessary just yet to collect tracing info across
suspend events, as accounting seems already broken after boot. :/

Again, really appreciating the help with debugging this!

And Dietmar, thanks for starting to look into this as well! Of course
feel free to suggest different approaches to debugging this. :)

Best,
Juri