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
