Endless retries in write_to_vm() cause head-of-line-blocking: http2: client connection lost

[leolannenmaki]

This issue relates to the PR #266 - I should have opened the issue first instead of the other way around.

Real world impact

We run workloads on Apple Silicon hosts with vfkit VMs. F.ex. BuildKit's cache client inside the guest downloads large cache objects over a shared HTTP/2 connection, the server's PING acks toward the guest get stuck behind the stalled queue, the client's health check times out, and the connection dies with "http2: client connection lost". In our case it always seems to happen during large concurrent downloads. Recovering happens once the guest catches up. It seems that any protocol with a heartbeat shorter than the stall (gRPC keepalives, TLS handshake timeouts, DNS) is affected the same way.

Reproduction

stall-repro.sh

#!/bin/bash
set -eu

vm="${1:?Usage: $0 VM_NAME [STALL_SECONDS]}"
stall="${2:-6}"
pings=$((stall + 6))

ip=$(dscacheutil -q host -a name "$vm-vmnet-helper.local" | awk '/^ip_address/ {print $2; exit}')
helper_log="$HOME/.vmnet-helper/vms/$vm/vmnet-helper.log"

# Virtualization.framework spawns a com.apple.Virtualization.VirtualMachine
# XPC process per VM, and that process holds the vm socket. 
# Find ours by its open VM disk.
vz_pid=""
for pid in $(pgrep -f com.apple.Virtualization.VirtualMachine); do
    if lsof -p "$pid" 2>/dev/null | grep -q "vms/$vm/disk.img"; then
        vz_pid="$pid"
        break
    fi
done
[ -n "$vz_pid" ] || { echo "no VirtualMachine process for $vm"; exit 1; }

echo "vm=$vm ip=$ip vz=$vz_pid stall=${stall}s"
echo

echo "== ping during a ${stall}s client stall (1 ping per second) =="
ping -i 1 -c "$pings" "$ip" > /tmp/stall-ping.txt &
ping_pid=$!

# Bulk host->vm traffic (~11 Mbit/s UDP) so the stall overflows the vm
# socket receive buffer and write_to_vm() hits ENOBUFS.
python3 - "$ip" $((stall + 4)) <<'EOF' &
import socket, sys, time
s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
payload = b"x" * 1400
end = time.time() + float(sys.argv[2])
while time.time() < end:
    s.sendto(payload, (sys.argv[1], 9))
    time.sleep(0.001)
EOF
blast_pid=$!

sleep 2
echo "-- SIGSTOP VirtualMachine process --"
kill -STOP "$vz_pid"
sleep "$stall"
echo "-- SIGCONT VirtualMachine process --"
kill -CONT "$vz_pid"

wait "$ping_pid" || true
wait "$blast_pid" || true
grep -E "icmp_seq|packet loss|round-trip" /tmp/stall-ping.txt

echo
echo "== helper log during the stall =="
tail -5 "$helper_log"

The script uses SIGSTOP to emulate what we see in our workloads.

In terminal 1

./run test

In terminal 2

./stall-repro.sh test 6

Output in the broken case

vm=test ip=192.168.64.14 vz=61214 stall=6s

== ping during a 6s client stall (1 ping per second) ==
-- SIGSTOP VirtualMachine process --
-- SIGCONT VirtualMachine process --
64 bytes from 192.168.64.14: icmp_seq=0 ttl=64 time=0.295 ms
64 bytes from 192.168.64.14: icmp_seq=1 ttl=64 time=0.129 ms
Request timeout for icmp_seq 2
Request timeout for icmp_seq 3
Request timeout for icmp_seq 4
Request timeout for icmp_seq 5
Request timeout for icmp_seq 6
64 bytes from 192.168.64.14: icmp_seq=2 ttl=64 time=6012.425 ms
64 bytes from 192.168.64.14: icmp_seq=3 ttl=64 time=5011.270 ms
64 bytes from 192.168.64.14: icmp_seq=4 ttl=64 time=4011.324 ms
64 bytes from 192.168.64.14: icmp_seq=5 ttl=64 time=3006.248 ms
64 bytes from 192.168.64.14: icmp_seq=6 ttl=64 time=2001.181 ms
64 bytes from 192.168.64.14: icmp_seq=7 ttl=64 time=996.461 ms
64 bytes from 192.168.64.14: icmp_seq=8 ttl=64 time=0.192 ms
64 bytes from 192.168.64.14: icmp_seq=9 ttl=64 time=0.366 ms
64 bytes from 192.168.64.14: icmp_seq=10 ttl=64 time=0.287 ms
64 bytes from 192.168.64.14: icmp_seq=11 ttl=64 time=0.778 ms
12 packets transmitted, 12 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 0.129/1753.413/6012.425/2131.011 ms

