RE: About CPU hot-plug stress test failed in cpufreq driver

[Anson Huang <anson.huang@nxp.com>]

Hi, Rafael/Viresh
	We noticed some different behaviors on v5.4 and v4.19, on v4.19, dbs_update_util_handler() looks like ONLY run on the CPU whose frequency needs to be updated (never on the CPU which is being offline), but on v5.4, we found in most cases, dbs_update_util_handler() will be assigned to the CPU being offline, and the cpufreq_this_cpu_can_update() can NOT prevent this scenario, because " policy->dvfs_possible_from_any_cpu " is always TRUE for drivers using -dt driver, and also, policy-cpus ONLY be updated after cpufreq_dbs_governor_stop() finished, that means after irq_work_sync() is called on the CPU being offline, there are still dbs_update_util_handler() assigned to that CPU being offline but NOT power down yet, so the previous irq_work_sync() does NOT make sense enough.
	That will cause an issue window of irq work being queued to the CPU being offline, but maybe that CPU will stop execution at anytime before the irq work is finished, then issue happened.
	Could this behavior caused by something changed in kernel/sched/*.c ?

273 static void dbs_update_util_handler(struct update_util_data *data, u64 time,
274                                     unsigned int flags)
275 {
276         struct cpu_dbs_info *cdbs = container_of(data, struct cpu_dbs_info, update_util);
277         struct policy_dbs_info *policy_dbs = cdbs->policy_dbs;
278         u64 delta_ns, lst;
279
280         if (!cpufreq_this_cpu_can_update(policy_dbs->policy))
281                 return;


Anson

> Subject: Re: About CPU hot-plug stress test failed in cpufreq driver
> 
> On Thu, Dec 5, 2019 at 2:18 PM Anson Huang <anson.huang@nxp.com>
> wrote:
> >
> >
> >
> > > -----Original Message-----
> > > From: Rafael J. Wysocki <rjw@rjwysocki.net>
> > > Sent: Thursday, December 5, 2019 6:48 PM
> > > To: Anson Huang <anson.huang@nxp.com>
> > > Cc: Viresh Kumar <viresh.kumar@linaro.org>; Jacky Bai
> > > <ping.bai@nxp.com>; linux-pm@vger.kernel.org
> > > Subject: Re: About CPU hot-plug stress test failed in cpufreq driver
> > >
> > > On Thursday, December 5, 2019 9:53:20 AM CET Anson Huang wrote:
> > > > Hi, Rafael
> > > >     This issue is very weird, the irq_work used in
> > > > cpufreq_governor.c is
> > > very
> > > >     simple, ONLY one entry to claim the irq_work, and
> > > cpufreq_governor's irq_work
> > > >     is a private irq_work structure, no other drivers use it. I
> > > > added some
> > > trace
> > > >     event in cpufreq_governor.c and irq_work.c, every time, the
> > > > issue
> > > happened at
> > > >     the point of CPU1/2/3 all off, and CPU1 start ON line, but
> > > > when CPU1
> > > tried to
> > > >     sync the irq_work in cpufreq_dbs_governor_stop(), the irq_work
> > > shows that
> > > >     previous work is pending on CPU3 which is offline, I also had
> > > > the
> > > trace event
> > > >     in irq_work_claim(),  but no any log shows the
> > > > cpufreq_governor
> > > irq_work is
> > > >     claimed on CPU3 after CPU3 offline, below is the debug patch I
> > > > added
> > > and the
> > > >     log on 2 consoles:
> > > >     If I understand it correctly, the irq work used in
> > > > cpufreq_governor
> > > ONLY has
> > > >     one entry of calling irq_work_queue() which will be ONLY
> > > > claimed on
> > > the CPU
> > > >     calling the irq_work_queue(), but from trace result, I have
> > > > NOT see
> > > where
> > > >     CPU3 could call irq_work_queue() after it finishes the irq
> > > > work sync
> > > before
> > > >     offline.
> > >
> > > Right.
> > >
> > > Which means that this particular irq_work only runs on the CPU that
> > > has run
> > > irq_work_queue() for it.
> > >
> > > >     Could it something wrong related to cache maintain during CPU
> > > hotplug?
> > >
> > > I'm not sure what is going on, but I do agree that it is weird
> > > enough. :-)
> > >
> > > [cut]
> > >
> > > > LOG on console 1 which does CPU1/2/3 offline and online stress test:
> > > > CPUHotplug: 4575 times remaining
> > > > [ 1047.401185] CPU1: shutdown
> > > > [ 1047.403917] psci: CPU1 killed.
> > > > [ 1047.449153] CPU2: shutdown
> > > > [ 1047.451880] psci: CPU2 killed.
> > > > [ 1047.501131] CPU3: shutdown
> > > > [ 1047.503857] psci: CPU3 killed.
> > > > [ 1048.541939] Detected VIPT I-cache on CPU1 [ 1048.541983] GICv3:
> > > > CPU1: found redistributor 1 region 0:0x0000000051b20000 [
> > > > 1048.542050]
> > > > CPU1: Booted secondary processor 0x0000000001 [0x410fd042] [
> > > > 1048.585024] Detected VIPT I-cache on CPU2 [ 1048.585061] GICv3:
> CPU2:
> > > > found redistributor 2 region 0:0x0000000051b40000 [ 1048.585121]
> CPU2:
> > > > Booted secondary processor 0x0000000002 [0x410fd042] [
> > > > 1048.645070] Detected VIPT I-cache on CPU3 [ 1048.645112] GICv3:
> > > > CPU3: found redistributor 3 region 0:0x0000000051b60000
> [ 1048.645181] CPU3:
> > > > Booted secondary processor 0x0000000003 [0x410fd042]
> > > > CPUHotplug: 4574 times remaining
> > > > [ 1049.769187] CPU1: shutdown
> > > > [ 1049.771913] psci: CPU1 killed.
> > > > [ 1049.809126] CPU2: shutdown
> > > > [ 1049.811856] psci: CPU2 killed.
> > > > [ 1049.853135] CPU3: shutdown
> > > > [ 1049.855868] psci: CPU3 killed.
> > > >
> > > > Waiting here forever.....
> > > >
> > > > LOG on console 2 which enables the trace events I added upper:
> > > >              sed-4591  [003] d..4  1049.705561: cpu_frequency_irq_claim:
> > > cpu_id=3, flag=3
> > > >              sed-4591  [003] dNh1  1049.705604:
> > > > cpu_frequency_irq_run_list: cpu_id=3, flag=0
> > >
> > > So here CPU3 runs an IRQ work, presumably the cpufreq governor's one.
> > >
> > > After that its raised_list should be empty and it doesn't claim any
> > > IRQ works going forward.
> > >
> > > >           <idle>-0     [001] d.s2  1049.716308: cpu_frequency_irq_work:
> > > cpu_id=1, cpu=-1
> > > >           <idle>-0     [001] d.s2  1049.716319: cpu_frequency_irq_claim:
> > > cpu_id=1, flag=3
> > > >           <idle>-0     [001] dNH2  1049.716338: cpu_frequency_irq_run_list:
> > > cpu_id=1, flag=0
> > >
> > > And now CPU1 runs the cpufreq governor IRQ work, so it sets
> > > work->cpu to 1 and then to -1 (when flushing raised_list).
> > >
> > > >           <idle>-0     [002] d.s2  1049.728303: cpu_frequency_irq_work:
> > > cpu_id=2, cpu=-1
> > > >           <idle>-0     [002] d.s2  1049.728307: cpu_frequency_irq_claim:
> > > cpu_id=2, flag=3
> > > >           <idle>-0     [002] dNH2  1049.728320: cpu_frequency_irq_run_list:
> > > cpu_id=2, flag=0
> > > >           <idle>-0     [001] d.s2  1049.740305: cpu_frequency_irq_work:
> > > cpu_id=1, cpu=-1
> > > >           <idle>-0     [001] d.s2  1049.740307: cpu_frequency_irq_claim:
> > > cpu_id=1, flag=3
> > > >           <idle>-0     [001] dNH2  1049.740319: cpu_frequency_irq_run_list:
> > > cpu_id=1, flag=0
> > > >           <idle>-0     [001] d.s2  1049.752305: cpu_frequency_irq_work:
> > > cpu_id=1, cpu=-1
> > > >           <idle>-0     [001] d.s2  1049.752307: cpu_frequency_irq_claim:
> > > cpu_id=1, flag=3
> > > >           <idle>-0     [001] dNH2  1049.752316: cpu_frequency_irq_run_list:
> > > cpu_id=1, flag=0
> > > >          cpuhp/1-13    [001] ....  1049.768340:
> cpu_frequency_irq_work_sync:
> > > cpu_id=1, cpu=-1, flag=0
> > > >          cpuhp/1-13    [001] d..4  1049.768681: cpu_frequency_irq_work:
> > > cpu_id=1, cpu=-1
> > > >          cpuhp/1-13    [001] d..4  1049.768683: cpu_frequency_irq_claim:
> > > cpu_id=1, flag=3
> > > >          cpuhp/1-13    [001] dNh1  1049.768698:
> cpu_frequency_irq_run_list:
> > > cpu_id=1, flag=0
> > > >      smp_test.sh-734   [000] ...1  1049.771903: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=7
> > > >      smp_test.sh-734   [000] dNh1  1049.775009:
> cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=4
> > > >      smp_test.sh-734   [000] ...1  1049.776084: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=7
> > > >      smp_test.sh-734   [000] dNh.  1049.776392:
> cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=4
> > > >      smp_test.sh-734   [000] d..2  1049.779093: cpu_frequency_irq_work:
> > > cpu_id=0, cpu=-1
> > > >      smp_test.sh-734   [000] d..2  1049.779103: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=3
> > > >           <idle>-0     [000] dNh2  1049.779162: cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=0
> > > >           <idle>-0     [000] d.s2  1049.792305: cpu_frequency_irq_work:
> > > cpu_id=0, cpu=-1
> > > >           <idle>-0     [000] d.s2  1049.792315: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=3
> > > >           <idle>-0     [000] dNH2  1049.792329: cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=0
> > > >          cpuhp/2-18    [002] ....  1049.808315:
> cpu_frequency_irq_work_sync:
> > > cpu_id=2, cpu=-1, flag=0
> > > >          cpuhp/2-18    [002] d..4  1049.808642: cpu_frequency_irq_work:
> > > cpu_id=2, cpu=-1
> > > >          cpuhp/2-18    [002] d..4  1049.808645: cpu_frequency_irq_claim:
> > > cpu_id=2, flag=3
> > > >          cpuhp/2-18    [002] dNh1  1049.808658:
> cpu_frequency_irq_run_list:
> > > cpu_id=2, flag=0
> > > >      smp_test.sh-734   [000] ...1  1049.811848: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=7
> > > >      smp_test.sh-734   [000] dNh1  1049.814949:
> cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=4
> > > >      smp_test.sh-734   [000] ...1  1049.815988: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=7
> > > >      smp_test.sh-734   [000] dNh1  1049.816321:
> cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=4
> > > >      smp_test.sh-734   [000] d..3  1049.818936: cpu_frequency_irq_work:
> > > cpu_id=0, cpu=-1
> > > >      smp_test.sh-734   [000] d..3  1049.818946: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=3
> > > >      smp_test.sh-734   [000] dNh2  1049.818973:
> cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=0
> > > >           <idle>-0     [000] d.s4  1049.832308: cpu_frequency_irq_work:
> > > cpu_id=0, cpu=-1
> > > >           <idle>-0     [000] d.s4  1049.832317: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=3
> > > >           <idle>-0     [000] dNH3  1049.832332: cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=0
> > > >          cpuhp/3-23    [003] ....  1049.852314:
> cpu_frequency_irq_work_sync:
> > > cpu_id=3, cpu=-1, flag=0
> > > >
> > > > [Anson] when CPU3 offline, the irq work sync is successfully, no
> > > > irq work pending any more;
> > > >
> > > >      smp_test.sh-734   [000] ...1  1049.855859: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=7
> > > >      smp_test.sh-734   [000] dNh1  1049.858958:
> cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=4
> > > >      smp_test.sh-734   [000] ...1  1049.859990: cpu_frequency_irq_claim:
> > > cpu_id=0, flag=7
> > > >      smp_test.sh-734   [000] dNh.  1049.860346:
> cpu_frequency_irq_run_list:
> > > cpu_id=0, flag=4
> > > >           <idle>-0     [001] d.h1  1050.896329: cpu_frequency_irq_run_list:
> > > cpu_id=1, flag=4
> > > >          cpuhp/1-13    [001] ....  1050.916319:
> cpu_frequency_irq_work_sync:
> > > cpu_id=1, cpu=3, flag=3
> > > >
> > > > [Anson] we can see when CPU1 start online and tried to sync irq
> > > > work, found it is pending on CPU3 which is offline, and in this
> > > > period, no irq work claimed by cpufreq_governor,
> > >
> > > So I'm wondering how it is possible at all that work->cpu value is 3
> > > at this point.
> > >
> > > The last CPU that wrote to work->cpu was CPU0 and the written value
> > > was -1, and
> > > CPU3 saw that value when it was running irq_work_sync().
> > >
> > > There is no sane way by which work->cpu can be equal to 3 from
> > > CPU1's perspective, because the last value written to it by CPU1
> > > itself was -1 and the last value written to it by any other CPU also was -1.
> > >
> > > Moreover, after CPU3 had updated it last time (and the last value
> > > written to it by CPU3 had been -1), other CPUs, *including* CPU1,
> > > updated it too (and that for multiple times).
> > >
> > > So the only theory that can explain why CPU1 sees 3 in there when it
> > > is going online appears to be some silent memory corruption.
> > >
> > > That said, have you tried to make the READ_ONCE() change suggested a
> > > while ago?
> >
> > Below patch does NOT work using READ_ONCE() if I did the change
> correctly:
> 
> OK
> 
> > @@ -212,7 +208,7 @@ void irq_work_sync(struct irq_work *work)  {
> >         lockdep_assert_irqs_enabled();
> >
> > -       while (work->flags & IRQ_WORK_BUSY)
> > +       while (READ_ONCE(work->flags) & IRQ_WORK_BUSY)
> 
> You also may try using test_bit() instead of the raw read, but anyway at this
> point I would start talking to the arch/HW people if I were you.
> 
> >                 cpu_relax();
> >  }
> >
> > LOG:
> > CPUHotplug: 4937 times remaining
> > [  214.837047] CPU1: shutdown
> > [  214.839781] psci: CPU1 killed.
> > [  214.877041] CPU2: shutdown
> > [  214.879767] psci: CPU2 killed.
> > [  214.917026] CPU3: shutdown
> > [  214.919758] psci: CPU3 killed.
> > [  215.957816] Detected VIPT I-cache on CPU1 [  215.957860] GICv3:
> > CPU1: found redistributor 1 region 0:0x0000000051b20000 [  215.957930]
> > CPU1: Booted secondary processor 0x0000000001 [0x410fd042] [
> > 216.001025] Detected VIPT I-cache on CPU2 [  216.001064] GICv3: CPU2:
> > found redistributor 2 region 0:0x0000000051b40000 [  216.001126] CPU2:
> > Booted secondary processor 0x0000000002 [0x410fd042] [  216.068960]
> > Detected VIPT I-cache on CPU3 [  216.069004] GICv3: CPU3: found
> > redistributor 3 region 0:0x0000000051b60000 [  216.069076] CPU3:
> > Booted secondary processor 0x0000000003 [0x410fd042]
> > CPUHotplug: 4936 times remaining
> > [  217.201055] CPU1: shutdown
> > [  217.203779] psci: CPU1 killed.
> > [  400.506869] audit: type=1006 audit(1573738201.312:3): pid=1332
> > uid=0 old-aui1 [ 4000.600430] audit: type=1006
> > audit(1573741801.408:4): pid=1352 uid=0 old-aui1 [ 7600.687496] audit:
> > type=1006 audit(1573745401.492:5): pid=1371 uid=0 old-aui1
> >
> >
> >          cpuhp/1-13    [001] ....   217.200231: cpu_frequency_irq_work_sync:
> cpu_id=1, cpu=-1, flag=0
> >      smp_test.sh-741   [002] ...1   217.203770: cpu_frequency_irq_claim:
> cpu_id=2, flag=7
> >      smp_test.sh-741   [002] d.h1   217.206873: cpu_frequency_irq_run_list:
> cpu_id=2, flag=4
> >      smp_test.sh-741   [002] ...1   217.206893: cpu_frequency_irq_claim:
> cpu_id=2, flag=7
> >      smp_test.sh-741   [002] dNh.   217.208222: cpu_frequency_irq_run_list:
> cpu_id=2, flag=4
> >          cpuhp/2-18    [002] ....   217.248206: cpu_frequency_irq_work_sync:
> cpu_id=2, cpu=1, flag=3
> >
> > [Anson] this time, the irq work is pending on CPU1 which is offline.
> >
> >          kauditd-31    [000] ...1   400.519304: cpu_frequency_irq_claim:
> cpu_id=0, flag=7
> >           <idle>-0     [000] dNh1   400.520231: cpu_frequency_irq_run_list:
> cpu_id=0, flag=4
> >          kauditd-31    [003] ...1  4000.612845: cpu_frequency_irq_claim:
> cpu_id=3, flag=7
> >            crond-1352  [003] d.h.  4000.616221: cpu_frequency_irq_run_list:
> cpu_id=3, flag=4
> >          kauditd-31    [000] ...1  7600.699988: cpu_frequency_irq_claim:
> cpu_id=0, flag=7
> >           <idle>-0     [000] dNh1  7600.700205: cpu_frequency_irq_run_list:
> cpu_id=0, flag=4
> > root@imx8qxpmek:~#
> >
> >