perf related lockdep bug

From: Dave Jones
Date: Wed Nov 04 2015 - 00:17:31 EST


This is new to me since todays merge window.

Dave

[ 293.955261] ======================================================
[ 293.955395] [ INFO: possible circular locking dependency detected ]
[ 293.955536] 4.3.0-think+ #3 Not tainted
[ 293.955618] -------------------------------------------------------
[ 293.955756] trinity-c343/12586 is trying to acquire lock:
[ 293.955875] (rcu_node_0){-.-...}, at: [<ffffffffb00eb734>] rcu_report_exp_cpu_mult+0x24/0x70
[ 293.956070]
but task is already holding lock:
[ 293.956194] (&ctx->lock){-.....}, at: [<ffffffffb0180453>] perf_lock_task_context+0x53/0x300
[ 293.956386]
which lock already depends on the new lock.

[ 293.956559]
the existing dependency chain (in reverse order) is:
[ 293.956720]
-> #3 (&ctx->lock){-.....}:
[ 293.956807] [<ffffffffb00d53a3>] lock_acquire+0xc3/0x1d0
[ 293.956940] [<ffffffffb07efdd1>] _raw_spin_lock+0x41/0x80
[ 293.957075] [<ffffffffb0185b66>] __perf_event_task_sched_out+0x276/0x700
[ 293.957239] [<ffffffffb07e9f70>] __schedule+0x530/0xaf0
[ 293.957370] [<ffffffffb07ea6df>] schedule+0x3f/0x90
[ 293.957493] [<ffffffffb0001206>] exit_to_usermode_loop+0x76/0xa0
[ 293.957642] [<ffffffffb0001c13>] prepare_exit_to_usermode+0x53/0x60
[ 293.957795] [<ffffffffb07f1867>] retint_user+0x8/0x20
[ 293.957923]
-> #2 (&rq->lock){-.-.-.}:
[ 293.958008] [<ffffffffb00d53a3>] lock_acquire+0xc3/0x1d0
[ 293.958140] [<ffffffffb07efdd1>] _raw_spin_lock+0x41/0x80
[ 293.958275] [<ffffffffb00b198d>] sched_move_task+0x4d/0x270
[ 293.958417] [<ffffffffb00b1bde>] cpu_cgroup_fork+0xe/0x10
[ 293.958551] [<ffffffffb012a057>] cgroup_post_fork+0x67/0x160
[ 293.958692] [<ffffffffb007ae0a>] copy_process+0x147a/0x1e10
[ 293.958831] [<ffffffffb007b927>] _do_fork+0x97/0x680
[ 293.958955] [<ffffffffb007bf39>] kernel_thread+0x29/0x30
[ 293.959087] [<ffffffffb07e8477>] rest_init+0x27/0x140
[ 293.959211] [<ffffffffb0ef1f72>] start_kernel+0x450/0x45d
[ 293.959347] [<ffffffffb0ef12fe>] x86_64_start_reservations+0x2a/0x2c
[ 293.959503] [<ffffffffb0ef1468>] x86_64_start_kernel+0x168/0x176
[ 293.959652]
-> #1 (&p->pi_lock){-.-.-.}:
[ 293.959742] [<ffffffffb00d53a3>] lock_acquire+0xc3/0x1d0
[ 293.959876] [<ffffffffb07f00ec>] _raw_spin_lock_irqsave+0x4c/0x90
[ 293.960026] [<ffffffffb00ac070>] try_to_wake_up+0x30/0x5f0
[ 293.960165] [<ffffffffb00ac653>] wake_up_process+0x23/0x40
[ 293.960300] [<ffffffffb0f0b7a0>] rcu_spawn_gp_kthread+0xd5/0xfd
[ 293.960449] [<ffffffffb00002d3>] do_one_initcall+0xb3/0x1f0
[ 293.960587] [<ffffffffb0ef2080>] kernel_init_freeable+0x101/0x234
[ 293.960736] [<ffffffffb07e859e>] kernel_init+0xe/0xe0
[ 293.960860] [<ffffffffb07f10ff>] ret_from_fork+0x3f/0x70
[ 293.960993]
-> #0 (rcu_node_0){-.-...}:
[ 293.961081] [<ffffffffb00d4722>] __lock_acquire+0x19d2/0x1cf0
[ 293.961222] [<ffffffffb00d53a3>] lock_acquire+0xc3/0x1d0
[ 293.961351] [<ffffffffb07f00ec>] _raw_spin_lock_irqsave+0x4c/0x90
[ 293.961501] [<ffffffffb00eb734>] rcu_report_exp_cpu_mult+0x24/0x70
[ 293.961652] [<ffffffffb00f48e9>] rcu_read_unlock_special+0x109/0x5e0
[ 293.961808] [<ffffffffb00e88f7>] __rcu_read_unlock+0x87/0x90
[ 293.961947] [<ffffffffb018059d>] perf_lock_task_context+0x19d/0x300
[ 293.962101] [<ffffffffb018b5bf>] perf_event_init_task+0x9f/0x370
[ 293.962248] [<ffffffffb007a18a>] copy_process+0x7fa/0x1e10
[ 293.962385] [<ffffffffb007b927>] _do_fork+0x97/0x680
[ 293.962508] [<ffffffffb007bfb9>] SyS_clone+0x19/0x20
[ 293.962631] [<ffffffffb07f0d97>] entry_SYSCALL_64_fastpath+0x12/0x6f
[ 293.962787]
other info that might help us debug this:

