Bug 114741

Summary: ubsan: "-1364598267798016 * 25600 cannot be represented" in drivers/cpufreq/intel_pstate.c:874:11
Product: Platform Specific/Hardware Reporter: Peter Gerber (peter)
Component: IA-64Assignee: platform_ia-64
Status: NEW ---    
Severity: normal CC: dsmythies
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 4.5.0 Subsystem:
Regression: No Bisected commit-id:
Attachments: Trace example of MSR's reset after suspend

Description Peter Gerber 2016-03-15 20:38:14 UTC 
The following message appeared after waking up from suspension. Let me know should you need more information.


ar 15 15:37:53 ivy kernel: i8042 aux 00:04: System wakeup disabled by ACPI
Mar 15 15:37:53 ivy kernel: i8042 kbd 00:03: System wakeup enabled by ACPI
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming kernel object tree...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming client object trees...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming display...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming console...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: suspending console...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: suspending display...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: evicting buffers...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: waiting for kernel channels to go idle...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: suspending client object trees...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: suspending kernel object tree...
Mar 15 15:37:53 ivy kernel: PM: suspend of devices complete after 5231.600 msecs
Mar 15 15:37:53 ivy kernel: PM: late suspend of devices complete after 10.953 msecs
Mar 15 15:37:53 ivy kernel: ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
Mar 15 15:37:53 ivy kernel: r8169 0000:0b:00.0: System wakeup enabled by ACPI
Mar 15 15:37:53 ivy kernel: ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI
Mar 15 15:37:53 ivy kernel: xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
Mar 15 15:37:53 ivy kernel: PM: noirq suspend of devices complete after 21.925 msecs
Mar 15 15:37:53 ivy kernel: ACPI: Preparing to enter system sleep state S3
Mar 15 15:37:53 ivy kernel: ACPI : EC: EC stopped
Mar 15 15:37:53 ivy kernel: PM: Saving platform NVS memory
Mar 15 15:37:53 ivy kernel: Disabling non-boot CPUs ...
Mar 15 15:37:53 ivy kernel: smpboot: CPU 1 is now offline
Mar 15 15:37:53 ivy kernel: smpboot: CPU 2 is now offline
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 27
Mar 15 15:37:53 ivy kernel: smpboot: CPU 3 is now offline
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 27
Mar 15 15:37:53 ivy kernel: smpboot: CPU 4 is now offline
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 23
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 27
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 28
Mar 15 15:37:53 ivy kernel: smpboot: CPU 5 is now offline
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 23
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 27
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 28
Mar 15 15:37:53 ivy kernel: smpboot: CPU 6 is now offline
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 16
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 23
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 27
Mar 15 15:37:53 ivy kernel: Broke affinity for irq 28
Mar 15 15:37:53 ivy kernel: smpboot: CPU 7 is now offline
Mar 15 15:37:53 ivy kernel: ACPI: Low-level resume complete
Mar 15 15:37:53 ivy kernel: ACPI : EC: EC started
Mar 15 15:37:53 ivy kernel: PM: Restoring platform NVS memory
Mar 15 15:37:53 ivy kernel: Enabling non-boot CPUs ...
Mar 15 15:37:53 ivy kernel: ================================================================================
Mar 15 15:37:53 ivy kernel: UBSAN: Undefined behaviour in drivers/cpufreq/intel_pstate.c:874:11
Mar 15 15:37:53 ivy kernel: signed integer overflow:
Mar 15 15:37:53 ivy kernel: -1364598267798016 * 25600 cannot be represented in type 'long long int'
Mar 15 15:37:53 ivy kernel: CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.5.0-pege1 #1
Mar 15 15:37:53 ivy kernel: Hardware name: Hewlett-Packard HP ENVY dv6 Notebook PC/181B, BIOS F.29 10/03/2013
Mar 15 15:37:53 ivy kernel:  0000000000000000 e1c5c6bebd5b2880 ffffffff816fcef7 000000000000002a
Mar 15 15:37:53 ivy kernel:  e1c5c6bebd5b2880 ffff88045f203d28 0000000000006400 ffffffff817952a9
Mar 15 15:37:53 ivy kernel:  ffffffff830c69a8 ffffffff81795672 0000002a00000046 0000000000000202
Mar 15 15:37:53 ivy kernel: Call Trace:
Mar 15 15:37:53 ivy kernel:  <IRQ>  [<ffffffff816fcef7>] ? dump_stack+0x70/0xb9
Mar 15 15:37:53 ivy kernel:  [<ffffffff817952a9>] ? ubsan_epilogue+0x9/0x40
Mar 15 15:37:53 ivy kernel:  [<ffffffff81795672>] ? handle_overflow+0xd2/0x110
Mar 15 15:37:53 ivy kernel:  [<ffffffff811edcdc>] ? ktime_get+0x7c/0x220
Mar 15 15:37:53 ivy kernel:  [<ffffffff81a91f01>] ? intel_pstate_timer_func+0x451/0x820
Mar 15 15:37:53 ivy kernel:  [<ffffffff81a91ab0>] ? intel_hwp_timer_func+0x530/0x530
Mar 15 15:37:53 ivy kernel:  [<ffffffff811d8bf6>] ? call_timer_fn+0x46/0x2a0
Mar 15 15:37:53 ivy kernel:  [<ffffffff81a91ab0>] ? intel_hwp_timer_func+0x530/0x530
Mar 15 15:37:53 ivy kernel:  [<ffffffff811d913d>] ? run_timer_softirq+0x2ed/0x7a0
Mar 15 15:37:53 ivy kernel:  [<ffffffff810f353c>] ? __do_softirq+0x14c/0x600
Mar 15 15:37:53 ivy kernel:  [<ffffffff811e0e18>] ? hrtimer_interrupt+0x168/0x480
Mar 15 15:37:53 ivy kernel:  [<ffffffff810f3b67>] ? irq_exit+0xa7/0xd0
Mar 15 15:37:53 ivy kernel:  [<ffffffff81dfe764>] ? smp_apic_timer_interrupt+0x44/0x60
Mar 15 15:37:53 ivy kernel:  [<ffffffff81dfca22>] ? apic_timer_interrupt+0x82/0x90
Mar 15 15:37:53 ivy kernel:  <EOI>  [<ffffffff8103de68>] ? mwait_idle+0xf8/0x310
Mar 15 15:37:53 ivy kernel:  [<ffffffff8103ddf9>] ? mwait_idle+0x89/0x310
Mar 15 15:37:53 ivy kernel:  [<ffffffff81188032>] ? cpu_startup_entry+0x402/0x550
Mar 15 15:37:53 ivy kernel:  [<ffffffff81147ad9>] ? get_parent_ip+0x9/0x20
Mar 15 15:37:53 ivy kernel:  [<ffffffff8351f393>] ? start_kernel+0x502/0x522
Mar 15 15:37:53 ivy kernel:  [<ffffffff8351e120>] ? early_idt_handler_array+0x120/0x120
Mar 15 15:37:53 ivy kernel:  [<ffffffff8351e7bf>] ? x86_64_start_kernel+0x155/0x179
Mar 15 15:37:53 ivy kernel: ================================================================================
Mar 15 15:37:53 ivy kernel: x86: Booting SMP configuration:
Mar 15 15:37:53 ivy kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
Mar 15 15:37:53 ivy kernel:  cache: parent cpu1 should not be sleeping
Mar 15 15:37:53 ivy kernel: ================================================================================
Mar 15 15:37:53 ivy kernel: UBSAN: Undefined behaviour in drivers/cpufreq/intel_pstate.c:874:11
Mar 15 15:37:53 ivy kernel: signed integer overflow:
Mar 15 15:37:53 ivy kernel: -1229688334952448 * 25600 cannot be represented in type 'long long int'
Mar 15 15:37:53 ivy kernel: CPU: 0 PID: 8616 Comm: systemd-sleep Not tainted 4.5.0-pege1 #1
Mar 15 15:37:53 ivy kernel: Hardware name: Hewlett-Packard HP ENVY dv6 Notebook PC/181B, BIOS F.29 10/03/2013
Mar 15 15:37:53 ivy kernel:  0000000000000000 000000003c27923f ffffffff816fcef7 000000000000002a
Mar 15 15:37:53 ivy kernel:  000000003c27923f ffff8800010d3ad0 0000000000006400 ffffffff817952a9
Mar 15 15:37:53 ivy kernel:  ffffffff830c69a8 ffffffff81795672 0000002a8179632f 0000000000000202
Mar 15 15:37:53 ivy kernel: Call Trace:
Mar 15 15:37:53 ivy kernel:  [<ffffffff816fcef7>] ? dump_stack+0x70/0xb9
Mar 15 15:37:53 ivy kernel:  [<ffffffff817952a9>] ? ubsan_epilogue+0x9/0x40
Mar 15 15:37:53 ivy kernel:  [<ffffffff81795672>] ? handle_overflow+0xd2/0x110
Mar 15 15:37:53 ivy kernel:  [<ffffffff81a8dff8>] ? intel_pstate_set_pstate+0x1a8/0x450
Mar 15 15:37:53 ivy kernel:  [<ffffffff811edcdc>] ? ktime_get+0x7c/0x220
Mar 15 15:37:53 ivy kernel:  [<ffffffff81a8f780>] ? intel_pstate_cpu_init+0x7f0/0xe50
Mar 15 15:37:53 ivy kernel:  [<ffffffff81a868f8>] ? cpufreq_online+0x138/0xe80
Mar 15 15:37:53 ivy kernel:  [<ffffffff81a87677>] ? cpufreq_cpu_callback+0x37/0x50
Mar 15 15:37:53 ivy kernel:  [<ffffffff8112eadd>] ? notifier_call_chain+0x8d/0x170
Mar 15 15:37:53 ivy kernel:  [<ffffffff810e95ff>] ? cpu_notify+0x1f/0x40
Mar 15 15:37:53 ivy kernel:  [<ffffffff810ea06c>] ? _cpu_up+0x17c/0x1b0
Mar 15 15:37:53 ivy kernel:  [<ffffffff810ea70b>] ? enable_nonboot_cpus+0x10b/0x360
Mar 15 15:37:53 ivy kernel:  [<ffffffff81199047>] ? suspend_devices_and_enter+0x707/0xc60
Mar 15 15:37:53 ivy kernel:  [<ffffffff8132a33f>] ? printk+0x57/0x73
Mar 15 15:37:53 ivy kernel:  [<ffffffff81199a63>] ? pm_suspend+0x4c3/0x570
Mar 15 15:37:53 ivy kernel:  [<ffffffff811970a1>] ? state_store+0x91/0xf0
Mar 15 15:37:53 ivy kernel:  [<ffffffff81572ed0>] ? sysfs_kf_bin_read+0x2d0/0x2d0
Mar 15 15:37:53 ivy kernel:  [<ffffffff815711dd>] ? kernfs_fop_write+0x17d/0x330
Mar 15 15:37:53 ivy kernel:  [<ffffffff814523c7>] ? __vfs_write+0x67/0x360
Mar 15 15:37:53 ivy kernel:  [<ffffffff81147ad9>] ? get_parent_ip+0x9/0x20
Mar 15 15:37:53 ivy kernel:  [<ffffffff8119056b>] ? update_fast_ctr+0x4b/0x90
Mar 15 15:37:53 ivy kernel:  [<ffffffff814537b7>] ? vfs_write+0xe7/0x3e0
Mar 15 15:37:53 ivy kernel:  [<ffffffff81455e82>] ? SyS_write+0x52/0xc0
Mar 15 15:37:53 ivy kernel:  [<ffffffff81dfbcf6>] ? entry_SYSCALL_64_fastpath+0x16/0x75
Mar 15 15:37:53 ivy kernel: ================================================================================
Mar 15 15:37:53 ivy kernel: ================================================================================
Mar 15 15:37:53 ivy kernel: CPU1 is up
Mar 15 15:37:53 ivy kernel: smpboot: Booting Node 0 Processor 2 APIC 0x2
Mar 15 15:37:53 ivy kernel:  cache: parent cpu2 should not be sleeping
Mar 15 15:37:53 ivy kernel: CPU2 is up
Mar 15 15:37:53 ivy kernel: smpboot: Booting Node 0 Processor 3 APIC 0x3
Mar 15 15:37:53 ivy kernel:  cache: parent cpu3 should not be sleeping
Mar 15 15:37:53 ivy kernel: CPU3 is up
Mar 15 15:37:53 ivy kernel: smpboot: Booting Node 0 Processor 4 APIC 0x4
Mar 15 15:37:53 ivy kernel:  cache: parent cpu4 should not be sleeping
Mar 15 15:37:53 ivy kernel: CPU4 is up
Mar 15 15:37:53 ivy kernel: smpboot: Booting Node 0 Processor 5 APIC 0x5
Mar 15 15:37:53 ivy kernel:  cache: parent cpu5 should not be sleeping
Mar 15 15:37:53 ivy kernel: CPU5 is up
Mar 15 15:37:53 ivy kernel: smpboot: Booting Node 0 Processor 6 APIC 0x6
Mar 15 15:37:53 ivy kernel:  cache: parent cpu6 should not be sleeping
Mar 15 15:37:53 ivy kernel: CPU6 is up
Mar 15 15:37:53 ivy kernel: smpboot: Booting Node 0 Processor 7 APIC 0x7
Mar 15 15:37:53 ivy kernel:  cache: parent cpu7 should not be sleeping
Mar 15 15:37:53 ivy kernel: CPU7 is up
Mar 15 15:37:53 ivy kernel: ACPI: Waking up from system sleep state S3
Mar 15 15:37:53 ivy kernel: ehci-pci 0000:00:1d.0: System wakeup disabled by ACPI
Mar 15 15:37:53 ivy kernel: xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
Mar 15 15:37:53 ivy kernel: ehci-pci 0000:00:1a.0: System wakeup disabled by ACPI
Mar 15 15:37:53 ivy kernel: PM: noirq resume of devices complete after 12.254 msecs
Mar 15 15:37:53 ivy kernel: PM: early resume of devices complete after 0.831 msecs
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming kernel object tree...
Mar 15 15:37:53 ivy kernel: ath: phy0: ASPM enabled: 0x43
Mar 15 15:37:53 ivy kernel: sd 0:0:0:0: [sda] Starting disk
Mar 15 15:37:53 ivy kernel: r8169 0000:0b:00.0: System wakeup disabled by ACPI
Mar 15 15:37:53 ivy kernel: r8169 0000:0b:00.0 eth0: link down
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming client object trees...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming display...
Mar 15 15:37:53 ivy kernel: nouveau 0000:01:00.0: DRM: resuming console...
Mar 15 15:37:53 ivy kernel: usb 2-1.6: reset full-speed USB device number 3 using ehci-pci
Mar 15 15:37:53 ivy kernel: usb 1-1.1: reset full-speed USB device number 3 using ehci-pci
Mar 15 15:37:53 ivy kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Mar 15 15:37:53 ivy kernel: ata1.00: supports DRM functions and may not be fully accessible
Mar 15 15:37:53 ivy kernel: ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Mar 15 15:37:53 ivy kernel: ata1.00: disabling queued TRIM support
Mar 15 15:37:53 ivy kernel: ata1.00: supports DRM functions and may not be fully accessible
Mar 15 15:37:53 ivy kernel: ata1.00: disabling queued TRIM support
Mar 15 15:37:53 ivy kernel: ata1.00: configured for UDMA/133
Mar 15 15:37:53 ivy kernel: ata5.00: configured for UDMA/100
Mar 15 15:37:53 ivy kernel: usb 1-1.3: reset high-speed USB device number 4 using ehci-pci
Mar 15 15:37:53 ivy kernel: rtc_cmos 00:01: System wakeup disabled by ACPI
Mar 15 15:37:53 ivy kernel: i8042 kbd 00:03: System wakeup disabled by ACPI
Mar 15 15:37:53 ivy kernel: PM: resume of devices complete after 1085.734 msecs
Mar 15 15:37:53 ivy kernel: PM: Finishing wakeup.
Mar 15 15:37:53 ivy kernel: Restarting tasks ... done.
Mar 15 15:37:53 ivy kernel: mmc0: cannot verify signal voltage switch
Mar 15 15:37:53 ivy systemd[3174]: Time has been changed
Mar 15 15:37:53 ivy systemd[1489]: Time has been changed
Comment 1 Doug Smythies 2016-06-21 15:17:35 UTC 
I am having trouble to correlate your line 874 of the intel_pstate.c driver with any version I can extract from git. Could you please post the code fragment from that area, so that I can correlate it with some version of the intel_pstate.c driver that I have.

I believe the issue to be that the aperf, mperf, and tsc MSR's get reset during a suspend / resume cycle, and so the first sample to sample difference calculation after resume becomes ridiculous. While I have seen this issue before, I have never complained about it. Does the issue still occur with kernel 4.7-rc4?

I think, but am not sure yet, that you will want to change the bug report "Product" to "Power Management" and the "Component" to "intel_pstate". I stumbled across this by accident, while searching for bugs with the keyword intel_pstate.
Comment 2 Doug Smythies 2016-06-21 16:35:36 UTC 
Created attachment 220831 [details]
Trace example of MSR's reset after suspend

On kernel 4.7-rc4, I ran a trace, however trace messes up through a suspend/resume and only data for CPU 0 was acquired after the first suspend.

3 suspend / resumes were done. Observe the extreme numbers for aperf, mperf, and tsc on the first sample during resume. The reason, I have never complained about this before, it that there I never observed any bad side effect as a result.

Note: the trace post processing tools print the numbers as %u, or unsigned.