diff --git a/cmd/limactl/hostagent.go b/cmd/limactl/hostagent.go index 71015dccd65..c9588bf1e99 100644 --- a/cmd/limactl/hostagent.go +++ b/cmd/limactl/hostagent.go @@ -12,7 +12,9 @@ import ( "os" "os/signal" "runtime" + "sync" "syscall" + "time" "github.com/sirupsen/logrus" "github.com/spf13/cobra" @@ -140,13 +142,27 @@ type syncer interface { Sync() error } +// syncInterval bounds how long the log can go unflushed. +// +// Flushing on every write serialised the whole hostagent behind one fsync per +// record: logrus holds its output mutex across Out.Write, and the port +// forwarder logs once per tunnel teardown, so a burst of closing connections +// throttled all logging in the process. +// +// The flush cannot be dropped entirely. limactl start follows these files with +// fsnotify, and on Windows the tailer stops seeing new lines without it. +const syncInterval = 100 * time.Millisecond + type syncWriter struct { w io.Writer + + mu sync.Mutex + lastSync time.Time } func (w *syncWriter) Write(p []byte) (int, error) { written, err := w.w.Write(p) - if err == nil { + if err == nil && w.syncDue() { if s, ok := w.w.(syncer); ok { _ = s.Sync() } @@ -154,6 +170,18 @@ func (w *syncWriter) Write(p []byte) (int, error) { return written, err } +// syncDue reports whether syncInterval has passed since the last flush, and +// records the new flush time when it has. +func (w *syncWriter) syncDue() bool { + w.mu.Lock() + defer w.mu.Unlock() + if time.Since(w.lastSync) < syncInterval { + return false + } + w.lastSync = time.Now() + return true +} + func initLogrus(stderr io.Writer) { logrus.SetOutput(stderr) // JSON logs are parsed in pkg/hostagent/events.Watcher() diff --git a/cmd/limactl/hostagent_test.go b/cmd/limactl/hostagent_test.go new file mode 100644 index 00000000000..fa267532c73 --- /dev/null +++ b/cmd/limactl/hostagent_test.go @@ -0,0 +1,40 @@ +// SPDX-FileCopyrightText: Copyright The Lima Authors +// SPDX-License-Identifier: Apache-2.0 + +package main + +import ( + "testing" + "time" + + "gotest.tools/v3/assert" +) + +type countingSyncer struct { + writes, syncs int +} + +func (c *countingSyncer) Write(p []byte) (int, error) { c.writes++; return len(p), nil } +func (c *countingSyncer) Sync() error { c.syncs++; return nil } + +// TestSyncWriterCoalescesFlushes checks that every record still reaches the +// underlying writer, and that only the flushes are coalesced. +func TestSyncWriterCoalescesFlushes(t *testing.T) { + c := &countingSyncer{} + w := &syncWriter{w: c} + + const records = 1000 + for range records { + _, err := w.Write([]byte("record\n")) + assert.NilError(t, err) + } + assert.Equal(t, c.writes, records) + assert.Assert(t, c.syncs <= 2, "expected coalesced flushes, got %d for %d records", c.syncs, records) + + // The log must not be able to go unflushed indefinitely. + before := c.syncs + time.Sleep(syncInterval + 20*time.Millisecond) + _, err := w.Write([]byte("record\n")) + assert.NilError(t, err) + assert.Equal(t, c.syncs, before+1) +}