Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1184359 > unrolled thread

Re: perf: fuzzer triggered warning in intel_pmu_drain_pebs_nhm()

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: perf: fuzzer triggered warning in intel_pmu_drain_pebs_nhm() Stephane Eranian <eranian@googlemail.com> - 2015-07-15 08:50 +0200
    Re: perf: fuzzer triggered warning in intel_pmu_drain_pebs_nhm() Peter Zijlstra <peterz@infradead.org> - 2015-07-15 14:40 +0200
      Re: perf: fuzzer triggered warning in intel_pmu_drain_pebs_nhm() Stephane Eranian <eranian@googlemail.com> - 2015-07-16 23:20 +0200

#1184359 — Re: perf: fuzzer triggered warning in intel_pmu_drain_pebs_nhm()

On Fri, Jul 3, 2015 at 9:49 PM, Vince Weaver <vincent.weaver@maine.edu> wrote:
> On Fri, 3 Jul 2015, Peter Zijlstra wrote:
>
>> That said, its far too warm and I might just not be making sense.
>
> you need to come visit Maine!  Although I am not sure the cooler weather
> necessarily improves my kernel debugging skills.
>
> I managed to lock the machine (again this is with the patch applied).
>
I can reproduce the problem on my HSW running the fuzzer.

I can see why this could be happening if you are mixing PEBS and non PEBS events
in the bottom 4 counters. I suspect:
        for (bit = 0; bit < x86_pmu.max_pebs_events; bit++) {
                if ((counts[bit] == 0) && (error[bit] == 0))
                        continue;

This test is not correct when you have non-PEBS events mixed with PEBS
events and
they overflow at the same time. They will have counts[i] != 0 but
error[i] == 0, and thus
you fall thru the loop and hit the assert. Or it is something along those lines.


> [  299.366027] ------------[ cut here ]------------
> [  299.370985] WARNING: CPU: 2 PID: 8241 at arch/x86/kernel/cpu/perf_event_intel_ds.c:1198 intel_pmu_drain_pebs_nhm+0x283/0x2e0()
> [  299.456929] CPU: 2 PID: 8241 Comm: perf_fuzzer Tainted: G        W       4.1.0+ #164
> [  299.465750] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [  299.474274]  ffffffff81a105a0 ffff88011ea85b10 ffffffff8169f823 0000000000000000
> [  299.482864]  0000000000000000 ffff88011ea85b50 ffffffff8106ec8a ffff88011ea85ba0
> [  299.491488]  0000000000000000 0000000000000001 ffff88011ea8bd80 ffff8801190400c0
> [  299.500029] Call Trace:
> [  299.503190]  <NMI>  [<ffffffff8169f823>] dump_stack+0x45/0x57
> [  299.509936]  [<ffffffff8106ec8a>] warn_slowpath_common+0x8a/0xc0
> [  299.516901]  [<ffffffff8106ed7a>] warn_slowpath_null+0x1a/0x20
> [  299.523715]  [<ffffffff8102f783>] intel_pmu_drain_pebs_nhm+0x283/0x2e0
> [  299.531268]  [<ffffffff81032235>] intel_pmu_handle_irq+0x255/0x440
> [  299.538487]  [<ffffffff81028e76>] perf_event_nmi_handler+0x26/0x40
> [  299.545638]  [<ffffffff810181ad>] nmi_handle+0x9d/0x140
> [  299.551772]  [<ffffffff81018115>] ? nmi_handle+0x5/0x140
> [  299.558013]  [<ffffffff8101843a>] default_do_nmi+0x4a/0x120
> [  299.564527]  [<ffffffff8101859d>] do_nmi+0x8d/0xc0
> [  299.570185]  [<ffffffff816a979f>] end_repeat_nmi+0x1e/0x2e
> [  299.576580]  [<ffffffff811bc9d2>] ? check_poison_obj+0x92/0x230
> [  299.583390]  [<ffffffff811bc9d2>] ? check_poison_obj+0x92/0x230
> [  299.590163]  [<ffffffff811bc9d2>] ? check_poison_obj+0x92/0x230
> [  299.596922]  <<EOE>>  [<ffffffff8115bea8>] ? perf_event_alloc+0x58/0x680
> [  299.604594]  [<ffffffff811bcf7d>] cache_alloc_debugcheck_after.isra.51+0x1cd/0x250
> [  299.613140]  [<ffffffff811c08b6>] kmem_cache_alloc_trace+0xa6/0x510
> [  299.620330]  [<ffffffff8115bea8>] ? perf_event_alloc+0x58/0x680
> [  299.627088]  [<ffffffff8106ee48>] ? get_online_cpus+0x58/0x70
> [  299.633688]  [<ffffffff8115bea8>] perf_event_alloc+0x58/0x680
> [  299.640319]  [<ffffffff8115c897>] SYSC_perf_event_open+0x3c7/0xd40
> [  299.647353]  [<ffffffff8105f86b>] ? __do_page_fault+0x1ab/0x3f0
> [  299.654172]  [<ffffffff8115d689>] SyS_perf_event_open+0x9/0x10
> [  299.660871]  [<ffffffff816a7572>] entry_SYSCALL_64_fastpath+0x16/0x7a
> [  299.668236] ---[ end trace 3356c74581c13f1d ]---
> [  299.673648] Uhhuh. NMI received for unknown reason 31 on CPU 2.
> [  299.680427] Do you have a strange power saving mode enabled?
> [  299.686963] Dazed and confused, but trying to continue
> [  299.692904] Uhhuh. NMI received for unknown reason 31 on CPU 2.
> [  299.699748] Do you have a strange power saving mode enabled?
> [  299.706227] Dazed and confused, but trying to continue
> [  299.712172] Uhhuh. NMI received for unknown reason 31 on CPU 2.
> [  299.718946] Do you have a strange power saving mode enabled?
> [  299.725446] Dazed and confused, but trying to continue
> [  299.731419] Uhhuh. NMI received for unknown reason 31 on CPU 2.
> [  299.738235] Do you have a strange power saving mode enabled?
> [  299.744740] Dazed and confused, but trying to continue
> [  299.750660] Uhhuh. NMI received for unknown reason 21 on CPU 2.
> [  299.757398] Do you have a strange power saving mode enabled?
> [  299.763862] Dazed and confused, but trying to continue
>
> (machine eventually locks up after lots of these messages)
>
--
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]

