Groups > linux.kernel > #1163742 > unrolled thread

perf: aux area related crash and warnings

Started by	Vince Weaver <vincent.weaver@maine.edu>
First post	2015-06-12 05:20 +0200
Last post	2015-06-19 16:20 +0200
Articles	3 — 2 participants

Back to article view | Back to linux.kernel

  perf: aux area related crash and warnings Vince Weaver <vincent.weaver@maine.edu> - 2015-06-12 05:20 +0200
    Re: perf: aux area related crash and warnings Ingo Molnar <mingo@kernel.org> - 2015-06-15 22:30 +0200
    Re: perf: aux area related crash and warnings Vince Weaver <vincent.weaver@maine.edu> - 2015-06-19 16:20 +0200

#1163742 — perf: aux area related crash and warnings

From	Vince Weaver <vincent.weaver@maine.edu>
Date	2015-06-12 05:20 +0200
Subject	perf: aux area related crash and warnings
Message-ID	<pAnFE-1hj-9@gated-at.bofh.it>

The fuzzer turned these up (this is 4.1-rc7 with the fasync patch 
applied) on a Haswell.  I'm listing the crash first, but the warning
happened earlier, not sure if it is related.

[36298.986117] BUG: spinlock recursion on CPU#4, perf_fuzzer/3410
[36298.992915]  lock: 0xffff88011edf7cd0, .magic: dead4ead, .owner: perf_fuzzer/3410, .owner_cpu: 4
[36299.002919] CPU: 4 PID: 3410 Comm: perf_fuzzer Tainted: G        W       4.1.0-rc7+ #155
[36299.012152] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[36299.020606]  ffff88011edf7cd0 ffff88011eb059a0 ffffffff816d7229 0000000000000054
[36299.029199]  ffff8800c2f4ac50 ffff88011eb059c0 ffffffff810c2895 ffff88011edf7cd0
[36299.037796]  ffffffff81a1e481 ffff88011eb059e0 ffffffff810c2916 ffff88011edf7cd0
[36299.046338] Call Trace:
[36299.049501]  <NMI>  [<ffffffff816d7229>] dump_stack+0x45/0x57
[36299.056284]  [<ffffffff810c2895>] spin_dump+0x85/0xe0
[36299.062282]  [<ffffffff810c2916>] spin_bug+0x26/0x30
[36299.068111]  [<ffffffff810c2acf>] do_raw_spin_lock+0x13f/0x180
[36299.074897]  [<ffffffff816de6e9>] _raw_spin_lock+0x39/0x40
[36299.081276]  [<ffffffff8117a039>] ? free_pcppages_bulk+0x39/0x620
[36299.088340]  [<ffffffff8117a039>] free_pcppages_bulk+0x39/0x620
[36299.095182]  [<ffffffff81177e14>] ? free_pages_prepare+0x3a4/0x550
[36299.102291]  [<ffffffff811c9936>] ? kfree_debugcheck+0x16/0x40
[36299.108987]  [<ffffffff8117a938>] free_hot_cold_page+0x178/0x1a0
[36299.115850]  [<ffffffff8117aa47>] __free_pages+0x37/0x50
[36299.121991]  [<ffffffff8116ae0a>] rb_free_aux+0xba/0xf0
[36299.128034]  [<ffffffff8116b0e7>] perf_aux_output_end+0xb7/0xf0
[36299.134793]  [<ffffffff81037b0e>] intel_bts_interrupt+0x8e/0xd0
[36299.141543]  [<ffffffff810338bf>] intel_pmu_handle_irq+0x4f/0x450
[36299.148482]  [<ffffffff810bc288>] ? check_chain_key+0x128/0x1e0
[36299.155249]  [<ffffffff8102a4ab>] perf_event_nmi_handler+0x2b/0x50
[36299.162273]  [<ffffffff810185d0>] nmi_handle+0xa0/0x150
[36299.168278]  [<ffffffff81018535>] ? nmi_handle+0x5/0x150
[36299.174377]  [<ffffffff8101887a>] default_do_nmi+0x4a/0x140
[36299.180735]  [<ffffffff81018a08>] do_nmi+0x98/0xe0
[36299.186219]  [<ffffffff816e13ef>] end_repeat_nmi+0x1e/0x2e
[36299.192501]  [<ffffffff810bdc4e>] ? __lock_acquire.isra.31+0x27e/0x1000
[36299.199951]  [<ffffffff810bdc4e>] ? __lock_acquire.isra.31+0x27e/0x1000
[36299.207410]  [<ffffffff810bdc4e>] ? __lock_acquire.isra.31+0x27e/0x1000
[36299.214898]  <<EOE>>  [<ffffffff810bdd89>] ? __lock_acquire.isra.31+0x3b9/0x1000

