mbox series

[00/11] arm64: entry lockdep/rcu/tracing fixes

Message ID 20201126123602.23454-1-mark.rutland@arm.com (mailing list archive)
Headers show
Series arm64: entry lockdep/rcu/tracing fixes | expand

Message

Mark Rutland Nov. 26, 2020, 12:35 p.m. UTC 
Hi,

Dmitry and Marco both reported some weirdness with lockdep on arm64 erroneously
reporting the hardware IRQ state, and inexplicable RCU stalls:

  https://lore.kernel.org/r/CACT4Y+aAzoJ48Mh1wNYD17pJqyEcDnrxGfApir=-j171TnQXhw@mail.gmail.com
  https://lore.kernel.org/r/20201119193819.GA2601289@elver.google.com

Having investigated, I believe that this is largely down to the arm64 entry
code not correctly managing RCU, lockdep, irq flag tracing, and context
tracking. This series attempts to fix those cases, and I've Cc'd folk from the
previous threads as a heads-up.

Today, the arm64 entry code:

* Doesn't correctly save/restore the lockdep/tracing view of the HW IRQ
  state, leaving this inconsistent.

* Doesn't correctly wake/sleep RCU arounds its use (e.g. by the IRQ tracing
  functions).

* Calls the context tracking functions (which wake and sleep RCU) at the wrong
  point w.r.t. lockdep, tracing.

Fixing all this requires reworking the entry/exit sequences along the lines of
the generic/x86 entry code. Moving arm64 over to the generic entry code
requires signficant changes to both arm64 and the generic code, so for now I've
added arm64-specific helpers to achieve the same thing. There's a lot of
cleanup we could do here as a follow-up, but for now I've tried to do the bare
minimum to make things work as expected without making it unmaintainable.

The patches are based on v5.10-rc3, and I've pushed them out to my
arm64/entry-fixes branch on kernel.org:

  git://git.kernel.org/pub/scm/linux/kernel/git/mark/linux.git arm64/entry-fixes

Marco was able to test a WIP version of this, which seemed to address the
issues he was seeing. Since then I've had to alter the debug exception
handling, but I'm not expecting problems there. In future we'll want to make
more changes to the debug cases to align with x86, handling single-step,
watchpoints, and breakpoints as NMIs, but this will require significant
refactoring of the way we handle BRKs. For now I don't believe that there's a
major problem in practice with the approach taken in this series.

This version has seen an overnight soak under Syzkaller, where all the reports
I have so far look sound. I have been testing with additional debug patches:
  
  git://git.kernel.org/pub/scm/linux/kernel/git/mark/linux.git arm64/entry-fixes

... which I do not think we should merge now, but intent to respin in future
with all the other cleanup.

While investigating this Peter and I spotted a latent issue in the core idle
code, for which peter has a patch queued in the tip locking/urgent branch:

  https://lore.kernel.org/r/20201120114925.594122626@infradead.org

... which the second patch in this series refers to.

Thanks,
Mark.

Mark Rutland (11):
  arm64: syscall: exit userspace before unmasking exceptions
  arm64: mark idle code as noinstr
  arm64: entry: mark entry code as noinstr
  arm64: entry: move enter_from_user_mode to entry-common.c
  arm64: entry: prepare ret_to_user for function call
  arm64: entry: move el1 irq/nmi logic to C
  arm64: entry: fix non-NMI user<->kernel transitions
  arm64: ptrace: prepare for EL1 irq/rcu tracking
  arm64: entry: fix non-NMI kernel<->kernel transitions
  arm64: entry: fix NMI {user,kernel}->kernel transitions
  arm64: entry: fix EL1 debug transitions

 arch/arm64/include/asm/daifflags.h |   3 +
 arch/arm64/include/asm/exception.h |   5 +
 arch/arm64/include/asm/ptrace.h    |   7 ++
 arch/arm64/kernel/entry-common.c   | 246 +++++++++++++++++++++++++++----------
 arch/arm64/kernel/entry.S          |  78 ++++--------
 arch/arm64/kernel/irq.c            |  15 ---
 arch/arm64/kernel/process.c        |   8 +-
 arch/arm64/kernel/sdei.c           |   7 +-
 arch/arm64/kernel/syscall.c        |   1 -
 arch/arm64/kernel/traps.c          |  22 ++--
 arch/arm64/mm/fault.c              |  25 ----
 11 files changed, 237 insertions(+), 180 deletions(-)

Comments

Will Deacon Nov. 30, 2020, 11:23 a.m. UTC | #1 
Hi Mark,

Thanks for doing this.

On Thu, Nov 26, 2020 at 12:35:51PM +0000, Mark Rutland wrote:
> Dmitry and Marco both reported some weirdness with lockdep on arm64 erroneously
> reporting the hardware IRQ state, and inexplicable RCU stalls:
> 
>   https://lore.kernel.org/r/CACT4Y+aAzoJ48Mh1wNYD17pJqyEcDnrxGfApir=-j171TnQXhw@mail.gmail.com
>   https://lore.kernel.org/r/20201119193819.GA2601289@elver.google.com
> 
> Having investigated, I believe that this is largely down to the arm64 entry
> code not correctly managing RCU, lockdep, irq flag tracing, and context
> tracking. This series attempts to fix those cases, and I've Cc'd folk from the
> previous threads as a heads-up.

I've left some _minor_ comments on a few of the patches, and there was a
build failure in the SDEI code, as you know.

Please can you spin a quick v2 so that I can get this into linux-next
ASAP?

Cheers,

Will
Marco Elver Nov. 30, 2020, 12:03 p.m. UTC | #2 
[ FYI, this series was not Cc'd to LKML. ]

On Thu, Nov 26, 2020 at 12:35PM +0000, Mark Rutland wrote:
> Hi,
> 
> Dmitry and Marco both reported some weirdness with lockdep on arm64 erroneously
> reporting the hardware IRQ state, and inexplicable RCU stalls:
> 
>   https://lore.kernel.org/r/CACT4Y+aAzoJ48Mh1wNYD17pJqyEcDnrxGfApir=-j171TnQXhw@mail.gmail.com
>   https://lore.kernel.org/r/20201119193819.GA2601289@elver.google.com
> 
> Having investigated, I believe that this is largely down to the arm64 entry
> code not correctly managing RCU, lockdep, irq flag tracing, and context
> tracking. This series attempts to fix those cases, and I've Cc'd folk from the
> previous threads as a heads-up.
> 
> Today, the arm64 entry code:
> 
> * Doesn't correctly save/restore the lockdep/tracing view of the HW IRQ
>   state, leaving this inconsistent.
> 
> * Doesn't correctly wake/sleep RCU arounds its use (e.g. by the IRQ tracing
>   functions).
> 
> * Calls the context tracking functions (which wake and sleep RCU) at the wrong
>   point w.r.t. lockdep, tracing.
> 
> Fixing all this requires reworking the entry/exit sequences along the lines of
> the generic/x86 entry code. Moving arm64 over to the generic entry code
> requires signficant changes to both arm64 and the generic code, so for now I've
> added arm64-specific helpers to achieve the same thing. There's a lot of
> cleanup we could do here as a follow-up, but for now I've tried to do the bare
> minimum to make things work as expected without making it unmaintainable.
> 
> The patches are based on v5.10-rc3, and I've pushed them out to my
> arm64/entry-fixes branch on kernel.org:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/mark/linux.git arm64/entry-fixes
> 
> Marco was able to test a WIP version of this, which seemed to address the
> issues he was seeing. Since then I've had to alter the debug exception
> handling, but I'm not expecting problems there. In future we'll want to make
> more changes to the debug cases to align with x86, handling single-step,
> watchpoints, and breakpoints as NMIs, but this will require significant
> refactoring of the way we handle BRKs. For now I don't believe that there's a
> major problem in practice with the approach taken in this series.
> 
> This version has seen an overnight soak under Syzkaller, where all the reports
> I have so far look sound. I have been testing with additional debug patches:
>   
>   git://git.kernel.org/pub/scm/linux/kernel/git/mark/linux.git arm64/entry-fixes
> 
> ... which I do not think we should merge now, but intent to respin in future
> with all the other cleanup.

So, I was hoping that this would fix all the problems I was seeing when
running the ftrace tests ... unfortunately, it didn't. :-( Perhaps the
WIP version you had only worked because it ended up disabling lockdep
early?

I've attached the log and the symbolized report.

Thanks,
-- Marco
Testing all events: OK
Running tests again, along with the function tracer
Running tests on all trace events:
Testing all events: 
hrtimer: interrupt took 10487664 ns
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 13s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
    in-flight: 7:do_cache_clean
pool 2: cpus=0 flags=0x4 nice=0 hung=0s workers=3 idle: 61 99
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 24s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 11s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
    pending: neigh_periodic_work
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 17s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
    in-flight: 7:neigh_periodic_work
pool 2: cpus=0 flags=0x4 nice=0 hung=9s workers=3 idle: 61 99
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x5 nice=0 active=2/256 refcnt=4
    in-flight: 7:do_cache_clean
    pending: neigh_periodic_work
pool 2: cpus=0 flags=0x5 nice=0 hung=8s workers=2 manager: 61
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 16s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
    in-flight: 106:do_cache_clean
pool 2: cpus=0 flags=0x4 nice=0 hung=8s workers=3 idle: 61 7
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
BUG: workqueue lockup - pool cpus=0 flags=0x4 nice=0 stuck for 10s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x4 nice=0 active=3/256 refcnt=5
    in-flight: 106:check_lifetime
    pending: neigh_periodic_work, do_cache_clean
pool 2: cpus=0 flags=0x4 nice=0 hung=10s workers=3 idle: 61 7
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 15s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
pool 2: cpus=0 flags=0x5 nice=0 hung=6s workers=3 manager: 7 idle: 106 61
BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 12s!
BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 12s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    pending: vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x5 nice=0 active=1/256 refcnt=3
    pending: neigh_periodic_work
pool 2: cpus=0 flags=0x5 nice=0 hung=12s workers=3 manager: 7 idle: 106 61
BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 25s!
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
  pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
    in-flight: 15:vmstat_shepherd
workqueue events_power_efficient: flags=0x82
  pwq 2: cpus=0 flags=0x5 nice=0 active=3/256 refcnt=5
    pending: neigh_periodic_work, do_cache_clean, check_lifetime
pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=2s workers=2 idle: 5
pool 2: cpus=0 flags=0x5 nice=0 hung=26s workers=4 manager: 7 idle: 107 106 61
rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
	(detected by 0, t=3752 jiffies, g=2329, q=2)
rcu: All QSes seen, last rcu_preempt kthread activity 3503 (4295192252-4295188749), jiffies_till_next_fqs=1, root ->qsmask 0x0
rcu: rcu_preempt kthread starved for 3503 jiffies! g2329 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=0
rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
rcu: RCU grace-period kthread stack dump:
task:rcu_preempt     state:R  running task     stack:    0 pid:   10 ppid:     2 flags:0x00000428
Call trace:
 __switch_to+0x148/0x1f0 arch/arm64/kernel/process.c:577
 context_switch kernel/sched/core.c:4269 [inline]
 __schedule+0x2dc/0x9a0 kernel/sched/core.c:5019
 preempt_schedule_notrace+0x70/0x1c0 kernel/sched/core.c:5252
 __ftrace_ops_list_func kernel/trace/ftrace.c:6955 [inline]
 ftrace_ops_list_func+0x10c/0x218 kernel/trace/ftrace.c:6976
 ftrace_graph_call+0x0/0x4
 preempt_count_add+0x8/0x1a0 arch/arm64/include/asm/atomic.h:65
 schedule+0x44/0x100 kernel/sched/core.c:5097
 schedule_timeout+0x240/0x538 kernel/time/timer.c:1871
 rcu_gp_fqs_loop kernel/rcu/tree.c:1946 [inline]
 rcu_gp_kthread+0x618/0x1bd8 kernel/rcu/tree.c:2119
 kthread+0x13c/0x188 kernel/kthread.c:292
 ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
rcu: Stack dump where RCU GP kthread last ran:
Task dump for CPU 0:
task:event_benchmark state:R  running task     stack:    0 pid:  105 ppid:     2 flags:0x0000042a
Call trace:
 dump_backtrace+0x0/0x240 arch/arm64/kernel/stacktrace.c:100
 show_stack+0x34/0x88 arch/arm64/kernel/stacktrace.c:196
 sched_show_task kernel/sched/core.c:6948 [inline]
 sched_show_task+0x208/0x230 kernel/sched/core.c:6922
 dump_cpu_task+0x4c/0x5c kernel/sched/core.c:8986
 rcu_check_gp_kthread_starvation+0x240/0x388 kernel/rcu/tree_stall.h:480
 print_other_cpu_stall kernel/rcu/tree_stall.h:551 [inline]
 check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
 rcu_pending kernel/rcu/tree.c:3760 [inline]
 rcu_sched_clock_irq+0xc2c/0xd40 kernel/rcu/tree.c:2587
 update_process_times+0x6c/0xb8 kernel/time/timer.c:1709
 tick_sched_handle.isra.0+0x58/0x88 kernel/time/tick-sched.c:176
 tick_sched_timer+0x68/0xe0 kernel/time/tick-sched.c:1328
 __run_hrtimer kernel/time/hrtimer.c:1519 [inline]
 __hrtimer_run_queues+0x288/0x730 kernel/time/hrtimer.c:1583
 hrtimer_interrupt+0x114/0x288 kernel/time/hrtimer.c:1645
 timer_handler drivers/clocksource/arm_arch_timer.c:647 [inline]
 arch_timer_handler_virt+0x50/0x70 drivers/clocksource/arm_arch_timer.c:658
 handle_percpu_devid_irq+0x104/0x4c0 kernel/irq/chip.c:930
 generic_handle_irq_desc include/linux/irqdesc.h:152 [inline]
 generic_handle_irq+0x54/0x78 kernel/irq/irqdesc.c:650
 __handle_domain_irq+0xac/0x130 kernel/irq/irqdesc.c:687
 handle_domain_irq include/linux/irqdesc.h:170 [inline]
 gic_handle_irq+0x70/0x108 drivers/irqchip/irq-gic.c:370
 el1_irq+0xc4/0x180 arch/arm64/kernel/entry.S:640
 arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
 __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
 _raw_spin_unlock_irq+0x50/0x98 kernel/locking/spinlock.c:199
 finish_lock_switch kernel/sched/core.c:4047 [inline]
 finish_task_switch+0xb4/0x398 kernel/sched/core.c:4147
 context_switch kernel/sched/core.c:4272 [inline]
 __schedule+0x2e0/0x9a0 kernel/sched/core.c:5019
 preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
 arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
 el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
 arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
 trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
 benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
 kthread+0x13c/0x188 kernel/kthread.c:292
 ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929

