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

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

[Vince Weaver]

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 ]---

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

[Alexander Shishkin]

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

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

[Vince Weaver]

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 ]---

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

[Vince Weaver]

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.

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

[Vince Weaver]

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?


It's not just my Haswell machine either, my Core2 machine locked up with 
this (possibly related):

[69117.178434] WARNING: CPU: 1 PID: 31160 at kernel/events/core.c:4831 ring_buffer_put+0x3c/0x4f
[69117.178434] CPU: 1 PID: 31160 Comm: perf_fuzzer Tainted: G        W       4.8.0-rc1+ #208
[69117.178434] Hardware name: AOpen   DE7000/nMCP7ALPx-DE R1.06 Oct.19.2012, BIOS 080015  10/19/2012
[69117.178434]  0000000000000000 ffff88011932fb48 ffffffff812b7e50 0000000000000000
[69117.178434]  0000000000000000 ffff88011932fb88 ffffffff8104cab6 000012df1932fc50
[69117.178434]  ffff880119018000 ffff88011fc8b740 0000000000000000 ffff88003765d000
[69117.178434] Call Trace:
[69117.178434]  [<ffffffff812b7e50>] dump_stack+0x4d/0x63
[69117.178434]  [<ffffffff8104cab6>] __warn+0xca/0xe5
[69117.178434]  [<ffffffff8104cb8d>] warn_slowpath_null+0x1d/0x1f
[69117.178434]  [<ffffffff810f000f>] ring_buffer_put+0x3c/0x4f
[69117.178434]  [<ffffffff810f6625>] perf_aux_output_end+0xd2/0xd9
[69117.178434]  [<ffffffff81008eba>] bts_event_stop+0xb2/0xfc
[69117.178434]  [<ffffffff81008f17>] bts_event_del+0x13/0x15
[69117.178434]  [<ffffffff810ef33e>] event_sched_out+0xb0/0x184
[69117.178434]  [<ffffffff810ef43b>] group_sched_out+0x29/0x7a
[69117.178434]  [<ffffffff810ef758>] ctx_sched_out+0x182/0x198
[69117.178434]  [<ffffffff810ef7b9>] task_ctx_sched_out+0x4b/0x4d
[69117.178434]  [<ffffffff810f2e7e>] ctx_resched+0x25/0x4d
[69117.178434]  [<ffffffff810f2f61>] __perf_event_enable+0xbb/0xc4
[69117.178434]  [<ffffffff810eb649>] event_function+0x107/0x122
[69117.178434]  [<ffffffff810ec3b8>] ? perf_event_sysfs_show+0x22/0x22
[69117.178434]  [<ffffffff810ec3cf>] remote_function+0x17/0x44
[69117.178434]  [<ffffffff810a8fb4>] generic_exec_single+0x4e/0xce
[69117.178434]  [<ffffffff810ec3b8>] ? perf_event_sysfs_show+0x22/0x22
[69117.178434]  [<ffffffff810a90ed>] smp_call_function_single+0xb9/0xd9
[69117.178434]  [<ffffffff810f2ea6>] ? ctx_resched+0x4d/0x4d
[69117.178434]  [<ffffffff810eccda>] event_function_call+0xa1/0xfd
[69117.178434]  [<ffffffff810f2ea6>] ? ctx_resched+0x4d/0x4d
[69117.178434]  [<ffffffff810eb542>] ? perf_ctx_lock+0x22/0x22
[69117.178434]  [<ffffffff810ecda7>] ? perf_event_disable+0x27/0x27
[69117.178434]  [<ffffffff810ece00>] _perf_event_enable+0x59/0x5e
[69117.178434]  [<ffffffff810eb831>] perf_event_for_each_child+0x59/0x94
[69117.178434]  [<ffffffff810efa77>] perf_event_task_enable+0x6b/0xa1
[69117.178434]  [<ffffffff8105d140>] SyS_prctl+0x157/0x3b2
[69117.178434]  [<ffffffff81582cdf>] entry_SYSCALL_64_fastpath+0x17/0x93
[69117.178434] ---[ end trace 6960c0c785736820 ]---
[69117.431157] BUG: unable to handle kernel NULL pointer dereference at 0000000000000088
[69117.435117] IP: [<ffffffff810f1ed5>] perf_mmap_close+0x2d/0x252
[69117.435117] PGD 1192d5067 PUD 119be7067 PMD 0 
[69117.435117] Oops: 0000 [#1] SMP
[69117.435117] task: ffff8801198b40c0 task.stack: ffff88011932c000
[69117.435117] RIP: 0010:[<ffffffff810f1ed5>]  [<ffffffff810f1ed5>] perf_mmap_close+0x2d/0x252
[69117.435117] RSP: 0018:ffff88011932fe60  EFLAGS: 00010246
[69117.435117] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[69117.435117] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff880119018000
[69117.435117] RBP: ffff88011932fea0 R08: 0000000000000000 R09: 0000000000000000
[69117.435117] R10: 000000000001af54 R11: 000000000001af08 R12: ffff88003765d000
[69117.435117] R13: ffff880037536900 R14: ffff880119af6a80 R15: ffff880119af6a80
[69117.435117] FS:  00007f40dc148700(0000) GS:ffff88011fc00000(0000) knlGS:0000000000000000
[69117.435117] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[69117.435117] CR2: 0000000000000088 CR3: 000000011a8ef000 CR4: 00000000000407f0
[69117.435117] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[69117.435117] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[69117.435117] Stack:
[69117.435117]  ffffffff8111e2c0 ffff880037536920 0000000000000000 ffff880119af6a80
[69117.435117]  0000000000000000 ffff880037536900 ffff880119af6a80 ffff880119af6a80
[69117.435117]  ffff88011932fec0 ffffffff8111e7da ffff88003748d3c0 0000000000000000
[69117.435117] Call Trace:
[69117.435117]  [<ffffffff8111e2c0>] ? vma_gap_callbacks_propagate+0x1b/0x33
[69117.435117]  [<ffffffff8111e7da>] remove_vma+0x32/0x66
[69117.435117]  [<ffffffff811206cf>] do_munmap+0x2bf/0x2e3
[69117.435117]  [<ffffffff81120bd6>] SyS_munmap+0x50/0x69
[69117.435117]  [<ffffffff81582cdf>] entry_SYSCALL_64_fastpath+0x17/0x93
[69117.435117] Code: 89 e5 41 57 41 56 41 55 41 54 49 89 fe 53 48 83 ec 18 48 8b 87 a0 00 00 00 4c 8b a0 c8 00 00 00 4c 89 e7 e8 d0 e0 ff ff 48 89 c3 <4c> 8b a8 88 00 00 00 48 8b 80 80 00 00 00 48 89 45 d0 8b 43 18 
[69117.435117] RIP  [<ffffffff810f1ed5>] perf_mmap_close+0x2d/0x252
[69117.435117]  RSP <ffff88011932fe60>
[69117.435117] CR2: 0000000000000088
[69117.677732] ---[ end trace 6960c0c785736821 ]---

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

[Alexander Shishkin]

Yes, I tracked to a race between unmapping and set_output, trying to
come up with a good fix now.

On 12 August 2016 at 20:17, Vince Weaver <vincent.weaver@maine.edu> wrote:
>
> 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?
>
>
> It's not just my Haswell machine either, my Core2 machine locked up with
> this (possibly related):
>
> [69117.178434] WARNING: CPU: 1 PID: 31160 at kernel/events/core.c:4831 ring_buffer_put+0x3c/0x4f
> [69117.178434] CPU: 1 PID: 31160 Comm: perf_fuzzer Tainted: G        W       4.8.0-rc1+ #208
> [69117.178434] Hardware name: AOpen   DE7000/nMCP7ALPx-DE R1.06 Oct.19.2012, BIOS 080015  10/19/2012
> [69117.178434]  0000000000000000 ffff88011932fb48 ffffffff812b7e50 0000000000000000
> [69117.178434]  0000000000000000 ffff88011932fb88 ffffffff8104cab6 000012df1932fc50
> [69117.178434]  ffff880119018000 ffff88011fc8b740 0000000000000000 ffff88003765d000
> [69117.178434] Call Trace:
> [69117.178434]  [<ffffffff812b7e50>] dump_stack+0x4d/0x63
> [69117.178434]  [<ffffffff8104cab6>] __warn+0xca/0xe5
> [69117.178434]  [<ffffffff8104cb8d>] warn_slowpath_null+0x1d/0x1f
> [69117.178434]  [<ffffffff810f000f>] ring_buffer_put+0x3c/0x4f
> [69117.178434]  [<ffffffff810f6625>] perf_aux_output_end+0xd2/0xd9
> [69117.178434]  [<ffffffff81008eba>] bts_event_stop+0xb2/0xfc
> [69117.178434]  [<ffffffff81008f17>] bts_event_del+0x13/0x15
> [69117.178434]  [<ffffffff810ef33e>] event_sched_out+0xb0/0x184
> [69117.178434]  [<ffffffff810ef43b>] group_sched_out+0x29/0x7a
> [69117.178434]  [<ffffffff810ef758>] ctx_sched_out+0x182/0x198
> [69117.178434]  [<ffffffff810ef7b9>] task_ctx_sched_out+0x4b/0x4d
> [69117.178434]  [<ffffffff810f2e7e>] ctx_resched+0x25/0x4d
> [69117.178434]  [<ffffffff810f2f61>] __perf_event_enable+0xbb/0xc4
> [69117.178434]  [<ffffffff810eb649>] event_function+0x107/0x122
> [69117.178434]  [<ffffffff810ec3b8>] ? perf_event_sysfs_show+0x22/0x22
> [69117.178434]  [<ffffffff810ec3cf>] remote_function+0x17/0x44
> [69117.178434]  [<ffffffff810a8fb4>] generic_exec_single+0x4e/0xce
> [69117.178434]  [<ffffffff810ec3b8>] ? perf_event_sysfs_show+0x22/0x22
> [69117.178434]  [<ffffffff810a90ed>] smp_call_function_single+0xb9/0xd9
> [69117.178434]  [<ffffffff810f2ea6>] ? ctx_resched+0x4d/0x4d
> [69117.178434]  [<ffffffff810eccda>] event_function_call+0xa1/0xfd
> [69117.178434]  [<ffffffff810f2ea6>] ? ctx_resched+0x4d/0x4d
> [69117.178434]  [<ffffffff810eb542>] ? perf_ctx_lock+0x22/0x22
> [69117.178434]  [<ffffffff810ecda7>] ? perf_event_disable+0x27/0x27
> [69117.178434]  [<ffffffff810ece00>] _perf_event_enable+0x59/0x5e
> [69117.178434]  [<ffffffff810eb831>] perf_event_for_each_child+0x59/0x94
> [69117.178434]  [<ffffffff810efa77>] perf_event_task_enable+0x6b/0xa1
> [69117.178434]  [<ffffffff8105d140>] SyS_prctl+0x157/0x3b2
> [69117.178434]  [<ffffffff81582cdf>] entry_SYSCALL_64_fastpath+0x17/0x93
> [69117.178434] ---[ end trace 6960c0c785736820 ]---
> [69117.431157] BUG: unable to handle kernel NULL pointer dereference at 0000000000000088
> [69117.435117] IP: [<ffffffff810f1ed5>] perf_mmap_close+0x2d/0x252
> [69117.435117] PGD 1192d5067 PUD 119be7067 PMD 0
> [69117.435117] Oops: 0000 [#1] SMP
> [69117.435117] task: ffff8801198b40c0 task.stack: ffff88011932c000
> [69117.435117] RIP: 0010:[<ffffffff810f1ed5>]  [<ffffffff810f1ed5>] perf_mmap_close+0x2d/0x252
> [69117.435117] RSP: 0018:ffff88011932fe60  EFLAGS: 00010246
> [69117.435117] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
> [69117.435117] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff880119018000
> [69117.435117] RBP: ffff88011932fea0 R08: 0000000000000000 R09: 0000000000000000
> [69117.435117] R10: 000000000001af54 R11: 000000000001af08 R12: ffff88003765d000
> [69117.435117] R13: ffff880037536900 R14: ffff880119af6a80 R15: ffff880119af6a80
> [69117.435117] FS:  00007f40dc148700(0000) GS:ffff88011fc00000(0000) knlGS:0000000000000000
> [69117.435117] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [69117.435117] CR2: 0000000000000088 CR3: 000000011a8ef000 CR4: 00000000000407f0
> [69117.435117] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [69117.435117] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
> [69117.435117] Stack:
> [69117.435117]  ffffffff8111e2c0 ffff880037536920 0000000000000000 ffff880119af6a80
> [69117.435117]  0000000000000000 ffff880037536900 ffff880119af6a80 ffff880119af6a80
> [69117.435117]  ffff88011932fec0 ffffffff8111e7da ffff88003748d3c0 0000000000000000
> [69117.435117] Call Trace:
> [69117.435117]  [<ffffffff8111e2c0>] ? vma_gap_callbacks_propagate+0x1b/0x33
> [69117.435117]  [<ffffffff8111e7da>] remove_vma+0x32/0x66
> [69117.435117]  [<ffffffff811206cf>] do_munmap+0x2bf/0x2e3
> [69117.435117]  [<ffffffff81120bd6>] SyS_munmap+0x50/0x69
> [69117.435117]  [<ffffffff81582cdf>] entry_SYSCALL_64_fastpath+0x17/0x93
> [69117.435117] Code: 89 e5 41 57 41 56 41 55 41 54 49 89 fe 53 48 83 ec 18 48 8b 87 a0 00 00 00 4c 8b a0 c8 00 00 00 4c 89 e7 e8 d0 e0 ff ff 48 89 c3 <4c> 8b a8 88 00 00 00 48 8b 80 80 00 00 00 48 89 45 d0 8b 43 18
> [69117.435117] RIP  [<ffffffff810f1ed5>] perf_mmap_close+0x2d/0x252
> [69117.435117]  RSP <ffff88011932fe60>
> [69117.435117] CR2: 0000000000000088
> [69117.677732] ---[ end trace 6960c0c785736821 ]---
>

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

[Will Deacon]

Hi Alexander,

On Fri, Aug 12, 2016 at 08:54:49PM +0300, Alexander Shishkin wrote:
> Yes, I tracked to a race between unmapping and set_output, trying to
> come up with a good fix now.

Did you get anywhere with this? I think I just hit the same issue with
the intel-pt driver on my broadwell laptop with -rc3+PREEMPT (dump
below) and I'm more than happy to test a fix.

Will

--->8

[   64.827521] ------------[ cut here ]------------
[   64.827527] WARNING: CPU: 1 PID: 1762 at /home/kernel/COD/linux/kernel/events/ring_buffer.c:539 __rb_free_aux+0x10c/0x120
[   64.827528] Modules linked in: fuse binfmt_misc intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp nls_utf8 nls_cp437 kvm_intel iwlwifi vfat kvm fat irqbypass crct10dif_pclmul snd_soc_rt298 dell_laptop crc32_pclmul dell_wmi cfg80211 snd_soc_rt286 dell_led ghash_clmulni_intel dell_smbios dcdbas rtsx_pci_ms snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic snd_soc_rl6347a snd_soc_ssm4567 rfkill memstick snd_soc_core elan_i2c snd_hda_intel aesni_intel snd_compress snd_pcm_dmaengine snd_hda_codec aes_x86_64 lrw snd_hda_core gf128mul glue_helper snd_hwdep ablk_helper cryptd snd_pcm intel_cstate intel_rapl_perf videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_seq_midi videobuf2_core snd_seq_midi_event videodev joydev hid_multitouch efi_pstore media serio_raw snd_rawmidi efivars
[   64.827556]  snd_seq sg snd_seq_device snd_timer intel_pch_thermal mei_me snd soundcore mei shpchp lpc_ich battery intel_vbtn sparse_keymap soc_button_array int3403_thermal dw_dmac dw_dmac_core snd_soc_sst_acpi int3400_thermal i2c_designware_platform snd_soc_sst_match acpi_pad acpi_als int3406_thermal int3402_thermal acpi_thermal_rel i2c_designware_core ac evdev kfifo_buf processor_thermal_device int340x_thermal_zone intel_soc_dts_iosf industrialio tpm_tis tpm_tis_core tpm parport_pc ppdev lp parport efivarfs autofs4 ext4 crc16 jbd2 fscrypto mbcache sd_mod usbhid rtsx_pci_sdmmc i915 xhci_pci ehci_pci xhci_hcd ahci ehci_hcd psmouse crc32c_intel libahci usbcore libata i2c_algo_bit drm_kms_helper scsi_mod usb_common drm rtsx_pci mfd_core thermal fan wmi sdhci_acpi sdhci mmc_core video i2c_hid hid fjes
[   64.827587]  button
[   64.827589] CPU: 1 PID: 1762 Comm: pt-poker Tainted: G      D W       4.8.0-040800rc3-lowlatency #201608212032
[   64.827590] Hardware name: Dell Inc. XPS 13 9343/0F5KF3, BIOS A07 11/11/2015
[   64.827592]  0000000000000286 00000000cf433edf ffffffffa7148112 0000000000000000
[   64.827594]  0000000000000000 ffffffffa6e801fe ffff932a8d941000 ffff932a8f349a80
[   64.827595]  ffff932a8f349800 ffff932a8d940db0 ffff932a8d941000 ffffffffa7a40e00
[   64.827597] Call Trace:
[   64.827600]  [<ffffffffa7148112>] ? dump_stack+0x5c/0x7a
[   64.827602]  [<ffffffffa6e801fe>] ? __warn+0xbe/0xe0
[   64.827604]  [<ffffffffa6f8368c>] ? __rb_free_aux+0x10c/0x120
[   64.827606]  [<ffffffffa6f810b7>] ? perf_mmap_close+0x2c7/0x310
[   64.827607]  [<ffffffffa6f795b0>] ? perf_iterate_ctx+0x150/0x150
[   64.827609]  [<ffffffffa6fcbec5>] ? remove_vma+0x25/0x60
[   64.827610]  [<ffffffffa6fce3c3>] ? exit_mmap+0xe3/0x150
[   64.827612]  [<ffffffffa6e7d04a>] ? mmput+0x4a/0xf0
[   64.827613]  [<ffffffffa6e84463>] ? do_exit+0x273/0xb70
[   64.827614]  [<ffffffffa6e84dda>] ? do_group_exit+0x3a/0xa0
[   64.827616]  [<ffffffffa6e901cc>] ? get_signal+0x27c/0x690
[   64.827617]  [<ffffffffa6e2e5a6>] ? do_signal+0x36/0x6f0
[   64.827619]  [<ffffffffa6e2d751>] ? __switch_to+0x2c1/0x810
[   64.827620]  [<ffffffffa6ea6711>] ? finish_task_switch+0x71/0x1e0
[   64.827622]  [<ffffffffa74288e4>] ? __schedule+0x264/0x740
[   64.827624]  [<ffffffffa6e032b5>] ? exit_to_usermode_loop+0x85/0xc0
[   64.827626]  [<ffffffffa6e03b51>] ? prepare_exit_to_usermode+0x21/0x30
[   64.827627]  [<ffffffffa742dde5>] ? retint_user+0x8/0x10
[   64.827628] ---[ end trace 928bce4cbac61bf3 ]---
[   64.827643] BUG: scheduling while atomic: pt-poker/1762/0x00000002

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

[Peter Zijlstra]

On Tue, Aug 23, 2016 at 04:12:42PM +0100, Will Deacon wrote:
> Hi Alexander,
> 
> On Fri, Aug 12, 2016 at 08:54:49PM +0300, Alexander Shishkin wrote:
> > Yes, I tracked to a race between unmapping and set_output, trying to
> > come up with a good fix now.
> 
> Did you get anywhere with this? I think I just hit the same issue with
> the intel-pt driver on my broadwell laptop with -rc3+PREEMPT (dump
> below) and I'm more than happy to test a fix.

lkml.kernel.org/r/1471942474-1854-1-git-send-email-alexander.shishkin@linux.intel.com

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

[Alexander Shishkin]

Will Deacon <will.deacon@arm.com> writes:

> Hi Alexander,
>
> On Fri, Aug 12, 2016 at 08:54:49PM +0300, Alexander Shishkin wrote:
>> Yes, I tracked to a race between unmapping and set_output, trying to
>> come up with a good fix now.
>
> Did you get anywhere with this? I think I just hit the same issue with
> the intel-pt driver on my broadwell laptop with -rc3+PREEMPT (dump
> below) and I'm more than happy to test a fix.

Yes, I posted a patchset [1] this morning that should fix this; if this
is PT, 3/3 should suffice.

What's "pt-poker", btw? :)

[1] http://marc.info/?l=linux-kernel&m=147194269031047

Regards,
--
Alex

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

[Will Deacon]

Hi Alex,

On Tue, Aug 23, 2016 at 08:08:23PM +0300, Alexander Shishkin wrote:
> Will Deacon <will.deacon@arm.com> writes:
> > On Fri, Aug 12, 2016 at 08:54:49PM +0300, Alexander Shishkin wrote:
> >> Yes, I tracked to a race between unmapping and set_output, trying to
> >> come up with a good fix now.
> >
> > Did you get anywhere with this? I think I just hit the same issue with
> > the intel-pt driver on my broadwell laptop with -rc3+PREEMPT (dump
> > below) and I'm more than happy to test a fix.
> 
> Yes, I posted a patchset [1] this morning that should fix this; if this
> is PT, 3/3 should suffice.

Unfortunately, I still see the same issue with those three patches applied,
so perhaps it's not quite the same as the problem reported by Vince.

A little bit of digging suggests that the preempt count isn't balanced
across the call to perf_pmu_output_stop from perf_mmap_close. Further
digging revealed the unbalanced get_cpu_ptr in __perf_pmu_output_stop.
Fix below!

I also noticed that we go to some effort to return an error code from
__perf_pmu_output_stop, but it's completly ignored by the cpu_function_call
machinery :(

> What's "pt-poker", btw? :)

A very boring application I wrote that just opens a pt event with config=0,
mmaps the AUX buffer and then spins waiting for the data that never comes.
The issue above occurs when I ctrl+c the application under a preemptible
kernel.

Will

--->8

>From 0d59936e07aa9b00f2a5640661bd1153f66914dc Mon Sep 17 00:00:00 2001
From: Will Deacon <will.deacon@arm.com>
Date: Wed, 24 Aug 2016 10:07:14 +0100
Subject: [PATCH] perf/core: Use this_cpu_ptr when stopping AUX events

When tearing down an aux buf for an event via perf_mmap_close,
__perf_event_output_stop is called on the event's CPU to ensure that
trace generation is halted before the process of unmapping and
freeing the buffer pages begins.

The callback is performed via cpu_function_call, which ensures that it
runs with interrupts disabled and is therefore not preemptible.
Unfortunately, the current code grabs the per-cpu context pointer using
get_cpu_ptr, which unnecessarily disables preemption and doesn't pair
the call with put_cpu_ptr, leading to a preempt_count() imbalance and
a BUG when freeing the aux buffer later on:

[   92.159611] ------------[ cut here ]------------
[   92.159617] WARNING: CPU: 1 PID: 2249 at kernel/events/ring_buffer.c:539 __rb_free_aux+0x10c/0x120
[   92.159618] Modules linked in:
[   92.159620] CPU: 1 PID: 2249 Comm: spe-poker Tainted: G        W       4.8.0-rc3 #2
[   92.159621] Hardware name: Dell Inc. XPS 13 9343/0F5KF3, BIOS A07 11/11/2015
[   92.159622]  0000000000000000 ffff88020f91fad8 ffffffff813379dd 0000000000000000
[   92.159624]  0000000000000000 ffff88020f91fb18 ffffffff81059ff6 0000021b0f91fb98
[   92.159625]  ffff8802100fe300 ffff88020de1da80 ffff88020de1d800 ffff8802100b8228
[   92.159627] Call Trace:
[   92.159630]  [<ffffffff813379dd>] dump_stack+0x4f/0x72
[   92.159632]  [<ffffffff81059ff6>] __warn+0xc6/0xe0
[   92.159633]  [<ffffffff8105a0c8>] warn_slowpath_null+0x18/0x20
[   92.159634]  [<ffffffff8112761c>] __rb_free_aux+0x10c/0x120
[   92.159636]  [<ffffffff81128163>] rb_free_aux+0x13/0x20
[   92.159637]  [<ffffffff8112515e>] perf_mmap_close+0x29e/0x2f0
[   92.159638]  [<ffffffff8111da30>] ? perf_iterate_ctx+0xe0/0xe0
[   92.159640]  [<ffffffff8115f685>] remove_vma+0x25/0x60
[   92.159641]  [<ffffffff81161796>] exit_mmap+0x106/0x140
[   92.159643]  [<ffffffff8105725c>] mmput+0x1c/0xd0
[   92.159644]  [<ffffffff8105cac3>] do_exit+0x253/0xbf0
[   92.159645]  [<ffffffff8105e32e>] do_group_exit+0x3e/0xb0
[   92.159647]  [<ffffffff81068d49>] get_signal+0x249/0x640
[   92.159648]  [<ffffffff8101c273>] do_signal+0x23/0x640
[   92.159651]  [<ffffffff81905f42>] ? _raw_write_unlock_irq+0x12/0x30
[   92.159652]  [<ffffffff81905f69>] ? _raw_spin_unlock_irq+0x9/0x10
[   92.159653]  [<ffffffff81901896>] ? __schedule+0x2c6/0x710
[   92.159655]  [<ffffffff810022a4>] exit_to_usermode_loop+0x74/0x90
[   92.159656]  [<ffffffff81002a56>] prepare_exit_to_usermode+0x26/0x30
[   92.159658]  [<ffffffff81906d1b>] retint_user+0x8/0x10
[   92.159659] ---[ end trace 926e713af6f1575e ]---

This patch uses this_cpu_ptr instead of get_cpu_ptr, since preemption is
already disabled by the caller.

Fixes: 95ff4ca26c49 ("perf/core: Free AUX pages in unmap path")
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Signed-off-by: Will Deacon <will.deacon@arm.com>
---
 kernel/events/core.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 5650f5317e0c..3cfabdf7b942 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -6166,7 +6166,7 @@ static int __perf_pmu_output_stop(void *info)
 {
 	struct perf_event *event = info;
 	struct pmu *pmu = event->pmu;
-	struct perf_cpu_context *cpuctx = get_cpu_ptr(pmu->pmu_cpu_context);
+	struct perf_cpu_context *cpuctx = this_cpu_ptr(pmu->pmu_cpu_context);
 	struct remote_output ro = {
 		.rb	= event->rb,
 	};
-- 
2.5.0

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

[Alexander Shishkin]

Will Deacon <will.deacon@arm.com> writes:

> A little bit of digging suggests that the preempt count isn't balanced
> across the call to perf_pmu_output_stop from perf_mmap_close. Further
> digging revealed the unbalanced get_cpu_ptr in __perf_pmu_output_stop.
> Fix below!

Oh gee, that's embarrassing. Thanks!

> This patch uses this_cpu_ptr instead of get_cpu_ptr, since preemption is
> already disabled by the caller.
>
> Fixes: 95ff4ca26c49 ("perf/core: Free AUX pages in unmap path")
> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Signed-off-by: Will Deacon <will.deacon@arm.com>

Reviewed-by: Alexander Shishkin <alexander.shishkin@linux.intel.com>

Regards,
--
Alex

[tip:perf/urgent] perf/core: Use this_cpu_ptr() when stopping AUX events

[tip-bot for Will Deacon]

Commit-ID:  8b6a3fe8fab97716990a3abde1a01fb5a34552a3
Gitweb:     http://git.kernel.org/tip/8b6a3fe8fab97716990a3abde1a01fb5a34552a3
Author:     Will Deacon <will.deacon@arm.com>
AuthorDate: Wed, 24 Aug 2016 10:07:14 +0100
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Wed, 24 Aug 2016 15:03:10 +0200

perf/core: Use this_cpu_ptr() when stopping AUX events

When tearing down an AUX buf for an event via perf_mmap_close(),
__perf_event_output_stop() is called on the event's CPU to ensure that
trace generation is halted before the process of unmapping and
freeing the buffer pages begins.

The callback is performed via cpu_function_call(), which ensures that it
runs with interrupts disabled and is therefore not preemptible.
Unfortunately, the current code grabs the per-cpu context pointer using
get_cpu_ptr(), which unnecessarily disables preemption and doesn't pair
the call with put_cpu_ptr(), leading to a preempt_count() imbalance and
a BUG when freeing the AUX buffer later on:

  WARNING: CPU: 1 PID: 2249 at kernel/events/ring_buffer.c:539 __rb_free_aux+0x10c/0x120
  Modules linked in:
  [...]
  Call Trace:
   [<ffffffff813379dd>] dump_stack+0x4f/0x72
   [<ffffffff81059ff6>] __warn+0xc6/0xe0
   [<ffffffff8105a0c8>] warn_slowpath_null+0x18/0x20
   [<ffffffff8112761c>] __rb_free_aux+0x10c/0x120
   [<ffffffff81128163>] rb_free_aux+0x13/0x20
   [<ffffffff8112515e>] perf_mmap_close+0x29e/0x2f0
   [<ffffffff8111da30>] ? perf_iterate_ctx+0xe0/0xe0
   [<ffffffff8115f685>] remove_vma+0x25/0x60
   [<ffffffff81161796>] exit_mmap+0x106/0x140
   [<ffffffff8105725c>] mmput+0x1c/0xd0
   [<ffffffff8105cac3>] do_exit+0x253/0xbf0
   [<ffffffff8105e32e>] do_group_exit+0x3e/0xb0
   [<ffffffff81068d49>] get_signal+0x249/0x640
   [<ffffffff8101c273>] do_signal+0x23/0x640
   [<ffffffff81905f42>] ? _raw_write_unlock_irq+0x12/0x30
   [<ffffffff81905f69>] ? _raw_spin_unlock_irq+0x9/0x10
   [<ffffffff81901896>] ? __schedule+0x2c6/0x710
   [<ffffffff810022a4>] exit_to_usermode_loop+0x74/0x90
   [<ffffffff81002a56>] prepare_exit_to_usermode+0x26/0x30
   [<ffffffff81906d1b>] retint_user+0x8/0x10

This patch uses this_cpu_ptr() instead of get_cpu_ptr(), since preemption is
already disabled by the caller.

Signed-off-by: Will Deacon <will.deacon@arm.com>
Reviewed-by: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Vince Weaver <vincent.weaver@maine.edu>
Fixes: 95ff4ca26c49 ("perf/core: Free AUX pages in unmap path")
Link: http://lkml.kernel.org/r/20160824091905.GA16944@arm.com
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/events/core.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 5650f53..3cfabdf 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -6166,7 +6166,7 @@ static int __perf_pmu_output_stop(void *info)
 {
 	struct perf_event *event = info;
 	struct pmu *pmu = event->pmu;
-	struct perf_cpu_context *cpuctx = get_cpu_ptr(pmu->pmu_cpu_context);
+	struct perf_cpu_context *cpuctx = this_cpu_ptr(pmu->pmu_cpu_context);
 	struct remote_output ro = {
 		.rb	= event->rb,
 	};