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, LUN latency is observed similar to the entries listed below.
  
  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 7.x
  
  
• VMware vSphere ESXi 8.x

Cause

• Virtual Machine latency is caused by high DAVG/cmd (driver average latency per command) - ie : latency on the storage array or on the fabric/network.
  
  
• High DAVG/cmd can be observed in esxtop under device view : 

• From the above screenshot it is confirmed that,
  
  1) DAVG values (device average response time) are high for certain storage devices, which indicates that these devices are taking longer to respond to I/O requests.
  
  2) Some of these storage devices are reaching 100% utilization, causing I/O operations to queue in the kernel adding additional latency.
  
  3) High utilization and queuing can be the result of the high DAVG/cmd or additionally increased VM workload.

 

• Virtual Machine vmware.log files may report slow task complete, e.g....
  
  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

1. Engage storage vendor to investigate the high DAVG values reported in ESXTOP data.

2. Engage the application team to identify any increased I/O generation which may be contributing to increased latency.

Additional Information

The following kb gives instructions on the use of esxtop :  Using esxtop to identify storage performance issues for ESXi (multiple versions)