#1184765

On Wed, Jul 15, 2015 at 08:42:50AM +0200, Stephane Eranian wrote:
> On Fri, Jul 3, 2015 at 9:49 PM, Vince Weaver <vincent.weaver@maine.edu> wrote:
> > On Fri, 3 Jul 2015, Peter Zijlstra wrote:
> >
> >> That said, its far too warm and I might just not be making sense.
> >
> > you need to come visit Maine!  Although I am not sure the cooler weather
> > necessarily improves my kernel debugging skills.
> >
> > I managed to lock the machine (again this is with the patch applied).
> >
> I can reproduce the problem on my HSW running the fuzzer.
> 
> I can see why this could be happening if you are mixing PEBS and non PEBS events
> in the bottom 4 counters. I suspect:
>         for (bit = 0; bit < x86_pmu.max_pebs_events; bit++) {
>                 if ((counts[bit] == 0) && (error[bit] == 0))
>                         continue;
> 
> This test is not correct when you have non-PEBS events mixed with PEBS
> events and
> they overflow at the same time. They will have counts[i] != 0 but
> error[i] == 0, and thus
> you fall thru the loop and hit the assert. Or it is something along those lines.
> 

The only way I can make this work is if ->status only has !PEBS events
set, because if it has both set we'll take that slow path which masks
out the !PEBS bits.

After masking there are 3 options:

 - there is one bit set, and its @bit, we increment counts[bit].
 - there are multiple bits set, we increment error[] for each set bit,
   we do not increment counts[].
 - there are no bits set, we do nothing.

The intent was to never increment counts[] for !PEBS events.

Now if we start out with only a single !PEBS event set, we'll pass the
test and increment counts[] for a !PEBS and hit the warn.

The below patch modifies the code such that it can deal with that
particular issue. Can you try?

---
 arch/x86/kernel/cpu/perf_event_intel_ds.c | 29 +++++++++++++----------------
 1 file changed, 13 insertions(+), 16 deletions(-)

diff --git a/arch/x86/kernel/cpu/perf_event_intel_ds.c b/arch/x86/kernel/cpu/perf_event_intel_ds.c
index 71fc40238843..68d0ced1d229 100644
--- a/arch/x86/kernel/cpu/perf_event_intel_ds.c
+++ b/arch/x86/kernel/cpu/perf_event_intel_ds.c
@@ -1142,6 +1142,7 @@ static void intel_pmu_drain_pebs_nhm(struct pt_regs *iregs)
 
 	for (at = base; at < top; at += x86_pmu.pebs_record_size) {
 		struct pebs_record_nhm *p = at;
+		u64 pebs_status;
 
 		/* PEBS v3 has accurate status bits */
 		if (x86_pmu.intel_cap.pebs_format >= 3) {
@@ -1152,12 +1153,14 @@ static void intel_pmu_drain_pebs_nhm(struct pt_regs *iregs)
 			continue;
 		}
 
-		bit = find_first_bit((unsigned long *)&p->status,
+		pebs_status = p->status & cpuc->pebs_enabled;
+		pebs_status &= (1ULL << x86_pmu.max_pebs_events) - 1;
+
+		bit = find_first_bit((unsigned long *)&pebs_status,
 					x86_pmu.max_pebs_events);
 		if (bit >= x86_pmu.max_pebs_events)
 			continue;
-		if (!test_bit(bit, cpuc->active_mask))
-			continue;
+
 		/*
 		 * The PEBS hardware does not deal well with the situation
 		 * when events happen near to each other and multiple bits
@@ -1172,27 +1175,21 @@ static void intel_pmu_drain_pebs_nhm(struct pt_regs *iregs)
 		 * one, and it's not possible to reconstruct all events
 		 * that caused the PEBS record. It's called collision.
 		 * If collision happened, the record will be dropped.
-		 *
 		 */
-		if (p->status != (1 << bit)) {
-			u64 pebs_status;
-
-			/* slow path */
-			pebs_status = p->status & cpuc->pebs_enabled;
-			pebs_status &= (1ULL << MAX_PEBS_EVENTS) - 1;
-			if (pebs_status != (1 << bit)) {
-				for_each_set_bit(i, (unsigned long *)&pebs_status,
-						 MAX_PEBS_EVENTS)
-					error[i]++;
-				continue;
-			}
+		if (p->status != (1ULL << bit)) {
+			for_each_set_bit(i, (unsigned long *)&pebs_status,
+					 x86_pmu.max_pebs_events)
+				error[i]++;
+			continue;
 		}
+
 		counts[bit]++;
 	}
 
 	for (bit = 0; bit < x86_pmu.max_pebs_events; bit++) {
 		if ((counts[bit] == 0) && (error[bit] == 0))
 			continue;
+
 		event = cpuc->events[bit];
 		WARN_ON_ONCE(!event);
 		WARN_ON_ONCE(!event->attr.precise_ip);
--
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]

#1186263

hi,


The assertion I am seeing on HSW now is:
[  114.652263] WARNING: CPU: 6 PID: 3538 at
arch/x86/kernel/cpu/perf_event.c:1209 x86_pmu_start+0xaa/0x100()
[  114.652264] Modules linked in: snd_hda_codec_hdmi i915 bnep rfcomm
bluetooth drm_kms_helper snd_hda_codec_realtek snd_hda_codec_generic
drm snd_hda_intel snd_hda_codec snd_hda_core intel_rapl iosf_mbi
snd_hwdep x86_pkg_temp_thermal snd_pcm intel_powerclamp snd_seq_midi
snd_seq_midi_event coretemp snd_rawmidi snd_seq kvm_intel kvm
snd_seq_device snd_timer snd crct10dif_pclmul crc32_pclmul soundcore
mei_me mei ghash_clmulni_intel aesni_intel mxm_wmi aes_x86_64 lrw
i2c_algo_bit gf128mul lpc_ich glue_helper shpchp serio_raw ablk_helper
cryptd tpm_infineon soc_button_array wmi video mac_hid
intel_smartconnect nls_iso8859_1 parport_pc ppdev lp parport uas
usb_storage psmouse r8169 ahci libahci mii
[  114.652287] CPU: 6 PID: 3538 Comm: perf_fuzzer Not tainted 4.2.0-rc2+ #3
[  114.652287] Hardware name: MSI MS-7816/Z87-G43 (MS-7816), BIOS V1.0
04/02/2013
[  114.652288]  ffffffff81a8e078 ffff880232e33da8 ffffffff8178881a
0000000000000007
[  114.652289]  0000000000000000 ffff880232e33de8 ffffffff81073a4a
ffff88021f844900
[  114.652291]  ffff88023f38bbc0 ffff8800a85d8800 0000000000000000
ffff88023f31a8f8
[  114.652292] Call Trace:
[  114.652295]  [<ffffffff8178881a>] dump_stack+0x45/0x57
[  114.652299]  [<ffffffff81073a4a>] warn_slowpath_common+0x8a/0xc0
[  114.652300]  [<ffffffff81073b3a>] warn_slowpath_null+0x1a/0x20
[  114.652302]  [<ffffffff8102aeea>] x86_pmu_start+0xaa/0x100
[  114.652304]  [<ffffffff81162e09>] perf_ioctl+0x3b9/0x400
[  114.652306]  [<ffffffff811f851a>] do_vfs_ioctl+0x2ba/0x490
[  114.652307]  [<ffffffff811f700f>] ? f_modown+0x4f/0xa0
[  114.652308]  [<ffffffff811f70e5>] ? f_setown+0x45/0x50
[  114.652309]  [<ffffffff811f8769>] SyS_ioctl+0x79/0x90
[  114.652310]  [<ffffffff8178f52e>] tracesys_phase2+0x88/0x8d

Which corresponds to:
static void x86_pmu_start(struct perf_event *event, int flags)
{
        struct cpu_hw_events *cpuc = this_cpu_ptr(&cpu_hw_events);
        int idx = event->hw.idx;

        if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED)))
                return;
        ^^^^^ this one

The kernel is trying to start an event which was not stopped.

As for NHM, the irqstuck loop is there. After more instrumentation, it
seems to hit
only when sampling on fixed counter 3.


On Thu, Jul 16, 2015 at 9:30 AM, Stephane Eranian
<eranian@googlemail.com> wrote:
> On Thu, Jul 16, 2015 at 12:15 AM, Peter Zijlstra <peterz@infradead.org> wrote:
>> On Thu, Jul 16, 2015 at 08:02:03AM +0200, Stephane Eranian wrote:
>>> Been running it for a couple of hours, so far so good. I will let it
>>> run all night.
>>
>> Thanks!
>>
> Well, it died on NHM in the same function despite your patch. Need to
> look at the exact warning.\
> So more work is needed. But then I also saw the irq loop stuck message
> before that.
>
>
>>> > ---
>>> >  arch/x86/kernel/cpu/perf_event_intel_ds.c | 29 +++++++++++++----------------
>>> >  1 file changed, 13 insertions(+), 16 deletions(-)
>>> >
>>> > diff --git a/arch/x86/kernel/cpu/perf_event_intel_ds.c b/arch/x86/kernel/cpu/perf_event_intel_ds.c
>>> > index 71fc40238843..68d0ced1d229 100644
>>> > --- a/arch/x86/kernel/cpu/perf_event_intel_ds.c
>>> > +++ b/arch/x86/kernel/cpu/perf_event_intel_ds.c
>>> > @@ -1142,6 +1142,7 @@ static void intel_pmu_drain_pebs_nhm(struct pt_regs *iregs)
>>> >
>>> >         for (at = base; at < top; at += x86_pmu.pebs_record_size) {
>>> >                 struct pebs_record_nhm *p = at;
>>> > +               u64 pebs_status;
>>> >
>>> >                 /* PEBS v3 has accurate status bits */
>>> >                 if (x86_pmu.intel_cap.pebs_format >= 3) {
>>> > @@ -1152,12 +1153,14 @@ static void intel_pmu_drain_pebs_nhm(struct pt_regs *iregs)
>>> >                         continue;
>>> >                 }
>>> >
>>> > -               bit = find_first_bit((unsigned long *)&p->status,
>>> > +               pebs_status = p->status & cpuc->pebs_enabled;
>>> > +               pebs_status &= (1ULL << x86_pmu.max_pebs_events) - 1;
>>> > +
>>> > +               bit = find_first_bit((unsigned long *)&pebs_status,
>>> >                                         x86_pmu.max_pebs_events);
>>> >                 if (bit >= x86_pmu.max_pebs_events)
>>> >                         continue;
>>
>> Maybe we should WARN in this case? A PEBS entry without any PEBS bits
>> set in the status field would be 'weird', right?
>>
>> Maybe something like:
>>
>>                 if (WARN(bit >= x86_pmu.max_pebs_events,
>>                          "PEBS record without PEBS event! status=%Lx pebs_enabled=%Lx active_mask=%Lx",
>>                          p->status, cpuc->pebs_enabled, cpuc->active_mask))
>>                         continue;
>>
>> If that triggers we at least get more info.
--
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] | [standalone]

Back to top | Article view | linux.kernel

csiph-web