Re: [RFC PATCH] arm64: defconfig: Disable fine-grained task level IRQ time accounting

[Kurt Kanzenbach]

On Thu Jul 30 2020, Vladimir Oltean wrote:
> On Thu, Jul 30, 2020 at 09:23:44AM +0200, Kurt Kanzenbach wrote:
>> On Wed Jul 29 2020, Vladimir Oltean wrote:
>> > For more context, here is my original report of the issue:
>> > https://lkml.org/lkml/2020/6/4/1062
>> >
>> > Just like you, I could not reproduce the RCU stalls and system hang on a
>> > 5.6-rt kernel, just on mainline and derivatives, using the plain
>> > defconfig.
>> >
>> > The issue is not specific to Layerscape or i.MX8, but rather I was able
>> > to see the same behavior on Marvell Armada 37xx as well as Qualcomm
>> > MSM8976.
>> >
>> > So, while of course I agree that disabling IRQ time accounting for arm64
>> > isn't a real solution, it isn't by far an exaggerated proposal either.
>> > Nonetheless, the patch is just a RFC and should be treated as such. We
>> > are at a loss when it comes to debugging this any further and we would
>> > appreciate some pointers.
>> 
>> Yeah, sure. I'll try to reproduce this issue first. So it triggers with:
>> 
>>  * arm64
>>  * mainline, not -rt kernel
>>  * opened serial console
>>  * irq accounting enabled
>> 
>> Anything else?
>> 
>> Thanks,
>> Kurt
>
> Thanks for giving a helping hand, Kurt. The defconfig should be enough.
> In the interest of full disclosure, the only arm64 device on which we
> didn't reproduce this was the 16-core LX2160A. But we did reproduce on
> that with maxcpus=1 though. And also on msm8976 with all 8 cores booted.
> Just mentioning this in case you're testing on a 16-core system, you
> might want to reduce the number a bit.

OK. I've reproduced it on a Marvell Armada SoC with v5.6 mainline. See
splats below. Running with irq time accounting enabled, kills the
machine immediately. However, I'm not getting the possible deadlock
warnings in 8250 as you did. So that might be unrelated.

Unfortunately I have no idea what to debug here.

Thanks,
Kurt

Splats:

