Re: CPU excessively long times between frequency scaling driver calls - bisected

["Paul E. McKenney" <paulmck@kernel.org>]

On Fri, Feb 25, 2022 at 08:29:51AM +0800, Feng Tang wrote:
> Hi Paul,
> 
> On Thu, Feb 24, 2022 at 06:44:23AM -0800, Paul E. McKenney wrote:
> [...]
> > > > > > Rafael replied with one possible option. Alternatively when planing to
> > > > > > enter deep idle, set P-state to min with a callback like we do in
> > > > > > offline callback.
> > > > >
> > > > > Yes, if the system is going to idle, it makes sense to goto a lower
> > > > > cpufreq first (also what my debug patch will essentially lead to).
> > > > >
> > > > > Given cprfreq-util's normal running frequency is every 10ms, doing
> > > > > this before entering idle is not a big extra burden.
> > > > 
> > > > But this is not related to idle as such, but to the fact that idle
> > > > sometimes stops the scheduler tick which otherwise would run the
> > > > cpufreq governor callback on a regular basis.
> > > > 
> > > > It is stopping the tick that gets us into trouble, so I would avoid
> > > > doing it if the current performance state is too aggressive.
> > > 
> > > I've tried to simulate Doug's environment by using his kconfig, and
> > > offline my 36 CPUs Desktop to leave 12 CPUs online, and on it I can
> > > still see Local timer interrupts when there is no active load, with
> > > the longest interval between 2 timer interrupts is 4 seconds, while
> > > idle class's task_tick_idle() will do nothing, and CFS'
> > > task_tick_fair() will in turn call cfs_rq_util_change()
> > 
> > Every four seconds?  Could you please post your .config?
>  
> Aha, I didn't make it clear, that the timer interrupt was not always
> coming every 4 seconds, but when system is silent, the maxim interval
> between 2 timer interrupts was 4 seconds.
> 
> When initially I checked this, I doubted if the timer interrupt are
> too few on the system, so I used Doug's config and tried to make my
> desktop silent (like disabling GUI), following is some trace_printk
> log, though I figured out later when idle thread is running, the
> idle class' scheduler tick will not help as it doesn't call cpufreq
> callback.
> 
>           <idle>-0       [009] d.h1.   235.980053: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.981054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.982053: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.983053: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.984053: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.985053: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.986054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.987054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.988054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.989054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.990054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.991053: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.992054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.993054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   235.994054: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   236.331126: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   236.460130: hrtimer_interrupt: enter
>           <idle>-0       [009] d.s5.   236.460147: intel_pstate_update_util: old_state=48 new=27
>           <idle>-0       [009] d.h1.   238.380130: hrtimer_interrupt: enter
>           <idle>-0       [009] d.s5.   238.380147: intel_pstate_update_util: old_state=27 new=12
>           <idle>-0       [009] d.h1.   240.331133: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   240.364133: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   244.331135: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   248.331139: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   252.331138: hrtimer_interrupt: enter
>            <...>-1167    [009] d.h..   254.860056: hrtimer_interrupt: enter
>            snapd-1128    [009] d.h..   254.861054: hrtimer_interrupt: enter
>            snapd-1128    [009] d.h..   254.862055: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   254.863056: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   254.864056: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   254.865055: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   256.331133: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   260.331127: hrtimer_interrupt: enter
>           <idle>-0       [009] d.h1.   264.331135: hrtimer_interrupt: enter

Thank you for the clarification!

							Thanx, Paul