Home / server / Questions / 396282
Accepted
Wayne
Asked: 2012-06-07 17:23:51 +0800 CST

Why are virtual machines on vSphere 5.0 suddenly suspended?

  • 772

We just got our vSphere 5.0 and vCenter Server 5.0 configuration working with several VMS.

These are the vms.

  1. Jenkins appliance.
  2. vCenter Server Appliance
  3. Windows7x64
  4. Windows7x64-1
  5. Windows7x64-2

For some reason the Windows vms become unexpectedly suspended. To recover we simply power them back on it all is well until the next time. We found dcx some vmWare instructions to debug this via getting the log file from the vm. And here it is. But even with their hints..it's still unclear.

One important thing to notice in the log below is that this is only an portion of the file starting a few lines before where suspending started. So you can see the time stamp jumps 30 minutes because it ran fine for that long before it went suspended.

2012-06-06T17:22:28.762Z| vcpu-1| TOOLS unified loop capability requested by 'toolbox';now sending options via TCLO
2012-06-06T17:22:28.763Z| vcpu-1| TOOLS sending 'OS_PowerOn' (state=3 callback=0 clientData=0) state change request
2012-06-06T17:22:28.763Z| vcpu-1| Guest: toolbox: Version: build-621624
2012-06-06T17:22:28.835Z| vcpu-1| TOOLS state change 3 returned status 1
2012-06-06T17:22:56.558Z| vmx| GuestRpcSendTimedOut: message to toolbox-dnd timed out.
2012-06-06T17:52:30.943Z| vcpu-0| SVGA: Unregistering IOSpace at 0x10d0
2012-06-06T17:52:30.943Z| vcpu-0| SVGA: Unregistering MemSpace at 0xd8000000(0xd8000000) and 0xd0800000(0xd0800000)
2012-06-06T17:52:31.600Z| vcpu-0| PIIX4: PMAccessPM got ACPI S1 request
2012-06-06T17:52:31.600Z| vcpu-0| PIIX4: PM Suspending... (to S1 (0x4))
2012-06-06T17:52:31.601Z| vmx| VMXVmdbCbVmVmxExecState: Exec state change requested to state suspended without reset, hard, softOptionTimeout: 0.
2012-06-06T17:52:31.692Z| vmx| CPT current = 0, requesting 1
2012-06-06T17:52:31.692Z| vcpu-1| Done Sync monModules(1).
2012-06-06T17:52:31.692Z| vcpu-0| E1000: Syncing with mode 1.
2012-06-06T17:52:31.692Z| vcpu-0| Done Sync monModules(1).
2012-06-06T17:52:31.692Z| vcpu-0| CPT: monitor ACKing mode 1
2012-06-06T17:52:31.693Z| vcpu-0| Destroying virtual dev for scsi0:0 vscsi=8207
2012-06-06T17:52:31.693Z| vcpu-0| VMMon_VSCSIStopVports: No such target on adapter
2012-06-06T17:52:31.718Z| vcpu-0| CPT current = 1, requesting 2
2012-06-06T17:52:31.718Z| vcpu-0| CPT: monitor ACKing mode 2
2012-06-06T17:52:31.718Z| vcpu-0| Closing all the disks of the VM.
2012-06-06T17:52:31.718Z| vcpu-0| Closing disk scsi0:0
2012-06-06T17:52:31.718Z| vcpu-0| DISKLIB-VMFS  : "/vmfs/volumes/4fb4d5f9-127383b4-64d5-d4ae5292223d/Win7x64VS2010-2/Win7x64VS2010-2-flat.vmdk" : closed.
2012-06-06T17:52:31.718Z| vcpu-0| CPT current = 2, requesting 3
2012-06-06T17:52:31.718Z| vcpu-0| Done Cpt monModules(3).
2012-06-06T17:52:31.718Z| vcpu-0| CPT: monitor ACKing mode 3
2012-06-06T17:52:31.731Z| vcpu-0| Progress -1% (msg.checkpoint.saveStatus)
2012-06-06T17:52:31.731Z| vcpu-0| Checkpointed in VMware ESX, 5.0.0, build-623860, Linux Host
2012-06-06T17:52:31.754Z| vcpu-0| BusMemSampleCheckpoint: checkpoint 3 touched: initPct 75 pages 36700 : dirtied: initPct 75 pages 31457
2012-06-06T17:52:31.774Z| vcpu-0| Progress 0% (none)
2012-06-06T17:52:31.817Z| vcpu-0| Progress 1% (none)
2012-06-06T17:52:31.975Z| vcpu-0| Progress 2% (none)
2012-06-06T17:52:32.429Z| vcpu-0| Progress 3% (none)
2012-06-06T17:52:32.484Z| vcpu-0| Progress 4% (none)
2012-06-06T17:52:32.555Z| vcpu-0| Progress 5% (none)
2012-06-06T17:52:33.637Z| vcpu-0| Progress 6% (none)
2012-06-06T17:52:34.510Z| vcpu-0| Progress 7% (none)
2012-06-06T17:52:34.860Z| vcpu-0| Progress 8% (none)
2012-06-06T17:52:35.085Z| vcpu-0| Progress 9% (none)
2012-06-06T17:52:35.231Z| vcpu-0| Progress 10% (none)
2012-06-06T17:52:35.405Z| vcpu-0| Progress 11% (none)
2012-06-06T17:52:35.526Z| vcpu-0| Progress 12% (none)
2012-06-06T17:52:35.700Z| vcpu-0| Progress 13% (none)
2012-06-06T17:52:35.876Z| vcpu-0| Progress 14% (none)
2012-06-06T17:52:35.992Z| vcpu-0| Progress 15% (none)
2012-06-06T17:52:36.168Z| vcpu-0| Progress 16% (none)
2012-06-06T17:52:36.284Z| vcpu-0| Progress 17% (none)
2012-06-06T17:52:36.461Z| vcpu-0| Progress 18% (none)
2012-06-06T17:52:36.578Z| vcpu-0| Progress 19% (none)
2012-06-06T17:52:36.754Z| vcpu-0| Progress 20% (none)
2012-06-06T17:52:36.928Z| vcpu-0| Progress 21% (none)
2012-06-06T17:52:37.045Z| vcpu-0| Progress 22% (none)
2012-06-06T17:52:37.220Z| vcpu-0| Progress 23% (none)
2012-06-06T17:52:37.338Z| vcpu-0| Progress 24% (none)
2012-06-06T17:52:37.512Z| vcpu-0| Progress 25% (none)
2012-06-06T17:52:37.628Z| vcpu-0| Progress 26% (none)
2012-06-06T17:52:37.805Z| vcpu-0| Progress 27% (none)
2012-06-06T17:52:37.979Z| vcpu-0| Progress 28% (none)
2012-06-06T17:52:38.096Z| vcpu-0| Progress 29% (none)
2012-06-06T17:52:38.274Z| vcpu-0| Progress 30% (none)
2012-06-06T17:52:38.391Z| vcpu-0| Progress 31% (none)
2012-06-06T17:52:38.564Z| vcpu-0| Progress 32% (none)
2012-06-06T17:52:38.681Z| vcpu-0| Progress 33% (none)
2012-06-06T17:52:38.857Z| vcpu-0| Progress 34% (none)
2012-06-06T17:52:39.033Z| vcpu-0| Progress 35% (none)
2012-06-06T17:52:39.148Z| vcpu-0| Progress 36% (none)
2012-06-06T17:52:39.324Z| vcpu-0| Progress 37% (none)
2012-06-06T17:52:39.442Z| vcpu-0| Progress 38% (none)
2012-06-06T17:52:39.616Z| vcpu-0| Progress 39% (none)
2012-06-06T17:52:39.792Z| vcpu-0| Progress 40% (none)
2012-06-06T17:52:39.910Z| vcpu-0| Progress 41% (none)
2012-06-06T17:52:40.086Z| vcpu-0| Progress 42% (none)
2012-06-06T17:52:40.240Z| vcpu-0| Progress 43% (none)
2012-06-06T17:52:40.415Z| vcpu-0| Progress 44% (none)
2012-06-06T17:52:40.531Z| vcpu-0| Progress 45% (none)
2012-06-06T17:52:40.706Z| vcpu-0| Progress 46% (none)
2012-06-06T17:52:40.882Z| vcpu-0| Progress 47% (none)
2012-06-06T17:52:40.999Z| vcpu-0| Progress 48% (none)
2012-06-06T17:52:41.175Z| vcpu-0| Progress 49% (none)
2012-06-06T17:52:41.293Z| vcpu-0| Progress 50% (none)
2012-06-06T17:52:41.469Z| vcpu-0| Progress 51% (none)
2012-06-06T17:52:41.586Z| vcpu-0| Progress 52% (none)
2012-06-06T17:52:41.763Z| vcpu-0| Progress 53% (none)
2012-06-06T17:52:41.939Z| vcpu-0| Progress 54% (none)
2012-06-06T17:52:42.055Z| vcpu-0| Progress 55% (none)
2012-06-06T17:52:42.230Z| vcpu-0| Progress 56% (none)
2012-06-06T17:52:42.342Z| vcpu-0| Progress 57% (none)
2012-06-06T17:52:42.544Z| vcpu-0| Progress 58% (none)
2012-06-06T17:52:42.662Z| vcpu-0| Progress 59% (none)
2012-06-06T17:52:42.839Z| vcpu-0| Progress 60% (none)
2012-06-06T17:52:43.013Z| vcpu-0| Progress 61% (none)
2012-06-06T17:52:43.130Z| vcpu-0| Progress 62% (none)
2012-06-06T17:52:43.305Z| vcpu-0| Progress 63% (none)
2012-06-06T17:52:43.422Z| vcpu-0| Progress 64% (none)
2012-06-06T17:52:43.598Z| vcpu-0| Progress 65% (none)
2012-06-06T17:52:43.717Z| vcpu-0| Progress 66% (none)
2012-06-06T17:52:43.890Z| vcpu-0| Progress 67% (none)
2012-06-06T17:52:44.066Z| vcpu-0| Progress 68% (none)
2012-06-06T17:52:44.183Z| vcpu-0| Progress 69% (none)
2012-06-06T17:52:44.358Z| vcpu-0| Progress 70% (none)
2012-06-06T17:52:44.475Z| vcpu-0| Progress 71% (none)
2012-06-06T17:52:44.650Z| vcpu-0| Progress 72% (none)
2012-06-06T17:52:44.768Z| vcpu-0| Progress 73% (none)
2012-06-06T17:52:44.942Z| vcpu-0| Progress 74% (none)
2012-06-06T17:52:45.117Z| vcpu-0| Progress 75% (none)
2012-06-06T17:52:45.236Z| vcpu-0| Progress 76% (none)
2012-06-06T17:52:45.412Z| vcpu-0| Progress 77% (none)
2012-06-06T17:52:45.528Z| vcpu-0| Progress 78% (none)
2012-06-06T17:52:45.702Z| vcpu-0| Progress 79% (none)
2012-06-06T17:52:45.878Z| vcpu-0| Progress 80% (none)
2012-06-06T17:52:45.995Z| vcpu-0| Progress 81% (none)
2012-06-06T17:52:46.170Z| vcpu-0| Progress 82% (none)
2012-06-06T17:52:46.287Z| vcpu-0| Progress 83% (none)
2012-06-06T17:52:46.462Z| vcpu-0| Progress 84% (none)
2012-06-06T17:52:46.579Z| vcpu-0| Progress 85% (none)
2012-06-06T17:52:46.755Z| vcpu-0| Progress 86% (none)
2012-06-06T17:52:46.930Z| vcpu-0| Progress 87% (none)
2012-06-06T17:52:47.049Z| vcpu-0| Progress 88% (none)
2012-06-06T17:52:47.223Z| vcpu-0| Progress 89% (none)
2012-06-06T17:52:47.341Z| vcpu-0| Progress 90% (none)
2012-06-06T17:52:47.515Z| vcpu-0| Progress 91% (none)
2012-06-06T17:52:47.631Z| vcpu-0| Progress 92% (none)
2012-06-06T17:52:47.806Z| vcpu-0| Progress 93% (none)
2012-06-06T17:52:47.982Z| vcpu-0| Progress 94% (none)
2012-06-06T17:52:48.099Z| vcpu-0| Progress 95% (none)
2012-06-06T17:52:48.275Z| vcpu-0| Progress 96% (none)
2012-06-06T17:52:48.392Z| vcpu-0| Progress 97% (none)
2012-06-06T17:52:48.565Z| vcpu-0| Progress 98% (none)
2012-06-06T17:52:48.683Z| vcpu-0| Progress 99% (none)
2012-06-06T17:52:49.319Z| vcpu-0| DISKLIB-VMFS  : "/vmfs/volumes/4fb4d5f9-127383b4-64d5-d4ae5292223d/Win7x64VS2010-2/Win7x64VS2010-2-flat.vmdk" : open successful (21) size = 34359738368, hd = 0. Type 3
2012-06-06T17:52:49.319Z| vcpu-0| DISKLIB-VMFS  : "/vmfs/volumes/4fb4d5f9-127383b4-64d5-d4ae5292223d/Win7x64VS2010-2/Win7x64VS2010-2-flat.vmdk" : closed.
2012-06-06T17:52:49.321Z| vcpu-0| GuestRpc: Reinitializing Channel 0(toolbox)
2012-06-06T17:52:49.321Z| vcpu-0| GuestMsg: Channel 0, Cannot unpost because the previous post is already completed
2012-06-06T17:52:49.322Z| vcpu-0| GuestRpc: Channel 0 reinitialized.
2012-06-06T17:52:49.560Z| vcpu-0| Progress 101% (none)
2012-06-06T17:52:49.565Z| vcpu-0| Vix: [5408 mainDispatch.c:4084]: VMAutomation_ReportPowerOpFinished: statevar=1, newAppState=1875, success=1 additionalError=0
2012-06-06T17:52:49.565Z| vmx| Stopping VCPU threads...
2012-06-06T17:52:49.565Z| vcpu-0| VMMon_WaitForExit: vcpu-0: worldID=5403
2012-06-06T17:52:49.565Z| vcpu-1| VMMon_WaitForExit: vcpu-1: worldID=5405
2012-06-06T17:52:50.343Z| mks| Ending MKSRole pseudocalls, state was 1
2012-06-06T17:52:50.343Z| mks| Async MKS thread is exiting
2012-06-06T17:52:50.343Z| vmx| Vix: [5402 mainDispatch.c:1165]: VMAutomation_PowerOff: Powering off.
2012-06-06T17:52:50.345Z| vmx| 
2012-06-06T17:52:50.345Z| vmx| --> OvhdMem: Final Overheads
2012-06-06T17:52:50.345Z| vmx| 
2012-06-06T17:52:50.345Z| vmx| OvhdMem: Vmx overhead                              max used  max reserved  avg used
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxAllocTrack                  :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxCallStackProf               :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxGlobals                     :        0       1024          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxGlobalsLibs                 :        0       1024          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxHeap                        :        0       5120          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxMainMemCheck                :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxMks3d                       :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxMksShadowFB                 :      771       2176        769
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxPhysMemRingBuf              :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxReplayCheck                 :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxSLEntryBuf                  :        0        128          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxText                        :        X   [    3328]
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxTextLibs                    :        X   [   15360]
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxThreadMks                   :      512        512        512
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxThreadVmx                   :        0        512          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxThreadsVcpu                 :      512        512        512
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VmxThreadsWorker               :        0       1536          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem Total                                   :     1795      31232
2012-06-06T17:52:50.345Z| vmx| 
2012-06-06T17:52:50.345Z| vmx| OvhdMem: Vmm overhead                              max used  max reserved  avg used
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SharedArea                     :       54         95         54
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_TraceBitmapMainMem             :       16         16         16
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_KSTATS_vmm                     :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_STATS_vmm                      :        0          4          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_KSTATS_device                  :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_STATS_device                   :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_KSTATS_migrate                 :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PFrame                         :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VProbe                         :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_DFStackvcpu                    :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_DFCR3vcpu                      :        0          6          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_DFCR3PTvcpu                    :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_DFCR3PageDirForSwitchPg        :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VIDE_KSEG                      :       16         16         16
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VGA                            :       64         64         64
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_BusMemRemap                    :      131        131        131
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PShareMPN                      :        1          2          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_P2MUpdateMPN                   :        1          1          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_P2MUpdateBuffer                :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SharedMPNsPool                 :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SwapMPN                        :        1          1          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VMCIMPN                        :        1          1          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_LocalApic                      :        2          2          2
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_BusError                       :        1          1          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VBIOS                          :        8          8          8
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VnicGuest                      :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VnicMmap                       :        1          1          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_LSIBIOS                        :        0          4          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_LSIRings                       :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PCIPBIOS                       :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PVSCSIBIOS                     :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PVSCSIKickReg                  :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SAS1068BIOS                    :        4          4          4
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SBIOS                          :        0         16          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_FlashRam                       :      128        128        128
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SHPC_MemReg                    :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SVGAFB                         :     2048       2048       2048
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SVGAMEM                        :       64         64         64
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_HDAudioReg                     :        0          3          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_EHCIRegister                   :        0          1          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_XhciRegister                   :        0          1          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PhysMemDebug                   :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_MainMem                        :        X   [  524288]
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_HVIOBitmap                     :        0          3          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_HVMSRBitmap                    :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_vhvMSRBitmap                   :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_StateLoggerLogBuf              :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_DebugStubSSEvents              :        1          2          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_DebugStubBWPEvents             :        1          2          1
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PCIP                           :        0          0          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_VMsafe                         :        0          4          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_MonWired                       :      128        128        128
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_MonLow                         :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_MonNuma                        :      273        273          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_MonOther                       :        0         30          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_MonAnon                        :     3956       6216          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_SVMLowMem                      :        0          3          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem OvhdUser_PAEShadow                      :        0          2          0
2012-06-06T17:52:50.345Z| vmx| OvhdMem Total                                   :     6900     533585
2012-06-06T17:52:50.345Z| vmx| 
2012-06-06T17:52:50.345Z| vmx| OvhdAnon Detailed Sources                         max used  max rsvd  avg used
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_Alloc                           :       0       94        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BusMemFrame                     :    1751     1849     1751
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BusMemFramePGAR                 :       3       11        3
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BusMemMMTracePGAR               :       2        2        2
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BusMem2MRegionPGAR              :       8        8        8
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BusMemZapListMPN                :       1        1        1
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_MMU                             :      38      422       36
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_MonTLB                          :      12       12       12
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_DT                              :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_TCCoherency                     :      24       42       20
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_TC                              :    1536     1536     1024
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_ChainInfo                       :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_Island                          :       0        2        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BusMemScratchAS                 :       6       21        6
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BackdoorHintsMPN                :       0        3        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_HV                              :       2        2        2
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_VNPTShadow                      :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_VNPTBackmap                     :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_SVMIDT                          :       0        2        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_CallStackProfAnon               :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_Numa                            :      93      723       91
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_GPhysTraced                     :     177      233      124
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_GPhysEPT                        :     280     1173      230
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_GPhysNoTrace                    :      14       58        9
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BTScratchPage                   :       1        1        1
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_StateLoggerBufferPA             :       0        1        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_TraceALot                       :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_VIDE                            :       0        4        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_VMXNETWake                      :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_BusLogic                        :       0        8        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_PVSCSIShadowRing                :       0        0        0
2012-06-06T17:52:50.345Z| vmx| OvhdAnon OvhdMon_LSIRings                        :       8        8        8
2012-06-06T17:52:50.345Z| vmx| OvhdAnon Total                                   :    3956     6216
2012-06-06T17:52:50.345Z| vmx| 
2012-06-06T17:52:50.345Z| vmx| OvhdMem maximum overheads: paged 12550 nonpaged 3075 anonymous 5692
2012-06-06T17:52:50.345Z| vmx| 
2012-06-06T17:52:50.345Z| vmx| OvhdMem: average total user: 4464 anon: 3329
2012-06-06T17:52:50.345Z| vmx| OvhdMem: memsize 2048 MB VMK fixed 74 pages var 0 pages cbrcOverhead 0 pages total 1099 pages
2012-06-06T17:52:50.345Z| vmx| VMMEM: Maximum Reservation: 75MB (MainMem=2048MB SVGA=8MB) VMK=4MB
2012-06-06T17:52:50.347Z| vmx| VMXVmdb_SetToolsVersionStatus: status value set to 'ok', 'current', install possible
2012-06-06T17:52:50.349Z| vmx| Virtual Device for scsi0:0 was already successfully destroyed
2012-06-06T17:52:50.350Z| vmx| MKS local poweroff
2012-06-06T17:52:50.355Z| vmx| WORKER: asyncOps=0 maxActiveOps=0 maxPending=0 maxCompleted=0
2012-06-06T17:52:50.489Z| vmx| Vix: [5402 mainDispatch.c:4084]: VMAutomation_ReportPowerOpFinished: statevar=1, newAppState=1875, success=1 additionalError=0
2012-06-06T17:52:50.489Z| vmx| Vix: [5402 mainDispatch.c:4103]: VMAutomation: Ignoring ReportPowerOpFinished because the VMX is shutting down.
2012-06-06T17:52:50.508Z| vmx| Vix: [5402 mainDispatch.c:4084]: VMAutomation_ReportPowerOpFinished: statevar=0, newAppState=1870, success=1 additionalError=0
2012-06-06T17:52:50.508Z| vmx| Vix: [5402 mainDispatch.c:4103]: VMAutomation: Ignoring ReportPowerOpFinished because the VMX is shutting down.
2012-06-06T17:52:50.508Z| vmx| Transitioned vmx/execState/val to suspended
2012-06-06T17:52:50.512Z| vmx| VMX idle exit
2012-06-06T17:52:50.512Z| vmx| VMIOP: Exit
2012-06-06T17:52:50.514Z| vmx| Vix: [5402 mainDispatch.c:900]: VMAutomation_LateShutdown()
2012-06-06T17:52:50.515Z| vmx| Vix: [5402 mainDispatch.c:850]: VMAutomationCloseListenerSocket. Closing listener socket.
2012-06-06T17:52:50.516Z| vmx| Flushing VMX VMDB connections
2012-06-06T17:52:50.516Z| vmx| VmdbDbRemoveCnx: Removing Cnx from Db for '/db/connection/#1/'
2012-06-06T17:52:50.516Z| vmx| VmdbCnxDisconnect: Disconnect: closed pipe for pub cnx '/db/connection/#1/' (0)
2012-06-06T17:52:50.522Z| vmx| VMX exit (0).
2012-06-06T17:52:50.522Z| vmx| AIOMGR-S : stat o=2 r=6 w=0 i=0 br=98304 bw=0
2012-06-06T17:52:50.522Z| vmx| VMX has left the building: 0.
vmware-vcenter virtual-machines vmware-vsphere

1 Answers

  1. Best Answer

    99% of the time it's because the power saving features of the underlying OS has suspended or hibernated the machine.

    We have this issue with our development testing virtual machines. A quick GPO deployment fixed this, but if you don't have a GPO, just go into each VM and tell it not to hibernate or suspend after inactivity.

    The biggest giveaway is this line:

    2012-06-06T17:52:31.600Z| vcpu-0| PIIX4: PMAccessPM got ACPI S1 request

    Another giveaway here is the 30 minute timeframe. That's a pretty common inactivity time for the VM to suspend itself.

    • 6