== helper log during the stall ==
INFO  [main] using bulk_forwarding: true
INFO  [main] started vmnet interface
INFO  [main] started host forwarding
INFO  [main] started vm forwarding
INFO  [main] waiting for termination

The network looks lossless, but only by having unbounded latency.

Output in the "fixed" case

vm=test ip=192.168.64.14 vz=61174 stall=6s

== ping during a 6s client stall (1 ping per second) ==
-- SIGSTOP VirtualMachine process --
-- SIGCONT VirtualMachine process --
64 bytes from 192.168.64.14: icmp_seq=0 ttl=64 time=0.261 ms
64 bytes from 192.168.64.14: icmp_seq=1 ttl=64 time=0.311 ms
64 bytes from 192.168.64.14: icmp_seq=2 ttl=64 time=0.368 ms
Request timeout for icmp_seq 3
Request timeout for icmp_seq 4
Request timeout for icmp_seq 5
Request timeout for icmp_seq 6
64 bytes from 192.168.64.14: icmp_seq=3 ttl=64 time=5009.535 ms
64 bytes from 192.168.64.14: icmp_seq=4 ttl=64 time=4007.919 ms
64 bytes from 192.168.64.14: icmp_seq=5 ttl=64 time=3004.290 ms
64 bytes from 192.168.64.14: icmp_seq=6 ttl=64 time=1999.251 ms
64 bytes from 192.168.64.14: icmp_seq=7 ttl=64 time=996.027 ms
64 bytes from 192.168.64.14: icmp_seq=8 ttl=64 time=0.204 ms
64 bytes from 192.168.64.14: icmp_seq=9 ttl=64 time=0.211 ms
64 bytes from 192.168.64.14: icmp_seq=10 ttl=64 time=0.258 ms
64 bytes from 192.168.64.14: icmp_seq=11 ttl=64 time=0.624 ms
12 packets transmitted, 12 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 0.204/1251.605/5009.535/1741.061 ms

== helper log during the stall ==
INFO  [main] started vm forwarding
INFO  [main] waiting for termination
WARN  [host->vm] dropped 1 packets (1 total): peer is not reading from the socket
WARN  [host->vm] dropped 6 packets (698 total): peer is not reading from the socket
WARN  [host->vm] dropped 6 packets (1523 total): peer is not reading from the socket

In the fixed case we can observe the dropped packet count in the logs. Dropping of the packets should cause the sending endpoints to retransmit or maybe even slow down. This is for TCP, I guess for UDP it's up to the application to decide.

"Real world counterparts"

I'm no expert in either hardware networking gear or linux networking, but I guess we could come up with some example "write timeout" or "packet buffer" values from these.

Here's some documentation from Broadcom https://docs.broadcom.com/doc/BC-0503EN

Chip	Ports	Packet buffer (whole chip)	Time to drain the full buffer at port speed
BCM53101	5x 100 Mbit	64 KB	~5 ms at 100 Mbit/s
BCM53125	7x 1 GbE	128 KB	~1 ms at 1 Gbit/s
BCM53128	8x 1 GbE	192 KB	~1.5 ms
BCM5396	16x 1 GbE	256 KB	~2 ms
BCM53158	8x 1 GbE + 2x 10 GbE	1 MB	~0.8 ms at 10 G, ~8 ms at 1 G

Linux has

• https://www.kernel.org/doc/html/latest/admin-guide/sysctl/net.html#default-qdisc
• https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/include/net/codel.h?h=linux-7.1.y
• https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/include/net/codel_impl.h?h=linux-7.1.y#n57 params->target = MS2TIME(5)
• https://queue.acm.org/detail.cfm?id=2209336

[nirs]

This issue relates to the PR #266 - I should have opened the issue first instead of the other way around.

