perf(app): skip building the scene debug log when debug is off

The scenes loop formatted one string per window for every scene of every frame even when the debug level was disabled. logScenes now returns early per scene whose debug event is disabled: 3 allocs per two-scene set down to 0.

commit: 040eba7586f60f09102b6c4e5f17a0d46997eccd
author: brice · 6d ago · 2026-10-16 14:04 UTC
parent: 9dcad8d
signature: GPG VerifiedCD88F9E564E0102646FB6077A1A07C7C7C3E349D · arch-gpg Verified for the committer email

2 files · +74 -12

M internal/app/app.go +22 -12


@@ -157,24 +157,34 @@ func consumeScenes(ctx context.Context, scenes <-chan []ports.Scene, configError
157	157		}
158	158		}
159	159		latest(renderScenes, set) // this goroutine is the only sender
160		-	for _, s := range set {
161		-	ev := log.Debug().Str("output", s.Output).Uint64("seq", s.Seq).Int("out_w", s.OutputWidth).Int("out_h", s.OutputHeight).Float64("scale", s.Scale)
162		-	rects := make([]string, 0, len(s.Windows))
163		-	for _, w := range s.Windows {
164		-	rects = append(rects, fmt.Sprintf("%d:%d,%d %dx%d", w.ID, w.Rect.X, w.Rect.Y, w.Rect.W, w.Rect.H))
165		-	if w.FocusEffect > 0 {
166		-	// The focus indicator frame by frame: window and effect.
167		-	ev = ev.Uint64("focus_effect_window", uint64(w.ID)).Float64("focus_effect", w.FocusEffect)
168		-	}
169		-	}
170		-	ev.Strs("windows", rects).Msg("scene")
171		-	}
	160	+	logScenes(log, set)
172	161		case err := <-configErrors:
173	162		configLog.Warn().Err(err).Msg("config rejected")
174	163		}
175	164		}
176	165		}
177	166
	167	+	// logScenes logs each scene at debug level. The rect strings are built only
	168	+	// when debug is on: at the default level a frame costs no allocation here.
	169	+	func logScenes(log zerowrap.Logger, set []ports.Scene) {
	170	+	for _, s := range set {
	171	+	ev := log.Debug()
	172	+	if !ev.Enabled() {
	173	+	continue
	174	+	}
	175	+	ev = ev.Str("output", s.Output).Uint64("seq", s.Seq).Int("out_w", s.OutputWidth).Int("out_h", s.OutputHeight).Float64("scale", s.Scale)
	176	+	rects := make([]string, 0, len(s.Windows))
	177	+	for _, w := range s.Windows {
	178	+	rects = append(rects, fmt.Sprintf("%d:%d,%d %dx%d", w.ID, w.Rect.X, w.Rect.Y, w.Rect.W, w.Rect.H))
	179	+	if w.FocusEffect > 0 {
	180	+	// The focus indicator frame by frame: window and effect.
	181	+	ev = ev.Uint64("focus_effect_window", uint64(w.ID)).Float64("focus_effect", w.FocusEffect)
	182	+	}
	183	+	}
	184	+	ev.Strs("windows", rects).Msg("scene")
	185	+	}
	186	+	}
	187	+
178	188		// openXwayland reserves an X11 display for xwayland-satellite, or returns
179	189		// nil when X11 is off or unavailable: the session runs without it.
180	190		func openXwayland(ctx context.Context, opts Options, env []string, log zerowrap.Logger) *xwayland.Display {

 				}
 			}
 			latest(renderScenes, set) // this goroutine is the only sender
-			for _, s := range set {
+			logScenes(log, set)
-				ev := log.Debug().Str("output", s.Output).Uint64("seq", s.Seq).Int("out_w", s.OutputWidth).Int("out_h", s.OutputHeight).Float64("scale", s.Scale)
-				rects := make([]string, 0, len(s.Windows))
-				for _, w := range s.Windows {
-					rects = append(rects, fmt.Sprintf("%d:%d,%d %dx%d", w.ID, w.Rect.X, w.Rect.Y, w.Rect.W, w.Rect.H))
-					if w.FocusEffect > 0 {
-						// The focus indicator frame by frame: window and effect.
-						ev = ev.Uint64("focus_effect_window", uint64(w.ID)).Float64("focus_effect", w.FocusEffect)
-					}
-				}
-				ev.Strs("windows", rects).Msg("scene")
-			}
 		case err := <-configErrors:
 			configLog.Warn().Err(err).Msg("config rejected")
 		}
 	}
 }
