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

Groups > linux.kernel > #1458216 > unrolled thread

perf: WARNING: kernel/events/core.c:4893 perf_mmap_close

Back to article view | Back to linux.kernel

Contents

  perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Vince Weaver <vincent.weaver@maine.edu> - 2016-08-08 22:30 +0200
    Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Alexander Shishkin <alexander.shishkin@linux.intel.com> - 2016-08-09 07:20 +0200
      Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Vince Weaver <vincent.weaver@maine.edu> - 2016-08-09 14:50 +0200
      Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Vince Weaver <vincent.weaver@maine.edu> - 2016-08-09 15:00 +0200

#1458216 — perf: WARNING: kernel/events/core.c:4893 perf_mmap_close

Hello

running the perf_fuzzer on Haswell, this is a new warning I don't think 
I've seen before.

It works out to be this code here:

                /* this has to be the last one */
                rb_free_aux(rb);
                WARN_ON_ONCE(atomic_read(&rb->aux_refcount));

                mutex_unlock(&event->mmap_mutex);

[ 1102.250898] ------------[ cut here ]------------
[ 1102.257316] WARNING: CPU: 5 PID: 26043 at kernel/events/core.c:4893 perf_mmap_close+0x389/0x390
[ 1102.269074] Modules linked in: binfmt_misc intel_rapl iosf_mbi x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel snd_hda_codec_hdmi aes_x86_64 lrw gf128mul glue_helper snd_hda_codec_realtek snd_hda_codec_generic ablk_helper ppdev iTCO_wdt snd_hda_intel snd_hda_codec snd_hda_core cryptd evdev iTCO_vendor_support snd_hwdep snd_pcm snd_timer snd i915 drm_kms_helper parport_pc wmi parport psmouse tpm_tis tpm_tis_core pcspkr serio_raw sg button i2c_i801 soundcore lpc_ich drm mei_me mfd_core i2c_smbus tpm mei video battery i2c_algo_bit sr_mod sd_mod cdrom ahci libahci xhci_pci libata ehci_pci xhci_hcd ehci_hcd e1000e usbcore ptp crc32c_intel scsi_mod pps_core usb_common fan thermal
[ 1102.367852] CPU: 5 PID: 26043 Comm: perf_fuzzer Not tainted 4.8.0-rc1+ #187
[ 1102.377206] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[ 1102.387192]  0000000000000000 ffff880117b2bdd8 ffffffff81437641 0000000000000000
[ 1102.397466]  0000000000000000 ffff880117b2be18 ffffffff81076bab 0000131d00000282
[ 1102.407748]  ffff880118211c00 ffff8801173502d8 ffff880117350000 ffff880117d20458
[ 1102.418074] Call Trace:
[ 1102.421424]  [<ffffffff81437641>] dump_stack+0x63/0x82
[ 1102.428393]  [<ffffffff81076bab>] __warn+0xcb/0xf0
[ 1102.434873]  [<ffffffff81076c9d>] warn_slowpath_null+0x1d/0x20
[ 1102.442797]  [<ffffffff81174ab9>] perf_mmap_close+0x389/0x390
[ 1102.450557]  [<ffffffff81174955>] ? perf_mmap_close+0x225/0x390
[ 1102.458569]  [<ffffffff8116cf90>] ? perf_iterate_ctx+0x160/0x160
[ 1102.466720]  [<ffffffff811c0ca2>] remove_vma+0x32/0x70
[ 1102.473658]  [<ffffffff811c2cc8>] do_munmap+0x2b8/0x460
[ 1102.480721]  [<ffffffff811c2f33>] SyS_munmap+0x53/0x70
[ 1102.487663]  [<ffffffff817221b6>] entry_SYSCALL_64_fastpath+0x1e/0xad
[ 1102.496649] ---[ end trace 7ff7a520eaea4ee0 ]---

[toc] | [next] | [standalone]

#1458404

Vince Weaver <vincent.weaver@maine.edu> writes:

> Hello
>
> running the perf_fuzzer on Haswell, this is a new warning I don't think 
> I've seen before.
>
> It works out to be this code here:
>
>                 /* this has to be the last one */
>                 rb_free_aux(rb);
>                 WARN_ON_ONCE(atomic_read(&rb->aux_refcount));
>
>                 mutex_unlock(&event->mmap_mutex);

Awesome, I'll have a look. Can you tell it it was messing around with
intel_bts driver from the fuzzer log?

Thanks,
--
Alex

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

#1458694

On Tue, 9 Aug 2016, Alexander Shishkin wrote:

> Awesome, I'll have a look. Can you tell it it was messing around with
> intel_bts driver from the fuzzer log?

the fuzzer is messing around with the aux buffer, but this particular bug 
triggered quickly so I can't easily tell if this particular bug was doing 
things then.