================================
WARNING: inconsistent lock state
5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1 Not tainted
--------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
event_benchmark/105 [HC0[0]:SC0[0]:HE0:SE1] takes:
ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:512 [inline]
ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3760 [inline]
ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40 kernel/rcu/tree.c:2587
{IN-HARDIRQ-W} state was registered at:
  mark_lock kernel/locking/lockdep.c:4373 [inline]
  mark_usage kernel/locking/lockdep.c:4301 [inline]
  __lock_acquire+0xae8/0x1b00 kernel/locking/lockdep.c:4784
  lock_acquire kernel/locking/lockdep.c:5435 [inline]
  lock_acquire+0x268/0x508 kernel/locking/lockdep.c:5400
  __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
  _raw_spin_lock_irqsave+0x78/0x14c kernel/locking/spinlock.c:159
  print_other_cpu_stall kernel/rcu/tree_stall.h:512 [inline]
  check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
  rcu_pending kernel/rcu/tree.c:3760 [inline]
  rcu_sched_clock_irq+0x428/0xd40 kernel/rcu/tree.c:2587
  update_process_times+0x6c/0xb8 kernel/time/timer.c:1709
  tick_sched_handle.isra.0+0x58/0x88 kernel/time/tick-sched.c:176
  tick_sched_timer+0x68/0xe0 kernel/time/tick-sched.c:1328
  __run_hrtimer kernel/time/hrtimer.c:1519 [inline]
  __hrtimer_run_queues+0x288/0x730 kernel/time/hrtimer.c:1583
  hrtimer_interrupt+0x114/0x288 kernel/time/hrtimer.c:1645
  timer_handler drivers/clocksource/arm_arch_timer.c:647 [inline]
  arch_timer_handler_virt+0x50/0x70 drivers/clocksource/arm_arch_timer.c:658
  handle_percpu_devid_irq+0x104/0x4c0 kernel/irq/chip.c:930
  generic_handle_irq_desc include/linux/irqdesc.h:152 [inline]
  generic_handle_irq+0x54/0x78 kernel/irq/irqdesc.c:650
  __handle_domain_irq+0xac/0x130 kernel/irq/irqdesc.c:687
  handle_domain_irq include/linux/irqdesc.h:170 [inline]
  gic_handle_irq+0x70/0x108 drivers/irqchip/irq-gic.c:370
  el1_irq+0xc4/0x180 arch/arm64/kernel/entry.S:640
  arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
  __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
  _raw_spin_unlock_irq+0x50/0x98 kernel/locking/spinlock.c:199
  finish_lock_switch kernel/sched/core.c:4047 [inline]
  finish_task_switch+0xb4/0x398 kernel/sched/core.c:4147
  context_switch kernel/sched/core.c:4272 [inline]
  __schedule+0x2e0/0x9a0 kernel/sched/core.c:5019
  preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
  arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
  el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
  arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
  trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
  benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
  kthread+0x13c/0x188 kernel/kthread.c:292
  ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
irq event stamp: 67642
hardirqs last  enabled at (67641): [<ffffa17ef303ec78>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last  enabled at (67641): [<ffffa17ef303ec78>] _raw_spin_unlock_irq+0x48/0x98 kernel/locking/spinlock.c:199
hardirqs last disabled at (67642): [<ffffa17ef30310a8>] enter_el1_irq_or_nmi+0x20/0x30 arch/arm64/kernel/entry-common.c:93
softirqs last  enabled at (63366): [<ffffa17ef1c10b80>] __do_softirq+0x630/0x6b4 kernel/softirq.c:325
softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] do_softirq_own_stack include/linux/interrupt.h:568 [inline]
softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] invoke_softirq kernel/softirq.c:393 [inline]
softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] __irq_exit_rcu kernel/softirq.c:423 [inline]
softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] irq_exit+0x1cc/0x1e0 kernel/softirq.c:447

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(rcu_node_0);
  <Interrupt>
    lock(rcu_node_0);

 *** DEADLOCK ***

1 lock held by event_benchmark/105:
 #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:512 [inline]
 #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
 #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3760 [inline]
 #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40 kernel/rcu/tree.c:2587

stack backtrace:
CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
Hardware name: linux,dummy-virt (DT)
Call trace:
 dump_backtrace+0x0/0x240 arch/arm64/kernel/stacktrace.c:100
 show_stack+0x34/0x88 arch/arm64/kernel/stacktrace.c:196
 __dump_stack lib/dump_stack.c:79 [inline]
 dump_stack+0x140/0x1bc lib/dump_stack.c:120
 print_usage_bug kernel/locking/lockdep.c:3738 [inline]
 print_usage_bug+0x2a0/0x2f0 kernel/locking/lockdep.c:3705
 valid_state kernel/locking/lockdep.c:3749 [inline]
 mark_lock_irq kernel/locking/lockdep.c:3952 [inline]
 mark_lock.part.0+0x438/0x4e8 kernel/locking/lockdep.c:4409
 mark_lock kernel/locking/lockdep.c:4007 [inline]
 mark_held_locks+0x54/0x90 kernel/locking/lockdep.c:4010
 __trace_hardirqs_on_caller kernel/locking/lockdep.c:4028 [inline]
 lockdep_hardirqs_on_prepare+0xe0/0x290 kernel/locking/lockdep.c:4096
 trace_hardirqs_on+0x90/0x370 kernel/trace/trace_preemptirq.c:49
 exit_to_kernel_mode.isra.0+0xf8/0x208 arch/arm64/kernel/entry-common.c:51
 exit_el1_irq_or_nmi+0x24/0x38 arch/arm64/kernel/entry-common.c:101
 el1_irq+0xe4/0x180 arch/arm64/kernel/entry.S:658
 arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
 __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
 _raw_spin_unlock_irq+0x50/0x98 kernel/locking/spinlock.c:199
 finish_lock_switch kernel/sched/core.c:4047 [inline]
 finish_task_switch+0xb4/0x398 kernel/sched/core.c:4147
 context_switch kernel/sched/core.c:4272 [inline]
 __schedule+0x2e0/0x9a0 kernel/sched/core.c:5019
 preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
 arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
 el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
 arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
 trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
 benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
 kthread+0x13c/0x188 kernel/kthread.c:292
 ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
BUG: scheduling while atomic: event_benchmark/105/0x00000002
INFO: lockdep is turned off.
Modules linked in:
Preemption disabled at:
[<ffffa17ef3037114>] preempt_schedule_irq+0x3c/0xa0 kernel/sched/core.c:5279
CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
Hardware name: linux,dummy-virt (DT)
Call trace:
 dump_backtrace+0x0/0x240 arch/arm64/kernel/stacktrace.c:100
 show_stack+0x34/0x88 arch/arm64/kernel/stacktrace.c:196
 __dump_stack lib/dump_stack.c:79 [inline]
 dump_stack+0x140/0x1bc lib/dump_stack.c:120
 __schedule_bug+0xcc/0xe0 kernel/sched/core.c:4758
 schedule_debug kernel/sched/core.c:4785 [inline]
 __schedule+0x868/0x9a0 kernel/sched/core.c:4913
 preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
 arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
 el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
 arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
 trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
 benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
 kthread+0x13c/0x188 kernel/kthread.c:292
 ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x411fd070]
