open-vm-tools icon indicating copy to clipboard operation
open-vm-tools copied to clipboard
verified publisher icon vmware

Linux guest unable to hibernate

Open polarathene opened this issue 2 years ago • 6 comments

Describe the bug

On a Linux VM guest, hibernating fails to complete, leaving the VM guest stuck until powering off via VMware Workstation Player UI. Upon reboot, resume from hibernation is not successful.

Normally I do not need this functionality, as the VMware Workstation "Suspend" works well. When I did need to hibernate, I was surprised that it does not appear functional.

Reproduction steps

  1. Install a linux guest (CachyOS was used for report).
  2. Run systemctl hibernate to hibernate the system.
  3. Failure occurs.

Expected behavior

Successfully hibernate via OS.

Additional context

  • VMware Workstation 17 Player (17.0.2 build-21581411)
    • open-vm-tools version 12.2.5 installed in the guest OS.
  • Host: Windows 11
  • Guest: Linux OS (CachyOS / ArchLinux)
    • KDE Plasma 5.27.7 (X11)
    • Kernel 6.4.8 (also 6.1.50 LTS)
    • Mesa 23.1.5
    • Xorg 21.1.8
    • systemd 254
    • vmwgfx 2.20.0 (VMware SVGA II Adapter) VM configured with:
  • 12 CPU cores (host CPU is AMD 7940HS, 8/16 cores/threads) with virtualization engine enabled.
  • Memory 4GB.
  • Disk SCSI 32GB (swap partition and swapfile both attempted with 8GB size), each disk using a single .vmdk file.
  • 3D graphics enabled with 2GB memory (host has Nvidia RTX 4060 and AMD 780M).