This also turned up a bit later:

10772.606425] ------------[ cut here ]------------
[10772.611802] WARNING: CPU: 1 PID: 20027 at kernel/events/ring_buffer.c:539 __rb_free_aux+0x111/0x120
[10772.621856] Modules linked in: fuse binfmt_misc intel_rapl iosf_mbi x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel snd_hda_codec_hdmi aes_x86_64 lrw gf128mul glue_helper snd_hda_codec_realtek snd_hda_codec_generic ablk_helper ppdev iTCO_wdt snd_hda_intel snd_hda_codec snd_hda_core cryptd evdev iTCO_vendor_support snd_hwdep snd_pcm snd_timer snd i915 drm_kms_helper parport_pc wmi parport psmouse tpm_tis tpm_tis_core pcspkr serio_raw sg button i2c_i801 soundcore lpc_ich drm mei_me mfd_core i2c_smbus tpm mei video battery i2c_algo_bit sr_mod sd_mod cdrom ahci libahci xhci_pci libata ehci_pci xhci_hcd ehci_hcd e1000e usbcore ptp crc32c_intel scsi_mod pps_core usb_common fan thermal
[10772.699231] CPU: 1 PID: 20027 Comm: perf_fuzzer Tainted: G        W       4.8.0-rc1+ #187
[10772.708539] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[10772.717011]  0000000000000000 ffff88011ea43cb0 ffffffff81437641 0000000000000000
[10772.725555]  0000000000000000 ffff88011ea43cf0 ffffffff81076bab 0000021b1ea43d48
[10772.734103]  ffff8800d0663800 ffff88011ea4b700 0000000000000000 ffff880036cf9800
[10772.742694] Call Trace:
[10772.745818]  <IRQ>  [<ffffffff81437641>] dump_stack+0x63/0x82
[10772.752579]  [<ffffffff81076bab>] __warn+0xcb/0xf0
[10772.758260]  [<ffffffff81076c9d>] warn_slowpath_null+0x1d/0x20
[10772.765049]  [<ffffffff81177121>] __rb_free_aux+0x111/0x120
[10772.771540]  [<ffffffff81177d38>] rb_free_aux+0x18/0x20
[10772.777637]  [<ffffffff81177fc0>] perf_aux_output_end+0xc0/0x110
[10772.784578]  [<ffffffff8100cadd>] bts_event_stop+0xad/0x110
[10772.791025]  [<ffffffff8100cb53>] bts_event_del+0x13/0x20
[10772.797318]  [<ffffffff8116dcec>] event_sched_out.isra.91+0xbc/0x3a0
[10772.804686]  [<ffffffff8116e01b>] group_sched_out+0x4b/0xc0
[10772.811152]  [<ffffffff8116e206>] ctx_sched_out+0x176/0x2c0
[10772.817625]  [<ffffffff8116f05f>] perf_mux_hrtimer_handler+0x10f/0x2c0
[10772.825143]  [<ffffffff8116ef50>] ? __perf_install_in_context+0x130/0x130
[10772.832935]  [<ffffffff810eb3e3>] __hrtimer_run_queues+0x103/0x300
[10772.840128]  [<ffffffff810ebbab>] hrtimer_interrupt+0xab/0x1b0
[10772.846903]  [<ffffffff810513b8>] local_apic_timer_interrupt+0x38/0x60
[10772.854429]  [<ffffffff81724ab3>] smp_trace_apic_timer_interrupt+0x63/0x120
[10772.862446]  [<ffffffff81722e32>] trace_apic_timer_interrupt+0x82/0x90
[10772.869935]  <EOI> ---[ end trace 7ff7a520eaea4ee2 ]---

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

#1458712

and as the fuzzing continues I started to get these, a bit worrying.

[ 6501.254564] Slab corruption (Tainted: G        W      ): task_struct start=ffff8800c072e000, len=5760
[ 6501.264971] 010: 6a 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  jkkkkkkkkkkkkkkk
[ 6501.273650] Single bit error detected. Probably bad RAM.
[ 6501.279889] Run memtest86+ or a similar memory test tool.

[19535.776930] Slab corruption (Tainted: G        W      ): task_struct start=ffff8800c720e2c0, len=5760
[19535.787191] 010: 6a 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  jkkkkkkkkkkkkkkk
[19535.795771] Single bit error detected. Probably bad RAM.
[19535.801872] Run memtest86+ or a similar memory test tool.

Is it possible this was a decrement-after-free bug?

It could also be bad RAM I suppose, I was using this machine to do some 
pretty intense DRAM RAPL validation which involved a lot of DIMM swapping 
so it is conceivable that I managed to break something.

Also lots of
[ 4714.797333] perfevents: irq loop stuck!
errors as always, I think we decided those were probably a hardware issue.

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web