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

Groups > linux.kernel > #1461331 > unrolled thread

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

Started byVince Weaver <vincent.weaver@maine.edu>
First post2016-08-12 19:20 +0200
Last post2016-08-23 19:50 +0200
Articles 8 — 5 participants

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: WARNING: kernel/events/core.c:4893 perf_mmap_close Vince Weaver <vincent.weaver@maine.edu> - 2016-08-12 19:20 +0200
    Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Alexander Shishkin <alexander.shishkin@linux.intel.com> - 2016-08-12 20:00 +0200
      Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Will Deacon <will.deacon@arm.com> - 2016-08-23 17:20 +0200
        Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Alexander Shishkin <alexander.shishkin@linux.intel.com> - 2016-08-23 19:10 +0200
          Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Will Deacon <will.deacon@arm.com> - 2016-08-24 11:30 +0200
            Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Alexander Shishkin <alexander.shishkin@linux.intel.com> - 2016-08-24 13:50 +0200
            [tip:perf/urgent] perf/core: Use this_cpu_ptr() when stopping AUX  events tip-bot for Will Deacon <tipbot@zytor.com> - 2016-08-24 15:20 +0200
        Re: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close Peter Zijlstra <peterz@infradead.org> - 2016-08-23 19:50 +0200

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

FromVince Weaver <vincent.weaver@maine.edu>
Date2016-08-12 19:20 +0200
SubjectRe: perf: WARNING: kernel/events/core.c:4893 perf_mmap_close
Message-ID<s5ohH-4zo-15@gated-at.bofh.it>
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 ]---

[toc] | [next] | [standalone]

#1461352

FromAlexander Shishkin <alexander.shishkin@linux.intel.com>
Date2016-08-12 20:00 +0200
Message-ID<s5oUr-4QH-33@gated-at.bofh.it>
In reply to#1461331
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 ]---
>

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

#1468629

FromWill Deacon <will.deacon@arm.com>
Date2016-08-23 17:20 +0200
Message-ID<s9lEB-5Js-17@gated-at.bofh.it>
In reply to#1461352
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

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

#1468723

FromAlexander Shishkin <alexander.shishkin@linux.intel.com>
Date2016-08-23 19:10 +0200
Message-ID<s9nn4-6Up-11@gated-at.bofh.it>
In reply to#1468629
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

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

#1469275

FromWill Deacon <will.deacon@arm.com>
Date2016-08-24 11:30 +0200
Message-ID<s9CFs-gj-37@gated-at.bofh.it>
In reply to#1468723
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

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

#1469359

FromAlexander Shishkin <alexander.shishkin@linux.intel.com>
Date2016-08-24 13:50 +0200
Message-ID<s9EQW-1Ge-25@gated-at.bofh.it>
In reply to#1469275
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

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

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

Fromtip-bot for Will Deacon <tipbot@zytor.com>
Date2016-08-24 15:20 +0200
Subject[tip:perf/urgent] perf/core: Use this_cpu_ptr() when stopping AUX events
Message-ID<s9Gg2-2I8-25@gated-at.bofh.it>
In reply to#1469275
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,
 	};

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

#1468748

FromPeter Zijlstra <peterz@infradead.org>
Date2016-08-23 19:50 +0200
Message-ID<s9nZL-7aa-7@gated-at.bofh.it>
In reply to#1468629
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

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web