and while I was trying to cut and paste that, the locked haswell just took 
down the network switch so I can't get the rest until tomorrow.

The warning was
[27716.785131] WARNING: CPU: 2 PID: 17655 at kernel/events/ring_buffer.c:282 perf_aux_output_begin+0x1ce/0x1f0()

which corresponds to 
        /*
         * Nesting is not supported for AUX area, make sure nested
         * writers are caught early
         */
        if (WARN_ON_ONCE(local_xchg(&rb->aux_nest, 1)))
                goto err_put;

again just lost access to the machine with the serial console, for the 
full backtrace it will have to wait until I'm not remote.

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

[toc] | [next] | [standalone]

#1165534

From	Ingo Molnar <mingo@kernel.org>
Date	2015-06-15 22:30 +0200
Message-ID	<pBJb4-5IV-9@gated-at.bofh.it>
In reply to	#1163742

* Alexander Shishkin <alexander.shishkin@linux.intel.com> wrote:

> Peter Zijlstra <peterz@infradead.org> writes:
> 
> > Alex, any clue?
> 
> Let me look into it. Definitely haven't seen anything like that in my
> tests.

That's natural: Vince is running randomize fuzzing tests, so you should look out 
for boundary conditions and 'nonsensical' values that won't normally trigger in 
functional testing.

In fact Vince is using 'directed fuzzing': i.e. the fuzzer is aware of the general 
perf ABI structure and will try to generate partially valid, partially randomized 
requests, to be able to test 'leaf' functionality of the perf ABI as well, which 
would otherwise need astronomical odds to occur in a pure fuzzing test.

These crashes started popping up when Vince added 'AUX area awareness' to the 
fuzzer.

> >> [36299.068111]  [<ffffffff810c2acf>] do_raw_spin_lock+0x13f/0x180
> >> [36299.074897]  [<ffffffff816de6e9>] _raw_spin_lock+0x39/0x40
> >> [36299.081276]  [<ffffffff8117a039>] ? free_pcppages_bulk+0x39/0x620
> >> [36299.088340]  [<ffffffff8117a039>] free_pcppages_bulk+0x39/0x620
> >> [36299.095182]  [<ffffffff81177e14>] ? free_pages_prepare+0x3a4/0x550
> >> [36299.102291]  [<ffffffff811c9936>] ? kfree_debugcheck+0x16/0x40
> >> [36299.108987]  [<ffffffff8117a938>] free_hot_cold_page+0x178/0x1a0
> >> [36299.115850]  [<ffffffff8117aa47>] __free_pages+0x37/0x50
> >> [36299.121991]  [<ffffffff8116ae0a>] rb_free_aux+0xba/0xf0
> 
> This one goes to free aux pages from nmi context, looks like aux buffer was 
> unmapped while the event was running, so here it dropped the last reference.

Yeah, that in itself is an absolute no-no - so I guess refcounting went wrong 
somewhere? (assuming it exists properly).

Thanks,

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

[toc] | [prev] | [next] | [standalone]

#1168810

From	Vince Weaver <vincent.weaver@maine.edu>
Date	2015-06-19 16:20 +0200
Message-ID	<pD5jc-1lD-9@gated-at.bofh.it>
In reply to	#1163742

On Thu, 18 Jun 2015, Peter Zijlstra wrote:

> On Tue, Jun 16, 2015 at 02:37:06PM +0300, Alexander Shishkin wrote:
> > Ok, here's what I propose for this one.
> 
> As discussed yesterday, I think we want to change to how we do reference
> counting for the regular buffers, but that will require quite a bit of
> work.
> 
> For the interim we can avoid the issue by something like the below;
> compile tested only.

I did manage to crash the system with Alexander Shishkin's patch applied 
(See below).

I will try with this updated patch instead, but the bug usually takes a 
few days  to trigger with the fuzzer and I won't be able to let it run 
that long this time.

Vince

