Multiple VMs experience latency issues.

Products

• VMware vSphere ESXi

Issue/Introduction

• Multiple virtual machines (VMs) experience latency issues across all hosts.
• In the var/run/log/vmkernel.log file, similar entries are seen:
  
  YYYY-MM-DDTHH:MM.SSSZ cpu1:2097886)WARNING: ScsiDeviceIO: 1513: Device naa.#### performance has deteriorated. I/O latency increased from average value of 396microseconds to 8037 microseconds.
YYYY-MM-DDTHH:MM.SSSZ cpu17:2097896)WARNING: ScsiDeviceIO: 1513: Device naa.#### performance has deteriorated. I/O latency increased from average value of 396 microseconds to 21192 microseconds.
YYYY-MM-DDTHH:MM.SSSZ cpu21:2097892)ScsiDeviceIO: 1513: Device naa.#### performance has improved. I/O latency reduced from 21192 microseconds to 4179 microseconds.
YYYY-MM-DDTHH:MM.SSSZ cpu1:2097893)ScsiDeviceIO: 1513: Device naa.#### performance has improved. I/O latency reduced from 4179 microseconds to 823 microseconds.
YYYY-MM-DDTHH:MM.SSSZ cpu6:2097895)WARNING: ScsiDeviceIO: 1513: naa.#### performance has deteriorated. I/O latency increased from average value of 447 microseconds to 9825 microseconds.
YYYY-MM-DDTHH:MM.SSSZ cpu0:2097884)WARNING: ScsiDeviceIO: 1513: Device naa.#### performance has deteriorated. I/O latency increased from average value of 456 microseconds to 20588 microseconds.

Environment

• VMware vSphere ESXi 6.x
• VMware vSphere ESXi 7.x
• VMware vSphere ESXi 8.x

Cause

Latency issues are caused by high storage utilization and increased DAVG (Device Average Response Time) values.

Cause validation: 

• Observe the DAVG values and the storage utilization using ESXTOP data.
  
  Please refer to this KB : Using esxtop to identify storage performance issues for ESXi (multiple versions)
  
  
  
  
• From the above screenshot it is confirmed that,
  
  1) DAVG values (device average response time) are consistently high for the storage devices, which indicates that the storage devices are taking longer to respond to I/O requests.
  
  2) Also few storage devices are reaching 100% utilization, causing I/O operations to queue up and leading to these latency issues.
  
  
• Affected VM shows below entries from vmware.log 
  
  Log Path: less /vmfs/volumes/datastore/VM Name/vmware.log

YYYY-MM-DDTHH:MM.SSSZ In(05) vmx - VigorTransport_ServerSendResponse opID=###### seq=2766463: Completed GuestStats request.
YYYY-MM-DDTHH:MM.SSSZ In(05) vmx - GuestRpcSendTimedOut: message to toolbox timed out.
YYYY-MM-DDTHH:MM.SSSZ In(05) vmx - Tools: [AppStatus] Last heartbeat value 3346710 (last received 4s ago)
YYYY-MM-DDTHH:MM.SSSZ In(05) vmx - TOOLS: appName=toolbox, oldStatus=1, status=2, guestInitiated=0.
YYYY-MM-DDTHH:MM.SSSZ In(05) vmx - Guest: *** WARNING: GuestInfo collection interval longer than expected; actual=60 sec, expected=30 sec. ***   >>>>>>  As per the events this seems to be from Guest level operations (backup/other actions) performed during the time of the hung.
YYYY-MM-DDTHH:MM.SSSZ In(05)+ vmx -
YYYY-MM-DDTHH:MM.SSSZ In(05) vcpu-2 - Tools: [AppStatus] Last heartbeat value 3346710 (last received 9s ago)
YYYY-MM-DDTHH:MM.SSSZ In(05) vcpu-2 - TOOLS: appName=toolbox, oldStatus=2, status=1, guestInitiated=0.

Resolution

• Engage storage vendor to investigate the high DAVG values reported in ESXTOP data.
  
  
• Engage the application team to identify any increased I/O generation and work on resolving the underlying cause.