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

Thomas Gleixner
2024-03-14T09:32:11Z

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