|root@marvell ~ # [  150.996487] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
|[  150.999764]  (detected by 0, t=2602 jiffies, g=9697, q=24)
|[  151.005403] rcu: All QSes seen, last rcu_sched kthread activity 2602 (4294952389-4294949787), jiffies_till_next_fqs=1, root ->qsmask 0x0
|[  151.018034] stress-ng-hrtim R  running task        0  2251   2248 0x00000001
|[  151.025290] Call trace:
|[  151.027808]  dump_backtrace+0x0/0x198
|[  151.031563]  show_stack+0x1c/0x28
|[  151.034971]  sched_show_task+0x224/0x248
|[  151.039002]  rcu_sched_clock_irq+0x7c4/0x840
|[  151.043392]  update_process_times+0x34/0x70
|[  151.047694]  tick_sched_handle.isra.0+0x34/0x70
|[  151.052350]  tick_sched_timer+0x50/0xa0
|[  151.056295]  __hrtimer_run_queues+0x18c/0x5b0
|[  151.060773]  hrtimer_interrupt+0xec/0x248
|[  151.064896]  arch_timer_handler_phys+0x38/0x48
|[  151.069465]  handle_percpu_devid_irq+0xd0/0x3c8
|[  151.074124]  generic_handle_irq+0x2c/0x40
|[  151.078246]  __handle_domain_irq+0x68/0xc0
|[  151.082456]  gic_handle_irq+0x64/0x150
|[  151.086308]  el1_irq+0xbc/0x140
|[  151.089536]  lock_acquire+0xdc/0x250
|[  151.093210]  __might_fault+0x68/0x88
|[  151.096880]  setup_rt_frame+0x2a4/0xee8
|[  151.100823]  do_notify_resume+0x3b0/0x488
|[  151.104945]  work_pending+0x8/0x14
|[  151.108443] rcu: rcu_sched kthread starved for 2613 jiffies! g9697 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=1
|[  151.118741] rcu: RCU grace-period kthread stack dump:
|[  151.123939] rcu_sched       R  running task        0    10      2 0x00000028
|[  151.131196] Call trace:
|[  151.133707]  __switch_to+0x104/0x170
|[  151.137384]  __schedule+0x36c/0x860
|[  151.140966]  schedule+0x7c/0x108
|[  151.144280]  schedule_timeout+0x204/0x4c0
|[  151.148403]  rcu_gp_kthread+0x5b0/0x1798
|[  151.152435]  kthread+0x110/0x140
|[  151.155749]  ret_from_fork+0x10/0x18
|[  181.665482] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 55s!
|[  181.671022] BUG: workqueue lockup - pool cpus=1 node=0 flags=0x0 nice=0 stuck for 56s!
|[  181.679198] BUG: workqueue lockup - pool cpus=0-1 flags=0x4 nice=0 stuck for 56s!
|[  181.686902] Showing busy workqueues and worker pools:
|[  181.692059] workqueue events: flags=0x0
|[  181.696226]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=2/256 refcnt=3
|[  181.703039]     pending: dbs_work_handler, mv88e6xxx_ptp_overflow_check
|[  181.709826]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=2/256 refcnt=3
|[  181.716783]     pending: vmstat_shepherd, switchdev_deferred_process_work
|[  181.723804] workqueue events_unbound: flags=0x2
|[  181.728526]   pwq 4: cpus=0-1 flags=0x4 nice=0 active=1/512 refcnt=3
|[  181.735029]     pending: flush_to_ldisc
|[  181.738947] workqueue events_freezable: flags=0x4
|[  181.743755]   pwq 2: cpus=1 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
|[  181.750741]     pending: mmc_rescan
|[  181.754359] workqueue events_power_efficient: flags=0x82
|[  181.759825]   pwq 4: cpus=0-1 flags=0x4 nice=0 active=5/256 refcnt=7
|[  181.766329]     pending: gc_worker, neigh_periodic_work, neigh_periodic_work, do_cache_clean, check_lifetime
|[  181.776488] workqueue mm_percpu_wq: flags=0x8
|[  181.780942]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
|[  181.787924]     pending: vmstat_update
|[  181.791808] workqueue pm: flags=0x4
|[  181.795368]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
|[  181.802349]     pending: pm_runtime_work
|[  181.806412] workqueue writeback: flags=0x4a
|[  181.810686]   pwq 4: cpus=0-1 flags=0x4 nice=0 active=1/256 refcnt=3
|[  181.817224]     pending: wb_workfn
|[  181.820756] workqueue ipv6_addrconf: flags=0x40008
|[  181.825684]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/1 refcnt=2
|[  181.832456]     pending: addrconf_verify_work
|[  181.836968] workqueue nfsd4: flags=0x2
|[  181.840794]   pwq 4: cpus=0-1 flags=0x4 nice=0 active=1/256 refcnt=3
|[  181.847329]     pending: laundromat_main
|[  229.043792] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
|[  229.047053]  (detected by 0, t=10407 jiffies, g=9697, q=29)
|[  229.052785] rcu: All QSes seen, last rcu_sched kthread activity 10407 (4294960194-4294949787), jiffies_till_next_fqs=1, root ->qsmask 0x0
|[  229.065505] stress-ng-hrtim R  running task        0  2251   2248 0x00000001
|[  229.072763] Call trace:
|[  229.075276]  dump_backtrace+0x0/0x198
|[  229.079037]  show_stack+0x1c/0x28
|[  229.082443]  sched_show_task+0x224/0x248
|[  229.086476]  rcu_sched_clock_irq+0x7c4/0x840
|[  229.090866]  update_process_times+0x34/0x70
|[  229.095165]  tick_sched_handle.isra.0+0x34/0x70
|[  229.099824]  tick_sched_timer+0x50/0xa0
|[  229.103767]  __hrtimer_run_queues+0x18c/0x5b0
|[  229.108246]  hrtimer_interrupt+0xec/0x248
|[  229.112368]  arch_timer_handler_phys+0x38/0x48
|[  229.116938]  handle_percpu_devid_irq+0xd0/0x3c8
|[  229.121597]  generic_handle_irq+0x2c/0x40
|[  229.125718]  __handle_domain_irq+0x68/0xc0
|[  229.129930]  gic_handle_irq+0x64/0x150
|[  229.133781]  el1_irq+0xbc/0x140
|[  229.137008]  lock_acquire+0xdc/0x250
|[  229.140682]  __might_fault+0x68/0x88
|[  229.144354]  preserve_fpsimd_context+0x160/0x2f8
|[  229.149101]  setup_rt_frame+0x48c/0xee8
|[  229.153044]  do_notify_resume+0x3b0/0x488
|[  229.157167]  work_pending+0x8/0x14
|[  229.160666] rcu: rcu_sched kthread starved for 10418 jiffies! g9697 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=1
|[  229.171053] rcu: RCU grace-period kthread stack dump:
|[  229.176250] rcu_sched       R  running task        0    10      2 0x00000028
|[  229.183506] Call trace:
|[  229.186019]  __switch_to+0x104/0x170
|[  229.189697]  __schedule+0x36c/0x860
|[  229.193277]  schedule+0x7c/0x108
|[  229.196592]  schedule_timeout+0x204/0x4c0
|[  229.200714]  rcu_gp_kthread+0x5b0/0x1798
|[  229.204747]  kthread+0x110/0x140
|[  229.208061]  ret_from_fork+0x10/0x18

Attachment: signature.asc
Description: PGP signature