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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date: Thu, 14 Mar 2024 10:32:03 +0100
From: Thomas Gleixner <tglx@...utronix.de>
To: Boqun Feng <boqun.feng@...il.com>, Florian Fainelli <f.fainelli@...il.com>
Cc: Frederic Weisbecker <frederic@...nel.org>, "Russell King (Oracle)"
 <linux@...linux.org.uk>, Joel Fernandes <joel@...lfernandes.org>,
 Anna-Maria Behnsen <anna-maria@...utronix.de>, Linus Torvalds
 <torvalds@...ux-foundation.org>, linux-kernel@...r.kernel.org,
 kernel-team@...a.com, paulmck@...nel.org, mingo@...nel.org,
 rcu@...r.kernel.org, neeraj.upadhyay@....com, urezki@...il.com,
 qiang.zhang1211@...il.com, bigeasy@...utronix.de, chenzhongjin@...wei.com,
 yangjihong1@...wei.com, rostedt@...dmis.org, Justin Chen
 <justin.chen@...adcom.com>
Subject: Re: Unexplained long boot delays [Was Re: [GIT PULL] RCU changes
 for v6.9]

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