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

From: Marco Elver <elver@google.com>
To: Mark Rutland <mark.rutland@arm.com>
Cc: paulmck@kernel.org, peterz@infradead.org,
	catalin.marinas@arm.com, james.morse@arm.com,
	linux-arm-kernel@lists.infradead.org, will@kernel.org,
	dvyukov@google.com
Subject: Re: [PATCH 00/11] arm64: entry lockdep/rcu/tracing fixes
Date: Mon, 30 Nov 2020 13:03:05 +0100	[thread overview]
Message-ID: <20201130120305.GA1292961@elver.google.com> (raw)
In-Reply-To: <20201126123602.23454-1-mark.rutland@arm.com>

[-- Attachment #1: Type: text/plain, Size: 2918 bytes --]

[ 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

[-- Attachment #2: dmesg-symbolized --]
[-- Type: text/plain, Size: 16169 bytes --]

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

[-- Attachment #3: vm.log --]
[-- Type: text/plain, Size: 32807 bytes --]

[    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

[-- Attachment #4: Type: text/plain, Size: 176 bytes --]

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel