x86_pmu_start() warning hw.state PERF_HES_STOPPED

Found by

perf_fuzzer

Severity

Warning

First Seen

4.1-rc2

Most recently Seen

4.8-rc1

Reproducible

maybe. It's warn_on_once.

Found On

Haswell

Linux-kernel

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

Introduced by

Fixed in

Possibly by:
c7999c6f3fed9e383d3131474588f282ae6d56b9
perf: Fix PERF_EVENT_IOC_PERIOD migration race

Details

Maps to
	(4.0) arch/x86/kernel/cpu/perf_event.c:1151 x86_pmu_start+0xb2/0x120()
	(4.1) arch/x86/kernel/cpu/perf_event.c:1219 x86_pmu_start+0xaa/0x100()
	(4.4) arch/x86/kernel/cpu/perf_event.c:1209 x86_pmu_start+0xa2/0x100()

which is
	if (WARN_ON_ONCE(!(event->hw.state & PERF_HES_STOPPED)))
                return;

Kernel Splat

  1. 4.8-rc1
    *** perf_fuzzer 0.31-pre *** by Vince Weaver
    
            Linux version 4.8.0-rc1+ x86_64
            Processor: Intel 6/60/3
    
            Seeding random number generator with 1470778183
            /proc/sys/kernel/perf_event_max_sample_rate currently: 250/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 1470778183
    
    Pid=29156, sleeping 1s
    Iteration 20000
            Open attempts: 109135  Successful: 940  Currently open: 64
                    EPERM : 9
                    ENOENT : 620
                    E2BIG : 9615
                    EBADF : 9169
                    EBUSY : 7
                    EINVAL : 88650
                    EOPNOTSUPP : 125
                    Trinity Type (Normal 337/27329)(Sampling 34/27043)(Global 534/27191)(Random 35/27572)
                    Type (Hardware 238/15137)(software 339/14798)(tracepoint 48/14882)(Cache 63/13606)(cpu 197/14614)(breakpoint 12/14525)(intel_bts 23/873)(msr 5/926)(power 0/1021)(uncore_imc 2/954)(uncore_cbox_0 2/911)(uncore_cbox_1 4/883)(uncore_cbox_2 1/950)(uncore_cbox_3 2/950)(uncore_arb 0/876)(cstate_core 1/893)(cstate_pkg 3/1046)(#17 0/6)(#18 0/13)(>19 0/11271)
            Close:  882/882 Successful
            Read:   867/961 Successful
            Write:  0/959 Successful
            Ioctl:  360/889 Successful: (ENABLE 80/80)(DISABLE 87/87)(REFRESH 2/89)(RESET 75/75)(PERIOD 4/73)(SET_OUTPUT 7/74)(SET_FILTER 0/81)(ID 89/89)(SET_BPF 0/69)(PAUSE_OUTPUT 16/84)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/88)
            Mmap:   472/1086 Successful: (MMAP 472/1086)(TRASH 135/166)(READ 16/118)(UNMAP 471/1012)(AUX 1/123)(AUX_READ 2/11)
            Prctl:  898/898 Successful
            Fork:   458/458 Successful
            Poll:   848/858 Successful
            Access: 449/890 Successful
            Overflows: 0  Recursive: 0
            SIGIOs due to RT signal queue full: 0
    ==================================================
    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: 108950  Successful: 905  Currently open: 26
                    EPERM : 17
                    ENOENT : 611
                    E2BIG : 9535
                    EBADF : 9019
                    EBUSY : 16
                    EINVAL : 88743
                    EOPNOTSUPP : 104
                    Trinity Type (Normal 318/27395)(Sampling 24/27023)(Global 536/27248)(Random 27/27284)
                    Type (Hardware 209/15083)(software 344/14893)(tracepoint 43/14763)(Cache 56/13686)(cpu 208/14619)(breakpoint 15/14585)(intel_bts 7/884)(msr 8/862)(power 0/1005)(uncore_imc 0/888)(uncore_cbox_0 7/946)(uncore_cbox_1 1/871)(uncore_cbox_2 1/951)(uncore_cbox_3 2/981)(uncore_arb 3/879)(cstate_core 1/973)(cstate_pkg 0/984)(#17 0/10)(#18 0/11)(>19 0/11076)
            Close:  879/879 Successful
            Read:   765/848 Successful
            Write:  0/885 Successful
            Ioctl:  329/912 Successful: (ENABLE 79/79)(DISABLE 84/84)(REFRESH 4/79)(RESET 75/75)(PERIOD 5/96)(SET_OUTPUT 9/87)(SET_FILTER 0/79)(ID 67/67)(SET_BPF 0/98)(PAUSE_OUTPUT 6/84)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/84)
            Mmap:   410/1058 Successful: (MMAP 410/1058)(TRASH 137/169)(READ 29/152)(UNMAP 408/1040)(AUX 0/106)(AUX_READ 0/4)
            Prctl:  918/918 Successful
            Fork:   461/461 Successful
            Poll:   813/860 Successful
            Access: 468/912 Successful
            Overflows: 0  Recursive: 0
            SIGIOs due to RT signal queue full: 0
    Iteration 30000
            Open attempts: 109161  Successful: 962  Currently open: 139
                    EPERM : 8
                    ENOENT : 637
                    E2BIG : 9806
                    EBADF : 8617
                    EBUSY : 13
                    EINVAL : 89009
                    EOPNOTSUPP : 109
                    Trinity Type (Normal 309/27377)(Sampling 34/27497)(Global 579/27365)(Random 40/26922)
                    Type (Hardware 218/15557)(software 361/14769)(tracepoint 44/14734)(Cache 69/13506)(cpu 220/14759)(breakpoint 14/14665)(intel_bts 11/903)(msr 8/884)(power 0/1040)(uncore_imc 0/863)(uncore_cbox_0 6/891)(uncore_cbox_1 1/867)(uncore_cbox_2 1/946)(uncore_cbox_3 0/901)(uncore_arb 3/858)(cstate_core 3/883)(cstate_pkg 3/1007)(#17 0/17)(#18 0/11)(>19 0/11100)
            Close:  887/887 Successful
            Read:   850/928 Successful
            Write:  0/927 Successful
            Ioctl:  348/864 Successful: (ENABLE 71/71)(DISABLE 86/86)(REFRESH 7/85)(RESET 71/71)(PERIOD 6/61)(SET_OUTPUT 5/76)(SET_FILTER 0/77)(ID 97/97)(SET_BPF 0/89)(PAUSE_OUTPUT 5/82)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/69)
            Mmap:   454/1125 Successful: (MMAP 454/1125)(TRASH 132/138)(READ 13/163)(UNMAP 453/1051)(AUX 0/117)(AUX_READ 1/2)
            Prctl:  876/876 Successful
            Fork:   454/454 Successful
            Poll:   849/857 Successful
            Access: 467/925 Successful
            Overflows: 0  Recursive: 0
            SIGIOs due to RT signal queue full: 0
    [27288.628209] ------------[ cut here ]------------
    [27288.633711] WARNING: CPU: 3 PID: 27515 at arch/x86/events/core.c:1236 x86_pmu_start+0xae/0x100
    [27288.643473] 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 snd_hda_codec_realtek snd_hda_codec_generic ppdev snd_hda_intel evdev gf128mul iTCO_wdt iTCO_vendor_support snd_hda_codec snd_hda_core snd_hwdep snd_pcm glue_helper snd_timer ablk_helper cryptd snd psmouse sg tpm_tis serio_raw tpm_tis_core pcspkr i915 drm_kms_helper drm tpm soundcore i2c_algo_bit parport_pc mei_me video button battery mei parport i2c_i801 wmi i2c_smbus lpc_ich mfd_core sr_mod cdrom sd_mod ahci libahci xhci_pci libata ehci_pci xhci_hcd ehci_hcd e1000e ptp usbcore crc32c_intel scsi_mod pps_core usb_common fan thermal
    [27288.720776] CPU: 3 PID: 27515 Comm: perf_fuzzer Tainted: G        W       4.8.0-rc1+ #187
    [27288.730120] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
    [27288.738637]  0000000000000000 ffff88011eac3d68 ffffffff81437641 0000000000000000
    [27288.747267]  0000000000000000 ffff88011eac3da8 ffffffff81076bab 000004d400000000
    [27288.755887]  ffff88011eaca440 ffff88011ead40b0 0000000000000001 ffff8800b76458f0
    [27288.764495] Call Trace:
    [27288.767712]    [] dump_stack+0x63/0x82
    [27288.774480]  [] __warn+0xcb/0xf0
    [27288.780224]  [] warn_slowpath_null+0x1d/0x20
    [27288.787097]  [] x86_pmu_start+0xae/0x100
    [27288.793606]  [] perf_event_task_tick+0x2d0/0x360
    [27288.800868]  [] scheduler_tick+0x75/0xd0
    [27288.807369]  [] ? tick_sched_do_timer+0x30/0x30
    [27288.814501]  [] update_process_times+0x47/0x60
    [27288.821497]  [] tick_sched_handle.isra.14+0x25/0x60
    [27288.828964]  [] tick_sched_timer+0x3d/0x70
    [27288.835576]  [] __hrtimer_run_queues+0x103/0x300
    [27288.842792]  [] hrtimer_interrupt+0xab/0x1b0
    [27288.849674]  [] local_apic_timer_interrupt+0x38/0x60
    [27288.857235]  [] smp_apic_timer_interrupt+0x3d/0x50
    [27288.864604]  [] apic_timer_interrupt+0x82/0x90
    [27288.871634]   ---[ end trace 8da07322bed774f0 ]---
    
  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 1435845062
            /proc/sys/kernel/perf_event_max_sample_rate currently: 12500/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 1435845062
    
    Pid=32434, 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: 113873  Successful: 903  Currently open: 46
                    EPERM : 11
                    ENOENT : 634
                    E2BIG : 10201
                    EBADF : 9484
                    EBUSY : 3
                    EINVAL : 92348
                    EOPNOTSUPP : 289
                    Type (Hardware 206/16099)(software 315/16492)(tracepoint 64/16453)(Cache 46/14153)(cpu 231/16217)(breakpoint 11/16185)(power 0/2098)(intel_bts 29/2029)(uncore_imc 1/2140)(#9 0/8)(#10 0/7)(#11 0/5)(#12 0/12)(#13 0/7)(#14 0/6)(>14 0/11962)
            Close:  857/857 Successful
            Read:   746/858 Successful
            Write:  0/876 Successful
            Ioctl:  375/900 Successful: (ENABLE 87/87)(DISABLE 81/81)(REFRESH 7/88)(RESET 101/101)(PERIOD 9/114)(SET_OUTPUT 12/92)(SET_FILTER 0/88)(ID 78/78)(SET_BPF 0/81)(#9 0/0)(#10 0/0)(#11 0/0)(#12 0/0)(#13 0/0)(#14 0/0)(>14 0/90)
            Mmap:   451/1057 Successful: (MMAP 451/1057)(TRASH 129/156)(READ 13/140)(UNMAP 447/991)(AUX 1/264)(AUX_READ 3/12)
            Prctl:  944/944 Successful
            Fork:   456/456 Successful
            Poll:   850/888 Successful
            Access: 441/893 Successful
            Overflows: 0
    [  224.009431] ------------[ cut here ]------------
    [  224.014402] WARNING: CPU: 0 PID: 32434 at arch/x86/kernel/cpu/perf_event.c:1219 x86_pmu_start+0xaa/0x100()
    [  224.024747] 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
    [  224.098707] CPU: 0 PID: 32434 Comm: perf_fuzzer Not tainted 4.1.0+ #160
    [  224.105793] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
    [  224.113726]  ffffffff81a0f9f0 ffff8800cdc83da8 ffffffff8169e763 0000000000000000
    [  224.121707]  0000000000000000 ffff8800cdc83de8 ffffffff8106ecba 0000000181c4bc80
    [  224.129709]  ffff88011ea0bd80 ffff8800cec55000 0000000000000000 ffff88011eb1deb0
    [  224.137695] Call Trace:
    [  224.140301]  [] dump_stack+0x45/0x57
    [  224.145830]  [] warn_slowpath_common+0x8a/0xc0
    [  224.152273]  [] warn_slowpath_null+0x1a/0x20
    [  224.158535]  [] x86_pmu_start+0xaa/0x100
    [  224.164401]  [] perf_ioctl+0x429/0x470
    [  224.170101]  [] do_vfs_ioctl+0x2ba/0x4a0
    [  224.176012]  [] ? mntput+0x24/0x40
    [  224.181343]  [] ? __fput+0x17a/0x1e0
    [  224.186858]  [] SyS_ioctl+0x79/0x90
    [  224.192275]  [] entry_SYSCALL_64_fastpath+0x16/0x7a
    [  224.199197] ---[ end trace e3d880444bf5705a ]---
    
  3. *** perf_fuzzer 0.31-pre *** by Vince Weaver
    
            Linux version 4.1.0-rc2+ x86_64
            Processor: Intel 6/60/3
    
            Seeding random number generator with 1431210707
            /proc/sys/kernel/perf_event_max_sample_rate currently: 250/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 1431210707
    
    Pid=25348, 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: 108437  Successful: 905  Currently open: 43
                    EPERM : 15
                    ENOENT : 605
                    E2BIG : 9610
                    EBADF : 9073
                    EBUSY : 1
                    EINVAL : 87942
                    EOPNOTSUPP : 286
                    Type (Hardware 175/15086)(software 350/15696)(tracepoint 58/15719)(Cache 52/13488)(cpu 223/15538)(breakpoint 10/15471)(power 1/1906)(intel_bts 35/1942)(uncore_imc 1/1990)(#9 0/13)(#10 0/7)(#11 0/10)(#12 0/1)(#13 0/4)(#14 0/7)(>14 0/11559)
            Close attempts: 862  Successful: 862
            Read attempts: 863  Successful: 765
            Write attempts: 876  Successful: 0
            Ioctl attempts: 907  Successful: 405
            Mmap attempts: 905  Successful: 392
            Prctl attempts: 920  Successful: 920
            Fork attempts: 428  Successful: 428
            Poll attempts: 874  Successful: 818
            Access attempts: 931  Successful: 457
            Trash mmap attempts: 922  Successful: 922
            Overflows: 3
            SIGIOs due to RT signal queue full: 0
    Iteration 20000
            Open attempts: 112437  Successful: 927  Currently open: 98
                    EPERM : 13
                    ENOENT : 679
                    E2BIG : 9666
                    EBADF : 9373
                    EBUSY : 3
                    EINVAL : 91437
                    EOPNOTSUPP : 339
                    Type (Hardware 197/15821)(software 314/16231)(tracepoint 62/16037)(Cache 53/13973)(cpu 234/16241)(breakpoint 21/15998)(power 0/1968)(intel_bts 46/2076)(uncore_imc 0/2144)(#9 0/7)(#10 0/11)(#11 0/12)(#12 0/4)(#13 0/6)(#14 0/1)(>14 0/11907)
            Close attempts: 872  Successful: 872
            Read attempts: 922  Successful: 826
            Write attempts: 889  Successful: 0
            Ioctl attempts: 854  Successful: 387
            Mmap attempts: 927  Successful: 379
            Prctl attempts: 979  Successful: 979
            Fork attempts: 466  Successful: 466
            Poll attempts: 949  Successful: 940
            Access attempts: 928  Successful: 471
            Trash mmap attempts: 900  Successful: 900
            Overflows: 34
            SIGIOs due to RT signal queue full: 0
    [116917.481735] ------------[ cut here ]------------
    [116917.487333] WARNING: CPU: 1 PID: 25348 at arch/x86/kernel/cpu/perf_event.c:1151 x86_pmu_start+0xb2/0x120()
    [116917.498346] Modules linked in: fuse snd_hda_codec_realtek snd_hda_codec_generic snd_hda_codec_hdmi x86_pkg_temp_thermal intel_powerclamp snd_hda_intel intel_rapl iosf_mbi snd_hda_controller snd_hda_codec coretemp kvm crct10dif_pclmul crc32_pclmul snd_hda_core ghash_clmulni_intel aesni_intel snd_hwdep aes_x86_64 lrw i915 evdev ppdev psmouse drm_kms_helper iTCO_wdt iTCO_vendor_support snd_pcm gf128mul snd_timer glue_helper ablk_helper snd pcspkr serio_raw soundcore drm cryptd mei_me mei tpm_tis xhci_pci parport_pc i2c_algo_bit button video processor battery i2c_i801 xhci_hcd tpm parport lpc_ich wmi mfd_core sg sr_mod cdrom sd_mod ahci libahci libata ehci_pci ehci_hcd e1000e ptp usbcore scsi_mod crc32c_intel usb_common pps_core thermal fan thermal_sys
    [116917.573757] CPU: 1 PID: 25348 Comm: perf_fuzzer Tainted: G        W       4.1.0-rc2+ #142
    [116917.583317] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
    [116917.592002]  ffffffff81a08c08 ffff8800c5c03da8 ffffffff816d51d3 0000000000000000
    [116917.600844]  0000000000000000 ffff8800c5c03de8 ffffffff81072dfa 00000001ca10e000
    [116917.609672]  ffff88011ea4bd80 ffff8801176d9000 0000000000000000 ffff88011eb5ed78
    [116917.618465] Call Trace:
    [116917.621906]  [] dump_stack+0x45/0x57
    [116917.628212]  [] warn_slowpath_common+0x8a/0xc0
    [116917.635426]  [] warn_slowpath_null+0x1a/0x20
    [116917.642471]  [] x86_pmu_start+0xb2/0x120
    [116917.649131]  [] perf_ioctl+0x48c/0x4d0
    [116917.655640]  [] ? __do_page_fault+0x159/0x460
    [116917.662794]  [] do_vfs_ioctl+0x2e0/0x4e0
    [116917.669482]  [] ? up_read+0x23/0x40
    [116917.675728]  [] ? __do_page_fault+0x1d1/0x460
    [116917.682858]  [] SyS_ioctl+0x81/0xa0
    [116917.689077]  [] system_call_fastpath+0x16/0x7a
    [116917.696314] ---[ end trace 1f7cf34f6e082bd8 ]---
    
  4. *** perf_fuzzer 0.31-pre *** by Vince Weaver
    
            Linux version 4.1.0-rc2+ x86_64
            Processor: Intel 6/60/3
    
            Seeding random number generator with 1431032249
            /proc/sys/kernel/perf_event_max_sample_rate currently: 250/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 1431032249
    

Back to perf_fuzzer bugs found