[    0.000000] Linux version 5.10.0-rc4-next-20201119-00002-gc88aca8827ce (elver@elver.muc.corp.google.com) (aarch64-none-linux-gnu-gcc (GNU Toolchain for the A-profile Architecture 9.2-2019.12 (arm-9.10)) 9.2.1 20191025, GNU ld (GNU Toolchain for the A-profile Architecture 9.2-2019.12 (arm-9.10)) 2.33.1.20191209) #1 SMP PREEMPT Mon Nov 30 12:29:39 CET 2020
[    0.000000] Machine model: linux,dummy-virt
[    0.000000] efi: UEFI not found.
[    0.000000] cma: Reserved 32 MiB at 0x00000000be000000
[    0.000000] earlycon: pl11 at MMIO 0x0000000009000000 (options '')
[    0.000000] printk: bootconsole [pl11] enabled
[    0.000000] NUMA: No NUMA configuration found
[    0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000bfffffff]
[    0.000000] NUMA: NODE_DATA [mem 0xbdbf6000-0xbdbf7fff]
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000040000000-0x000000007fffffff]
[    0.000000]   DMA32    [mem 0x0000000080000000-0x00000000bfffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000bfffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000bfffffff]
[    0.000000] On node 0 totalpages: 524288
[    0.000000]   DMA zone: 4096 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 262144 pages, LIFO batch:63
[    0.000000]   DMA32 zone: 4096 pages used for memmap
[    0.000000]   DMA32 zone: 262144 pages, LIFO batch:63
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv0.2 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] percpu: Embedded 49 pages/cpu s162704 r8192 d29808 u200704
[    0.000000] pcpu-alloc: s162704 r8192 d29808 u200704 alloc=49*4096
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Detected PIPT I-cache on CPU0
[    0.000000] CPU features: detected: ARM erratum 832075
[    0.000000] CPU features: detected: ARM erratum 834220
[    0.000000] CPU features: detected: EL2 vector hardening
[    0.000000] CPU features: kernel page table isolation forced ON by KASLR
[    0.000000] CPU features: detected: Kernel page table isolation (KPTI)
[    0.000000] CPU features: detected: Spectre-v2
[    0.000000] CPU features: detected: Spectre-v4
[    0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 516096
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: console=ttyAMA0 root=/dev/sda debug earlycon earlyprintk=serial slub_debug=UZ slub_debug=- workqueue.watchdog_thresh=10
[    0.000000] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.000000] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x000000007bfff000-0x000000007ffff000] (64MB)
[    0.000000] Memory: 1903696K/2097152K available (20800K kernel code, 4024K rwdata, 8508K rodata, 8896K init, 11238K bss, 160688K reserved, 32768K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] ftrace: allocating 56173 entries in 220 pages
[    0.000000] ftrace: allocated 220 pages with 5 groups
[    0.000000] Running RCU self tests
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu: 	RCU event tracing is enabled.
[    0.000000] rcu: 	RCU lockdep checking is enabled.
[    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=1.
[    0.000000] 	Trampoline variant of Tasks RCU enabled.
[    0.000000] 	Rude variant of Tasks RCU enabled.
[    0.000000] 	Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GICv2m: range[mem 0x08020000-0x08020fff], SPI[80:143]
[    0.000000] random: get_random_bytes called from start_kernel+0x468/0x670 with crng_init=0
[    0.000000] arch_timer: cp15 timer(s) running at 62.50MHz (virt).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x1cd42e208c, max_idle_ns: 881590405314 ns
[    0.000236] sched_clock: 56 bits at 62MHz, resolution 16ns, wraps every 4398046511096ns
[    0.011810] Console: colour dummy device 80x25
[    0.013175] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.013507] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.013762] ... MAX_LOCK_DEPTH:          48
[    0.014021] ... MAX_LOCKDEP_KEYS:        8192
[    0.014276] ... CLASSHASH_SIZE:          4096
[    0.014529] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.014784] ... MAX_LOCKDEP_CHAINS:      65536
[    0.015040] ... CHAINHASH_SIZE:          32768
[    0.015295]  memory used by lock dependency info: 6365 kB
[    0.015563]  memory used for stack traces: 4224 kB
[    0.015825]  per task-struct memory footprint: 1920 bytes
[    0.018643] Calibrating delay loop (skipped), value calculated using timer frequency.. 125.00 BogoMIPS (lpj=250000)
[    0.019296] pid_max: default: 32768 minimum: 301
[    0.022474] LSM: Security Framework initializing
[    0.024666] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
[    0.025865] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
[    0.113064] rcu: Hierarchical SRCU implementation.
[    0.132492] EFI services will not be available.
[    0.137227] smp: Bringing up secondary CPUs ...
[    0.137657] smp: Brought up 1 node, 1 CPU
[    0.137985] SMP: Total of 1 processors activated.
[    0.138417] CPU features: detected: 32-bit EL0 Support
[    0.139154] CPU features: detected: CRC32 instructions
[    0.139529] CPU features: detected: 32-bit EL1 Support
[    0.563634] CPU: All CPU(s) started at EL1
[    0.564913] alternatives: patching kernel code
[    0.623566] devtmpfs: initialized
[    0.695671] KASLR enabled
[    0.724860] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.725586] futex hash table entries: 256 (order: 3, 32768 bytes, linear)
[    0.727427] Running postponed tracer tests:
[    0.731229] Testing tracer function: PASSED
[    8.838201] Testing dynamic ftrace: PASSED
[    9.788507] Testing dynamic ftrace ops #1: 
[   12.441107] (1 0 1 0 0) 
[   12.441603] (1 1 2 0 0) 
[   20.513697] (2 1 3 0 1132022) 
[   20.516513] (2 2 4 0 1132450) PASSED
[   24.660860] Testing dynamic ftrace ops #2: 
[   34.874589] (1 0 1 1111841 0) 
[   34.875920] (1 1 2 1112053 0) 
[   34.941152] (2 1 3 1 2837) 
[   34.942414] (2 2 4 200 3036) PASSED
[   38.187248] Testing ftrace recursion: PASSED
[   38.937602] Testing ftrace recursion safe: PASSED
[   39.684401] Testing ftrace regs: PASSED
[   40.438336] Testing tracer nop: PASSED
[   40.442591] Testing tracer irqsoff: PASSED
[   48.502343] Testing tracer preemptoff: PASSED
[   56.603251] Testing tracer preemptirqsoff: PASSED
[   64.741333] Testing tracer wakeup: PASSED
[   72.700877] Testing tracer wakeup_rt: PASSED
[   80.672483] Testing tracer wakeup_dl: PASSED
[   88.647205] Testing tracer function_graph: PASSED
[   95.311654] pinctrl core: initialized pinctrl subsystem
[   95.357604] DMI not present or invalid.
[   95.377573] NET: Registered protocol family 16
[   95.442282] DMA: preallocated 256 KiB GFP_KERNEL pool for atomic allocations
[   95.443718] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[   95.446121] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[   95.448632] audit: initializing netlink subsys (disabled)
[   95.457722] audit: type=2000 audit(83.900:1): state=initialized audit_enabled=0 res=1
[   95.495840] thermal_sys: Registered thermal governor 'step_wise'
[   95.496081] thermal_sys: Registered thermal governor 'power_allocator'
[   95.499286] cpuidle: using governor menu
[   95.505170] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[   95.506521] ASID allocator initialised with 32768 entries
[   95.541565] Serial: AMBA PL011 UART driver
[   96.469419] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 47, base_baud = 0) is a PL011 rev1
[   96.472001] printk: console [ttyAMA0] enabled
[   96.472001] printk: console [ttyAMA0] enabled
[   96.472789] printk: bootconsole [pl11] disabled
[   96.472789] printk: bootconsole [pl11] disabled
[   96.934788] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[   96.935322] HugeTLB registered 32.0 MiB page size, pre-allocated 0 pages
[   96.936042] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[   96.936454] HugeTLB registered 64.0 KiB page size, pre-allocated 0 pages
[   97.007523] cryptd: max_cpu_qlen set to 1000
[   97.143352] ACPI: Interpreter disabled.
[   97.207646] iommu: Default domain type: Translated 
[   97.216776] vgaarb: loaded
[   97.228660] SCSI subsystem initialized
[   97.234310] libata version 3.00 loaded.
[   97.243658] usbcore: registered new interface driver usbfs
[   97.245446] usbcore: registered new interface driver hub
[   97.247375] usbcore: registered new device driver usb
[   97.271932] pps_core: LinuxPPS API ver. 1 registered
[   97.272326] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[   97.273108] PTP clock support registered
[   97.278967] EDAC MC: Ver: 3.0.0
[   97.330734] FPGA manager framework
[   97.334916] Advanced Linux Sound Architecture Driver Initialized.
[   97.367534] clocksource: Switched to clocksource arch_sys_counter
[  114.521600] VFS: Disk quotas dquot_6.6.0
[  114.523765] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[  114.533650] pnp: PnP ACPI: disabled
[  114.765263] NET: Registered protocol family 2
[  114.788981] tcp_listen_portaddr_hash hash table entries: 1024 (order: 4, 81920 bytes, linear)
[  114.790064] TCP established hash table entries: 16384 (order: 5, 131072 bytes, linear)
[  114.798325] TCP bind hash table entries: 16384 (order: 8, 1179648 bytes, linear)
[  114.806169] TCP: Hash tables configured (established 16384 bind 16384)
[  114.810413] UDP hash table entries: 1024 (order: 5, 163840 bytes, linear)
[  114.814124] UDP-Lite hash table entries: 1024 (order: 5, 163840 bytes, linear)
[  114.819502] NET: Registered protocol family 1
[  114.837488] RPC: Registered named UNIX socket transport module.
[  114.838082] RPC: Registered udp transport module.
[  114.838453] RPC: Registered tcp transport module.
[  114.838809] RPC: Registered tcp NFSv4.1 backchannel transport module.
[  114.839760] PCI: CLS 0 bytes, default 64
[  114.870930] hw perfevents: enabled with armv8_pmuv3 PMU driver, 5 counters available
[  114.873385] kvm [1]: HYP mode not available
[  115.096835] Initialise system trusted keyrings
[  115.102788] workingset: timestamp_bits=44 max_order=19 bucket_order=0
[  115.399347] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[  115.420555] NFS: Registering the id_resolver key type
[  115.422030] Key type id_resolver registered
[  115.422598] Key type id_legacy registered
[  115.426472] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[  115.434896] 9p: Installing v9fs 9p2000 file system support
[  115.521422] Key type asymmetric registered
[  115.522091] Asymmetric key parser 'x509' registered
[  115.523839] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
[  115.524497] io scheduler mq-deadline registered
[  115.524989] io scheduler kyber registered
[  115.894160] pl061_gpio 9030000.pl061: PL061 GPIO chip registered
[  115.952465] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:
[  115.954473] pci-host-generic 4010000000.pcie:       IO 0x003eff0000..0x003effffff -> 0x0000000000
[  115.956630] pci-host-generic 4010000000.pcie:      MEM 0x0010000000..0x003efeffff -> 0x0010000000
[  115.957484] pci-host-generic 4010000000.pcie:      MEM 0x8000000000..0xffffffffff -> 0x8000000000
[  115.960592] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]
[  115.965840] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00
[  115.966564] pci_bus 0000:00: root bus resource [bus 00-ff]
[  115.967435] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[  115.967879] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]
[  115.968308] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]
[  115.970981] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000
[  115.982358] pci 0000:00:01.0: [1af4:1009] type 00 class 0x000200
[  115.983896] pci 0000:00:01.0: reg 0x10: [io  0x0000-0x003f]
[  115.984527] pci 0000:00:01.0: reg 0x14: [mem 0x00000000-0x00000fff]
[  115.985710] pci 0000:00:01.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
[  115.993649] pci 0000:00:02.0: [1af4:1009] type 00 class 0x000200
[  115.994489] pci 0000:00:02.0: reg 0x10: [io  0x0000-0x003f]
[  115.995425] pci 0000:00:02.0: reg 0x14: [mem 0x00000000-0x00000fff]
[  115.996526] pci 0000:00:02.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
[  116.004182] pci 0000:00:03.0: [1af4:1000] type 00 class 0x020000
[  116.005039] pci 0000:00:03.0: reg 0x10: [io  0x0000-0x001f]
[  116.005630] pci 0000:00:03.0: reg 0x14: [mem 0x00000000-0x00000fff]
[  116.006717] pci 0000:00:03.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
[  116.007694] pci 0000:00:03.0: reg 0x30: [mem 0x00000000-0x0003ffff pref]
[  116.014983] pci 0000:00:04.0: [1af4:1004] type 00 class 0x010000
[  116.016150] pci 0000:00:04.0: reg 0x10: [io  0x0000-0x003f]
[  116.016744] pci 0000:00:04.0: reg 0x14: [mem 0x00000000-0x00000fff]
[  116.017823] pci 0000:00:04.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
[  116.031717] pci 0000:00:03.0: BAR 6: assigned [mem 0x10000000-0x1003ffff pref]
[  116.032501] pci 0000:00:01.0: BAR 4: assigned [mem 0x8000000000-0x8000003fff 64bit pref]
[  116.033388] pci 0000:00:02.0: BAR 4: assigned [mem 0x8000004000-0x8000007fff 64bit pref]
[  116.034240] pci 0000:00:03.0: BAR 4: assigned [mem 0x8000008000-0x800000bfff 64bit pref]
[  116.035359] pci 0000:00:04.0: BAR 4: assigned [mem 0x800000c000-0x800000ffff 64bit pref]
[  116.036108] pci 0000:00:01.0: BAR 1: assigned [mem 0x10040000-0x10040fff]
[  116.036664] pci 0000:00:02.0: BAR 1: assigned [mem 0x10041000-0x10041fff]
[  116.037196] pci 0000:00:03.0: BAR 1: assigned [mem 0x10042000-0x10042fff]
[  116.037723] pci 0000:00:04.0: BAR 1: assigned [mem 0x10043000-0x10043fff]
[  116.038274] pci 0000:00:01.0: BAR 0: assigned [io  0x1000-0x103f]
[  116.038817] pci 0000:00:02.0: BAR 0: assigned [io  0x1040-0x107f]
[  116.039686] pci 0000:00:04.0: BAR 0: assigned [io  0x1080-0x10bf]
[  116.040213] pci 0000:00:03.0: BAR 0: assigned [io  0x10c0-0x10df]
[  116.110878] EINJ: ACPI disabled.
[  116.586823] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)
[  116.601358] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)
[  116.613837] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)
[  116.624404] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)
[  116.807519] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[  116.898052] SuperH (H)SCI(F) driver initialized
[  116.916586] msm_serial: driver initialized
[  116.966160] cacheinfo: Unable to detect cache hierarchy for CPU 0
[  117.230609] loop: module loaded
[  117.261553] megasas: 07.714.04.00-rc1
[  117.299460] scsi host0: Virtio SCSI HBA
[  117.332400] scsi 0:0:0:0: Direct-Access     QEMU     QEMU HARDDISK    2.5+ PQ: 0 ANSI: 5
[  119.896235] random: fast init done
[  119.962094] sd 0:0:0:0: Power-on or device reset occurred
[  119.988603] sd 0:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
[  119.990909] sd 0:0:0:0: [sda] Write Protect is off
[  119.991894] sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08
[  120.000849] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  120.005403] sda: detected capacity change from 0 to 268435456
[  120.104701] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]
[  120.107055] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
[  120.113218] Intel/Sharp Extended Query Table at 0x0031
[  120.114867] Using buffer write method
[  120.125192] erase region 0: offset=0x0,size=0x40000,blocks=256
[  120.126226] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]
[  120.127789] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
[  120.128353] Intel/Sharp Extended Query Table at 0x0031
[  120.129355] Using buffer write method
[  120.129810] erase region 0: offset=0x0,size=0x40000,blocks=256
[  120.130313] Concatenating MTD devices:
[  120.130686] (0): "0.flash"
[  120.135876] (1): "0.flash"
[  120.136225] into device "0.flash"
[  120.192278] sda: detected capacity change from 0 to 268435456
[  120.193045] sd 0:0:0:0: [sda] Attached SCSI disk
[  120.387475] libphy: Fixed MDIO Bus: probed
[  120.432985] tun: Universal TUN/TAP device driver, 1.6
[  120.489130] thunder_xcv, ver 1.0
[  120.490797] thunder_bgx, ver 1.0
[  120.492770] nicpf, ver 1.0
[  120.537316] hclge is initializing
[  120.538538] hns3: Hisilicon Ethernet Network Driver for Hip08 Family - version
[  120.538958] hns3: Copyright (c) 2017 Huawei Corporation.
[  120.541156] e1000: Intel(R) PRO/1000 Network Driver
[  120.541528] e1000: Copyright (c) 1999-2006 Intel Corporation.
[  120.543589] e1000e: Intel(R) PRO/1000 Network Driver
[  120.543956] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[  120.545789] igb: Intel(R) Gigabit Ethernet Network Driver
[  120.546176] igb: Copyright (c) 2007-2014 Intel Corporation.
[  120.547883] igbvf: Intel(R) Gigabit Virtual Function Network Driver
[  120.548276] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
[  120.562052] sky2: driver version 1.30
[  120.597519] VFIO - User Level meta-driver version: 0.3
[  120.658110] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[  120.658597] ehci-pci: EHCI PCI platform driver
[  120.660406] ehci-platform: EHCI generic platform driver
[  120.664987] ehci-orion: EHCI orion driver
[  120.669400] ehci-exynos: EHCI Exynos driver
[  120.673747] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[  120.674701] ohci-pci: OHCI PCI platform driver
[  120.676572] ohci-platform: OHCI generic platform driver
[  120.681095] ohci-exynos: OHCI Exynos driver
[  120.697532] usbcore: registered new interface driver usb-storage
[  120.806431] rtc-pl031 9010000.pl031: registered as rtc0
[  120.808336] rtc-pl031 9010000.pl031: setting system clock to 2020-11-30T11:37:20 UTC (1606736240)
[  120.831534] i2c /dev entries driver
[  121.067859] sdhci: Secure Digital Host Controller Interface driver
[  121.068255] sdhci: Copyright(c) Pierre Ossman
[  121.084261] Synopsys Designware Multimedia Card Interface Driver
[  121.122438] sdhci-pltfm: SDHCI platform and OF driver helper
[  121.176067] ledtrig-cpu: registered to indicate activity on CPUs
[  121.237585] usbcore: registered new interface driver usbhid
[  121.237987] usbhid: USB HID core driver
[  121.414229] drop_monitor: Initializing network drop monitor service
[  121.418007] NET: Registered protocol family 17
[  121.424102] 9pnet: Installing 9P2000 support
[  121.443895] Key type dns_resolver registered
[  121.451895] registered taskstats version 1
[  121.453581] Running tests on all trace events:
[  121.453937] Testing all events: OK
[  180.314804] Running tests again, along with the function tracer
[  180.334448] Running tests on all trace events:
[  180.346904] Testing all events: 
[  186.731798] hrtimer: interrupt took 10487664 ns
[  219.711287] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 13s!
[  219.875132] Showing busy workqueues and worker pools:
[  219.910747] workqueue events: flags=0x0
[  219.939591]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  219.951310]     pending: vmstat_shepherd
[  219.963073] workqueue events_power_efficient: flags=0x82
[  219.999935]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
[  220.009975]     in-flight: 7:do_cache_clean
[  220.030092] pool 2: cpus=0 flags=0x4 nice=0 hung=0s workers=3 idle: 61 99
[  230.303201] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 24s!
[  230.410755] Showing busy workqueues and worker pools:
[  230.427157] workqueue events: flags=0x0
[  230.443262]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  230.454087]     pending: vmstat_shepherd
[  351.797552] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 11s!
[  351.843185] Showing busy workqueues and worker pools:
[  351.875356] workqueue events: flags=0x0
[  351.906690]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  351.917412]     pending: vmstat_shepherd
[  351.938890] workqueue events_power_efficient: flags=0x82
[  351.970790]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
[  351.979994]     pending: neigh_periodic_work
[  389.525557] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 17s!
[  389.600725] Showing busy workqueues and worker pools:
[  389.617453] workqueue events: flags=0x0
[  389.623272]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  389.634046]     pending: vmstat_shepherd
[  389.650704] workqueue events_power_efficient: flags=0x82
[  389.671328]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
[  389.680463]     in-flight: 7:neigh_periodic_work
[  389.704734] pool 2: cpus=0 flags=0x4 nice=0 hung=9s workers=3 idle: 61 99
[  453.731592] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
[  453.790537] Showing busy workqueues and worker pools:
[  453.796398] workqueue events: flags=0x0
[  453.823200]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  453.833529]     pending: vmstat_shepherd
[  453.852558] workqueue events_power_efficient: flags=0x82
[  453.858588]   pwq 2: cpus=0 flags=0x5 nice=0 active=2/256 refcnt=4
[  453.867424]     in-flight: 7:do_cache_clean
[  453.874323]     pending: neigh_periodic_work
[  453.894345] pool 2: cpus=0 flags=0x5 nice=0 hung=8s workers=2 manager: 61
[  598.019250] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 16s!
[  598.131254] Showing busy workqueues and worker pools:
[  598.200541] workqueue events: flags=0x0
[  598.217960]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  598.228669]     pending: vmstat_shepherd
[  598.246863] workqueue events_power_efficient: flags=0x82
[  598.279406]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
[  598.288499]     in-flight: 106:do_cache_clean
[  598.319372] pool 2: cpus=0 flags=0x4 nice=0 hung=8s workers=3 idle: 61 7
[  795.287162] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
[  795.311095] BUG: workqueue lockup - pool cpus=0 flags=0x4 nice=0 stuck for 10s!
[  795.334433] Showing busy workqueues and worker pools:
[  795.343043] workqueue events: flags=0x0
[  795.354006]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  795.361092]     pending: vmstat_shepherd
[  795.370452] workqueue events_power_efficient: flags=0x82
[  795.379095]   pwq 2: cpus=0 flags=0x4 nice=0 active=3/256 refcnt=5
[  795.385173]     in-flight: 106:check_lifetime
[  795.389953]     pending: neigh_periodic_work, do_cache_clean
[  795.401803] pool 2: cpus=0 flags=0x4 nice=0 hung=10s workers=3 idle: 61 7
[  840.280588] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 15s!
[  840.370856] Showing busy workqueues and worker pools:
[  840.400495] workqueue events: flags=0x0
[  840.417468]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  840.427827]     pending: vmstat_shepherd
[  840.473295] pool 2: cpus=0 flags=0x5 nice=0 hung=6s workers=3 manager: 7 idle: 106 61
[  889.716728] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 12s!
[  889.787233] BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 12s!
[  889.936565] Showing busy workqueues and worker pools:
[  889.953557] workqueue events: flags=0x0
[  889.959094]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  889.969435]     pending: vmstat_shepherd
[  889.990858] workqueue events_power_efficient: flags=0x82
[  890.022774]   pwq 2: cpus=0 flags=0x5 nice=0 active=1/256 refcnt=3
[  890.031587]     pending: neigh_periodic_work
[  890.059229] pool 2: cpus=0 flags=0x5 nice=0 hung=12s workers=3 manager: 7 idle: 106 61
[  903.560770] BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 25s!
[  903.610830] Showing busy workqueues and worker pools:
[  903.616897] workqueue events: flags=0x0
[  903.633819]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  903.644574]     in-flight: 15:vmstat_shepherd
[  903.662870] workqueue events_power_efficient: flags=0x82
[  903.726795]   pwq 2: cpus=0 flags=0x5 nice=0 active=3/256 refcnt=5
[  903.736114]     pending: neigh_periodic_work, do_cache_clean, check_lifetime
[  903.758987] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=2s workers=2 idle: 5
[  903.785300] pool 2: cpus=0 flags=0x5 nice=0 hung=26s workers=4 manager: 7 idle: 107 106 61
[ 1211.521119] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 1211.527302] 	(detected by 0, t=3752 jiffies, g=2329, q=2)
[ 1211.529303] rcu: All QSes seen, last rcu_preempt kthread activity 3503 (4295192252-4295188749), jiffies_till_next_fqs=1, root ->qsmask 0x0
[ 1211.540472] rcu: rcu_preempt kthread starved for 3503 jiffies! g2329 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=0
[ 1211.546502] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
[ 1211.552234] rcu: RCU grace-period kthread stack dump:
[ 1211.556893] task:rcu_preempt     state:R  running task     stack:    0 pid:   10 ppid:     2 flags:0x00000428
[ 1211.566196] Call trace:
[ 1211.570036]  __switch_to+0x148/0x1f0
[ 1211.574189]  __schedule+0x2dc/0x9a0
[ 1211.578355]  preempt_schedule_notrace+0x70/0x1c0
[ 1211.582822]  ftrace_ops_list_func+0x10c/0x218
[ 1211.587212]  ftrace_graph_call+0x0/0x4
[ 1211.591434]  preempt_count_add+0x8/0x1a0
[ 1211.595716]  schedule+0x44/0x100
[ 1211.599779]  schedule_timeout+0x240/0x538
[ 1211.604098]  rcu_gp_kthread+0x618/0x1bd8
[ 1211.608398]  kthread+0x13c/0x188
[ 1211.612480]  ret_from_fork+0x10/0x34
[ 1211.616726] rcu: Stack dump where RCU GP kthread last ran:
[ 1211.621458] Task dump for CPU 0:
[ 1211.625472] task:event_benchmark state:R  running task     stack:    0 pid:  105 ppid:     2 flags:0x0000042a
[ 1211.634526] Call trace:
[ 1211.638364]  dump_backtrace+0x0/0x240
[ 1211.642586]  show_stack+0x34/0x88
[ 1211.646715]  sched_show_task+0x208/0x230
[ 1211.650995]  dump_cpu_task+0x4c/0x5c
[ 1211.655215]  rcu_check_gp_kthread_starvation+0x240/0x388
[ 1211.659949]  rcu_sched_clock_irq+0xc2c/0xd40
[ 1211.664331]  update_process_times+0x6c/0xb8
[ 1211.668703]  tick_sched_handle.isra.0+0x58/0x88
[ 1211.673168]  tick_sched_timer+0x68/0xe0
[ 1211.677459]  __hrtimer_run_queues+0x288/0x730
[ 1211.681873]  hrtimer_interrupt+0x114/0x288
[ 1211.686235]  arch_timer_handler_virt+0x50/0x70
[ 1211.690664]  handle_percpu_devid_irq+0x104/0x4c0
[ 1211.695127]  generic_handle_irq+0x54/0x78
[ 1211.699396]  __handle_domain_irq+0xac/0x130
[ 1211.703736]  gic_handle_irq+0x70/0x108
[ 1211.707949]  el1_irq+0xc4/0x180
[ 1211.711937]  _raw_spin_unlock_irq+0x50/0x98
[ 1211.716304]  finish_task_switch+0xb4/0x398
[ 1211.720649]  __schedule+0x2e0/0x9a0
[ 1211.724815]  preempt_schedule_irq+0x4c/0xa0
[ 1211.729191]  arm64_preempt_schedule_irq+0xd0/0x118
[ 1211.733737]  el1_irq+0xdc/0x180
[ 1211.737771]  benchmark_event_kthread+0x144/0x4b0
[ 1211.742255]  kthread+0x13c/0x188
[ 1211.746320]  ret_from_fork+0x10/0x34
[ 1211.755343] 
[ 1211.757649] ================================
[ 1211.760669] WARNING: inconsistent lock state
[ 1211.763880] 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1 Not tainted
[ 1211.767588] --------------------------------
[ 1211.770630] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
[ 1211.774224] event_benchmark/105 [HC0[0]:SC0[0]:HE0:SE1] takes:
[ 1211.777779] ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40
[ 1211.785746] {IN-HARDIRQ-W} state was registered at:
[ 1211.789124]   __lock_acquire+0xae8/0x1b00
[ 1211.792183]   lock_acquire+0x268/0x508
[ 1211.795161]   _raw_spin_lock_irqsave+0x78/0x14c
[ 1211.798335]   rcu_sched_clock_irq+0x428/0xd40
[ 1211.801476]   update_process_times+0x6c/0xb8
[ 1211.804567]   tick_sched_handle.isra.0+0x58/0x88
[ 1211.807746]   tick_sched_timer+0x68/0xe0
[ 1211.810778]   __hrtimer_run_queues+0x288/0x730
[ 1211.813963]   hrtimer_interrupt+0x114/0x288
[ 1211.817035]   arch_timer_handler_virt+0x50/0x70
[ 1211.820187]   handle_percpu_devid_irq+0x104/0x4c0
[ 1211.823434]   generic_handle_irq+0x54/0x78
[ 1211.826498]   __handle_domain_irq+0xac/0x130
[ 1211.829584]   gic_handle_irq+0x70/0x108
[ 1211.832555]   el1_irq+0xc4/0x180
[ 1211.835370]   _raw_spin_unlock_irq+0x50/0x98
[ 1211.838473]   finish_task_switch+0xb4/0x398
[ 1211.841540]   __schedule+0x2e0/0x9a0
[ 1211.844477]   preempt_schedule_irq+0x4c/0xa0
[ 1211.847590]   arm64_preempt_schedule_irq+0xd0/0x118
[ 1211.850859]   el1_irq+0xdc/0x180
[ 1211.853636]   benchmark_event_kthread+0x144/0x4b0
[ 1211.856906]   kthread+0x13c/0x188
[ 1211.859729]   ret_from_fork+0x10/0x34
[ 1211.862686] irq event stamp: 67642
[ 1211.865588] hardirqs last  enabled at (67641): [<ffffa17ef303ec78>] _raw_spin_unlock_irq+0x48/0x98
[ 1211.870078] hardirqs last disabled at (67642): [<ffffa17ef30310a8>] enter_el1_irq_or_nmi+0x20/0x30
[ 1211.874532] softirqs last  enabled at (63366): [<ffffa17ef1c10b80>] __do_softirq+0x630/0x6b4
[ 1211.878770] softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] irq_exit+0x1cc/0x1e0
[ 1211.882828] 
[ 1211.882828] other info that might help us debug this:
[ 1211.886512]  Possible unsafe locking scenario:
[ 1211.886512] 
[ 1211.889961]        CPU0
[ 1211.892451]        ----
[ 1211.894935]   lock(rcu_node_0);
[ 1211.899732]   <Interrupt>
[ 1211.902272]     lock(rcu_node_0);
[ 1211.906707] 
[ 1211.906707]  *** DEADLOCK ***
[ 1211.906707] 
[ 1211.910237] 1 lock held by event_benchmark/105:
[ 1211.913352]  #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40
[ 1211.922068] 
[ 1211.922068] stack backtrace:
[ 1211.925381] CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
[ 1211.930018] Hardware name: linux,dummy-virt (DT)
[ 1211.933192] Call trace:
[ 1211.935795]  dump_backtrace+0x0/0x240
[ 1211.938733]  show_stack+0x34/0x88
[ 1211.941539]  dump_stack+0x140/0x1bc
[ 1211.944421]  print_usage_bug+0x2a0/0x2f0
[ 1211.947405]  mark_lock.part.0+0x438/0x4e8
[ 1211.950420]  mark_held_locks+0x54/0x90
[ 1211.953393]  lockdep_hardirqs_on_prepare+0xe0/0x290
[ 1211.956665]  trace_hardirqs_on+0x90/0x370
[ 1211.959701]  exit_to_kernel_mode.isra.0+0xf8/0x208
[ 1211.962948]  exit_el1_irq_or_nmi+0x24/0x38
[ 1211.965971]  el1_irq+0xe4/0x180
[ 1211.968779]  _raw_spin_unlock_irq+0x50/0x98
[ 1211.971832]  finish_task_switch+0xb4/0x398
[ 1211.974885]  __schedule+0x2e0/0x9a0
[ 1211.977744]  preempt_schedule_irq+0x4c/0xa0
[ 1211.980856]  arm64_preempt_schedule_irq+0xd0/0x118
[ 1211.984101]  el1_irq+0xdc/0x180
[ 1211.986889]  benchmark_event_kthread+0x144/0x4b0
[ 1211.990118]  kthread+0x13c/0x188
[ 1211.992910]  ret_from_fork+0x10/0x34
[ 1211.998610] BUG: scheduling while atomic: event_benchmark/105/0x00000002
[ 1212.010060] INFO: lockdep is turned off.
[ 1212.018261] Modules linked in:
[ 1212.030227] Preemption disabled at:
[ 1212.034171] [<ffffa17ef3037114>] preempt_schedule_irq+0x3c/0xa0
[ 1212.049696] CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
[ 1212.054368] Hardware name: linux,dummy-virt (DT)
[ 1212.057507] Call trace:
[ 1212.060101]  dump_backtrace+0x0/0x240
[ 1212.063052]  show_stack+0x34/0x88
[ 1212.065890]  dump_stack+0x140/0x1bc
[ 1212.068791]  __schedule_bug+0xcc/0xe0
[ 1212.071729]  __schedule+0x868/0x9a0
[ 1212.074625]  preempt_schedule_irq+0x4c/0xa0
[ 1212.077714]  arm64_preempt_schedule_irq+0xd0/0x118
[ 1212.080945]  el1_irq+0xdc/0x180
[ 1212.083732]  benchmark_event_kthread+0x144/0x4b0
[ 1212.086931]  kthread+0x13c/0x188
[ 1212.089704]  ret_from_fork+0x10/0x34
Mark Rutland Nov. 30, 2020, 12:38 p.m. UTC | #3 
Hi Marco,