vmx file 
.encoding = "windows-1252"
config.version = "8"
virtualHW.version = "20"
pciBridge0.present = "TRUE"
pciBridge4.present = "TRUE"
pciBridge4.virtualDev = "pcieRootPort"
pciBridge4.functions = "8"
pciBridge5.present = "TRUE"
pciBridge5.virtualDev = "pcieRootPort"
pciBridge5.functions = "8"
pciBridge6.present = "TRUE"
pciBridge6.virtualDev = "pcieRootPort"
pciBridge6.functions = "8"
pciBridge7.present = "TRUE"
pciBridge7.virtualDev = "pcieRootPort"
pciBridge7.functions = "8"
vmci0.present = "TRUE"
hpet0.present = "TRUE"
nvram = "linux_throwaway.nvram"
virtualHW.productCompatibility = "hosted"
gui.exitOnCLIHLT = "FALSE"
powerType.powerOff = "soft"
powerType.powerOn = "soft"
powerType.suspend = "soft"
powerType.reset = "soft"
displayName = "linux_throwaway"
guestOS = "other5xlinux-64"
vhv.enable = "TRUE"
vpmc.enable = "TRUE"
tools.syncTime = "FALSE"
sound.autoDetect = "TRUE"
sound.fileName = "-1"
sound.present = "TRUE"
numvcpus = "12"
cpuid.coresPerSocket = "3"
vcpu.hotadd = "TRUE"
memsize = "4096"
mem.hotadd = "TRUE"
scsi0.virtualDev = "lsilogic"
scsi0.present = "TRUE"
scsi0:0.fileName = "linux_throwaway.vmdk"
scsi0:0.present = "TRUE"
ide1:0.deviceType = "cdrom-image"
ide1:0.fileName = "D:\iso\cachyos-kde-linux-230709.iso"
ide1:0.present = "TRUE"
usb.present = "TRUE"
ehci.present = "TRUE"
svga.graphicsMemoryKB = "2097152"
ethernet0.connectionType = "nat"
ethernet0.addressType = "generated"
ethernet0.virtualDev = "e1000"
ethernet0.present = "TRUE"
extendedConfigFile = "linux_throwaway.vmxf"
floppy0.present = "FALSE"
firmware = "efi"
vmxstats.filename = "linux_throwaway.scoreboard"
uuid.bios = "56 4d 35 ee 8a 05 85 bf-ce 57 43 17 6a 1b 0c 74"
uuid.location = "56 4d 35 ee 8a 05 85 bf-ce 57 43 17 6a 1b 0c 74"
pciBridge0.pciSlotNumber = "17"
pciBridge4.pciSlotNumber = "21"
pciBridge5.pciSlotNumber = "22"
pciBridge6.pciSlotNumber = "23"
pciBridge7.pciSlotNumber = "24"
scsi0.pciSlotNumber = "16"
usb.pciSlotNumber = "32"
ethernet0.pciSlotNumber = "33"
sound.pciSlotNumber = "34"
ehci.pciSlotNumber = "35"
usb_xhci.pciSlotNumber = "160"
scsi0:0.redo = ""
svga.vramSize = "268435456"
vmotion.checkpointFBSize = "4194304"
vmotion.checkpointSVGAPrimarySize = "268435456"
vmotion.svga.mobMaxSize = "1073741824"
vmotion.svga.graphicsMemoryKB = "2097152"
vmotion.svga.supports3D = "1"
vmotion.svga.baseCapsLevel = "9"
vmotion.svga.maxPointSize = "1"
vmotion.svga.maxTextureSize = "16384"
vmotion.svga.maxVolumeExtent = "2048"
vmotion.svga.maxTextureAnisotropy = "16"
vmotion.svga.lineStipple = "0"
vmotion.svga.dxMaxConstantBuffers = "15"
vmotion.svga.dxProvokingVertex = "0"
vmotion.svga.sm41 = "1"
vmotion.svga.multisample2x = "1"
vmotion.svga.multisample4x = "1"
vmotion.svga.msFullQuality = "1"
vmotion.svga.logicOps = "1"
vmotion.svga.bc67 = "9"
vmotion.svga.sm5 = "1"
vmotion.svga.multisample8x = "1"
vmotion.svga.logicBlendOps = "0"
vmotion.svga.maxForcedSampleCount = "16"
vmotion.svga.gl43 = "1"
ethernet0.generatedAddress = "00:0c:29:1b:0c:74"
ethernet0.generatedAddressOffset = "0"
vmci0.id = "1780157556"
monitor.phys_bits_used = "45"
cleanShutdown = "TRUE"
softPowerOff = "TRUE"
ide1:0.startConnected = "FALSE"
usb.generic.allowHID = "TRUE"
svga.guestBackedPrimaryAware = "TRUE"
guestInfo.detailed.data = "architecture='X86' bitness='64' buildNumber='rolling' distroName='CachyOS Linux' familyName='Linux' kernelVersion='6.4.8-2-cachyos' prettyName='CachyOS'"
tools.remindInstall = "FALSE"
gui.lastPoweredViewMode = "fullscreen"
scsi0:1.fileName = "data.vmdk"
scsi0:1.present = "TRUE"
scsi0:1.redo = ""
checkpoint.vmState = ""
usb_xhci:6.speed = "2"
usb_xhci:6.present = "TRUE"
usb_xhci:6.deviceType = "hub"
usb_xhci:6.port = "6"
usb_xhci:6.parent = "-1"
usb_xhci:7.speed = "4"
usb_xhci:7.present = "TRUE"
usb_xhci:7.deviceType = "hub"
usb_xhci:7.port = "7"
usb_xhci:7.parent = "-1"
scsi0:2.fileName = "linux_throwaway-swap.vmdk"
scsi0:2.present = "TRUE"
scsi0:2.redo = ""
usb:1.speed = "2"
usb:1.present = "TRUE"
usb:1.deviceType = "hub"
usb:1.port = "1"
usb:1.parent = "-1"
mks.enable3d = "TRUE"
usb_xhci.present = "TRUE"
usb_xhci:4.present = "TRUE"
usb_xhci:4.deviceType = "hid"
usb_xhci:4.port = "4"
usb_xhci:4.parent = "-1"

vmware.log just prior to running systemctl hibernate:

