Received-SPF: pass (google.com: domain of linux-kernel+bounces-103056-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.48.161 as permitted sender) client-ip=147.75.48.161;
From: Thomas Gleixner <tglx@linutronix.de>
To: Boqun Feng <boqun.feng@gmail.com>, Florian Fainelli <f.fainelli@gmail.com>
Cc: Frederic Weisbecker <frederic@kernel.org>, "Russell King (Oracle)"
 <linux@armlinux.org.uk>, Joel Fernandes <joel@joelfernandes.org>,
 Anna-Maria Behnsen <anna-maria@linutronix.de>, Linus Torvalds
 <torvalds@linux-foundation.org>, linux-kernel@vger.kernel.org,
 kernel-team@meta.com, paulmck@kernel.org, mingo@kernel.org,
 rcu@vger.kernel.org, neeraj.upadhyay@amd.com, urezki@gmail.com,
 qiang.zhang1211@gmail.com, bigeasy@linutronix.de, chenzhongjin@huawei.com,
 yangjihong1@huawei.com, rostedt@goodmis.org, Justin Chen
 <justin.chen@broadcom.com>
Subject: Re: Unexplained long boot delays [Was Re: [GIT PULL] RCU changes
 for v6.9]
In-Reply-To: <ZfKaHQXdYCKrT3Yr@Boquns-Mac-mini.home>
References: <c5f9c640-4c06-495e-9c7e-0c208b914fa7@gmail.com>
 <CAHk-=wgP=9JxdOJ5oYtVO5yM6pFi5+3FPxfCQa4ezpagJuXq3g@mail.gmail.com>
 <ZfDptafiK0jns050@boqun-archlinux>
 <CAEXW_YRvz8xf-6hpwpYqS=YNa-xkn4CsuJzELJxOH_2FP+6ptQ@mail.gmail.com>
 <2fb110ed-ba04-4320-9ef0-8766c9df5578@gmail.com>
 <ZfIh33YAYkLaDeAS@shell.armlinux.org.uk>
 <533151c9-afb5-453b-8014-9fbe7c3b26c2@gmail.com>
 <ZfIuRMo8oKbR08Af@lothringen>
 <f4a2a18c-1c81-4857-a3a0-d049ec5c79b3@gmail.com>
 <ZfKHKtt4ar6HyRKu@Boquns-Mac-mini.home>
 <ZfKaHQXdYCKrT3Yr@Boquns-Mac-mini.home>
Date: Thu, 14 Mar 2024 10:32:03 +0100
Message-ID: <87il1pma5o.ffs@tglx>
Precedence: bulk
MIME-Version: 1.0
Content-Type: text/plain

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