[183592.949539] BUG: spinlock recursion on CPU#2, perf_fuzzer/434
[183592.956559]  lock: pool_lock+0x0/0x40, .magic: dead4ead, .owner: perf_fuzzer/434, .owner_cpu: 2
[183592.966783] CPU: 2 PID: 434 Comm: perf_fuzzer Tainted: G        W       4.1.0-rc8+ #157
[183592.976228] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[183592.984997]  ffffffff81cc2120 ffff88011ea85970 ffffffff816d7419 0000000000000053
[183592.993871]  ffff8800cf26a8d0 ffff88011ea85990 ffffffff810c28a5 ffffffff81cc2120
[183593.002787]  ffffffff81a1e4d1 ffff88011ea859b0 ffffffff810c2926 ffffffff81cc2120
[183593.011632] Call Trace:
[183593.015016]  <NMI>  [<ffffffff816d7419>] dump_stack+0x45/0x57
[183593.021966]  [<ffffffff810c28a5>] spin_dump+0x85/0xe0
[183593.028153]  [<ffffffff810c2926>] spin_bug+0x26/0x30
[183593.034234]  [<ffffffff810c2adf>] do_raw_spin_lock+0x13f/0x180
[183593.041233]  [<ffffffff816de8d9>] _raw_spin_lock+0x39/0x40
[183593.047849]  [<ffffffff81428d2d>] ? __debug_object_init+0xad/0x450
[183593.055189]  [<ffffffff81428d2d>] __debug_object_init+0xad/0x450
[183593.062375]  [<ffffffff814290eb>] debug_object_init+0x1b/0x20
[183593.069267]  [<ffffffff810d8fb8>] rcuhead_fixup_activate+0x28/0x40
[183593.076638]  [<ffffffff81429201>] debug_object_activate+0xf1/0x1e0
[183593.083969]  [<ffffffff8115e690>] ? free_event_rcu+0x40/0x40
[183593.090781]  [<ffffffff810dc8cb>] __call_rcu.constprop.58+0x3b/0x340
[183593.098321]  [<ffffffff8115711c>] ? irq_work_queue+0x6c/0x80
[183593.105123]  [<ffffffff810dcc27>] call_rcu_sched+0x17/0x20
[183593.111709]  [<ffffffff81166680>] rb_free_aux+0x40/0x90
[183593.118046]  [<ffffffff8116b067>] perf_aux_output_end+0xb7/0xf0
[183593.125089]  [<ffffffff81037b0e>] intel_bts_interrupt+0x8e/0xd0
[183593.132069]  [<ffffffff810338bf>] intel_pmu_handle_irq+0x4f/0x450
[183593.139335]  [<ffffffff8102a4ab>] perf_event_nmi_handler+0x2b/0x50
[183593.146687]  [<ffffffff810185d0>] nmi_handle+0xa0/0x150
[183593.153012]  [<ffffffff81018535>] ? nmi_handle+0x5/0x150
[183593.159406]  [<ffffffff8101887a>] default_do_nmi+0x4a/0x140
[183593.166117]  [<ffffffff81018a08>] do_nmi+0x98/0xe0
[183593.171983]  [<ffffffff816e15ef>] end_repeat_nmi+0x1e/0x2e
[183593.178613]  [<ffffffff810c2b70>] ? do_raw_spin_trylock+0x50/0x50
[183593.185823]  [<ffffffff810c2b70>] ? do_raw_spin_trylock+0x50/0x50
[183593.193059]  [<ffffffff810c2b70>] ? do_raw_spin_trylock+0x50/0x50
[183593.200306]  <<EOE>>  [<ffffffff816dea7b>] ? _raw_spin_unlock+0x2b/0x40
[183593.208107]  [<ffffffff81428ded>] __debug_object_init+0x16d/0x450
[183593.215328]  [<ffffffff8142919a>] ? debug_object_activate+0x8a/0x1e0
[183593.222812]  [<ffffffff814291ea>] ? debug_object_activate+0xda/0x1e0
[183593.230328]  [<ffffffff814290eb>] debug_object_init+0x1b/0x20
[183593.237143]  [<ffffffff810d8fb8>] rcuhead_fixup_activate+0x28/0x40
[183593.244413]  [<ffffffff81429201>] debug_object_activate+0xf1/0x1e0
[183593.251702]  [<ffffffff8115e650>] ? perf_unpin_context+0x40/0x40
[183593.258799]  [<ffffffff810dc8cb>] __call_rcu.constprop.58+0x3b/0x340
[183593.266311]  [<ffffffff81170b57>] ? __static_key_slow_dec+0x27/0xc0
[183593.273694]  [<ffffffff810dcc27>] call_rcu_sched+0x17/0x20
[183593.280180]  [<ffffffff81165439>] _free_event+0x109/0x290
[183593.286619]  [<ffffffff811656cf>] put_event+0x10f/0x160
[183593.292855]  [<ffffffff811655f0>] ? put_event+0x30/0x160
[183593.299153]  [<ffffffff81165755>] perf_release+0x15/0x20
[183593.305442]  [<ffffffff811edeec>] __fput+0xdc/0x1f0
[183593.311296]  [<ffffffff811ee04e>] ____fput+0xe/0x10
[183593.317138]  [<ffffffff81091577>] task_work_run+0xb7/0xf0
[183593.323509]  [<ffffffff81014189>] do_notify_resume+0x59/0x80
[183593.330207]  [<ffffffff816df550>] int_signal+0x12/0x17
[183602.817462] ------------[ cut here ]------------

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]

csiph-web

perf: aux area related crash and warnings

Contents

#1163742 — perf: aux area related crash and warnings

#1165534

#1168810