On Mon, Nov 30, 2020 at 01:03:05PM +0100, Marco Elver wrote:
> [ FYI, this series was not Cc'd to LKML. ]

Yes -- I had assumed LAKML was sufficient for this, though I'm happy to
CC LKML in future if people would like me to.

BTW, I've just sent a v2 (which should not functionally differ from v1
other than when building SDEI):

  https://lore.kernel.org/r/20201130115950.22492-1-mark.rutland@arm.com
  
> On Thu, Nov 26, 2020 at 12:35PM +0000, Mark Rutland wrote:
> > Dmitry and Marco both reported some weirdness with lockdep on arm64 erroneously
> > reporting the hardware IRQ state, and inexplicable RCU stalls:
> > 
> >   https://lore.kernel.org/r/CACT4Y+aAzoJ48Mh1wNYD17pJqyEcDnrxGfApir=-j171TnQXhw@mail.gmail.com
> >   https://lore.kernel.org/r/20201119193819.GA2601289@elver.google.com
> > 
> > Having investigated, I believe that this is largely down to the arm64 entry
> > code not correctly managing RCU, lockdep, irq flag tracing, and context
> > tracking. This series attempts to fix those cases, and I've Cc'd folk from the
> > previous threads as a heads-up.

[...]

> So, I was hoping that this would fix all the problems I was seeing when
> running the ftrace tests ... unfortunately, it didn't. :-( Perhaps the
> WIP version you had only worked because it ended up disabling lockdep
> early?

Possibly, yes. Either that or the way we do / do-not treat debug
exceptions as true NMIs. Either way this appears to be a latent issue
rather than something introduced by this series.

From the log below I see you're using:

  5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1 Not tainted

... and it's possible that the issue you're seeing now is a delta
between v5.10-rc3 and what's queued in linux-next -- I've been running
the ftrace tests locally without issue atop v5.10-rc3 and v5.10-rc5.

Are you able to reproduce this on my branch alone? If so that gives us a
stable tree to investigate, and if not that gives us a stable base for a
bisect against linux-next.

This area is really sensitive to config options, so if you can reproduce
this on a stable base, could you share youir exact config?

> I've attached the log and the symbolized report.