Click to expand 
2023-08-31T06:24:05.002Z In(05) vmx GuestInfo: HostinfoDetailedDataHeader version: 1
2023-08-31T06:24:05.002Z No(00) vmx ConfigDB: Setting guestInfo.detailed.data = <not printed>
2023-08-31T06:24:05.051Z In(05) vcpu-10 TOOLS call to unity.show.taskbar failed.
2023-08-31T06:26:19.028Z In(05) vcpu-9 Guest: Mesa: SVGA3D; build: RELEASE;  LLVM;
2023-08-31T06:26:19.028Z In(05) vcpu-9 Guest: Mesa: 23.1.5
2023-08-31T06:26:25.451Z In(05) vmx GuestRpcSendTimedOut: message to toolbox timed out.
2023-08-31T06:26:25.451Z In(05) vmx Tools: [AppStatus] Last heartbeat value 171 (last received 5s ago)
2023-08-31T06:26:25.451Z In(05) vmx TOOLS: appName=toolbox, oldStatus=1, status=2, guestInitiated=0.
2023-08-31T06:26:27.183Z In(05) svga SWBScreen: Screen 1 Destroyed: xywh(0, 0, 1280, 800) flags=0x2
2023-08-31T06:26:27.183Z In(05) vmx GuestRpc: Got error for channel 0 connection 7: Remote disconnected
2023-08-31T06:26:27.183Z In(05) vmx GuestRpc: GuestRpcResetVsockChannel: channel 0
2023-08-31T06:26:27.183Z In(05) vmx GuestRpc: Closing channel 0 connection 7
2023-08-31T06:26:27.183Z In(05) vmx GuestRpc: Got error for channel 1 connection 8: Remote disconnected
2023-08-31T06:26:27.183Z In(05) vmx GuestRpc: GuestRpcResetVsockChannel: channel 1
2023-08-31T06:26:27.183Z In(05) vmx GuestRpc: Closing channel 1 connection 8
2023-08-31T06:26:27.195Z In(05) vcpu-11 SCSI0: RESET BUS
2023-08-31T06:26:30.606Z In(05) vmx GuestRpcSendTimedOut: message to toolbox-dnd timed out.
2023-08-31T06:26:30.606Z In(05) vmx TOOLS: appName=toolbox-dnd, oldStatus=1, status=2, guestInitiated=0.
2023-08-31T06:26:41.201Z In(05) vcpu-0 Tools: Tools heartbeat timeout.
2023-08-31T06:26:41.201Z In(05) vcpu-0 Tools: Running status rpc handler: 1 => 0.
2023-08-31T06:26:41.201Z In(05) vcpu-0 Tools: Changing running status: 1 => 0.
2023-08-31T06:26:41.201Z In(05) vcpu-0 Tools: [RunningStatus] Last heartbeat value 171 (last received 20s ago)
2023-08-31T06:26:45.452Z In(05) vmx GuestRpcSendTimedOut: message to toolbox timed out.
2023-08-31T06:26:45.452Z In(05) vmx GuestRpc: app toolbox's second ping timeout; assuming app is down
2023-08-31T06:26:45.452Z In(05) vmx Tools: [AppStatus] Last heartbeat value 171 (last received 25s ago)
2023-08-31T06:26:45.452Z In(05) vmx TOOLS: appName=toolbox, oldStatus=2, status=0, guestInitiated=0.
2023-08-31T06:26:45.457Z In(05) vmx GuestRpc: Reinitializing Channel 0(toolbox)
2023-08-31T06:26:45.457Z In(05) vmx GuestMsg: Channel 0, Cannot unpost because the previous post is already completed
2023-08-31T06:26:45.457Z In(05) vmx Tools: [AppStatus] Last heartbeat value 171 (last received 25s ago)
2023-08-31T06:26:45.457Z In(05) vmx TOOLS: appName=toolbox, oldStatus=0, status=0, guestInitiated=0.
2023-08-31T06:26:50.608Z In(05) vmx GuestRpcSendTimedOut: message to toolbox-dnd timed out.
2023-08-31T06:26:50.608Z In(05) vmx GuestRpc: app toolbox-dnd's second ping timeout; assuming app is down
2023-08-31T06:26:50.608Z In(05) vmx TOOLS: appName=toolbox-dnd, oldStatus=2, status=0, guestInitiated=0.
2023-08-31T06:26:50.608Z In(05) vmx GuestRpc: Reinitializing Channel 1(toolbox-dnd)
2023-08-31T06:26:50.608Z In(05) vmx GuestMsg: Channel 1, Cannot unpost because the previous post is already completed
2023-08-31T06:26:50.608Z In(05) vmx TOOLS: appName=toolbox-dnd, oldStatus=0, status=0, guestInitiated=0.
2023-08-31T06:29:45.459Z In(05) vmx GuestRpcSendTimedOut: message to toolbox timed out.
2023-08-31T06:29:45.459Z In(05) vmx Vix: [guestCommands.c:1945]: Error VIX_E_TOOLS_NOT_RUNNING in VMAutomationTranslateGuestRpcError(): VMware Tools are not running in the guest
2023-08-31T06:30:30.393Z In(05) vmx GuestRpcSendTimedOut: message to toolbox-dnd timed out.

