Re: WARNING: at arch/x86/kernel/kvmclock.c:127

From: Sedat Dilek
Date: Sun Jun 10 2012 - 12:08:40 EST

Next message: Alex Williamson: "Re: [PATCH] uio_pci_generic does not export memory resources"
Previous message: Sedat Dilek: "Re: WARNING: at arch/x86/kernel/kvmclock.c:127"
In reply to: Sedat Dilek: "Re: WARNING: at arch/x86/kernel/kvmclock.c:127"
Next in thread: Eric B Munson: "Re: WARNING: at arch/x86/kernel/kvmclock.c:127"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Sun, Jun 10, 2012 at 5:47 PM, Sedat Dilek <sedat.dilek@xxxxxxxxxxxxxx> wrote:
> Hi,
>
> I see the same warning especially when resuming from a suspend (see
> timestamps >=30-35sec) between Linux v3.5-rc1..v3.5-rc2.
>
> $ sudo grep kvmclock.c /var/log/kern.log
> Jun Â4 21:11:32 fambox kernel: [ Â784.037237] WARNING: at
> arch/x86/kernel/kvmclock.c:127
> kvm_check_and_clear_guest_paused+0x52/0x60()
> Jun Â5 20:35:57 fambox kernel: [ 1928.458060] WARNING: at
> arch/x86/kernel/kvmclock.c:127
> kvm_check_and_clear_guest_paused+0x52/0x60()
> Jun Â8 09:35:52 fambox kernel: [ 3290.134637] WARNING: at
> arch/x86/kernel/kvmclock.c:127
> kvm_check_and_clear_guest_paused+0x52/0x60()
> Jun Â8 09:35:52 fambox kernel: [ 3290.238592] WARNING: at
> arch/x86/kernel/kvmclock.c:127
> kvm_check_and_clear_guest_paused+0x52/0x60()
> Jun Â8 12:11:20 fambox kernel: [ 5777.023571] WARNING: at
> arch/x86/kernel/kvmclock.c:127
> kvm_check_and_clear_guest_paused+0x52/0x60()
> Jun Â9 13:32:50 fambox kernel: [ 2778.842695] WARNING: at
> arch/x86/kernel/kvmclock.c:127
> kvm_check_and_clear_guest_paused+0x52/0x60()
>
> From [1]:
>
> "...The warning itself is not required for the check_and_clear
> function and can be removed as far as I am concerned."
>
> From [2] commit 3b5d56b9317fa7b5407dff1aa7b115bf6cdbd494 ("kvmclock:
> Add functions to check if the host has stopped the vm")
> ...
> +bool kvm_check_and_clear_guest_paused(void)
> +{
> + Â Â Â bool ret = false;
> + Â Â Â struct pvclock_vcpu_time_info *src;
> +
> + Â Â Â /*
> + Â Â Â Â* per_cpu() is safe here because this function is only called from
> + Â Â Â Â* timer functions where preemption is already disabled.
> + Â Â Â Â*/
> + Â Â Â WARN_ON(!in_atomic());
> + Â Â Â src = &__get_cpu_var(hv_clock);
> + Â Â Â if ((src->flags & PVCLOCK_GUEST_STOPPED) != 0) {
> + Â Â Â Â Â Â Â __this_cpu_and(hv_clock.flags, ~PVCLOCK_GUEST_STOPPED);
> + Â Â Â Â Â Â Â ret = true;
> + Â Â Â }
> +
> + Â Â Â return ret;
> +}
> +EXPORT_SYMBOL_GPL(kvm_check_and_clear_guest_paused);
> +
> ...
> ( The export macro was dropped in a followup commit. )
>
> So you mean "WARN_ON(!in_atomic());" can be deleted?
>
> Regards,
> - Sedat -
>
> [1] http://www.spinics.net/lists/kvm/msg73732.html
> [2] http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=blobdiff;f=arch/x86/kernel/kvmclock.c;h=4ba090ca689db5322fb242b98b53158de5447dc9;hp=f8492da65bfcb03e2775638ad5ce9502099d62c8;hb=3b5d56b9317fa7b5407dff1aa7b115bf6cdbd494;hpb=eae3ee7d8a7c59cf63441dedf28674889f5fc477

[ Removed Glauber Costa - Email-address @ RH does not exist anymore ]
[ Added CC to Rafael J. Wysocki (S/R) ]

I added for the sake of correctness the last call-trace I have seen
with Linux v3.5-rc2.
And... I had loaded kvm and kvm_intel kernel-modules, but no KVM
instance actively running or active while doing suspend/resume (S/R).

- Sedat -
Jun 9 13:32:50 fambox kernel: [ 2777.787365] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jun 9 13:32:50 fambox kernel: [ 2777.803351] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jun 9 13:32:50 fambox kernel: [ 2777.803354] PM: Entering mem sleep
Jun 9 13:32:50 fambox kernel: [ 2777.803420] Suspending console(s) (use no_console_suspend to debug)
Jun 9 13:32:50 fambox kernel: [ 2777.803806] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
Jun 9 13:32:50 fambox kernel: [ 2777.803850] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Jun 9 13:32:50 fambox kernel: [ 2777.804168] sd 0:0:0:0: [sda] Stopping disk
Jun 9 13:32:50 fambox kernel: [ 2777.806550] sd 1:0:0:0: [sdb] Stopping disk
Jun 9 13:32:50 fambox kernel: [ 2778.422876] PM: suspend of devices complete after 619.779 msecs
Jun 9 13:32:50 fambox kernel: [ 2778.422878] PM: suspend devices took 0.620 seconds
Jun 9 13:32:50 fambox kernel: [ 2778.423006] PM: late suspend of devices complete after 0.126 msecs
Jun 9 13:32:50 fambox kernel: [ 2778.438920] r8169 0000:02:00.0: wake-up capability enabled by ACPI
Jun 9 13:32:50 fambox kernel: [ 2778.502850] PM: noirq suspend of devices complete after 79.895 msecs
Jun 9 13:32:50 fambox kernel: [ 2778.503082] ACPI: Preparing to enter system sleep state S3
Jun 9 13:32:50 fambox kernel: [ 2778.526894] PM: Saving platform NVS memory
Jun 9 13:32:50 fambox kernel: [ 2778.531564] Disabling non-boot CPUs ...
Jun 9 13:32:50 fambox kernel: [ 2778.634664] CPU 1 is now offline
Jun 9 13:32:50 fambox kernel: [ 2778.738600] CPU 2 is now offline
Jun 9 13:32:50 fambox kernel: [ 2778.739230] Broke affinity for irq 9
Jun 9 13:32:50 fambox kernel: [ 2778.739247] Broke affinity for irq 16
Jun 9 13:32:50 fambox kernel: [ 2778.842535] CPU 3 is now offline
Jun 9 13:32:50 fambox kernel: [ 2778.842688] ------------[ cut here ]------------
Jun 9 13:32:50 fambox kernel: [ 2778.842695] WARNING: at arch/x86/kernel/kvmclock.c:127 kvm_check_and_clear_guest_paused+0x52/0x60()
Jun 9 13:32:50 fambox kernel: [ 2778.842696] Hardware name: <HIDDEN>
Jun 9 13:32:50 fambox kernel: [ 2778.842723] Modules linked in: sch_fq_codel sch_htb snd_hda_codec_hdmi snd_hda_codec_realtek rfcomm parport_pc bnep ppdev joydev snd_hda_intel arc4 snd_hda_codec coretemp snd_hwdep kvm_intel snd_pcm snd_page_alloc kvm i915 snd_seq_midi iwlwifi snd_seq_midi_event snd_rawmidi snd_seq ghash_clmulni_intel snd_seq_device drm_kms_helper aesni_intel snd_timer uvcvideo drm aes_x86_64 mac80211 cryptd videobuf2_vmalloc snd videobuf2_memops psmouse i2c_algo_bit btusb videobuf2_core samsung_laptop soundcore microcode cfg80211 videodev lp bluetooth serio_raw mei hid_generic mac_hid lpc_ich video parport usbhid hid r8169
Jun 9 13:32:50 fambox kernel: [ 2778.842725] Pid: 5475, comm: pm-suspend Not tainted 3.5.0-rc2-1-iniza-generic #1
Jun 9 13:32:50 fambox kernel: [ 2778.842727] Call Trace:
Jun 9 13:32:50 fambox kernel: [ 2778.842731] [<ffffffff810527bf>] warn_slowpath_common+0x7f/0xc0
Jun 9 13:32:50 fambox kernel: [ 2778.842734] [<ffffffff8105281a>] warn_slowpath_null+0x1a/0x20
Jun 9 13:32:50 fambox kernel: [ 2778.842736] [<ffffffff8103fc82>] kvm_check_and_clear_guest_paused+0x52/0x60
Jun 9 13:32:50 fambox kernel: [ 2778.842739] [<ffffffff810dda6d>] watchdog_timer_fn+0x8d/0x180
Jun 9 13:32:50 fambox kernel: [ 2778.842742] [<ffffffff8107a506>] __run_hrtimer+0x76/0x1f0
Jun 9 13:32:50 fambox kernel: [ 2778.842744] [<ffffffff810dd9e0>] ? __touch_watchdog+0x30/0x30
Jun 9 13:32:50 fambox kernel: [ 2778.842746] [<ffffffff8101b349>] ? read_tsc+0x9/0x20
Jun 9 13:32:50 fambox kernel: [ 2778.842748] [<ffffffff8107adc3>] hrtimer_interrupt+0xe3/0x200
Jun 9 13:32:50 fambox kernel: [ 2778.842750] [<ffffffff8107af0b>] __hrtimer_peek_ahead_timers.part.26+0x2b/0x30
Jun 9 13:32:50 fambox kernel: [ 2778.842754] [<ffffffff816527c2>] hrtimer_cpu_notify+0x1c3/0x1eb
Jun 9 13:32:50 fambox kernel: [ 2778.842757] [<ffffffff81668f5d>] notifier_call_chain+0x4d/0x70
Jun 9 13:32:50 fambox kernel: [ 2778.842758] [<ffffffff8107c54e>] __raw_notifier_call_chain+0xe/0x10
Jun 9 13:32:50 fambox kernel: [ 2778.842761] [<ffffffff81055620>] __cpu_notify+0x20/0x40
Jun 9 13:32:50 fambox kernel: [ 2778.842762] [<ffffffff81055775>] cpu_notify_nofail+0x15/0x20
Jun 9 13:32:50 fambox kernel: [ 2778.842765] [<ffffffff816365ad>] _cpu_down+0x10d/0x270
Jun 9 13:32:50 fambox kernel: [ 2778.842767] [<ffffffff81055927>] disable_nonboot_cpus+0xa7/0x150
Jun 9 13:32:50 fambox kernel: [ 2778.842770] [<ffffffff8109952c>] suspend_devices_and_enter+0x22c/0x310
Jun 9 13:32:50 fambox kernel: [ 2778.842771] [<ffffffff8109979f>] pm_suspend+0x18f/0x1f0
Jun 9 13:32:50 fambox kernel: [ 2778.842773] [<ffffffff810987ae>] state_store+0x8e/0xf0
Jun 9 13:32:50 fambox kernel: [ 2778.842775] [<ffffffff81319aff>] kobj_attr_store+0xf/0x30
Jun 9 13:32:50 fambox kernel: [ 2778.842778] [<ffffffff811eddcf>] sysfs_write_file+0xef/0x170
Jun 9 13:32:50 fambox kernel: [ 2778.842781] [<ffffffff8117ed93>] vfs_write+0xb3/0x180
Jun 9 13:32:50 fambox kernel: [ 2778.842782] [<ffffffff8117f0ba>] sys_write+0x4a/0x90
Jun 9 13:32:50 fambox kernel: [ 2778.842785] [<ffffffff8166d229>] system_call_fastpath+0x16/0x1b
Jun 9 13:32:50 fambox kernel: [ 2778.842786] ---[ end trace c32bb8d548ae6e7f ]---
Jun 9 13:32:50 fambox kernel: [ 2778.843016] Extended CMOS year: 2000
Jun 9 13:32:50 fambox kernel: [ 2778.844289] ACPI: Low-level resume complete
Jun 9 13:32:50 fambox kernel: [ 2778.844335] PM: Restoring platform NVS memory
Jun 9 13:32:50 fambox kernel: [ 2778.845559] Extended CMOS year: 2000
Jun 9 13:32:50 fambox kernel: [ 2778.845604] Enabling non-boot CPUs ...
Jun 9 13:32:50 fambox kernel: [ 2778.845694] Booting Node 0 Processor 1 APIC 0x1
Jun 9 13:32:50 fambox kernel: [ 2778.856634] Disabled fast string operations
Jun 9 13:32:50 fambox kernel: [ 2778.859002] NMI watchdog: enabled, takes one hw-pmu counter.
Jun 9 13:32:50 fambox kernel: [ 2778.859289] CPU1 is up
Jun 9 13:32:50 fambox kernel: [ 2778.859424] Booting Node 0 Processor 2 APIC 0x2
Jun 9 13:32:50 fambox kernel: [ 2778.870461] Disabled fast string operations
Jun 9 13:32:50 fambox kernel: [ 2778.872826] NMI watchdog: enabled, takes one hw-pmu counter.
Jun 9 13:32:50 fambox kernel: [ 2778.873148] CPU2 is up
Jun 9 13:32:50 fambox kernel: [ 2778.873243] Booting Node 0 Processor 3 APIC 0x3
Jun 9 13:32:50 fambox kernel: [ 2778.884278] Disabled fast string operations
Jun 9 13:32:50 fambox kernel: [ 2778.886641] NMI watchdog: enabled, takes one hw-pmu counter.
Jun 9 13:32:50 fambox kernel: [ 2778.886944] CPU3 is up
Jun 9 13:32:50 fambox kernel: [ 2778.891780] ACPI: Waking up from system sleep state S3
Jun 9 13:32:50 fambox kernel: [ 2778.943274] PM: noirq resume of devices complete after 2.200 msecs
Jun 9 13:32:50 fambox kernel: [ 2778.943379] PM: early resume of devices complete after 0.065 msecs
Jun 9 13:32:50 fambox kernel: [ 2778.943451] i915 0000:00:02.0: setting latency timer to 64
Jun 9 13:32:50 fambox kernel: [ 2778.943461] ehci_hcd 0000:00:1a.0: setting latency timer to 64
Jun 9 13:32:50 fambox kernel: [ 2778.943497] ehci_hcd 0000:00:1d.0: setting latency timer to 64
Jun 9 13:32:50 fambox kernel: [ 2778.943509] ahci 0000:00:1f.2: setting latency timer to 64
Jun 9 13:32:50 fambox kernel: [ 2778.943585] r8169 0000:02:00.0: wake-up capability disabled by ACPI
Jun 9 13:32:50 fambox kernel: [ 2778.943638] iwlwifi 0000:01:00.0: RF_KILL bit toggled to enable radio.
Jun 9 13:32:50 fambox kernel: [ 2778.943651] snd_hda_intel 0000:00:1b.0: irq 50 for MSI/MSI-X
Jun 9 13:32:50 fambox kernel: [ 2778.943682] usb usb3: root hub lost power or was reset
Jun 9 13:32:50 fambox kernel: [ 2778.943684] usb usb4: root hub lost power or was reset
Jun 9 13:32:50 fambox kernel: [ 2778.948575] xhci_hcd 0000:03:00.0: irq 41 for MSI/MSI-X
Jun 9 13:32:50 fambox kernel: [ 2778.948581] xhci_hcd 0000:03:00.0: irq 42 for MSI/MSI-X
Jun 9 13:32:50 fambox kernel: [ 2778.948586] xhci_hcd 0000:03:00.0: irq 43 for MSI/MSI-X
Jun 9 13:32:50 fambox kernel: [ 2778.948592] xhci_hcd 0000:03:00.0: irq 44 for MSI/MSI-X
Jun 9 13:32:50 fambox kernel: [ 2778.948597] xhci_hcd 0000:03:00.0: irq 45 for MSI/MSI-X
Jun 9 13:32:50 fambox kernel: [ 2779.001863] [drm] Enabling RC6 states: RC6 on, RC6p off, RC6pp off
Jun 9 13:32:50 fambox kernel: [ 2779.276755] ata4: SATA link down (SStatus 0 SControl 300)
Jun 9 13:32:50 fambox kernel: [ 2779.284757] ata5: SATA link down (SStatus 0 SControl 300)
Jun 9 13:32:50 fambox kernel: [ 2779.292760] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jun 9 13:32:50 fambox kernel: [ 2779.297042] ata2.00: configured for UDMA/133
Jun 9 13:32:50 fambox kernel: [ 2779.312786] sd 1:0:0:0: [sdb] Starting disk
Jun 9 13:32:50 fambox kernel: [ 2779.380807] usb 2-1.4: reset low-speed USB device number 3 using ehci_hcd
Jun 9 13:32:50 fambox kernel: [ 2779.732579] usb 1-1.4: reset high-speed USB device number 3 using ehci_hcd
Jun 9 13:32:50 fambox kernel: [ 2781.483191] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jun 9 13:32:50 fambox kernel: [ 2781.485651] ata1.00: configured for UDMA/133
Jun 9 13:32:50 fambox kernel: [ 2781.499271] sd 0:0:0:0: [sda] Starting disk
Jun 9 13:32:50 fambox kernel: [ 2781.501362] Extended CMOS year: 2000
Jun 9 13:32:50 fambox kernel: [ 2781.528530] PM: resume of devices complete after 2586.977 msecs
Jun 9 13:32:50 fambox kernel: [ 2781.528604] PM: resume devices took 2.588 seconds
Jun 9 13:32:50 fambox kernel: [ 2781.528646] PM: Finishing wakeup.
Jun 9 13:32:50 fambox kernel: [ 2781.531291] Restarting tasks ... done.
Jun 9 13:32:50 fambox kernel: [ 2781.537436] video LNXVIDEO:00: Restoring backlight state

Next message: Alex Williamson: "Re: [PATCH] uio_pci_generic does not export memory resources"
Previous message: Sedat Dilek: "Re: WARNING: at arch/x86/kernel/kvmclock.c:127"
In reply to: Sedat Dilek: "Re: WARNING: at arch/x86/kernel/kvmclock.c:127"
Next in thread: Eric B Munson: "Re: WARNING: at arch/x86/kernel/kvmclock.c:127"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]