Thanks for all this. I'll see if I can tickle this locally while waiting
for the above. If you could share your config from this time around
that'd be a great head-start!

Thanks,
Mark.

> Testing all events: OK
> Running tests again, along with the function tracer
> Running tests on all trace events:
> Testing all events: 
> hrtimer: interrupt took 10487664 ns
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 13s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
>     in-flight: 7:do_cache_clean
> pool 2: cpus=0 flags=0x4 nice=0 hung=0s workers=3 idle: 61 99
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 24s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 11s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
>     pending: neigh_periodic_work
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 17s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
>     in-flight: 7:neigh_periodic_work
> pool 2: cpus=0 flags=0x4 nice=0 hung=9s workers=3 idle: 61 99
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x5 nice=0 active=2/256 refcnt=4
>     in-flight: 7:do_cache_clean
>     pending: neigh_periodic_work
> pool 2: cpus=0 flags=0x5 nice=0 hung=8s workers=2 manager: 61
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 16s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
>     in-flight: 106:do_cache_clean
> pool 2: cpus=0 flags=0x4 nice=0 hung=8s workers=3 idle: 61 7
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
> BUG: workqueue lockup - pool cpus=0 flags=0x4 nice=0 stuck for 10s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x4 nice=0 active=3/256 refcnt=5
>     in-flight: 106:check_lifetime
>     pending: neigh_periodic_work, do_cache_clean
> pool 2: cpus=0 flags=0x4 nice=0 hung=10s workers=3 idle: 61 7
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 15s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> pool 2: cpus=0 flags=0x5 nice=0 hung=6s workers=3 manager: 7 idle: 106 61
> BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 12s!
> BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 12s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     pending: vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x5 nice=0 active=1/256 refcnt=3
>     pending: neigh_periodic_work
> pool 2: cpus=0 flags=0x5 nice=0 hung=12s workers=3 manager: 7 idle: 106 61
> BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 25s!
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
>   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
>     in-flight: 15:vmstat_shepherd
> workqueue events_power_efficient: flags=0x82
>   pwq 2: cpus=0 flags=0x5 nice=0 active=3/256 refcnt=5
>     pending: neigh_periodic_work, do_cache_clean, check_lifetime
> pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=2s workers=2 idle: 5
> pool 2: cpus=0 flags=0x5 nice=0 hung=26s workers=4 manager: 7 idle: 107 106 61
> rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> 	(detected by 0, t=3752 jiffies, g=2329, q=2)
> rcu: All QSes seen, last rcu_preempt kthread activity 3503 (4295192252-4295188749), jiffies_till_next_fqs=1, root ->qsmask 0x0
> rcu: rcu_preempt kthread starved for 3503 jiffies! g2329 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=0
> rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> rcu: RCU grace-period kthread stack dump:
> task:rcu_preempt     state:R  running task     stack:    0 pid:   10 ppid:     2 flags:0x00000428
> Call trace:
>  __switch_to+0x148/0x1f0 arch/arm64/kernel/process.c:577
>  context_switch kernel/sched/core.c:4269 [inline]
>  __schedule+0x2dc/0x9a0 kernel/sched/core.c:5019
>  preempt_schedule_notrace+0x70/0x1c0 kernel/sched/core.c:5252
>  __ftrace_ops_list_func kernel/trace/ftrace.c:6955 [inline]
>  ftrace_ops_list_func+0x10c/0x218 kernel/trace/ftrace.c:6976
>  ftrace_graph_call+0x0/0x4
>  preempt_count_add+0x8/0x1a0 arch/arm64/include/asm/atomic.h:65
>  schedule+0x44/0x100 kernel/sched/core.c:5097
>  schedule_timeout+0x240/0x538 kernel/time/timer.c:1871
>  rcu_gp_fqs_loop kernel/rcu/tree.c:1946 [inline]
>  rcu_gp_kthread+0x618/0x1bd8 kernel/rcu/tree.c:2119
>  kthread+0x13c/0x188 kernel/kthread.c:292
>  ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
> rcu: Stack dump where RCU GP kthread last ran:
> Task dump for CPU 0:
> task:event_benchmark state:R  running task     stack:    0 pid:  105 ppid:     2 flags:0x0000042a
> Call trace:
>  dump_backtrace+0x0/0x240 arch/arm64/kernel/stacktrace.c:100
>  show_stack+0x34/0x88 arch/arm64/kernel/stacktrace.c:196
>  sched_show_task kernel/sched/core.c:6948 [inline]
>  sched_show_task+0x208/0x230 kernel/sched/core.c:6922
>  dump_cpu_task+0x4c/0x5c kernel/sched/core.c:8986
>  rcu_check_gp_kthread_starvation+0x240/0x388 kernel/rcu/tree_stall.h:480
>  print_other_cpu_stall kernel/rcu/tree_stall.h:551 [inline]
>  check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
>  rcu_pending kernel/rcu/tree.c:3760 [inline]
>  rcu_sched_clock_irq+0xc2c/0xd40 kernel/rcu/tree.c:2587
>  update_process_times+0x6c/0xb8 kernel/time/timer.c:1709
>  tick_sched_handle.isra.0+0x58/0x88 kernel/time/tick-sched.c:176
>  tick_sched_timer+0x68/0xe0 kernel/time/tick-sched.c:1328
>  __run_hrtimer kernel/time/hrtimer.c:1519 [inline]
>  __hrtimer_run_queues+0x288/0x730 kernel/time/hrtimer.c:1583
>  hrtimer_interrupt+0x114/0x288 kernel/time/hrtimer.c:1645
>  timer_handler drivers/clocksource/arm_arch_timer.c:647 [inline]
>  arch_timer_handler_virt+0x50/0x70 drivers/clocksource/arm_arch_timer.c:658
>  handle_percpu_devid_irq+0x104/0x4c0 kernel/irq/chip.c:930
>  generic_handle_irq_desc include/linux/irqdesc.h:152 [inline]
>  generic_handle_irq+0x54/0x78 kernel/irq/irqdesc.c:650
>  __handle_domain_irq+0xac/0x130 kernel/irq/irqdesc.c:687
>  handle_domain_irq include/linux/irqdesc.h:170 [inline]
>  gic_handle_irq+0x70/0x108 drivers/irqchip/irq-gic.c:370
>  el1_irq+0xc4/0x180 arch/arm64/kernel/entry.S:640
>  arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
>  __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
>  _raw_spin_unlock_irq+0x50/0x98 kernel/locking/spinlock.c:199
>  finish_lock_switch kernel/sched/core.c:4047 [inline]
>  finish_task_switch+0xb4/0x398 kernel/sched/core.c:4147
>  context_switch kernel/sched/core.c:4272 [inline]
>  __schedule+0x2e0/0x9a0 kernel/sched/core.c:5019
>  preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
>  arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
>  el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
>  arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
>  trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
>  benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
>  kthread+0x13c/0x188 kernel/kthread.c:292
>  ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
> 
> ================================
> WARNING: inconsistent lock state
> 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1 Not tainted
> --------------------------------
> inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
> event_benchmark/105 [HC0[0]:SC0[0]:HE0:SE1] takes:
> ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:512 [inline]
> ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
> ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3760 [inline]
> ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40 kernel/rcu/tree.c:2587
> {IN-HARDIRQ-W} state was registered at:
>   mark_lock kernel/locking/lockdep.c:4373 [inline]
>   mark_usage kernel/locking/lockdep.c:4301 [inline]
>   __lock_acquire+0xae8/0x1b00 kernel/locking/lockdep.c:4784
>   lock_acquire kernel/locking/lockdep.c:5435 [inline]
>   lock_acquire+0x268/0x508 kernel/locking/lockdep.c:5400
>   __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
>   _raw_spin_lock_irqsave+0x78/0x14c kernel/locking/spinlock.c:159
>   print_other_cpu_stall kernel/rcu/tree_stall.h:512 [inline]
>   check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
>   rcu_pending kernel/rcu/tree.c:3760 [inline]
>   rcu_sched_clock_irq+0x428/0xd40 kernel/rcu/tree.c:2587
>   update_process_times+0x6c/0xb8 kernel/time/timer.c:1709
>   tick_sched_handle.isra.0+0x58/0x88 kernel/time/tick-sched.c:176
>   tick_sched_timer+0x68/0xe0 kernel/time/tick-sched.c:1328
>   __run_hrtimer kernel/time/hrtimer.c:1519 [inline]
>   __hrtimer_run_queues+0x288/0x730 kernel/time/hrtimer.c:1583
>   hrtimer_interrupt+0x114/0x288 kernel/time/hrtimer.c:1645
>   timer_handler drivers/clocksource/arm_arch_timer.c:647 [inline]
>   arch_timer_handler_virt+0x50/0x70 drivers/clocksource/arm_arch_timer.c:658
>   handle_percpu_devid_irq+0x104/0x4c0 kernel/irq/chip.c:930
>   generic_handle_irq_desc include/linux/irqdesc.h:152 [inline]
>   generic_handle_irq+0x54/0x78 kernel/irq/irqdesc.c:650
>   __handle_domain_irq+0xac/0x130 kernel/irq/irqdesc.c:687
>   handle_domain_irq include/linux/irqdesc.h:170 [inline]
>   gic_handle_irq+0x70/0x108 drivers/irqchip/irq-gic.c:370
>   el1_irq+0xc4/0x180 arch/arm64/kernel/entry.S:640
>   arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
>   __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
>   _raw_spin_unlock_irq+0x50/0x98 kernel/locking/spinlock.c:199
>   finish_lock_switch kernel/sched/core.c:4047 [inline]
>   finish_task_switch+0xb4/0x398 kernel/sched/core.c:4147
>   context_switch kernel/sched/core.c:4272 [inline]
>   __schedule+0x2e0/0x9a0 kernel/sched/core.c:5019
>   preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
>   arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
>   el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
>   arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
>   trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
>   benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
>   kthread+0x13c/0x188 kernel/kthread.c:292
>   ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
> irq event stamp: 67642
> hardirqs last  enabled at (67641): [<ffffa17ef303ec78>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
> hardirqs last  enabled at (67641): [<ffffa17ef303ec78>] _raw_spin_unlock_irq+0x48/0x98 kernel/locking/spinlock.c:199
> hardirqs last disabled at (67642): [<ffffa17ef30310a8>] enter_el1_irq_or_nmi+0x20/0x30 arch/arm64/kernel/entry-common.c:93
> softirqs last  enabled at (63366): [<ffffa17ef1c10b80>] __do_softirq+0x630/0x6b4 kernel/softirq.c:325
> softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] do_softirq_own_stack include/linux/interrupt.h:568 [inline]
> softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] invoke_softirq kernel/softirq.c:393 [inline]
> softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] __irq_exit_rcu kernel/softirq.c:423 [inline]
> softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] irq_exit+0x1cc/0x1e0 kernel/softirq.c:447
> 
> other info that might help us debug this:
>  Possible unsafe locking scenario:
> 
>        CPU0
>        ----
>   lock(rcu_node_0);
>   <Interrupt>
>     lock(rcu_node_0);
> 
>  *** DEADLOCK ***
> 
> 1 lock held by event_benchmark/105:
>  #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: print_other_cpu_stall kernel/rcu/tree_stall.h:512 [inline]
>  #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: check_cpu_stall kernel/rcu/tree_stall.h:671 [inline]
>  #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_pending kernel/rcu/tree.c:3760 [inline]
>  #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40 kernel/rcu/tree.c:2587
> 
> stack backtrace:
> CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
> Hardware name: linux,dummy-virt (DT)
> Call trace:
>  dump_backtrace+0x0/0x240 arch/arm64/kernel/stacktrace.c:100
>  show_stack+0x34/0x88 arch/arm64/kernel/stacktrace.c:196
>  __dump_stack lib/dump_stack.c:79 [inline]
>  dump_stack+0x140/0x1bc lib/dump_stack.c:120
>  print_usage_bug kernel/locking/lockdep.c:3738 [inline]
>  print_usage_bug+0x2a0/0x2f0 kernel/locking/lockdep.c:3705
>  valid_state kernel/locking/lockdep.c:3749 [inline]
>  mark_lock_irq kernel/locking/lockdep.c:3952 [inline]
>  mark_lock.part.0+0x438/0x4e8 kernel/locking/lockdep.c:4409
>  mark_lock kernel/locking/lockdep.c:4007 [inline]
>  mark_held_locks+0x54/0x90 kernel/locking/lockdep.c:4010
>  __trace_hardirqs_on_caller kernel/locking/lockdep.c:4028 [inline]
>  lockdep_hardirqs_on_prepare+0xe0/0x290 kernel/locking/lockdep.c:4096
>  trace_hardirqs_on+0x90/0x370 kernel/trace/trace_preemptirq.c:49
>  exit_to_kernel_mode.isra.0+0xf8/0x208 arch/arm64/kernel/entry-common.c:51
>  exit_el1_irq_or_nmi+0x24/0x38 arch/arm64/kernel/entry-common.c:101
>  el1_irq+0xe4/0x180 arch/arm64/kernel/entry.S:658
>  arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
>  __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
>  _raw_spin_unlock_irq+0x50/0x98 kernel/locking/spinlock.c:199
>  finish_lock_switch kernel/sched/core.c:4047 [inline]
>  finish_task_switch+0xb4/0x398 kernel/sched/core.c:4147
>  context_switch kernel/sched/core.c:4272 [inline]
>  __schedule+0x2e0/0x9a0 kernel/sched/core.c:5019
>  preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
>  arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
>  el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
>  arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
>  trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
>  benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
>  kthread+0x13c/0x188 kernel/kthread.c:292
>  ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929
> BUG: scheduling while atomic: event_benchmark/105/0x00000002
> INFO: lockdep is turned off.
> Modules linked in:
> Preemption disabled at:
> [<ffffa17ef3037114>] preempt_schedule_irq+0x3c/0xa0 kernel/sched/core.c:5279
> CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
> Hardware name: linux,dummy-virt (DT)
> Call trace:
>  dump_backtrace+0x0/0x240 arch/arm64/kernel/stacktrace.c:100
>  show_stack+0x34/0x88 arch/arm64/kernel/stacktrace.c:196
>  __dump_stack lib/dump_stack.c:79 [inline]
>  dump_stack+0x140/0x1bc lib/dump_stack.c:120
>  __schedule_bug+0xcc/0xe0 kernel/sched/core.c:4758
>  schedule_debug kernel/sched/core.c:4785 [inline]
>  __schedule+0x868/0x9a0 kernel/sched/core.c:4913
>  preempt_schedule_irq+0x4c/0xa0 kernel/sched/core.c:5281
>  arm64_preempt_schedule_irq+0xd0/0x118 arch/arm64/kernel/process.c:725
>  el1_irq+0xdc/0x180 arch/arm64/kernel/entry.S:653
>  arch_local_irq_enable arch/arm64/include/asm/irqflags.h:37 [inline]
>  trace_do_benchmark kernel/trace/trace_benchmark.c:56 [inline]
>  benchmark_event_kthread+0x144/0x4b0 kernel/trace/trace_benchmark.c:154
>  kthread+0x13c/0x188 kernel/kthread.c:292
>  ret_from_fork+0x10/0x34 arch/arm64/kernel/entry.S:929