When 3D accel feature is not enabled. systemctl hibernate instead fails differently:

vmware.log:

Click to expand 
2023-08-31T06:06:14.698Z In(05) vmx GuestRpc: Got error for channel 0 connection 6: Remote disconnected
2023-08-31T06:06:14.698Z In(05) vmx GuestRpc: GuestRpcResetVsockChannel: channel 0
2023-08-31T06:06:14.698Z In(05) vmx GuestRpc: Closing channel 0 connection 6
2023-08-31T06:06:14.698Z In(05) vmx GuestRpc: Got error for channel 1 connection 7: Remote disconnected
2023-08-31T06:06:14.698Z In(05) vmx GuestRpc: GuestRpcResetVsockChannel: channel 1
2023-08-31T06:06:14.698Z In(05) vmx GuestRpc: Closing channel 1 connection 7
2023-08-31T06:06:14.699Z In(05) svga SWBScreen: Screen 1 Destroyed: xywh(0, 0, 1280, 800) flags=0x2
2023-08-31T06:06:14.700Z In(05) svga SVGA-ScreenMgr: Screen type changed to RegisterMode
2023-08-31T06:06:14.700Z In(05) svga SWBScreen: Screen 1 Defined: xywh(0, 0, 1024, 768) flags=0x2
2023-08-31T06:06:14.707Z In(05) svga SWBScreen: Screen 1 Destroyed: xywh(0, 0, 1024, 768) flags=0x2
2023-08-31T06:06:14.708Z In(05) svga SVGA-ScreenMgr: Screen type changed to ScreenTarget
2023-08-31T06:06:14.708Z In(05) svga SWBScreen: Screen 1 Defined: xywh(0, 0, 1280, 800) flags=0x2
2023-08-31T06:06:15.234Z In(05) vcpu-11 VMMouse: Disabling VMMouse mode
2023-08-31T06:06:15.234Z In(05) vcpu-11 VMMouse: CMD Read ID
2023-08-31T06:06:15.236Z In(05) vcpu-10 SOUND 235.267058 ES1371Win32GetMixerCtl mixerGetLineInfo error 1024
2023-08-31T06:06:15.951Z In(05) vcpu-1 VMCI QueuePair: VMCIQueuePairDetach failed --- handle 6a1b0c74:400 not found.
2023-08-31T06:06:15.952Z In(05) vmx GuestRpc: Got RPCI vsocket connection 8, assigned to channel 0.

This variation allows for some additional log info:

journalctl -b | grep -i hibernation:

Click to expand 
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x00001000-0x00001fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000bffff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x000c0000-0x000fffff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0dbb7000-0x0dbb7fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0dbb8000-0x0dbb8fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0dbb9000-0x0dbb9fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0dbbb000-0x0dbbbfff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0dbbc000-0x0dbbcfff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0dbc4000-0x0dbc4fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0dbc6000-0x0dbc6fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0e04b000-0x0e050fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0fb6f000-0x0fbdefff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0fbdf000-0x0fbfafff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0x0fbfb000-0x0fbfefff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0xc0000000-0xffbfffff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0xffc00000-0xffc29fff]
Aug 31 18:01:29 vm-cachyos kernel: PM: hibernation: Registered nosave memory: [mem 0xffc2a000-0xffffffff]

