From 151bee8d9d6f1411c7fe25778a089b138884611c Mon Sep 17 00:00:00 2001 From: okuegow Date: Mon, 25 May 2026 16:04:48 +0200 Subject: [PATCH] logstash: track ring length in O(1) instead of ring.Len() per write (#30201) --- util/logstash/log.go | 17 +++++++++++--- util/logstash/log_test.go | 49 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 63 insertions(+), 3 deletions(-) diff --git a/util/logstash/log.go b/util/logstash/log.go index 717fbbc51..f20c05b18 100644 --- a/util/logstash/log.go +++ b/util/logstash/log.go @@ -29,13 +29,19 @@ type logger struct { mu sync.RWMutex data *ring.Ring size int + // length mirrors data.Len() so Write avoids an O(n) ring.Len() call on every + // log line (see Write). Invariant: any code that changes the number of nodes + // in data must keep length in sync. + length int } func New(size int) *logger { - return &logger{ + l := &logger{ data: ring.New(1), size: size, } + l.length = l.data.Len() // keep length in sync with the initial ring + return l } var _ io.Writer = (*logger)(nil) @@ -47,9 +53,14 @@ func (l *logger) Write(p []byte) (n int, err error) { if !strings.HasPrefix(string(p), "[cache ]") { l.data.Value = element(string(p)) - // dynamically grow the ring - if l.data.Len() < l.size { + // dynamically grow the ring until it reaches the configured size. + // Track the length in O(1) instead of calling ring.Len(), which walks + // the whole ring on every write — once the ring is full (size 10000) + // that is 10000 pointer chases per log line and dominates CPU on weak + // hardware (e.g. Victron Venus OS / ARMv7) under verbose trace logging. + if l.length < l.size { l.data.Link(ring.New(1)) + l.length++ } l.data = l.data.Next() diff --git a/util/logstash/log_test.go b/util/logstash/log_test.go index 9240a85ff..6915d6910 100644 --- a/util/logstash/log_test.go +++ b/util/logstash/log_test.go @@ -36,6 +36,55 @@ func TestLog(t *testing.T) { assert.Equal(t, []string{"test1", "test2"}, log.Areas()) } +// TestRingGrowsThenCaps writes more lines than the configured size and verifies +// the ring grows up to size and then keeps only the most recent size entries. +// This guards the grow/cap accounting in Write (length tracked in O(1)). +func TestRingGrowsThenCaps(t *testing.T) { + const size = 3 + log := New(size) + + lines := []string{ + "[test ] TRACE line1", + "[test ] TRACE line2", + "[test ] TRACE line3", + "[test ] TRACE line4", + "[test ] TRACE line5", + } + for _, l := range lines { + log.Write([]byte(l)) + } + + // only the last `size` lines survive, in chronological order + got := log.All(nil, jww.LevelTrace, 0) + assert.Len(t, got, size, "ring must not exceed configured size") + assert.Equal(t, lines[len(lines)-size:], got) +} + +// TestRingSkipCacheLinesDoesNotGrow verifies that "[cache ]" lines take the +// early-return path: they are not stored and must neither grow the ring nor the +// length counter, which has to stay in sync with data.Len(). +func TestRingSkipCacheLinesDoesNotGrow(t *testing.T) { + log := New(3) + + // grow the ring past a single node first, so a stray cursor advance on the + // cache path would actually be observable (Next() on a 1-node ring is a no-op) + log.Write([]byte(s1)) + log.Write([]byte(s2)) + + stored := log.All(nil, jww.LevelTrace, 0) + lenBefore := log.length + cursorBefore := log.data + + for range 10 { + log.Write([]byte("[cache ] cache line")) + } + + assert.Equal(t, stored, log.All(nil, jww.LevelTrace, 0), "cache lines must not change stored content") + assert.Equal(t, log.data.Len(), log.length, "length counter must stay in sync with the ring") + assert.Equal(t, lenBefore, log.length, "cache lines must not grow the ring") + assert.Same(t, cursorBefore, log.data, "cache lines must not advance the write cursor") +} + func BenchmarkLog(b *testing.B) { log := New(10000)