> [    0.000000] Booting Linux on physical CPU 0x0000000000 [0x411fd070]
> [    0.000000] Linux version 5.10.0-rc4-next-20201119-00002-gc88aca8827ce (elver@elver.muc.corp.google.com) (aarch64-none-linux-gnu-gcc (GNU Toolchain for the A-profile Architecture 9.2-2019.12 (arm-9.10)) 9.2.1 20191025, GNU ld (GNU Toolchain for the A-profile Architecture 9.2-2019.12 (arm-9.10)) 2.33.1.20191209) #1 SMP PREEMPT Mon Nov 30 12:29:39 CET 2020
> [    0.000000] Machine model: linux,dummy-virt
> [    0.000000] efi: UEFI not found.
> [    0.000000] cma: Reserved 32 MiB at 0x00000000be000000
> [    0.000000] earlycon: pl11 at MMIO 0x0000000009000000 (options '')
> [    0.000000] printk: bootconsole [pl11] enabled
> [    0.000000] NUMA: No NUMA configuration found
> [    0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000000bfffffff]
> [    0.000000] NUMA: NODE_DATA [mem 0xbdbf6000-0xbdbf7fff]
> [    0.000000] Zone ranges:
> [    0.000000]   DMA      [mem 0x0000000040000000-0x000000007fffffff]
> [    0.000000]   DMA32    [mem 0x0000000080000000-0x00000000bfffffff]
> [    0.000000]   Normal   empty
> [    0.000000] Movable zone start for each node
> [    0.000000] Early memory node ranges
> [    0.000000]   node   0: [mem 0x0000000040000000-0x00000000bfffffff]
> [    0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000bfffffff]
> [    0.000000] On node 0 totalpages: 524288
> [    0.000000]   DMA zone: 4096 pages used for memmap
> [    0.000000]   DMA zone: 0 pages reserved
> [    0.000000]   DMA zone: 262144 pages, LIFO batch:63
> [    0.000000]   DMA32 zone: 4096 pages used for memmap
> [    0.000000]   DMA32 zone: 262144 pages, LIFO batch:63
> [    0.000000] psci: probing for conduit method from DT.
> [    0.000000] psci: PSCIv0.2 detected in firmware.
> [    0.000000] psci: Using standard PSCI v0.2 function IDs
> [    0.000000] psci: Trusted OS migration not required
> [    0.000000] percpu: Embedded 49 pages/cpu s162704 r8192 d29808 u200704
> [    0.000000] pcpu-alloc: s162704 r8192 d29808 u200704 alloc=49*4096
> [    0.000000] pcpu-alloc: [0] 0 
> [    0.000000] Detected PIPT I-cache on CPU0
> [    0.000000] CPU features: detected: ARM erratum 832075
> [    0.000000] CPU features: detected: ARM erratum 834220
> [    0.000000] CPU features: detected: EL2 vector hardening
> [    0.000000] CPU features: kernel page table isolation forced ON by KASLR
> [    0.000000] CPU features: detected: Kernel page table isolation (KPTI)
> [    0.000000] CPU features: detected: Spectre-v2
> [    0.000000] CPU features: detected: Spectre-v4
> [    0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923
> [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 516096
> [    0.000000] Policy zone: DMA32
> [    0.000000] Kernel command line: console=ttyAMA0 root=/dev/sda debug earlycon earlyprintk=serial slub_debug=UZ slub_debug=- workqueue.watchdog_thresh=10
> [    0.000000] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
> [    0.000000] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
> [    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
> [    0.000000] software IO TLB: mapped [mem 0x000000007bfff000-0x000000007ffff000] (64MB)
> [    0.000000] Memory: 1903696K/2097152K available (20800K kernel code, 4024K rwdata, 8508K rodata, 8896K init, 11238K bss, 160688K reserved, 32768K cma-reserved)
> [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
> [    0.000000] ftrace: allocating 56173 entries in 220 pages
> [    0.000000] ftrace: allocated 220 pages with 5 groups
> [    0.000000] Running RCU self tests
> [    0.000000] rcu: Preemptible hierarchical RCU implementation.
> [    0.000000] rcu: 	RCU event tracing is enabled.
> [    0.000000] rcu: 	RCU lockdep checking is enabled.
> [    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=1.
> [    0.000000] 	Trampoline variant of Tasks RCU enabled.
> [    0.000000] 	Rude variant of Tasks RCU enabled.
> [    0.000000] 	Tracing variant of Tasks RCU enabled.
> [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
> [    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
> [    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
> [    0.000000] GICv2m: range[mem 0x08020000-0x08020fff], SPI[80:143]
> [    0.000000] random: get_random_bytes called from start_kernel+0x468/0x670 with crng_init=0
> [    0.000000] arch_timer: cp15 timer(s) running at 62.50MHz (virt).
> [    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x1cd42e208c, max_idle_ns: 881590405314 ns
> [    0.000236] sched_clock: 56 bits at 62MHz, resolution 16ns, wraps every 4398046511096ns
> [    0.011810] Console: colour dummy device 80x25
> [    0.013175] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
> [    0.013507] ... MAX_LOCKDEP_SUBCLASSES:  8
> [    0.013762] ... MAX_LOCK_DEPTH:          48
> [    0.014021] ... MAX_LOCKDEP_KEYS:        8192
> [    0.014276] ... CLASSHASH_SIZE:          4096
> [    0.014529] ... MAX_LOCKDEP_ENTRIES:     32768
> [    0.014784] ... MAX_LOCKDEP_CHAINS:      65536
> [    0.015040] ... CHAINHASH_SIZE:          32768
> [    0.015295]  memory used by lock dependency info: 6365 kB
> [    0.015563]  memory used for stack traces: 4224 kB
> [    0.015825]  per task-struct memory footprint: 1920 bytes
> [    0.018643] Calibrating delay loop (skipped), value calculated using timer frequency.. 125.00 BogoMIPS (lpj=250000)
> [    0.019296] pid_max: default: 32768 minimum: 301
> [    0.022474] LSM: Security Framework initializing
> [    0.024666] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
> [    0.025865] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
> [    0.113064] rcu: Hierarchical SRCU implementation.
> [    0.132492] EFI services will not be available.
> [    0.137227] smp: Bringing up secondary CPUs ...
> [    0.137657] smp: Brought up 1 node, 1 CPU
> [    0.137985] SMP: Total of 1 processors activated.
> [    0.138417] CPU features: detected: 32-bit EL0 Support
> [    0.139154] CPU features: detected: CRC32 instructions
> [    0.139529] CPU features: detected: 32-bit EL1 Support
> [    0.563634] CPU: All CPU(s) started at EL1
> [    0.564913] alternatives: patching kernel code
> [    0.623566] devtmpfs: initialized
> [    0.695671] KASLR enabled
> [    0.724860] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
> [    0.725586] futex hash table entries: 256 (order: 3, 32768 bytes, linear)
> [    0.727427] Running postponed tracer tests:
> [    0.731229] Testing tracer function: PASSED
> [    8.838201] Testing dynamic ftrace: PASSED
> [    9.788507] Testing dynamic ftrace ops #1: 
> [   12.441107] (1 0 1 0 0) 
> [   12.441603] (1 1 2 0 0) 
> [   20.513697] (2 1 3 0 1132022) 
> [   20.516513] (2 2 4 0 1132450) PASSED
> [   24.660860] Testing dynamic ftrace ops #2: 
> [   34.874589] (1 0 1 1111841 0) 
> [   34.875920] (1 1 2 1112053 0) 
> [   34.941152] (2 1 3 1 2837) 
> [   34.942414] (2 2 4 200 3036) PASSED
> [   38.187248] Testing ftrace recursion: PASSED
> [   38.937602] Testing ftrace recursion safe: PASSED
> [   39.684401] Testing ftrace regs: PASSED
> [   40.438336] Testing tracer nop: PASSED
> [   40.442591] Testing tracer irqsoff: PASSED
> [   48.502343] Testing tracer preemptoff: PASSED
> [   56.603251] Testing tracer preemptirqsoff: PASSED
> [   64.741333] Testing tracer wakeup: PASSED
> [   72.700877] Testing tracer wakeup_rt: PASSED
> [   80.672483] Testing tracer wakeup_dl: PASSED
> [   88.647205] Testing tracer function_graph: PASSED
> [   95.311654] pinctrl core: initialized pinctrl subsystem
> [   95.357604] DMI not present or invalid.
> [   95.377573] NET: Registered protocol family 16
> [   95.442282] DMA: preallocated 256 KiB GFP_KERNEL pool for atomic allocations
> [   95.443718] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
> [   95.446121] DMA: preallocated 256 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
> [   95.448632] audit: initializing netlink subsys (disabled)
> [   95.457722] audit: type=2000 audit(83.900:1): state=initialized audit_enabled=0 res=1
> [   95.495840] thermal_sys: Registered thermal governor 'step_wise'
> [   95.496081] thermal_sys: Registered thermal governor 'power_allocator'
> [   95.499286] cpuidle: using governor menu
> [   95.505170] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
> [   95.506521] ASID allocator initialised with 32768 entries
> [   95.541565] Serial: AMBA PL011 UART driver
> [   96.469419] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 47, base_baud = 0) is a PL011 rev1
> [   96.472001] printk: console [ttyAMA0] enabled
> [   96.472001] printk: console [ttyAMA0] enabled
> [   96.472789] printk: bootconsole [pl11] disabled
> [   96.472789] printk: bootconsole [pl11] disabled
> [   96.934788] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
> [   96.935322] HugeTLB registered 32.0 MiB page size, pre-allocated 0 pages
> [   96.936042] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
> [   96.936454] HugeTLB registered 64.0 KiB page size, pre-allocated 0 pages
> [   97.007523] cryptd: max_cpu_qlen set to 1000
> [   97.143352] ACPI: Interpreter disabled.
> [   97.207646] iommu: Default domain type: Translated 
> [   97.216776] vgaarb: loaded
> [   97.228660] SCSI subsystem initialized
> [   97.234310] libata version 3.00 loaded.
> [   97.243658] usbcore: registered new interface driver usbfs
> [   97.245446] usbcore: registered new interface driver hub
> [   97.247375] usbcore: registered new device driver usb
> [   97.271932] pps_core: LinuxPPS API ver. 1 registered
> [   97.272326] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
> [   97.273108] PTP clock support registered
> [   97.278967] EDAC MC: Ver: 3.0.0
> [   97.330734] FPGA manager framework
> [   97.334916] Advanced Linux Sound Architecture Driver Initialized.
> [   97.367534] clocksource: Switched to clocksource arch_sys_counter
> [  114.521600] VFS: Disk quotas dquot_6.6.0
> [  114.523765] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
> [  114.533650] pnp: PnP ACPI: disabled
> [  114.765263] NET: Registered protocol family 2
> [  114.788981] tcp_listen_portaddr_hash hash table entries: 1024 (order: 4, 81920 bytes, linear)
> [  114.790064] TCP established hash table entries: 16384 (order: 5, 131072 bytes, linear)
> [  114.798325] TCP bind hash table entries: 16384 (order: 8, 1179648 bytes, linear)
> [  114.806169] TCP: Hash tables configured (established 16384 bind 16384)
> [  114.810413] UDP hash table entries: 1024 (order: 5, 163840 bytes, linear)
> [  114.814124] UDP-Lite hash table entries: 1024 (order: 5, 163840 bytes, linear)
> [  114.819502] NET: Registered protocol family 1
> [  114.837488] RPC: Registered named UNIX socket transport module.
> [  114.838082] RPC: Registered udp transport module.
> [  114.838453] RPC: Registered tcp transport module.
> [  114.838809] RPC: Registered tcp NFSv4.1 backchannel transport module.
> [  114.839760] PCI: CLS 0 bytes, default 64
> [  114.870930] hw perfevents: enabled with armv8_pmuv3 PMU driver, 5 counters available
> [  114.873385] kvm [1]: HYP mode not available
> [  115.096835] Initialise system trusted keyrings
> [  115.102788] workingset: timestamp_bits=44 max_order=19 bucket_order=0
> [  115.399347] squashfs: version 4.0 (2009/01/31) Phillip Lougher
> [  115.420555] NFS: Registering the id_resolver key type
> [  115.422030] Key type id_resolver registered
> [  115.422598] Key type id_legacy registered
> [  115.426472] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
> [  115.434896] 9p: Installing v9fs 9p2000 file system support
> [  115.521422] Key type asymmetric registered
> [  115.522091] Asymmetric key parser 'x509' registered
> [  115.523839] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
> [  115.524497] io scheduler mq-deadline registered
> [  115.524989] io scheduler kyber registered
> [  115.894160] pl061_gpio 9030000.pl061: PL061 GPIO chip registered
> [  115.952465] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:
> [  115.954473] pci-host-generic 4010000000.pcie:       IO 0x003eff0000..0x003effffff -> 0x0000000000
> [  115.956630] pci-host-generic 4010000000.pcie:      MEM 0x0010000000..0x003efeffff -> 0x0010000000
> [  115.957484] pci-host-generic 4010000000.pcie:      MEM 0x8000000000..0xffffffffff -> 0x8000000000
> [  115.960592] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]
> [  115.965840] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00
> [  115.966564] pci_bus 0000:00: root bus resource [bus 00-ff]
> [  115.967435] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
> [  115.967879] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]
> [  115.968308] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]
> [  115.970981] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000
> [  115.982358] pci 0000:00:01.0: [1af4:1009] type 00 class 0x000200
> [  115.983896] pci 0000:00:01.0: reg 0x10: [io  0x0000-0x003f]
> [  115.984527] pci 0000:00:01.0: reg 0x14: [mem 0x00000000-0x00000fff]
> [  115.985710] pci 0000:00:01.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
> [  115.993649] pci 0000:00:02.0: [1af4:1009] type 00 class 0x000200
> [  115.994489] pci 0000:00:02.0: reg 0x10: [io  0x0000-0x003f]
> [  115.995425] pci 0000:00:02.0: reg 0x14: [mem 0x00000000-0x00000fff]
> [  115.996526] pci 0000:00:02.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
> [  116.004182] pci 0000:00:03.0: [1af4:1000] type 00 class 0x020000
> [  116.005039] pci 0000:00:03.0: reg 0x10: [io  0x0000-0x001f]
> [  116.005630] pci 0000:00:03.0: reg 0x14: [mem 0x00000000-0x00000fff]
> [  116.006717] pci 0000:00:03.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
> [  116.007694] pci 0000:00:03.0: reg 0x30: [mem 0x00000000-0x0003ffff pref]
> [  116.014983] pci 0000:00:04.0: [1af4:1004] type 00 class 0x010000
> [  116.016150] pci 0000:00:04.0: reg 0x10: [io  0x0000-0x003f]
> [  116.016744] pci 0000:00:04.0: reg 0x14: [mem 0x00000000-0x00000fff]
> [  116.017823] pci 0000:00:04.0: reg 0x20: [mem 0x00000000-0x00003fff 64bit pref]
> [  116.031717] pci 0000:00:03.0: BAR 6: assigned [mem 0x10000000-0x1003ffff pref]
> [  116.032501] pci 0000:00:01.0: BAR 4: assigned [mem 0x8000000000-0x8000003fff 64bit pref]
> [  116.033388] pci 0000:00:02.0: BAR 4: assigned [mem 0x8000004000-0x8000007fff 64bit pref]
> [  116.034240] pci 0000:00:03.0: BAR 4: assigned [mem 0x8000008000-0x800000bfff 64bit pref]
> [  116.035359] pci 0000:00:04.0: BAR 4: assigned [mem 0x800000c000-0x800000ffff 64bit pref]
> [  116.036108] pci 0000:00:01.0: BAR 1: assigned [mem 0x10040000-0x10040fff]
> [  116.036664] pci 0000:00:02.0: BAR 1: assigned [mem 0x10041000-0x10041fff]
> [  116.037196] pci 0000:00:03.0: BAR 1: assigned [mem 0x10042000-0x10042fff]
> [  116.037723] pci 0000:00:04.0: BAR 1: assigned [mem 0x10043000-0x10043fff]
> [  116.038274] pci 0000:00:01.0: BAR 0: assigned [io  0x1000-0x103f]
> [  116.038817] pci 0000:00:02.0: BAR 0: assigned [io  0x1040-0x107f]
> [  116.039686] pci 0000:00:04.0: BAR 0: assigned [io  0x1080-0x10bf]
> [  116.040213] pci 0000:00:03.0: BAR 0: assigned [io  0x10c0-0x10df]
> [  116.110878] EINJ: ACPI disabled.
> [  116.586823] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)
> [  116.601358] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)
> [  116.613837] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)
> [  116.624404] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)
> [  116.807519] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
> [  116.898052] SuperH (H)SCI(F) driver initialized
> [  116.916586] msm_serial: driver initialized
> [  116.966160] cacheinfo: Unable to detect cache hierarchy for CPU 0
> [  117.230609] loop: module loaded
> [  117.261553] megasas: 07.714.04.00-rc1
> [  117.299460] scsi host0: Virtio SCSI HBA
> [  117.332400] scsi 0:0:0:0: Direct-Access     QEMU     QEMU HARDDISK    2.5+ PQ: 0 ANSI: 5
> [  119.896235] random: fast init done
> [  119.962094] sd 0:0:0:0: Power-on or device reset occurred
> [  119.988603] sd 0:0:0:0: [sda] 524288 512-byte logical blocks: (268 MB/256 MiB)
> [  119.990909] sd 0:0:0:0: [sda] Write Protect is off
> [  119.991894] sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08
> [  120.000849] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> [  120.005403] sda: detected capacity change from 0 to 268435456
> [  120.104701] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]
> [  120.107055] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
> [  120.113218] Intel/Sharp Extended Query Table at 0x0031
> [  120.114867] Using buffer write method
> [  120.125192] erase region 0: offset=0x0,size=0x40000,blocks=256
> [  120.126226] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]
> [  120.127789] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000
> [  120.128353] Intel/Sharp Extended Query Table at 0x0031
> [  120.129355] Using buffer write method
> [  120.129810] erase region 0: offset=0x0,size=0x40000,blocks=256
> [  120.130313] Concatenating MTD devices:
> [  120.130686] (0): "0.flash"
> [  120.135876] (1): "0.flash"
> [  120.136225] into device "0.flash"
> [  120.192278] sda: detected capacity change from 0 to 268435456
> [  120.193045] sd 0:0:0:0: [sda] Attached SCSI disk
> [  120.387475] libphy: Fixed MDIO Bus: probed
> [  120.432985] tun: Universal TUN/TAP device driver, 1.6
> [  120.489130] thunder_xcv, ver 1.0
> [  120.490797] thunder_bgx, ver 1.0
> [  120.492770] nicpf, ver 1.0
> [  120.537316] hclge is initializing
> [  120.538538] hns3: Hisilicon Ethernet Network Driver for Hip08 Family - version
> [  120.538958] hns3: Copyright (c) 2017 Huawei Corporation.
> [  120.541156] e1000: Intel(R) PRO/1000 Network Driver
> [  120.541528] e1000: Copyright (c) 1999-2006 Intel Corporation.
> [  120.543589] e1000e: Intel(R) PRO/1000 Network Driver
> [  120.543956] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
> [  120.545789] igb: Intel(R) Gigabit Ethernet Network Driver
> [  120.546176] igb: Copyright (c) 2007-2014 Intel Corporation.
> [  120.547883] igbvf: Intel(R) Gigabit Virtual Function Network Driver
> [  120.548276] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
> [  120.562052] sky2: driver version 1.30
> [  120.597519] VFIO - User Level meta-driver version: 0.3
> [  120.658110] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> [  120.658597] ehci-pci: EHCI PCI platform driver
> [  120.660406] ehci-platform: EHCI generic platform driver
> [  120.664987] ehci-orion: EHCI orion driver
> [  120.669400] ehci-exynos: EHCI Exynos driver
> [  120.673747] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
> [  120.674701] ohci-pci: OHCI PCI platform driver
> [  120.676572] ohci-platform: OHCI generic platform driver
> [  120.681095] ohci-exynos: OHCI Exynos driver
> [  120.697532] usbcore: registered new interface driver usb-storage
> [  120.806431] rtc-pl031 9010000.pl031: registered as rtc0
> [  120.808336] rtc-pl031 9010000.pl031: setting system clock to 2020-11-30T11:37:20 UTC (1606736240)
> [  120.831534] i2c /dev entries driver
> [  121.067859] sdhci: Secure Digital Host Controller Interface driver
> [  121.068255] sdhci: Copyright(c) Pierre Ossman
> [  121.084261] Synopsys Designware Multimedia Card Interface Driver
> [  121.122438] sdhci-pltfm: SDHCI platform and OF driver helper
> [  121.176067] ledtrig-cpu: registered to indicate activity on CPUs
> [  121.237585] usbcore: registered new interface driver usbhid
> [  121.237987] usbhid: USB HID core driver
> [  121.414229] drop_monitor: Initializing network drop monitor service
> [  121.418007] NET: Registered protocol family 17
> [  121.424102] 9pnet: Installing 9P2000 support
> [  121.443895] Key type dns_resolver registered
> [  121.451895] registered taskstats version 1
> [  121.453581] Running tests on all trace events:
> [  121.453937] Testing all events: OK
> [  180.314804] Running tests again, along with the function tracer
> [  180.334448] Running tests on all trace events:
> [  180.346904] Testing all events: 
> [  186.731798] hrtimer: interrupt took 10487664 ns
> [  219.711287] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 13s!
> [  219.875132] Showing busy workqueues and worker pools:
> [  219.910747] workqueue events: flags=0x0
> [  219.939591]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  219.951310]     pending: vmstat_shepherd
> [  219.963073] workqueue events_power_efficient: flags=0x82
> [  219.999935]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
> [  220.009975]     in-flight: 7:do_cache_clean
> [  220.030092] pool 2: cpus=0 flags=0x4 nice=0 hung=0s workers=3 idle: 61 99
> [  230.303201] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 24s!
> [  230.410755] Showing busy workqueues and worker pools:
> [  230.427157] workqueue events: flags=0x0
> [  230.443262]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  230.454087]     pending: vmstat_shepherd
> [  351.797552] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 11s!
> [  351.843185] Showing busy workqueues and worker pools:
> [  351.875356] workqueue events: flags=0x0
> [  351.906690]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  351.917412]     pending: vmstat_shepherd
> [  351.938890] workqueue events_power_efficient: flags=0x82
> [  351.970790]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
> [  351.979994]     pending: neigh_periodic_work
> [  389.525557] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 17s!
> [  389.600725] Showing busy workqueues and worker pools:
> [  389.617453] workqueue events: flags=0x0
> [  389.623272]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  389.634046]     pending: vmstat_shepherd
> [  389.650704] workqueue events_power_efficient: flags=0x82
> [  389.671328]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
> [  389.680463]     in-flight: 7:neigh_periodic_work
> [  389.704734] pool 2: cpus=0 flags=0x4 nice=0 hung=9s workers=3 idle: 61 99
> [  453.731592] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
> [  453.790537] Showing busy workqueues and worker pools:
> [  453.796398] workqueue events: flags=0x0
> [  453.823200]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  453.833529]     pending: vmstat_shepherd
> [  453.852558] workqueue events_power_efficient: flags=0x82
> [  453.858588]   pwq 2: cpus=0 flags=0x5 nice=0 active=2/256 refcnt=4
> [  453.867424]     in-flight: 7:do_cache_clean
> [  453.874323]     pending: neigh_periodic_work
> [  453.894345] pool 2: cpus=0 flags=0x5 nice=0 hung=8s workers=2 manager: 61
> [  598.019250] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 16s!
> [  598.131254] Showing busy workqueues and worker pools:
> [  598.200541] workqueue events: flags=0x0
> [  598.217960]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  598.228669]     pending: vmstat_shepherd
> [  598.246863] workqueue events_power_efficient: flags=0x82
> [  598.279406]   pwq 2: cpus=0 flags=0x4 nice=0 active=1/256 refcnt=3
> [  598.288499]     in-flight: 106:do_cache_clean
> [  598.319372] pool 2: cpus=0 flags=0x4 nice=0 hung=8s workers=3 idle: 61 7
> [  795.287162] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 10s!
> [  795.311095] BUG: workqueue lockup - pool cpus=0 flags=0x4 nice=0 stuck for 10s!
> [  795.334433] Showing busy workqueues and worker pools:
> [  795.343043] workqueue events: flags=0x0
> [  795.354006]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  795.361092]     pending: vmstat_shepherd
> [  795.370452] workqueue events_power_efficient: flags=0x82
> [  795.379095]   pwq 2: cpus=0 flags=0x4 nice=0 active=3/256 refcnt=5
> [  795.385173]     in-flight: 106:check_lifetime
> [  795.389953]     pending: neigh_periodic_work, do_cache_clean
> [  795.401803] pool 2: cpus=0 flags=0x4 nice=0 hung=10s workers=3 idle: 61 7
> [  840.280588] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 15s!
> [  840.370856] Showing busy workqueues and worker pools:
> [  840.400495] workqueue events: flags=0x0
> [  840.417468]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  840.427827]     pending: vmstat_shepherd
> [  840.473295] pool 2: cpus=0 flags=0x5 nice=0 hung=6s workers=3 manager: 7 idle: 106 61
> [  889.716728] BUG: workqueue lockup - pool cpus=0 node=0 flags=0x0 nice=0 stuck for 12s!
> [  889.787233] BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 12s!
> [  889.936565] Showing busy workqueues and worker pools:
> [  889.953557] workqueue events: flags=0x0
> [  889.959094]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  889.969435]     pending: vmstat_shepherd
> [  889.990858] workqueue events_power_efficient: flags=0x82
> [  890.022774]   pwq 2: cpus=0 flags=0x5 nice=0 active=1/256 refcnt=3
> [  890.031587]     pending: neigh_periodic_work
> [  890.059229] pool 2: cpus=0 flags=0x5 nice=0 hung=12s workers=3 manager: 7 idle: 106 61
> [  903.560770] BUG: workqueue lockup - pool cpus=0 flags=0x5 nice=0 stuck for 25s!
> [  903.610830] Showing busy workqueues and worker pools:
> [  903.616897] workqueue events: flags=0x0
> [  903.633819]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
> [  903.644574]     in-flight: 15:vmstat_shepherd
> [  903.662870] workqueue events_power_efficient: flags=0x82
> [  903.726795]   pwq 2: cpus=0 flags=0x5 nice=0 active=3/256 refcnt=5
> [  903.736114]     pending: neigh_periodic_work, do_cache_clean, check_lifetime
> [  903.758987] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=2s workers=2 idle: 5
> [  903.785300] pool 2: cpus=0 flags=0x5 nice=0 hung=26s workers=4 manager: 7 idle: 107 106 61
> [ 1211.521119] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> [ 1211.527302] 	(detected by 0, t=3752 jiffies, g=2329, q=2)
> [ 1211.529303] rcu: All QSes seen, last rcu_preempt kthread activity 3503 (4295192252-4295188749), jiffies_till_next_fqs=1, root ->qsmask 0x0
> [ 1211.540472] rcu: rcu_preempt kthread starved for 3503 jiffies! g2329 f0x2 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=0
> [ 1211.546502] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> [ 1211.552234] rcu: RCU grace-period kthread stack dump:
> [ 1211.556893] task:rcu_preempt     state:R  running task     stack:    0 pid:   10 ppid:     2 flags:0x00000428
> [ 1211.566196] Call trace:
> [ 1211.570036]  __switch_to+0x148/0x1f0
> [ 1211.574189]  __schedule+0x2dc/0x9a0
> [ 1211.578355]  preempt_schedule_notrace+0x70/0x1c0
> [ 1211.582822]  ftrace_ops_list_func+0x10c/0x218
> [ 1211.587212]  ftrace_graph_call+0x0/0x4
> [ 1211.591434]  preempt_count_add+0x8/0x1a0
> [ 1211.595716]  schedule+0x44/0x100
> [ 1211.599779]  schedule_timeout+0x240/0x538
> [ 1211.604098]  rcu_gp_kthread+0x618/0x1bd8
> [ 1211.608398]  kthread+0x13c/0x188
> [ 1211.612480]  ret_from_fork+0x10/0x34
> [ 1211.616726] rcu: Stack dump where RCU GP kthread last ran:
> [ 1211.621458] Task dump for CPU 0:
> [ 1211.625472] task:event_benchmark state:R  running task     stack:    0 pid:  105 ppid:     2 flags:0x0000042a
> [ 1211.634526] Call trace:
> [ 1211.638364]  dump_backtrace+0x0/0x240
> [ 1211.642586]  show_stack+0x34/0x88
> [ 1211.646715]  sched_show_task+0x208/0x230
> [ 1211.650995]  dump_cpu_task+0x4c/0x5c
> [ 1211.655215]  rcu_check_gp_kthread_starvation+0x240/0x388
> [ 1211.659949]  rcu_sched_clock_irq+0xc2c/0xd40
> [ 1211.664331]  update_process_times+0x6c/0xb8
> [ 1211.668703]  tick_sched_handle.isra.0+0x58/0x88
> [ 1211.673168]  tick_sched_timer+0x68/0xe0
> [ 1211.677459]  __hrtimer_run_queues+0x288/0x730
> [ 1211.681873]  hrtimer_interrupt+0x114/0x288
> [ 1211.686235]  arch_timer_handler_virt+0x50/0x70
> [ 1211.690664]  handle_percpu_devid_irq+0x104/0x4c0
> [ 1211.695127]  generic_handle_irq+0x54/0x78
> [ 1211.699396]  __handle_domain_irq+0xac/0x130
> [ 1211.703736]  gic_handle_irq+0x70/0x108
> [ 1211.707949]  el1_irq+0xc4/0x180
> [ 1211.711937]  _raw_spin_unlock_irq+0x50/0x98
> [ 1211.716304]  finish_task_switch+0xb4/0x398
> [ 1211.720649]  __schedule+0x2e0/0x9a0
> [ 1211.724815]  preempt_schedule_irq+0x4c/0xa0
> [ 1211.729191]  arm64_preempt_schedule_irq+0xd0/0x118
> [ 1211.733737]  el1_irq+0xdc/0x180
> [ 1211.737771]  benchmark_event_kthread+0x144/0x4b0
> [ 1211.742255]  kthread+0x13c/0x188
> [ 1211.746320]  ret_from_fork+0x10/0x34
> [ 1211.755343] 
> [ 1211.757649] ================================
> [ 1211.760669] WARNING: inconsistent lock state
> [ 1211.763880] 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1 Not tainted
> [ 1211.767588] --------------------------------
> [ 1211.770630] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
> [ 1211.774224] event_benchmark/105 [HC0[0]:SC0[0]:HE0:SE1] takes:
> [ 1211.777779] ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40
> [ 1211.785746] {IN-HARDIRQ-W} state was registered at:
> [ 1211.789124]   __lock_acquire+0xae8/0x1b00
> [ 1211.792183]   lock_acquire+0x268/0x508
> [ 1211.795161]   _raw_spin_lock_irqsave+0x78/0x14c
> [ 1211.798335]   rcu_sched_clock_irq+0x428/0xd40
> [ 1211.801476]   update_process_times+0x6c/0xb8
> [ 1211.804567]   tick_sched_handle.isra.0+0x58/0x88
> [ 1211.807746]   tick_sched_timer+0x68/0xe0
> [ 1211.810778]   __hrtimer_run_queues+0x288/0x730
> [ 1211.813963]   hrtimer_interrupt+0x114/0x288
> [ 1211.817035]   arch_timer_handler_virt+0x50/0x70
> [ 1211.820187]   handle_percpu_devid_irq+0x104/0x4c0
> [ 1211.823434]   generic_handle_irq+0x54/0x78
> [ 1211.826498]   __handle_domain_irq+0xac/0x130
> [ 1211.829584]   gic_handle_irq+0x70/0x108
> [ 1211.832555]   el1_irq+0xc4/0x180
> [ 1211.835370]   _raw_spin_unlock_irq+0x50/0x98
> [ 1211.838473]   finish_task_switch+0xb4/0x398
> [ 1211.841540]   __schedule+0x2e0/0x9a0
> [ 1211.844477]   preempt_schedule_irq+0x4c/0xa0
> [ 1211.847590]   arm64_preempt_schedule_irq+0xd0/0x118
> [ 1211.850859]   el1_irq+0xdc/0x180
> [ 1211.853636]   benchmark_event_kthread+0x144/0x4b0
> [ 1211.856906]   kthread+0x13c/0x188
> [ 1211.859729]   ret_from_fork+0x10/0x34
> [ 1211.862686] irq event stamp: 67642
> [ 1211.865588] hardirqs last  enabled at (67641): [<ffffa17ef303ec78>] _raw_spin_unlock_irq+0x48/0x98
> [ 1211.870078] hardirqs last disabled at (67642): [<ffffa17ef30310a8>] enter_el1_irq_or_nmi+0x20/0x30
> [ 1211.874532] softirqs last  enabled at (63366): [<ffffa17ef1c10b80>] __do_softirq+0x630/0x6b4
> [ 1211.878770] softirqs last disabled at (63347): [<ffffa17ef1cc5c74>] irq_exit+0x1cc/0x1e0
> [ 1211.882828] 
> [ 1211.882828] other info that might help us debug this:
> [ 1211.886512]  Possible unsafe locking scenario:
> [ 1211.886512] 
> [ 1211.889961]        CPU0
> [ 1211.892451]        ----
> [ 1211.894935]   lock(rcu_node_0);
> [ 1211.899732]   <Interrupt>
> [ 1211.902272]     lock(rcu_node_0);
> [ 1211.906707] 
> [ 1211.906707]  *** DEADLOCK ***
> [ 1211.906707] 
> [ 1211.910237] 1 lock held by event_benchmark/105:
> [ 1211.913352]  #0: ffffa17ef42247d8 (rcu_node_0){?.-.}-{2:2}, at: rcu_sched_clock_irq+0x428/0xd40
> [ 1211.922068] 
> [ 1211.922068] stack backtrace:
> [ 1211.925381] CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
> [ 1211.930018] Hardware name: linux,dummy-virt (DT)
> [ 1211.933192] Call trace:
> [ 1211.935795]  dump_backtrace+0x0/0x240
> [ 1211.938733]  show_stack+0x34/0x88
> [ 1211.941539]  dump_stack+0x140/0x1bc
> [ 1211.944421]  print_usage_bug+0x2a0/0x2f0
> [ 1211.947405]  mark_lock.part.0+0x438/0x4e8
> [ 1211.950420]  mark_held_locks+0x54/0x90
> [ 1211.953393]  lockdep_hardirqs_on_prepare+0xe0/0x290
> [ 1211.956665]  trace_hardirqs_on+0x90/0x370
> [ 1211.959701]  exit_to_kernel_mode.isra.0+0xf8/0x208
> [ 1211.962948]  exit_el1_irq_or_nmi+0x24/0x38
> [ 1211.965971]  el1_irq+0xe4/0x180
> [ 1211.968779]  _raw_spin_unlock_irq+0x50/0x98
> [ 1211.971832]  finish_task_switch+0xb4/0x398
> [ 1211.974885]  __schedule+0x2e0/0x9a0
> [ 1211.977744]  preempt_schedule_irq+0x4c/0xa0
> [ 1211.980856]  arm64_preempt_schedule_irq+0xd0/0x118
> [ 1211.984101]  el1_irq+0xdc/0x180
> [ 1211.986889]  benchmark_event_kthread+0x144/0x4b0
> [ 1211.990118]  kthread+0x13c/0x188
> [ 1211.992910]  ret_from_fork+0x10/0x34
> [ 1211.998610] BUG: scheduling while atomic: event_benchmark/105/0x00000002
> [ 1212.010060] INFO: lockdep is turned off.
> [ 1212.018261] Modules linked in:
> [ 1212.030227] Preemption disabled at:
> [ 1212.034171] [<ffffa17ef3037114>] preempt_schedule_irq+0x3c/0xa0
> [ 1212.049696] CPU: 0 PID: 105 Comm: event_benchmark Not tainted 5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1
> [ 1212.054368] Hardware name: linux,dummy-virt (DT)
> [ 1212.057507] Call trace:
> [ 1212.060101]  dump_backtrace+0x0/0x240
> [ 1212.063052]  show_stack+0x34/0x88
> [ 1212.065890]  dump_stack+0x140/0x1bc
> [ 1212.068791]  __schedule_bug+0xcc/0xe0
> [ 1212.071729]  __schedule+0x868/0x9a0
> [ 1212.074625]  preempt_schedule_irq+0x4c/0xa0
> [ 1212.077714]  arm64_preempt_schedule_irq+0xd0/0x118
> [ 1212.080945]  el1_irq+0xdc/0x180
> [ 1212.083732]  benchmark_event_kthread+0x144/0x4b0
> [ 1212.086931]  kthread+0x13c/0x188
> [ 1212.089704]  ret_from_fork+0x10/0x34
Mark Rutland Nov. 30, 2020, 4:54 p.m. UTC | #4 
On Mon, Nov 30, 2020 at 02:32:45PM +0100, Marco Elver wrote:
> On Mon, Nov 30, 2020 at 12:38PM +0000, Mark Rutland wrote:
> > On Mon, Nov 30, 2020 at 01:03:05PM +0100, Marco Elver wrote:

