x86_pmu_stop() warning hw.state PERF_HES_STOPPED

Found by

perf_fuzzer

Severity

Warning

First Seen

possibly related to much older bugs seen 4.2-rc0

Most recently Seen

4.9-rc0 (pentium 4)

Reproducible

maybe. It's warn_on_once.

Found On

Haswell

Linux-kernel

2 July 2015 -- perf: fuzzer, lots of warnings

Introduced by

Fixed in

n/a

Details

Maps to
	arch/x86/kernel/cpu/perf_event.c:1307 x86_pmu_stop+0xb8/0xd0()

which is
	WARN_ON_ONCE(hwc->state & PERF_HES_STOPPED);

Kernel Splat

  1. *** perf_fuzzer 0.31-pre *** by Vince Weaver
    
            Linux version 4.8.0+ x86_64
            Processor: Intel 15/6/5
    
            Seeding random number generator with 1476389472
            /proc/sys/kernel/perf_event_max_sample_rate currently: 40750/s
            /proc/sys/kernel/perf_event_paranoid currently: 2
            Logging perf_event_open() failures: no
            Running fsync after every syscall: no
            To reproduce, try: ./perf_fuzzer -s 30000 -r 1476389472
    
    Pid=4571, sleeping 1s
    ==================================================
    Fuzzing the following syscalls:
            mmap perf_event_open close read write ioctl fork prctl poll 
    *NOT* Fuzzing the following syscalls:
    
    Also attempting the following:
            signal-handler-on-overflow busy-instruction-loop accessing-perf-proc-and
    -sys-files trashing-the-mmap-page 
    *NOT* attempting the following:
    
    ==================================================
    Cannot open /sys/kernel/tracing/kprobe_events
    Iteration 10000
            Open attempts: 651420  Successful: 866  Currently open: 11
                    EPERM : 13
                    ENOENT : 987
                    E2BIG : 56855
                    EBADF : 15447
                    EACCES : 75838
                    EINVAL : 501398
                    UNKNOWN 75 : 3
                    EOPNOTSUPP : 13
                    Trinity Type (Normal 705/162563)(Sampling 71/162513)(Global 0/16
    3238)(Random 90/163106)
                    Type (Hardware 253/90984)(software 402/99081)(tracepoint 68/9850
    6)(Cache 11/81689)(cpu 98/98185)(breakpoint 34/97589)(msr 0/16351)(#7 0/34)(#8 0
    /629)(#9 0/74)(#10 0/58)(#11 0/35)(#12 0/42)(#13 0/32)(#14 0/43)(#15 0/29)(#16 0
    /707)(#17 0/67)(#18 0/52)(>19 0/67233)
            Close:  855/855 Successful
            Read:   717/811 Successful
            Write:  0/767 Successful
            Ioctl:  364/831 Successful: (ENABLE 71/71)(DISABLE 92/92)(REFRESH 4/81)(
    RESET 81/81)(PERIOD 15/78)(SET_OUTPUT 11/83)(SET_FILTER 0/59)(ID 81/81)(SET_BPF 
    0/70)(PAUSE_OUTPUT 9/71)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/64)
            Mmap:   380/1019 Successful: (MMAP 380/1019)(TRASH 68/142)(READ 68/71)(U
    NMAP 380/930)(AUX 0/104)(AUX_READ 0/0)
            Prctl:  945/945 Successful
            Fork:   448/448 Successful
            Poll:   852/908 Successful
            Access: 119/856 Successful
            Overflows: 0  Recursive: 0
            SIGIOs due to RT signal queue full: 0
    Signal from invalid fd 12 Bad file descriptor
    Iteration 20000
            Open attempts: 698698  Successful: 946  Currently open: 7
                    EPERM : 16
                    ENOENT : 1142
                    E2BIG : 61273
                    EBADF : 15926
                    EACCES : 81249
                    EINVAL : 538116
                    ENOSPC : 6
                    UNKNOWN 75 : 9
                    EOPNOTSUPP : 15
                    Trinity Type (Normal 757/174643)(Sampling 71/174728)(Global 0/17
    4732)(Random 118/174595)
                    Type (Hardware 245/97606)(software 437/106013)(tracepoint 82/105
    570)(Cache 8/87391)(cpu 128/105489)(breakpoint 46/104950)(msr 0/17615)(#7 0/45)(
    #8 0/693)(#9 0/75)(#10 0/53)(#11 0/59)(#12 0/54)(#13 0/43)(#14 0/41)(#15 0/38)(#
    16 0/749)(#17 0/62)(#18 0/63)(>19 0/72089)
            Close:  950/950 Successful
            Read:   740/857 Successful
            Write:  0/882 Successful
            Ioctl:  340/901 Successful: (ENABLE 75/75)(DISABLE 83/83)(REFRESH 15/87)
    (RESET 73/73)(PERIOD 19/102)(SET_OUTPUT 9/78)(SET_FILTER 1/85)(ID 58/58)(SET_BPF
     0/97)(PAUSE_OUTPUT 7/82)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/81)
            Mmap:   425/1088 Successful: (MMAP 425/1088)(TRASH 72/136)(READ 156/421)
    (UNMAP 424/1031)(AUX 0/111)(AUX_READ 11/142)
            Prctl:  908/908 Successful
            Fork:   460/460 Successful
            Poll:   901/914 Successful
            Access: 104/875 Successful
            Overflows: 495  Recursive: 0
            SIGIOs due to RT signal queue full: 0
    [  211.663271] ------------[ cut here ]------------
    [  211.664008] WARNING: CPU: 0 PID: 5778 at arch/x86/events/core.c:1336 x86_pmu_stop+0xb9/0xd0
    [  211.664008] CPU: 0 PID: 5778 Comm: perf_fuzzer Tainted: G        W       4.8.0+ #5
    [  211.664008] Hardware name: LENOVO 88088NU/LENOVO, BIOS 2JKT37AUS 07/12/2007
    [  211.664008]  ffff88003f403dd8 ffffffff81334768 0000000000000000 0000000000000000
    [  211.664008]  ffff88003f403e18 ffffffff810620e1 000005380000000a ffff88003f40a480
    [  211.664008]  ffff88003a8cb000 0000000000000004 ffff88003f41e864 0000000000cbf5ad
    [  211.664008] Call Trace:
    [  211.664008]   [  211.664008]  [] dump_stack+0x4d/0x65
    [  211.664008]  [] __warn+0xd1/0xf0
    [  211.664008]  [] warn_slowpath_null+0x1d/0x20
    [  211.664008]  [] x86_pmu_stop+0xb9/0xd0
    [  211.664008]  [] x86_pmu_del+0x54/0x140
    [  211.664008]  [] event_sched_out.isra.99+0xd6/0x320
    [  211.664008]  [] group_sched_out+0x52/0xd0
    [  211.664008]  [] __perf_event_disable+0xbf/0xf0
    [  211.664008]  [] event_function+0x9b/0x160
    [  211.664008]  [] ? perf_cgroup_attach+0x50/0x50
    [  211.664008]  [] remote_function+0x3b/0x50
    [  211.664008]  [] flush_smp_call_function_queue+0x76/0x160
    [  211.664008]  [] generic_smp_call_function_single_interrupt+0x13/0x60
    [  211.664008]  [] smp_trace_call_function_single_interrupt+0x32/0xe0
    [  211.664008]  [] trace_call_function_single_interrupt+0x7f/0x90
    [  211.664008]   [  211.664008] ---[ end trace 7698eb74ca460958 ]---
    
  2. *** perf_fuzzer 0.31-pre *** by Vince Weaver
    
            Linux version 4.1.0+ x86_64
            Processor: Intel 6/60/3
    
            Seeding random number generator with 1435846044
            /proc/sys/kernel/perf_event_max_sample_rate currently: 3250/s
            /proc/sys/kernel/perf_event_paranoid currently: 0
            Logging perf_event_open() failures: no
            Running fsync after every syscall: no
            To reproduce, try: ./perf_fuzzer -s 30000 -r 1435846044
    
    Pid=7953, sleeping 1s
    ==================================================
    Fuzzing the following syscalls:
            mmap perf_event_open close read write ioctl fork prctl poll 
    *NOT* Fuzzing the following syscalls:
            
    Also attempting the following:
            signal-handler-on-overflow busy-instruction-loop accessing-perf-proc-and-sys-files trashing-the-mmap-page 
    *NOT* attempting the following:
            
    ==================================================
    Iteration 10000
            Open attempts: 101345  Successful: 897  Currently open: 20
                    EPERM : 10
                    ENOENT : 519
                    E2BIG : 8711
                    EBADF : 8517
                    EBUSY : 1
                    EINVAL : 82427
                    EOPNOTSUPP : 263
                    Type (Hardware 177/14007)(software 343/14606)(tracepoint 60/14544)(Cache 53/12620)(cpu 202/14755)(breakpoint 13/14682)(power 0/1834)(intel_bts 45/1774)(uncore_imc 4/1862)(#9 0/11)(#10 0/11)(#11 0/4)(#12 0/5)(#13 0/7)(#14 0/2)(>14 0/10621)
            Close:  877/877 Successful
            Read:   782/872 Successful
            Write:  0/829 Successful
            Ioctl:  360/820 Successful: (ENABLE 81/81)(DISABLE 85/85)(REFRESH 7/77)(RESET 85/85)(PERIOD 9/83)(SET_OUTPUT 11/87)(SET_FILTER 2/82)(ID 80/80)(SET_BPF 0/72)(#9 0/0)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/88)
            Mmap:   413/1055 Successful: (MMAP 413/1055)(TRASH 112/159)(READ 25/131)(UNMAP 412/1026)(AUX 1/263)(AUX_READ 3/15)
            Prctl:  912/912 Successful
            Fork:   451/451 Successful
            Poll:   748/839 Successful
            Access: 448/892 Successful
            Overflows: 0
    Iteration 20000
            Open attempts: 108412  Successful: 951  Currently open: 91
                    EPERM : 12
                    ENOENT : 658
                    E2BIG : 9590
                    EBADF : 8748
                    EBUSY : 2
                    EINVAL : 88145
                    EOPNOTSUPP : 306
                    Type (Hardware 198/15217)(software 362/15743)(tracepoint 61/15597)(Cache 54/13512)(cpu 211/15680)(breakpoint 20/15464)(power 2/1939)(intel_bts 43/1905)(uncore_imc 0/1980)(#9 0/12)(#10 0/14)(#11 0/10)(#12 0/13)(#13 0/4)(#14 0/4)(>14 0/11318)
            Close:  880/880 Successful
            Read:   852/958 Successful
            Write:  0/892 Successful
            Ioctl:  399/927 Successful: (ENABLE 86/86)(DISABLE 107/107)(REFRESH 2/100)(RESET 89/89)(PERIOD 2/84)(SET_OUTPUT 9/77)(SET_FILTER 0/98)(ID 104/104)(SET_BPF 0/89)(#9 0/0)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/93)
            Mmap:   499/1103 Successful: (MMAP 499/1103)(TRASH 120/133)(READ 7668/7784)(UNMAP 494/1046)(AUX 0/281)(AUX_READ 2/6)
            Prctl:  849/849 Successful
            Fork:   470/470 Successful
            Poll:   867/877 Successful
            Access: 474/898 Successful
            Overflows: 7658
    [ 1210.496111] ------------[ cut here ]------------
    [ 1210.501445] WARNING: CPU: 6 PID: 0 at arch/x86/kernel/cpu/perf_event.c:1307 x
    86_pmu_stop+0xb8/0xd0()
    [ 1210.511622] Modules linked in: fuse x86_pkg_temp_thermal intel_powerclamp intel_rapl iosf_mbi coretemp kvm_intel kvm snd_hda_codec_hdmi crct10dif_pclmul crc32_pclmul ghash_clmulni_intel hmac drbg i915 ansi_cprng snd_hda_codec_realtek snd_hda_codec_generic iTCO_wdt ppdev snd_hda_intel snd_hda_codec aesni_intel aes_x86_64 snd_hda_core lrw evdev snd_hwdep drm_kms_helper drm psmouse iTCO_vendor_support snd_pcm gf128mul glue_helper ablk_helper serio_raw pcspkr cryptd snd_timer i2c_i801 processor battery video snd mei_me parport_pc i2c_algo_bit button soundcore lpc_ich mfd_core tpm_tis mei parport tpm wmi sg sr_mod sd_mod cdrom ehci_pci ehci_hcd ahci libahci libata xhci_pci xhci_hcd e1000e ptp usbcore crc32c_intel fan scsi_mod pps_core usb_common thermal thermal_sys
    [ 1210.588151] CPU: 6 PID: 0 Comm: swapper/6 Tainted: G        W       4.1.0+ #160
    [ 1210.596395] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
    [ 1210.604743]  ffffffff81a0f9f0 ffff88011eb83d98 ffffffff8169e763 0000000000000000
    [ 1210.613195]  0000000000000000 ffff88011eb83dd8 ffffffff8106ecba 0000000000000008
    [ 1210.621646]  ffff88011eb8bd80 ffff8801172fc000 0000000000000004 ffff88011eb9deb0
    [ 1210.630071] Call Trace:
    [ 1210.633120]    [] dump_stack+0x45/0x57
    [ 1210.639787]  [] warn_slowpath_common+0x8a/0xc0
    [ 1210.646665]  [] warn_slowpath_null+0x1a/0x20
    [ 1210.653328]  [] x86_pmu_stop+0xb8/0xd0
    [ 1210.659466]  [] x86_pmu_del+0x46/0x140
    [ 1210.665607]  [] event_sched_out.isra.80+0x124/0x320
    [ 1210.672924]  [] ? __perf_event_disable+0x53/0x130
    [ 1210.680097]  [] group_sched_out+0x48/0xc0
    [ 1210.686530]  [] ? native_sched_clock+0x28/0x90
    [ 1210.693445]  [] __perf_event_disable+0xfe/0x130
    [ 1210.700408]  [] ? cpu_clock_event_start+0x40/0x40
    [ 1210.707550]  [] remote_function+0x42/0x50
    [ 1210.713942]  [] flush_smp_call_function_queue+0x7b/0x170
    [ 1210.721762]  [] generic_smp_call_function_single_interrupt+0x13/0x60
    [ 1210.730679]  [] smp_trace_call_function_single_interrupt+0x38/0xb0
    [ 1210.739467]  [] trace_call_function_single_interrupt+0x6b/0x70
    [ 1210.747820]    [] ? cpuidle_enter_state+0xf4/0x220
    [ 1210.755614]  [] ? cpuidle_enter_state+0xd0/0x220
    [ 1210.762708]  [] cpuidle_enter+0x17/0x20
    [ 1210.768966]  [] call_cpuidle+0x3b/0x70
    [ 1210.775135]  [] ? cpuidle_select+0x13/0x20
    [ 1210.781637]  [] cpu_startup_entry+0x245/0x310
    [ 1210.788411]  [] start_secondary+0x120/0x130
    [ 1210.795024] ---[ end trace e3d880444bf5705c ]---
    

Back to perf_fuzzer bugs found