Real world impact

We run workloads on Apple Silicon hosts with vfkit VMs. F.ex. BuildKit's cache client inside the guest downloads large cache objects over a shared HTTP/2 connection, the server's PING acks toward the guest get stuck behind the stalled queue, the client's health check times out, and the connection dies with "http2: client connection lost". In our case it always seems to happen during large concurrent downloads. Recovering happens once the guest catches up. It seems that any protocol with a heartbeat shorter than the stall (gRPC keepalives, TLS handshake timeouts, DNS) is affected the same way.

I don't understand the use case and the impact. The issue is with a single VM or muultiple VMs (e.g. vms stops reading affects the other vms)?

Please share instructions on how to reproduce this with in the same way you reproduce the issue in your real world use case.

I don't reproducion script, just instruction on how to setup the vms and which workloads to run.

[nirs]

write_to_vm() retries ENOBUFS forever when the client stops reading

Rename to describe the user visible issue.

[nirs]

@leolannenmaki

We run workloads on Apple Silicon hosts with vfkit

How do you run vfkit and vmnet-helper? Share the vmnet-helper command.

If you use —fd - do you set socket send/recv buffer size to the same values used by the run script?

[nirs]

@leolannenmaki Thanks for the detailed report and the PR. I could not reproduce this issue since you did not provide steps to reproduce, but I agree that endless retries are not a good idea and they can cause high priority messages to arrive too late.

When downloading and unpacking images the VM may be bounded by CPU, and drain too slowly from vmnet-helper socket. The recv buffer becomes full and vmnet-helper may retry sendmsg_x() or write() without any bound.

An HTTP/2 PING packet may be blocked for long time behind data packets. If the VM is reading slow enough, the PING packet may arrive too late and cause the connection lost issue you report.

I like the suggested approach in #266 - limit the number of retries. I'm working on a simpler fix using the new stats counters (#268) for tracking drops instead of the rate-limited special log.

[nirs]

@leolannenmaki please test #278 - I could not reproduce your issue with vfkit or krunkit, but this change should avoid it.

[leolannenmaki]

Very sorry for being unresponsive regarding this issue. I didn't have time to work on this issue first and then was AFK for some days.

I tested #278 / commit 172b94b on an M5 Pro host (macOS 26.5.2) with vfkit (1 vCPU, 1 GiB guest, --stats-interval 1, default buffer sizes) locally. The script in this issue works fine now. I'll try this deployed and try to exercise the fix in a way which originally triggered the issue. Will report back soon.

How do you run vfkit and vmnet-helper? Share the vmnet-helper command.

We create the socketpair ourselves and set these on both ends:
SO_SNDBUF 65 KiB, SO_RCVBUF 8 MiB (same send size as the run script, 2x its receive size).

vmnet-helper --fd=N --start-address=<gateway> --end-address=<broadcast-1> --subnet-mask=255.255.255.0

[nirs]

I tested #278 / commit 172b94b on an M5 Pro host (macOS 26.5.2) with vfkit (1 vCPU, 1 GiB guest, --stats-interval 1, default buffer sizes) locally.

We don't have benchmarks results for M5 yet. If you like to contribute:

• https://github.com/nirs/vmnet-helper/blob/main/docs/development.md#benchmarking

[leolannenmaki]

Will report back soon.

It's been running in a staging environment for some hours now and I've ran the same workloads many times that used to fail with the old code and it seems to be working as it should. I'll keep you posted on how it goes, but I'm pretty happy about the fix! Thank you so much for the help.

Happy to contribute some benchmarks. Should I open a PR or how do you want them? This PR or v0.12 or something else?

[nirs]

Will report back soon.

It's been running in a staging environment for some hours now and I've ran the same workloads many times that used to fail with the old code and it seems to be working as it should. I'll keep you posted on how it goes, but I'm pretty happy about the fix! Thank you so much for the help.

I hope you can share the vmnet-helper logs when done. I would like to see the stats for real world workloads.

Happy to contribute some benchmarks. Should I open a PR or how do you want them?

You can open a PR with new benchmark results - ideally the full benchmark for a newer machine using the same style. If it is not clear how to do this, just share the output files. Thanks!

This PR or v0.12 or something else?

Testing this PR will be more useful, or wait until we merge it?