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): [] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline] hardirqs last enabled at (67641): [] _raw_spin_unlock_irq+0x48/0x98 kernel/locking/spinlock.c:199 hardirqs last disabled at (67642): [] enter_el1_irq_or_nmi+0x20/0x30 arch/arm64/kernel/entry-common.c:93 softirqs last enabled at (63366): [] __do_softirq+0x630/0x6b4 kernel/softirq.c:325 softirqs last disabled at (63347): [] do_softirq_own_stack include/linux/interrupt.h:568 [inline] softirqs last disabled at (63347): [] invoke_softirq kernel/softirq.c:393 [inline] softirqs last disabled at (63347): [] __irq_exit_rcu kernel/softirq.c:423 [inline] softirqs last disabled at (63347): [] 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); 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: [] 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