> > > So, I was hoping that this would fix all the problems I was seeing when
> > > running the ftrace tests ... unfortunately, it didn't. :-( Perhaps the
> > > WIP version you had only worked because it ended up disabling lockdep
> > > early?
> > 
> > Possibly, yes. Either that or the way we do / do-not treat debug
> > exceptions as true NMIs. Either way this appears to be a latent issue
> > rather than something introduced by this series.
> > 
> > From the log below I see you're using:
> > 
> >   5.10.0-rc4-next-20201119-00002-gc88aca8827ce #1 Not tainted
> > 
> > ... and it's possible that the issue you're seeing now is a delta
> > between v5.10-rc3 and what's queued in linux-next -- I've been running
> > the ftrace tests locally without issue atop v5.10-rc3 and v5.10-rc5.
> > 
> > Are you able to reproduce this on my branch alone? If so that gives us a
> > stable tree to investigate, and if not that gives us a stable base for a
> > bisect against linux-next.
> 
> It's the same problem as before and that I've been reporting in the
> other thread [1]. We know mainline is fine, however, -next is broken. We
> also know that next-20201105 was still fine, and next-202010 started
> breaking:
> 
> 	https://lkml.kernel.org/r/20201111133813.GA81547@elver.google.com
> 
> The recent tests have been on next-20201119 (including the logs from
> previous email).
>
> I tried bisection, but results are never conclusive (the closest I got
> was a -rcu merge commit). As discussed in the thread at [1] (and its
> ancestors) we never really got anywhere and really exhausted all options
> (several bisection attempts, etc.).

