Description
When a workload creates a large number of short-lived TCP connections through a forwarded port, publishing the next port can sometimes stall. In our case, using Lima's default gRPC port forwarder, the new container was already running and listening inside the VM, but its port did not become reachable from the host for 9 to 11 seconds.
We first saw this through Colima while running an integration test suite. About one in five container starts failed its readiness check because the host-side port did not become available in time.
Startup times were very consistent: around 750 ms normally, but became 9 to 11 seconds when the problem occurred.
Environment
- Lima 2.2.0
- macOS 14.8.5
- Apple Silicon
vz- APFS
- gRPC port forwarder, Lima's default
- Found through Colima 0.10.3, which uses Lima's hostagent unchanged
Workload
Our integration test harness repeatedly:
- starts a container and publishes a port;
- sends HTTP traffic through that port;
- removes the container;
- immediately starts another container with a published port; and
- waits for the new host-side port to become reachable.
Each cycle creates hundreds to a few thousand short-lived TCP connections.
Debug
I went old school, adding various log lines into various points to try and figure out where the time was going. This included many false leads that I cannot remember.
Tracing the host-side event handling showed that the event callback could take 10 to 11 seconds to return. While it was blocked, the host was not processing later guest-agent events.
Most of that time was spent inside two logrus.Debugf calls.
Logging behaviour
cmd/limactl/hostagent.go wraps the hostagent's stdout and stderr in a syncWriter:
Each successful write is followed by Sync().
On our host we benchmarked and there is a significant performance penalty to this approach - with sync vs. without:
| Method |
Rate |
Per record |
| write + fsync per record |
242 lines/s |
4.13 ms |
| write only |
709,143 lines/s |
0.0014 ms |
We also measured the live hostagent log drain rate at 183 to 234 lines/s across six separate samples.
The reproduction above generated 3,214 log records. At around 200 records per second, that is enough to explain a delay of roughly the size we were seeing.
Note the next part is AI-assisted - I got to the cause of the delay, but trying to explain the interactions got tricky so I needed help. I'll get on to options at the end - but jumping ahead: removing the sync after every write is the patch I made locally and the stall disappeared (also tested the coalesce option).
Cause
The stall comes from the interaction between logging and the gRPC port forwarder.
syncWriter calls Sync() after every hostagent log write.
At the same time, logrus holds its process-wide output lock while writing each record. This means each log record holds that lock while the fsync completes.
The gRPC port forwarder writes several debug records when each TCP tunnel is closed. A burst of hundreds of short-lived connections can therefore create thousands of log records.
Other goroutines that need to log have to wait behind that backlog.
One of those is the guest-agent event callback. GuestAgentClient.Events runs that callback inline on the event receive loop.
If the callback blocks while logging, the host stops reading further guest-agent events. The event for the next forwarded port has already been sent by the guest, but it is not processed until the logging backlog clears.
That is where the 9 to 11 second delay comes from.
Why it mainly affects the gRPC forwarder
The per-record fsync applies to all hostagent logging, but the gRPC forwarder produces much more log traffic during connection churn.
| Forwarder |
Debug records per TCP connection |
Scales with |
| gRPC |
4 (pkg/portfwd/client.go:26,174,181,187) |
connection count |
| SSH |
0, only per-port Infof (pkg/hostagent/port.go:129,147,156) |
port count |
With the SSH forwarder, the connection data is carried by the SSH ControlMaster rather than through limactl, so there are no hostagent log records for each TCP connection teardown.
In an otherwise identical workload, the SSH hostagent log contained 25 ssh -O forward commands and no tunnel teardown records. The gRPC run produced about 45,000 tunnel teardown records.
This is why the problem first looked specific to the gRPC forwarder.
The underlying logging issue is not limited to gRPC. The gRPC path simply produces enough records to expose it during normal connection churn.
Log level
There is another factor that increases the amount of logging.
initLogrus in cmd/limactl/hostagent.go forces the hostagent to Debug level, or Trace when limactl itself is at Debug.
There does not appear to be a supported way to reduce the hostagent log level below Debug (note the logic is if debug.. else..: so this seems like an issue too as it's not possible to be less verbose?).
This means users of the gRPC forwarder cannot avoid the per-connection debug records through configuration.
Suggested fix
Instead of calling Sync() after every log record, flush periodically.
We tested a 100 ms coalescing interval.
In the same microbenchmark, throughput increased to:
There were four flushes across 200,000 log records.
Running the same reproduction against that build changed the port publication time from:
to:
The hostagent log still grew by the same 3,214 records.
No logging was removed. The records were simply written without an fsync after each one.
Removing Sync() completely is about 22% faster in the microbenchmark, but the difference is small at normal log volumes.
A short coalescing interval keeps the original behaviour of regularly flushing the log while avoiding a disk sync for every record.
Origin
The per-write sync was introduced in:
722b7d1b (hostagent: sync every (io.Writer).Write)
It was added in July 2021 and first released in v0.6.0.
At the time, the hostagent produced relatively few log records during the lifetime of an instance.
The cost became more noticeable later when the port forwarder started producing records for individual connection teardowns.
Description
When a workload creates a large number of short-lived TCP connections through a forwarded port, publishing the next port can sometimes stall. In our case, using Lima's default gRPC port forwarder, the new container was already running and listening inside the VM, but its port did not become reachable from the host for 9 to 11 seconds.
We first saw this through Colima while running an integration test suite. About one in five container starts failed its readiness check because the host-side port did not become available in time.
Startup times were very consistent: around 750 ms normally, but became 9 to 11 seconds when the problem occurred.
Environment
vzWorkload
Our integration test harness repeatedly:
Each cycle creates hundreds to a few thousand short-lived TCP connections.
Debug
I went old school, adding various log lines into various points to try and figure out where the time was going. This included many false leads that I cannot remember.
Tracing the host-side event handling showed that the event callback could take 10 to 11 seconds to return. While it was blocked, the host was not processing later guest-agent events.
Most of that time was spent inside two
logrus.Debugfcalls.Logging behaviour
cmd/limactl/hostagent.gowraps the hostagent's stdout and stderr in a syncWriter:Each successful write is followed by Sync().
On our host we benchmarked and there is a significant performance penalty to this approach - with sync vs. without:
We also measured the live hostagent log drain rate at 183 to 234 lines/s across six separate samples.
The reproduction above generated 3,214 log records. At around 200 records per second, that is enough to explain a delay of roughly the size we were seeing.
Note the next part is AI-assisted - I got to the cause of the delay, but trying to explain the interactions got tricky so I needed help. I'll get on to options at the end - but jumping ahead: removing the sync after every write is the patch I made locally and the stall disappeared (also tested the coalesce option).
Cause
The stall comes from the interaction between logging and the gRPC port forwarder.
syncWritercallsSync()after every hostagent log write.At the same time,
logrusholds its process-wide output lock while writing each record. This means each log record holds that lock while thefsynccompletes.The gRPC port forwarder writes several debug records when each TCP tunnel is closed. A burst of hundreds of short-lived connections can therefore create thousands of log records.
Other goroutines that need to log have to wait behind that backlog.
One of those is the guest-agent event callback.
GuestAgentClient.Eventsruns that callback inline on the event receive loop.If the callback blocks while logging, the host stops reading further guest-agent events. The event for the next forwarded port has already been sent by the guest, but it is not processed until the logging backlog clears.
That is where the 9 to 11 second delay comes from.
Why it mainly affects the gRPC forwarder
The per-record
fsyncapplies to all hostagent logging, but the gRPC forwarder produces much more log traffic during connection churn.pkg/portfwd/client.go:26,174,181,187)Infof(pkg/hostagent/port.go:129,147,156)With the SSH forwarder, the connection data is carried by the SSH ControlMaster rather than through
limactl, so there are no hostagent log records for each TCP connection teardown.In an otherwise identical workload, the SSH hostagent log contained 25
ssh -O forwardcommands and no tunnel teardown records. The gRPC run produced about 45,000 tunnel teardown records.This is why the problem first looked specific to the gRPC forwarder.
The underlying logging issue is not limited to gRPC. The gRPC path simply produces enough records to expose it during normal connection churn.
Log level
There is another factor that increases the amount of logging.
initLogrus in
cmd/limactl/hostagent.goforces the hostagent to Debug level, or Trace whenlimactlitself is at Debug.There does not appear to be a supported way to reduce the hostagent log level below Debug (note the logic is
if debug.. else..: so this seems like an issue too as it's not possible to be less verbose?).This means users of the gRPC forwarder cannot avoid the per-connection debug records through configuration.
Suggested fix
Instead of calling
Sync()after every log record, flush periodically.We tested a 100 ms coalescing interval.
In the same microbenchmark, throughput increased to:
There were four flushes across 200,000 log records.
Running the same reproduction against that build changed the port publication time from:
to:
The hostagent log still grew by the same 3,214 records.
No logging was removed. The records were simply written without an
fsyncafter each one.Removing
Sync()completely is about 22% faster in the microbenchmark, but the difference is small at normal log volumes.A short coalescing interval keeps the original behaviour of regularly flushing the log while avoiding a disk sync for every record.
Origin
The per-write sync was introduced in:
722b7d1b(hostagent: sync every (io.Writer).Write)It was added in July 2021 and first released in v0.6.0.
At the time, the hostagent produced relatively few log records during the lifetime of an instance.
The cost became more noticeable later when the port forwarder started producing records for individual connection teardowns.