[ 293.962955] Chain exists of:
rcu_node_0 --> &rq->lock --> &ctx->lock

[ 293.963106] Possible unsafe locking scenario:

[ 293.963233] CPU0 CPU1
[ 293.963332] ---- ----
[ 293.963430] lock(&ctx->lock);
[ 293.963500] lock(&rq->lock);
[ 293.963627] lock(&ctx->lock);
[ 293.963755] lock(rcu_node_0);
[ 293.963824]
*** DEADLOCK ***

[ 293.963947] 2 locks held by trinity-c343/12586:
[ 293.964047] #0: (rcu_read_lock){......}, at: [<ffffffffb01804d0>] perf_lock_task_context+0xd0/0x300
[ 293.964258] #1: (&ctx->lock){-.....}, at: [<ffffffffb0180453>] perf_lock_task_context+0x53/0x300
[ 293.972934]
stack backtrace:
[ 293.990221] CPU: 3 PID: 12586 Comm: trinity-c343 Not tainted 4.3.0-think+ #3
[ 293.999210] ffff8804fb6824a0 ffff88044a0efa60 ffffffffb03607bc ffffffffb1779630
[ 294.008115] ffff88044a0efaa0 ffffffffb00d1453 ffff88044a0efb10 0000000000000002
[ 294.017066] ffff8804fb682468 ffff8804fb6824a0 0000000000000001 ffff8804fb681b80
[ 294.026109] Call Trace:
[ 294.035079] [<ffffffffb03607bc>] dump_stack+0x4e/0x82
[ 294.044014] [<ffffffffb00d1453>] print_circular_bug+0x1e3/0x250
[ 294.052982] [<ffffffffb00d4722>] __lock_acquire+0x19d2/0x1cf0
[ 294.061926] [<ffffffffb00cedf9>] ? get_lock_stats+0x19/0x60
[ 294.070878] [<ffffffffb00d53a3>] lock_acquire+0xc3/0x1d0
[ 294.079828] [<ffffffffb00eb734>] ? rcu_report_exp_cpu_mult+0x24/0x70
[ 294.088805] [<ffffffffb07f00ec>] _raw_spin_lock_irqsave+0x4c/0x90
[ 294.097771] [<ffffffffb00eb734>] ? rcu_report_exp_cpu_mult+0x24/0x70
[ 294.106807] [<ffffffffb00eb734>] rcu_report_exp_cpu_mult+0x24/0x70
[ 294.115823] [<ffffffffb00f48e9>] rcu_read_unlock_special+0x109/0x5e0
[ 294.124813] [<ffffffffb00cedf9>] ? get_lock_stats+0x19/0x60
[ 294.133801] [<ffffffffb0180453>] ? perf_lock_task_context+0x53/0x300
[ 294.142790] [<ffffffffb00e88f7>] __rcu_read_unlock+0x87/0x90
[ 294.151675] [<ffffffffb018059d>] perf_lock_task_context+0x19d/0x300
[ 294.160420] [<ffffffffb01804d0>] ? perf_lock_task_context+0xd0/0x300
[ 294.169166] [<ffffffffb018b5bf>] perf_event_init_task+0x9f/0x370
[ 294.177832] [<ffffffffb00a64a5>] ? preempt_count_sub+0xa5/0xf0
[ 294.186477] [<ffffffffb007a18a>] copy_process+0x7fa/0x1e10
[ 294.195036] [<ffffffffb00cedf9>] ? get_lock_stats+0x19/0x60
[ 294.203564] [<ffffffffb00ced1d>] ? trace_hardirqs_off+0xd/0x10
[ 294.212042] [<ffffffffb0146101>] ? __acct_update_integrals+0x91/0xf0
[ 294.220411] [<ffffffffb00a64a5>] ? preempt_count_sub+0xa5/0xf0
[ 294.228778] [<ffffffffb007b927>] _do_fork+0x97/0x680
[ 294.237038] [<ffffffffb018fd73>] ? context_tracking_user_exit+0x13/0x20
[ 294.245322] [<ffffffffb00017ca>] ? enter_from_user_mode+0x1a/0x50
[ 294.253586] [<ffffffffb00018bc>] ? syscall_trace_enter_phase1+0xbc/0x110
[ 294.261919] [<ffffffffb0001017>] ? trace_hardirqs_on_thunk+0x17/0x19
[ 294.270306] [<ffffffffb007bfb9>] SyS_clone+0x19/0x20
[ 294.278672] [<ffffffffb07f0d97>] entry_SYSCALL_64_fastpath+0x12/0x6f

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/