+// logScenes logs each scene at debug level. The rect strings are built only
+// when debug is on: at the default level a frame costs no allocation here.
+func logScenes(log zerowrap.Logger, set []ports.Scene) {
+	for _, s := range set {
+		ev := log.Debug()
+		if !ev.Enabled() {
+			continue
+		}
+		ev = ev.Str("output", s.Output).Uint64("seq", s.Seq).Int("out_w", s.OutputWidth).Int("out_h", s.OutputHeight).Float64("scale", s.Scale)
+		rects := make([]string, 0, len(s.Windows))
+		for _, w := range s.Windows {
+			rects = append(rects, fmt.Sprintf("%d:%d,%d %dx%d", w.ID, w.Rect.X, w.Rect.Y, w.Rect.W, w.Rect.H))
+			if w.FocusEffect > 0 {
+				// The focus indicator frame by frame: window and effect.
+				ev = ev.Uint64("focus_effect_window", uint64(w.ID)).Float64("focus_effect", w.FocusEffect)
+			}
+		}
+		ev.Strs("windows", rects).Msg("scene")
+	}
+}
 // openXwayland reserves an X11 display for xwayland-satellite, or returns
 // nil when X11 is off or unavailable: the session runs without it.
 func openXwayland(ctx context.Context, opts Options, env []string, log zerowrap.Logger) *xwayland.Display {

A internal/app/scenelog_test.go +52 -0

@@ -0,0 +1,52 @@
	1	+	package app
	2	+
	3	+	import (
	4	+	"strings"
	5	+	"testing"
	6	+
	7	+	"github.com/bnema/neferwl/internal/ports"
	8	+	"github.com/bnema/zerowrap"
	9	+	)
	10	+
	11	+	func logTestScenes() []ports.Scene {
	12	+	return []ports.Scene{{
	13	+	Output: "A", Seq: 7, OutputWidth: 1920, OutputHeight: 1080, Scale: 1,
	14	+	Windows: []ports.SceneWindow{
	15	+	{ID: 1, Rect: ports.Rect{X: 10, Y: 20, W: 300, H: 200}},
	16	+	{ID: 2, Rect: ports.Rect{X: 5, Y: 6, W: 7, H: 8}, FocusEffect: 0.5},
	17	+	},
	18	+	}, {Output: "B"}}
	19	+	}
	20	+
	21	+	// With debug off the scene log builds nothing: no rect strings, no event.
	22	+	// Measured before the level check: 3 allocations per run for two scenes.
	23	+	func TestLogScenesAllocations(t *testing.T) {
	24	+	out := &lockedBuffer{}
	25	+	log := zerowrap.New(zerowrap.Config{Format: "json", Level: "info", Output: out})
	26	+	set := logTestScenes()
	27	+	if got := testing.AllocsPerRun(100, func() { logScenes(log, set) }); got != 0 {
	28	+	t.Fatalf("logScenes at info level: %g allocations per run, want 0", got)
	29	+	}
	30	+	if out.String() != "" {
	31	+	t.Fatalf("info level logged: %s", out.String())
	32	+	}
	33	+	}
	34	+
	35	+	func TestLogScenesDebug(t *testing.T) {
	36	+	out := &lockedBuffer{}
	37	+	log := zerowrap.New(zerowrap.Config{Format: "json", Level: "debug", Output: out})
	38	+	logScenes(log, logTestScenes())
	39	+	got := out.String()
	40	+	for _, want := range []string{
	41	+	`"output":"A"`, `"seq":7`, `"out_w":1920`, `"out_h":1080`, `"scale":1`,
	42	+	`"windows":["1:10,20 300x200","2:5,6 7x8"]`,
	43	+	`"focus_effect_window":2`, `"focus_effect":0.5`, `"message":"scene"`,
	44	+	} {
	45	+	if !strings.Contains(got, want) {
	46	+	t.Fatalf("debug log lacks %s: %s", want, got)
	47	+	}
	48	+	}
	49	+	if n := strings.Count(got, `"message":"scene"`); n != 2 {
	50	+	t.Fatalf("%d scene entries, want 2: %s", n, got)
	51	+	}
	52	+	}

@@ -0,0 +1,52 @@
	1	+	package app
	2	+
	3	+	import (
	4	+	"strings"
	5	+	"testing"
	6	+
	7	+	"github.com/bnema/neferwl/internal/ports"
	8	+	"github.com/bnema/zerowrap"
	9	+	)
	10	+
	11	+	func logTestScenes() []ports.Scene {
	12	+	return []ports.Scene{{
	13	+	Output: "A", Seq: 7, OutputWidth: 1920, OutputHeight: 1080, Scale: 1,
	14	+	Windows: []ports.SceneWindow{
	15	+	{ID: 1, Rect: ports.Rect{X: 10, Y: 20, W: 300, H: 200}},
	16	+	{ID: 2, Rect: ports.Rect{X: 5, Y: 6, W: 7, H: 8}, FocusEffect: 0.5},
	17	+	},
	18	+	}, {Output: "B"}}
	19	+	}
	20	+
	21	+	// With debug off the scene log builds nothing: no rect strings, no event.
	22	+	// Measured before the level check: 3 allocations per run for two scenes.
	23	+	func TestLogScenesAllocations(t *testing.T) {
	24	+	out := &lockedBuffer{}
	25	+	log := zerowrap.New(zerowrap.Config{Format: "json", Level: "info", Output: out})
	26	+	set := logTestScenes()
	27	+	if got := testing.AllocsPerRun(100, func() { logScenes(log, set) }); got != 0 {
	28	+	t.Fatalf("logScenes at info level: %g allocations per run, want 0", got)
	29	+	}
	30	+	if out.String() != "" {
	31	+	t.Fatalf("info level logged: %s", out.String())
	32	+	}
	33	+	}
	34	+
	35	+	func TestLogScenesDebug(t *testing.T) {
	36	+	out := &lockedBuffer{}
	37	+	log := zerowrap.New(zerowrap.Config{Format: "json", Level: "debug", Output: out})
	38	+	logScenes(log, logTestScenes())
	39	+	got := out.String()
	40	+	for _, want := range []string{
	41	+	`"output":"A"`, `"seq":7`, `"out_w":1920`, `"out_h":1080`, `"scale":1`,
	42	+	`"windows":["1:10,20 300x200","2:5,6 7x8"]`,
	43	+	`"focus_effect_window":2`, `"focus_effect":0.5`, `"message":"scene"`,
	44	+	} {
	45	+	if !strings.Contains(got, want) {
	46	+	t.Fatalf("debug log lacks %s: %s", want, got)
	47	+	}
	48	+	}
	49	+	if n := strings.Count(got, `"message":"scene"`); n != 2 {
	50	+	t.Fatalf("%d scene entries, want 2: %s", n, got)
	51	+	}
	52	+	}