On Thu, Mar 14 2024 at 22:21, Thomas Gleixner wrote:
> On Thu, Mar 14 2024 at 21:45, Thomas Gleixner wrote:
>> On Thu, Mar 14 2024 at 12:09, Florian Fainelli wrote:
>>> https://gist.github.com/ffainelli/cb562c1a60ef8e0e69e7d42143c48e8f
>>>
>>> this one is does include the tmigr events. Thanks!
>>
>> You need 8ca1836769d758e4fbf5851bb81e181c52193f5d too.
>
> So from the above trace it's clear where it goes south:
>
> [ 236.318158] <idle>-0 3..s.. 2928466us : tmigr_handle_remote:
> group=aecb05cb lvl=0
> [ 236.326526] <idle>-0 3d.s.. 2928467us : tmigr_handle_remote_cpu:
> cpu=0 parent=aecb05cb wakeup=9223372036854775807
> [ 236.357809] <idle>-0 3d.s.. 2928469us : tmigr_update_events:
> child=00000000 group=aecb05cb group_lvl=0 child_active=0 group_active=8
> nextevt=3103000000 next_expiry=2934000000 child_evt_expiry=0 child_evtcpu=0
>
> [ 236.377222] <idle>-0 0dn... 2928471us : tmigr_cpu_active: cpu=0
> parent=aecb05cb wakeup=9223372036854775807
> [ 236.387765] <idle>-0 0dn... 2928471us :
> tmigr_group_set_cpu_active: group=aecb05cb lvl=0 numa=0 active=9 migrator=8
> parent=00000000 childmask=1
>
> [ 236.401526] <idle>-0 0d.... 2928477us : tmigr_update_events:
> child=00000000 group=aecb05cb group_lvl=0 child_active=0 group_active=8
> nextevt=3103000000 next_expiry=2934000000 child_evt_expiry=0 child_evtcpu=0
> [ 236.420940] <idle>-0 0d.... 2928478us :
> tmigr_group_set_cpu_inactive: group=aecb05cb lvl=0 numa=0 active=8 migrator=8
> parent=00000000 childmask=1
> [ 236.434874] <idle>-0 0d.... 2928478us : tmigr_cpu_idle: cpu=0
> parent=aecb05cb nextevt=3103000000 wakeup=9223372036854775807
>
> [ 236.446896] <idle>-0 3d.... 2929469us :
> tmigr_group_set_cpu_inactive: group=aecb05cb lvl=0 numa=0 active=0
> migrator=ff parent=00000000 childmask=8
> [ 236.460916] <idle>-0 3d.... 2929470us : tmigr_cpu_idle: cpu=3
> parent=aecb05cb nextevt=9223372036854775807 wakeup=9223372036854775807
> [ 236.473721] <idle>-0 3d.... 2934471us :
> tmigr_cpu_new_timer_idle: cpu=3 parent=aecb05cb nextevt=9223372036854775807
> wakeup=9223372036854775807
>
> CPU3 is the last active CPU and goes idle. So it should take care of the
> pending events, but it does not.
>
> This is the next trace entry where CPU0 magically comes back to life.
>
> [ 236.487393] <idle>-0 0d.s.. 162001359us : timer_cancel:
> timer=8c725d84
>
> 8ca1836769d758e4fbf5851bb81e181c52193f5d is related, but dos not fully
> explain the fail. I haven't yet spotted where this goes into lala land.
The first expiring pending global timer is this one:
[ 236.112089] kworker/-1198 1d.... 2923481us : timer_start:
timer=ffd09a61 function=process_timeout expires=4294670230 [timeout=10]
bucket_expiry=4294670231 cpu=1 idx=23 flags=
Bucket expiry is the relevant number: 4294670231 (jiffies)
The last timer expiry happened about 1ms before the fail:
[ 236.344917] <idle>-0 3..s.. 2928468us : timer_expire_entry:
timer=2f09af03 function=process_timeout now=4294670225 baseclk=4294670225
Jiffies at that point: 4294670225
AFAICT this is a HZ=1000 configuration.
4294670231 - 4294670225 = 6
So the relevant wakeup should be around 2934468us
which is damned close to the point where the last active CPU vanishes into idle:
> [ 236.446896] <idle>-0 3d.... 2929469us :
> tmigr_group_set_cpu_inactive: group=aecb05cb lvl=0 numa=0 active=0
> migrator=ff parent=00000000 childmask=8
> [ 236.460916] <idle>-0 3d.... 2929470us : tmigr_cpu_idle: cpu=3
> parent=aecb05cb nextevt=9223372036854775807 wakeup=9223372036854775807
> [ 236.473721] <idle>-0 3d.... 2934471us :
> tmigr_cpu_new_timer_idle: cpu=3 parent=aecb05cb nextevt=9223372036854775807
> wakeup=9223372036854775807
Unless someone beats me to it, I'm going to continue staring at that
code tomorrow as my brain has started to melt by now.
Thanks,
tglx
