Re: Unexplained long boot delays [Was Re: [GIT PULL] RCU changes for v6.9]

[Thomas Gleixner <tglx@linutronix.de>]

On Wed, Mar 13 2024 at 23:33, Boqun Feng wrote:
> but here:
>
> 	[  221.555265] kworker/-44        0d.... 3279414us : timer_start: timer=95703ccd function=process_timeout expires=4294670586 [timeout=10] bucket_expiry=4294670587 cpu=0 idx =59 flags=
>
> this is a normal timer.
>
> 	[  221.571298] rcu_sche-15        3d.... 3279417us : timer_start: timer=7e541f87 function=process_timeout expires=4294670579 [timeout=3] bucket_expiry=4294670580 cpu=3 idx= 52 flags=
> 	[  221.587241]   <idle>-0         1d.s.. 3283405us : timer_cancel: timer=7e541f87
> 	[  221.594488]   <idle>-0         1..s.. 3283407us : timer_expire_entry: timer=7e541f87 function=process_timeout now=4294670580 baseclk=4294670580
> 	[  221.607388] rcu_sche-15        3d.... 3283416us : timer_start: timer=7e541f87 function=process_timeout expires=4294670583 [timeout=3] bucket_expiry=4294670584 cpu=3 idx= 56 flags=
> 	[  221.623331]   <idle>-0         1d.s.. 3287404us : timer_cancel: timer=7e541f87
> 	[  221.630578]   <idle>-0         1..s.. 3287405us : timer_expire_entry: timer=7e541f87 function=process_timeout now=4294670584 baseclk=4294670584
> 	[  221.643475]   <idle>-0         0d.s.. 162361292us : timer_cancel: timer=95703ccd
> 	[  221.650896]   <idle>-0         0..s.. 162361292us : timer_expire_entry: timer=95703ccd function=process_timeout now=4294829657 baseclk=4294670587
>
> which got fired here.
>
> 	[  221.663967]   <idle>-0         0dns.. 162361296us : timer_cancel: timer=d03eaa1d
> 	[  221.671388]   <idle>-0         0.ns.. 162361297us : timer_expire_entry: timer=d03eaa1d function=process_timeout now=4294829657 baseclk=4294670856
>
> And looks to me CPU 0 is the tick_do_timer_cpu CPU, since it's the first
> one that got timers after a long wait and was doing a few catch-ups. Now
> the problem is why CPU 0 didn't program its hardware timer to expire at
> 4294670587? I.e. the earliest timer.

That's not the problem. It's not clear whether CPU0 was the last one
going idle. It doesn't look so:

> 	[  221.623331]   <idle>-0         1d.s.. 3287404us : timer_cancel: timer=7e541f87
> 	[  221.630578]   <idle>-0         1..s.. 3287405us : timer_expire_entry: timer=7e541f87 function=process_timeout now=4294670584 baseclk=4294670584

The timer in question is supposed to wake up 2 ticks later, so CPU1
should have armed it. But without the migration trace points enabled
this is all guess work.

Thanks,

        tglx