Aug 31 18:06:04 vm-cachyos kernel: PM: hibernation: hibernation entry

Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x00000000-0x00001fff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x000a0000-0x000fffff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x0dbb7000-0x0dbb9fff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x0dbbb000-0x0dbbcfff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x0dbc4000-0x0dbc4fff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x0dbc6000-0x0dbc6fff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x0e04b000-0x0e050fff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0x0fb6f000-0x0fbfefff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Marking nosave pages: [mem 0xc0000000-0xffffffff]
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Basic memory bitmaps created
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Preallocating image memory
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Allocated 364819 pages for snapshot
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Allocated 1459276 kbytes in 7.40 seconds (197.19 MB/s)
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: Basic memory bitmaps freed
Aug 31 18:06:12 vm-cachyos kernel: PM: hibernation: hibernation exit
Aug 31 18:06:12 vm-cachyos systemd[1]: Dependency failed for System Hibernation.

systemctl status systemd-hibernate

Click to expand 
× systemd-hibernate.service - Hibernate
     Loaded: loaded (/usr/lib/systemd/system/systemd-hibernate.service; static)
     Active: failed (Result: exit-code) since Thu 2023-08-31 18:06:12 NZST; 6min ago
       Docs: man:systemd-hibernate.service(8)
    Process: 3899 ExecStart=/usr/lib/systemd/systemd-sleep hibernate (code=exited, status=1/FAILURE)
   Main PID: 3899 (code=exited, status=1/FAILURE)
        CPU: 7.427s

Aug 31 18:06:04 vm-cachyos systemd[1]: Starting Hibernate...
Aug 31 18:06:04 vm-cachyos systemd-sleep[3899]: Entering sleep state 'hibernate'...
Aug 31 18:06:12 vm-cachyos systemd-sleep[3899]: Failed to put system to sleep. System resumed again: Device or resource busy
Aug 31 18:06:12 vm-cachyos systemd[1]: systemd-hibernate.service: Main process exited, code=exited, status=1/FAILURE
Aug 31 18:06:12 vm-cachyos systemd[1]: systemd-hibernate.service: Failed with result 'exit-code'.
Aug 31 18:06:12 vm-cachyos systemd[1]: Failed to start Hibernate.
Aug 31 18:06:12 vm-cachyos systemd[1]: systemd-hibernate.service: Consumed 7.427s CPU time.

Avoiding systemctl hibernate and instead trying to hibernate directly (suspend to disk) fails for the same reason:

$ echo 'disk' | sudo tee /sys/power/state

tee: /sys/power/state: Device or resource busy

Due to that failure, the VM guest is still functional, but some of the functionality is not restored. Such as the VM guest cursor has become invisible as part of the hibernation attempt.

polarathene avatar Aug 31 '23 07:08 polarathene

Resolved - Unrelated compatibility issue with update to 6.5 kernel

UPDATE: As the 6.4 kernel was working fine, but the issues described below started after the update to 6.5 kernel, I verified with the 6.1.50 LTS kernel which is working properly (still no hibernation) performance wise.

Not quite sure what happened. After this bug report, I powered off a VM guest stuck in the blank hibernation window (1st scenario with 3D graphics enabled), and booted the VM again.

It booted into the desktop, but only the top quarter of the display output was rendered, the other 3 quarters were black. The visible region was not responding to mouse input.

Checked the vmware.log and it spammed the last line repeatedly:

2023-08-31T07:21:19.993Z In(05) vcpu-5 SVGA: FIFO is already mapped
2023-08-31T07:21:19.993Z In(05) vcpu-5 SVGA: Registering IOSpace at 0x2140
2023-08-31T07:21:19.993Z In(05) vcpu-5 SVGA: Registering MemSpace at 0xf0000000(0xf0000000) and 0xfb800000(0xfb800000)
2023-08-31T07:21:19.994Z In(05) vcpu-5 SVGA: FIFO is already mapped
2023-08-31T07:21:20.220Z In(05) vcpu-3 UHCI: HCReset
2023-08-31T07:21:20.335Z In(05) vcpu-4 UHCI: HCReset
2023-08-31T07:21:21.287Z In(05) vcpu-10 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:21.287Z In(05) vcpu-10 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:21.287Z In(05) vcpu-10 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:21.287Z In(05) vcpu-10 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2