Ah; I'd lost track and missed that you'd already identified this was
introduced in linux-next, and that bisection wasn't getting anywhere.
Thanks for bearing with me! :)

> > This area is really sensitive to config options, so if you can reproduce
> > this on a stable base, could you share youir exact config?
> 
> No, it's not reproducible on mainline.
> 
> Which might also mean that it's something else in -next and your work is
> unrelated.
> 
> But I was surprised your WIP series fixed the problems on next-20201119
> (or so it seemed). So, given all the confusion in [1], I was really
> hoping this would be it...

The major difference between that and the version upstreamed is the way
debug exceptions (including BRKs) got handled as true NMIs, which hints
that there could be a subtle interaction in that area (or that the
lockdep disable calls in the NMI paths simply masked the problem).

One simple thing to try would be to hack the debug exception cases to
enter/exit as true NMIs and see whether that hides the issue again. If
so, we can start teasing that apart to narrow it down.

> > > I've attached the log and the symbolized report.
> > 
> > Thanks for all this. I'll see if I can tickle this locally while waiting
> > for the above. If you could share your config from this time around
> > that'd be a great head-start!
> 
> It's the same as I've been using for the work in
> 
> 	[1] https://lore.kernel.org/r/20201119193819.GA2601289@elver.google.com
> 
> In summary, to repro:
> 
> 	1. Switch to next-20201119 (possibly even latest, but I haven't tested)
> 
> 	2. Apply provoke-bug.diff
> 
> 	3. Use the attached .config
> 
> 	4. Run with 
> 
> 	   qemu-system-aarch64 -kernel $KERNEL_WORKTREE/arch/arm64/boot/Image \
> 		-append "console=ttyAMA0 root=/dev/sda debug earlycon earlyprintk=serial workqueue.watchdog_thresh=10" \
> 		-nographic -smp 1 -machine virt -cpu cortex-a57 -m 2G

Thanks for the comprehensive repro information!

I note that you're using QEMU in TCG mode, whereas I've been testing
with KVM acceleration. Those differ in speed by ordered of magnitude, so
I wonder if the stalls you see are down to TCG simply being slow, and my
patches just happened to shuffle where that slowness was felt.

I gave the above a go, but I wasn't able to reproduce the issue under
either TCG or KVM acceleration after a few attempts. I'm not sure
whether this is intermittent and I'm just getting lucky, or if something
is different between our setups that's causing me to not hit this.

FWIW I'm testing on a ThunderX2 workstation running Debian 10.6, using
the packaged GCC 8.3.0-6, and a locally-built QEMU 5.1.50
(v5.1.0-2347-g1f3081f6de). The QEMU has a couple of test patches atop
upstream commit ba2a9a9e6318bfd93a2306dec40137e198205b86.

> The tests I ran on your WIP series and just now were applied on top of
> next-20201119+provoke-bug.diff. Your WIP series seemed to fix whatever
> it was we were debugging in [1] (but with some new warnings), but this
> latest series shows no difference and behaviour is unchanged again.
> 
> I also want to emphasize it is really hard to say if your series here is
> related or the fact that the WIP series worked was some other
> side-effect we don't understand.

Sure; I think we're aligned on that understanding. There are a
sufficient number of moving parts here that the WIP might have been
masking a problem, or might have unintentionally solved a problem we
haven't realised exists.

> So I leave it to your judgement to decide to what extent this series
> could possibly help, because I wouldn't want to make you go down a
> rabbit hole that doesn't lead anywhere (as I had already done to
> somehow debug the problem in [1]).

I think as you say it's not at all clear, but I'd hope this series at
least removes a number of potential problems from the search space.

Thanks,
Mark.