vMotion stalls at 13% with "Invoking callbacks" due to storage latency and CTK file access errors
search cancel

vMotion stalls at 13% with "Invoking callbacks" due to storage latency and CTK file access errors

book

Article ID: 427492

calendar_today

Updated On:

Products

VMware vCenter Server 8.0 VMware vSphere ESXi 8.0

Issue/Introduction

  • The Task Console displays the status: "Invoking callbacks".
  • The source ESXi host becomes unresponsive in vCenter Server.
  • Virtual machines on the affected host may appear as "Inaccessible" or "Disconnected."
  • Standard reboot commands via the vSphere Client may fail to execute.
  • Can see below log entries in ESXi host.
    • /var/run/log/hostd.log 
      [YYYY-MM-DDTHH:MM:SS] In(166) Hostd[####]: [Originator@#### sub=Vcsvc.VMotionDst.3069372####10522203] ResolveCb: VMX reports needsUnregister = false for migrateType MIGRATE_TYPE_VMOTION
[YYYY-MM-DDTHH:MM:SS] In(166) Hostd[####]: [Originator@#### sub=Vcsvc.VMotionDst.3069372####10522203] ResolveCb: Succeeded
[YYYY-MM-DDTHH:MM:SS] In(166) Hostd[####]: [Originator@#### sub=Vmsvc.vm:/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx] Disk access enabled.
[YYYY-MM-DDTHH:MM:SS] In(166) Hostd[####]: [Originator@#### sub=Vmsvc.vm:/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx] State Transition (VM_STATE_IMMIGRATING -> VM_STATE_ON)
[YYYY-MM-DDTHH:MM:SS] In(166) Hostd[####]: [Originator@#### sub=Vmsvc.vm:/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx] Send config update invoked
[YYYY-MM-DDTHH:MM:SS] In(166) Hostd[2098900]: --> [context]zKq7AVICAg#####+cgEVaG9zd#####20VGxpYnZtYWNvcmUuc########wB3hD0Bnfj4aG9zdGQAAes1+YHv4wUBgcIg####r2LfAZ5l3wFxSd+Bm#######2wUBgcDdBQGB######E6FLEBNRZ1AB7bLADg/ywAO1######AGxpYnB0aHJlYWQuc28u#####1IPbGliYy5zby42AA==[/context]
[YYYY-MM-DDTHH:MM:SS] In(166) Hostd[####]: [Originator@#### sub=DiskLib] DISKLIB-CTK   : ChangeTrackerOpenOnDiskWork: Could not open tracking file /vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>-000001-ctk.vmdk (4).
[YYYY-MM-DDTHH:MM:SS] In(166) Hostd[####]: [Originator@#### sub=DiskLib] DISKLIB-CTK   : Could not open change tracking file "/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>-000001-ctk.vmdk": Could not open or create change tracking file.
[YYYY-MM-DDTHH:MM:SS] Wa(164) Hostd[####]: [Originator@#### sub=Vmsvc.vm:/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx] Change tracking information is not available for /vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>-000001.vmdk (2108): Could not open or create change tracking file
[YYYY-MM-DDTHH:MM:SS] Db(167) Hostd[####]: [Originator@#### sub=Vmsvc.vm:/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx] Time to gather config: 27 (msecs)
[YYYY-MM-DDTHH:MM:SS] Db(167) Hostd[####]: [Originator@#### sub=Vmsvc.vm:/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx] CfgUpdate refresh all core files.
[YYYY-MM-DDTHH:MM:SS] Wa(164) Hostd[####]: [Originator@#### sub=Vmsvc.vm:/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx] File - failed to get objectId, '/vmfs/volumes/5e5023d7-########-66aa-#####5650a05/<VMName>/<VMName>.vmx': Operation not supported (11)
    • /var/run/log/vmkernel.log 
      [YYYY-MM-DDTHH:MM:SS] Al(177) vmkalert: cpu36:#####)ALERT: hostd performance has degraded due to high system latency
[YYYY-MM-DDTHH:MM:SS] Al(177) vmkalert: cpu36:#####)ALERT: hostd performance has degraded due to high system latency
[YYYY-MM-DDTHH:MM:SS] Al(177) vmkalert: cpu29:#####)ALERT: hostd performance has degraded due to high system latency
[YYYY-MM-DDTHH:MM:SS] Al(177) vmkalert: cpu10:#####)ALERT: hostd performance has degraded due to high system latency
[YYYY-MM-DDTHH:MM:SS] Al(177) vmkalert: cpu0:#####)ALERT: hostd performance has degraded due to high system latency
[YYYY-MM-DDTHH:MM:SS] Al(177) vmkalert: cpu2:#####)ALERT: hostd performance has degraded due to high system latency
[YYYY-MM-DDTHH:MM:SS] Al(177) vmkalert: cpu2:#####)ALERT: hostd performance has degraded due to high system latency
[YYYY-MM-DDTHH:MM:SS] In(182) vmkernel: 0:00:00:00.394 cpu0:1)Vmkperf: 433: Architectural performance monitoring version = 5
[YYYY-MM-DDTHH:MM:SS] In(182) vmkernel: 0:00:00:00.394 cpu0:1)Vmkperf: 483: Number of performance counters: architectural 8, fixed_functional 4, off_core 2, Perf counter width = 48
[YYYY-MM-DDTHH:MM:SS] In(182) vmkernel: 0:00:00:04.302 cpu0:2097152)CpuSched: 18486: Switching to NHCC performance counter for CPU time accounting
[YYYY-MM-DDTHH:MM:SS] Wa(180) vmkwarning: cpu44:2098159)WARNING: ScsiDeviceIO: 1779: Device naa.600a09803831#####0244d643076646c performance has deteriorated. I/O latency increased from average value of 260 microseconds to 8083 microseconds.
[YYYY-MM-DDTHH:MM:SS] In(182) vmkernel: cpu1:2098157)ScsiDeviceIO: 1779: Device naa.600a09803831#####0244d643076646c performance has improved. I/O latency reduced from 8083 microseconds to 1660 microseconds.
[YYYY-MM-DDTHH:MM:SS] Wa(180) vmkwarning: cpu44:2098157)WARNING: ScsiDeviceIO: 1779: Device naa.600a09803831#####0244d643076646c performance has deteriorated. I/O latency increased from average value of 260 microseconds to 7163 microseconds.
[YYYY-MM-DDTHH:MM:SS] In(182) vmkernel: cpu1:2098159)ScsiDeviceIO: 1779: Device naa.600a09803831#####0244d643076646c performance has improved. I/O latency reduced from 7163 microseconds to 1378 microseconds.
[YYYY-MM-DDTHH:MM:SS] Wa(180) vmkwarning: cpu44:2098159)WARNING: ScsiDeviceIO: 1779: Device naa.600a09803831#####0244d643076646c performance has deteriorated. I/O latency increased from average value of 260 microseconds to 5907 microseconds.
[YYYY-MM-DDTHH:MM:SS] In(182) vmkernel: cpu1:2098157)ScsiDeviceIO: 1779: Device naa.600a09803831#####0244d643076646c performance has improved. I/O latency reduced from 5907 microseconds to 1338 microseconds.

Cause

This issue is typically triggered by an underlying storage latency or connectivity failure. When the vMotion process attempts to hand over the memory state, it waits for a confirmation (callback) from the storage layer. If the storage sub-system is experiencing SCSI command failures, the host agent (hostd) may hang while waiting for an I/O response.

Resolution

The primary goal is to restore host manageability and release stale file locks on virtual machines. When an ESXi host becomes sluggish due to storage command failures, the management agents (hostd/vpxa) often hang while waiting for storage responses. By restarting these agents or performing a hard reset. Finally, because the root cause is at the storage layer (SCSI failures), a parallel investigation with storage and fabric vendors is required to prevent a recurrence.

  1. Immediate Host Recovery.
    1. Since the ESXi host is sluggish or unresponsive, a graceful reboot may not be possible.
    2. If the host remains unresponsive, a hard reset (cold boot) from the management tool (iDRAC, ILO, or IPMI) of the physical server may be required to release the file locks on the VMs.
  2. Storage Vendor Engagement.
    • Engage the storage/Switch vendor to investigate the cause of SCSI command failures observed in ESXi host logs /var/run/log/vmkernel.log

Additional Information

Powered by Wolken Software