...

2023-08-31T07:21:21.876Z In(05) vcpu-10 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:21.876Z In(05) vcpu-10 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:21.876Z In(05) vcpu-10 VIDE: (0x170) Switching active drive from 0 to 1 while command 0xa0 is in progress (status 0x08).
2023-08-31T07:21:21.876Z In(05) vcpu-10 VIDE: IDE1:0: Aborting command a0, I/O was not in progress
2023-08-31T07:21:22.053Z In(05) vcpu-9 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:22.053Z In(05) vcpu-9 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:22.053Z In(05) vcpu-9 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:22.053Z In(05) vcpu-9 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2

...

2023-08-31T07:21:22.053Z In(05) vcpu-9 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:22.053Z In(05) vcpu-9 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2
2023-08-31T07:21:26.632Z No(00) vcpu-9 <<< file Throttled >>>

Using the Player "Suspend" UI button, I opened VMware Workstation Player again and resumed the VM. It restored the guest with display fully rendering again and responsive to mouse input.

However the vmware.log contains similar spam output as shown above, but for different vcpu (vcpu-0, vcpu-7, vcpu-6). Unclear if that was related to the failed hibernation attempt. A shutdown of the VM guest and starting it again seems to cause the same behaviour.

Stalling on Triggering uevents... for about 5 minutes or so. The first time (_the quarter display issue) it proceeded to boot after the long delay. This one updated with the following and stalled:

image

A few minutes later that updated again:

image

And the system booted up as normal and quickly again after that. This time with the full display output as it should.

Running the command sudo blkid stalled for 38 seconds until responding with output.

Ignore - Not related to the swap partition

Here is the root partition (sda2) and the swap partition (sdc1):

/dev/sdc1: LABEL="hibernation" UUID="d3b3e4d1-0f2e-446b-8cd5-629f8c5fafbf" TYPE="swap" PARTUUID="deb27f41-49ea-4256-900d-04f9ed2a157a"
/dev/sda2: UUID="fe346b77-491a-4a5b-a780-af173f112b3e" BLOCK_SIZE="512" TYPE="xfs" PARTLABEL="root" PARTUUID="7e2cfa9d-ff4d-4ed6-b147-f1300eb9ae85"

Swap device is functional:

$ swapon --show

NAME       TYPE        SIZE USED PRIO
/dev/sdc1  partition     8G   0B   -2
/dev/zram0 partition 970.2M   0B  100

$ cat /etc/fstab

# <file system>             <mount point>  <type>  <options>  <dump>  <pass>
UUID=7DE1-3F5B                            /boot          vfat    defaults,noatime 0 2
UUID=fe346b77-491a-4a5b-a780-af173f112b3e /              xfs     defaults,lazytime,noatime,attr2,inode64,logbsize=256k,noquota 0 1
UUID=3406082d-37a8-4328-ac72-ccfb70528a5e /data          btrfs   defaults,lazytime,noatime,compress-force=zstd
UUID=d3b3e4d1-0f2e-446b-8cd5-629f8c5fafbf none swap sw 0 0


$ cat /proc/cmdline
initrd=\amd-ucode.img initrd=\initramfs-linux-cachyos.img root=PARTUUID=7e2cfa9d-ff4d-4ed6-b147-f1300eb9ae85 rw zswap.enabled=0 nowatchdog


$ cat /boot/loader/entries/linux-cachyos.conf

title   Linux Cachyos
linux   /vmlinuz-linux-cachyos
initrd  /amd-ucode.img
initrd  /initramfs-linux-cachyos.img
options root=PARTUUID=7e2cfa9d-ff4d-4ed6-b147-f1300eb9ae85 rw zswap.enabled=0 nowatchdog

As 2nd half of above shows, the kernel boot parameter resume is now missing. I updated the guest after the bug report, and was not aware that CachyOS was configured to modify the linux-cachyos.conf removing my change. Instead that is intended to be managed by /etc/sdboot-manage.conf (appears to be a tool of their own).

Since /etc/mkinitcpio.conf still had the resume hook I added to HOOKS, the hibernation boot error message is due to lacking the resume kernel parameter.

Correcting the kernel boot parameters to include resume did not help with the performance degradation.

Although that does not explain why sudo blkid (a 2nd attempt took almost 3 minutes to respond) would be stalled for so long, or the massive log spam to vmware.log?

Looking at the boot logs via journalctl -b I wonder if this is related:

Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.0: BAR 15: assigned [mem 0xfef00000-0xff0fffff 64bit pref]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:10.0: BAR 6: assigned [mem 0xff100000-0xff103fff pref]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.0: BAR 13: assigned [io  0x3000-0x3fff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.1: BAR 13: assigned [io  0x4000-0x4fff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.2: BAR 13: assigned [io  0x6000-0x6fff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.3: BAR 13: assigned [io  0x7000-0x7fff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.4: BAR 13: assigned [io  0x8000-0x8fff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.5: BAR 13: assigned [io  0x9000-0x9fff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.6: BAR 13: assigned [io  0xa000-0xafff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:15.7: BAR 13: assigned [io  0xb000-0xbfff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.0: BAR 13: assigned [io  0xc000-0xcfff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.1: BAR 13: assigned [io  0xd000-0xdfff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.2: BAR 13: assigned [io  0xe000-0xefff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.3: BAR 13: assigned [io  0xf000-0xffff]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.4: BAR 13: no space for [io  size 0x1000]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.4: BAR 13: failed to assign [io  size 0x1000]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.5: BAR 13: no space for [io  size 0x1000]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.5: BAR 13: failed to assign [io  size 0x1000]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.6: BAR 13: no space for [io  size 0x1000]
Aug 31 19:35:42 vm-cachyos kernel: pci 0000:00:16.6: BAR 13: failed to assign [io  size 0x1000]

UPDATE: These logs above remain with the 6.1.50 LTS kernel, but the stalls experienced with the 6.5 kernel are gone and these logs no longer show in vmware.log:

2023-08-31T07:21:22.053Z In(05) vcpu-9 VIDE: (0x170) Unexpected IN for cmd 0xa3 len 2

polarathene avatar Aug 31 '23 08:08 polarathene

Related is systemctl suspend (S3). I was filing a separate issue for that, with logs collected but I when I returned to complete the bug report Windows had decided to force restart the system to apply an update... 😫

That took a while to prepare, and I don't have time to go through that again. Gist of it was:

  • Sometimes the VM guest could successfully resume from S3.
  • While in the suspended state CPU usage was high (with the guest configured to 16 vCPU (on 16 thread system)), constant at 72% on the host.
  • Often the suspended state could not resume and was similarly stuck like the hibernation scenario.

polarathene avatar Sep 01 '23 02:09 polarathene

Thank you for reporting the problem. We have informed the product team responsible for this issue. As this issue is not related to open-vm-tools, please use VMTN (https://communities.vmware.com/) or VMware Support service for further updates on this issue or other product issues unrelated to open-vm-tools.

rprabhud avatar Sep 11 '23 11:09 rprabhud

As this issue is not related to open-vm-tools

How do you determine when it is related? There is clearly log entries from open-vm-tools related to the failure.

polarathene avatar Sep 11 '23 22:09 polarathene

Guest hibernate is not an open-vm-tools feature. The log messages about "Tools heartbeat timeout" or GuestRpc timeout/error are result of hibernate/power-off indicating loss of connection between vmx and tools. Those errors messages are not causing hibernate failure.

rprabhud avatar Sep 12 '23 05:09 rprabhud

I have the same problem.

When I try hibernating the Kubuntu guest, the guest OS gets stuck with a black screen. When I reboot the guest, the saved context is lost. I had this problem on my two different distributions as a guest OS.

Note that Kubuntu with the same configuration can hibernate correctly on a physical machine.

  • Host
    • Windows 11 pro 24H2
    • VMWare Workstation Pro 17.5.2 build-23775571
  • Guest
    • Kubuntu 25.04
    • Kernel 6.14.0-15-generic

suikan4github avatar May 03 '25 23:05 suikan4github