cb64d9f feat(output): log merged flips in output stats · neferwl

M docs/performance.md +1 -0


@@ -53,5 +53,6 @@ Every 10 s, each output logs a `stats` entry:
53	53		\| `max_commit_delay_ms` \| Longest wait from "frame due" to commit \|
54	54		\| `late_fences` \| Missed vblanks where the GPU finished too late (needs `--debug=drm-flip`) \|
55	55		\| `redrawn_pixels` \| Pixels drawn \|
	56	+	\| `merged_flips` \| Flips merged because wayland was not reading output reports \|
56	57
57	58		Missed vblanks with `late_fences` mean the GPU was late. Without `late_fences` but with a large `max_commit_delay_ms`, the CPU was late.


@@ -53,5 +53,6 @@ Every 10 s, each output logs a `stats` entry:
53	\| `max_commit_delay_ms` \| Longest wait from "frame due" to commit \|	53		\| `max_commit_delay_ms` \| Longest wait from "frame due" to commit \|
54	\| `late_fences` \| Missed vblanks where the GPU finished too late (needs `--debug=drm-flip`) \|	54		\| `late_fences` \| Missed vblanks where the GPU finished too late (needs `--debug=drm-flip`) \|
55	\| `redrawn_pixels` \| Pixels drawn \|	55		\| `redrawn_pixels` \| Pixels drawn \|
		56	+	\| `merged_flips` \| Flips merged because wayland was not reading output reports \|
56		57
57	Missed vblanks with `late_fences` mean the GPU was late. Without `late_fences` but with a large `max_commit_delay_ms`, the CPU was late.	58		Missed vblanks with `late_fences` mean the GPU was late. Without `late_fences` but with a large `max_commit_delay_ms`, the CPU was late.

M internal/adapters/drm/output.go +6 -2


@@ -156,7 +156,10 @@ type Output struct {
156	156		traceFlips bool
157	157		lastFlipAt time.Duration
158	158		flipStats flipStats
159		-	wantedAt time.Duration
	159	+	// mergedFlips counts flips merged because wayland was not reading
	160	+	// reports, reported and reset with the periodic stats.
	161	+	mergedFlips int
	162	+	wantedAt time.Duration
160	163		// vrrFlipGap is the minimum time between a game frame's flip event
161	164		// and the next frame commit under VRR (render.vrr-flip-gap, 0: off);
162	165		// flipGapUntil is when the next frame may commit: the gap from the

@@ -1454,7 +1457,8 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
1454	1457		fs := o.takeFlipStats()
1455	1458		ev = ev.Int("missed_vblanks", fs.missedVblanks).Float64("max_flip_interval_ms", ms(fs.maxInterval))
1456	1459		ev = ev.Float64("max_commit_delay_ms", ms(fs.maxCommitDelay)).Float64("max_flip_to_read_ms", ms(fs.maxFlipToRead))
1457		-	ev = ev.Int("redrawn_pixels", r.TakeRedrawn())
	1460	+	ev = ev.Int("redrawn_pixels", r.TakeRedrawn()).Int("merged_flips", o.mergedFlips)
	1461	+	o.mergedFlips = 0
1458	1462		if o.traceFlips {
1459	1463		ev = ev.Int("late_fences", fs.lateFences)
1460	1464		}

 	traceFlips bool
 	lastFlipAt time.Duration
 	flipStats  flipStats
-	wantedAt   time.Duration
+	// mergedFlips counts flips merged because wayland was not reading
+	// reports, reported and reset with the periodic stats.
+	mergedFlips int
+	wantedAt    time.Duration
 	// vrrFlipGap is the minimum time between a game frame's flip event
 	// and the next frame commit under VRR (render.vrr-flip-gap, 0: off);
 	// flipGapUntil is when the next frame may commit: the gap from the
 			fs := o.takeFlipStats()
 			ev = ev.Int("missed_vblanks", fs.missedVblanks).Float64("max_flip_interval_ms", ms(fs.maxInterval))
 			ev = ev.Float64("max_commit_delay_ms", ms(fs.maxCommitDelay)).Float64("max_flip_to_read_ms", ms(fs.maxFlipToRead))
-			ev = ev.Int("redrawn_pixels", r.TakeRedrawn())
+			ev = ev.Int("redrawn_pixels", r.TakeRedrawn()).Int("merged_flips", o.mergedFlips)
+			o.mergedFlips = 0
 			if o.traceFlips {
 				ev = ev.Int("late_fences", fs.lateFences)
 			}

M internal/adapters/drm/output_test.go +3 -2


@@ -743,6 +743,7 @@ func TestRunTrimsRendererOnStatsTick(t *testing.T) {
743	743		var statsLog bytes.Buffer // written by Run's goroutine, read after it ends
744	744		o.log = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &statsLog})
745	745		o.flipStats = flipStats{missedVblanks: 3, maxInterval: 50 * time.Millisecond, maxFlipToRead: 25 * time.Millisecond, lateFences: 2}
	746	+	o.mergedFlips = 4
746	747		trimmed := make(chan struct{}, 2)
747	748		failure := os.ErrInvalid
748	749		calls := 0 // Run's goroutine only

@@ -769,12 +770,12 @@ func TestRunTrimsRendererOnStatsTick(t *testing.T) {
769	770		t.Fatalf("run: %v", err)
770	771		}
771	772		// Reported once, then reset. late_fences needs flip tracing.
772		-	for _, want := range []string{`"message":"stats"`, `"missed_vblanks":3`, `"max_flip_interval_ms":50`, `"max_flip_to_read_ms":25`, `"redrawn_pixels":1234`} {
	773	+	for _, want := range []string{`"message":"stats"`, `"missed_vblanks":3`, `"max_flip_interval_ms":50`, `"max_flip_to_read_ms":25`, `"redrawn_pixels":1234`, `"merged_flips":4`} {
773	774		if !strings.Contains(statsLog.String(), want) {
774	775		t.Fatalf("stats entry lacks %s: %s", want, statsLog.String())
775	776		}
776	777		}
777		-	if strings.Contains(statsLog.String(), "late_fences") \|\| o.flipStats != (flipStats{}) {
	778	+	if strings.Contains(statsLog.String(), "late_fences") \|\| o.flipStats != (flipStats{}) \|\| o.mergedFlips != 0 {
778	779		t.Fatalf("late fences untraced or stats not reset: %s %+v", statsLog.String(), o.flipStats)
779	780		}
780	781		}

 	var statsLog bytes.Buffer // written by Run's goroutine, read after it ends
 	o.log = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &statsLog})
 	o.flipStats = flipStats{missedVblanks: 3, maxInterval: 50 * time.Millisecond, maxFlipToRead: 25 * time.Millisecond, lateFences: 2}
+	o.mergedFlips = 4
 	trimmed := make(chan struct{}, 2)
 	failure := os.ErrInvalid
 	calls := 0 // Run's goroutine only
 		t.Fatalf("run: %v", err)
 	}
 	// Reported once, then reset. late_fences needs flip tracing.
-	for _, want := range []string{`"message":"stats"`, `"missed_vblanks":3`, `"max_flip_interval_ms":50`, `"max_flip_to_read_ms":25`, `"redrawn_pixels":1234`} {
+	for _, want := range []string{`"message":"stats"`, `"missed_vblanks":3`, `"max_flip_interval_ms":50`, `"max_flip_to_read_ms":25`, `"redrawn_pixels":1234`, `"merged_flips":4`} {
 		if !strings.Contains(statsLog.String(), want) {
 			t.Fatalf("stats entry lacks %s: %s", want, statsLog.String())
 		}
 	}
-	if strings.Contains(statsLog.String(), "late_fences") || o.flipStats != (flipStats{}) {
+	if strings.Contains(statsLog.String(), "late_fences") || o.flipStats != (flipStats{}) || o.mergedFlips != 0 {
 		t.Fatalf("late fences untraced or stats not reset: %s %+v", statsLog.String(), o.flipStats)
 	}
 }

M internal/adapters/drm/report.go +1 -0


@@ -18,6 +18,7 @@ func (o Output) report(flip ports.FlipInfo, seen map[ports.WindowID]uint64) {
18	18		seen, reads, o.capped = o.capHidden(seen)
19	19		}
20	20		if o.reports.Push(ports.OutputPresented{Output: o.conn.name, Flip: flip, Shown: o.shown, Queued: o.queued, Seen: seen, ChildReads: reads}) {
	21	+	o.mergedFlips++
21	22		o.log.Warn().Str("connector", o.conn.name).Msg("wayland is not reading output reports; flips merged")
22	23		}
23	24		}


@@ -18,6 +18,7 @@ func (o Output) report(flip ports.FlipInfo, seen map[ports.WindowID]uint64) {
18	seen, reads, o.capped = o.capHidden(seen)	18		seen, reads, o.capped = o.capHidden(seen)
19	}	19		}
20	if o.reports.Push(ports.OutputPresented{Output: o.conn.name, Flip: flip, Shown: o.shown, Queued: o.queued, Seen: seen, ChildReads: reads}) {	20		if o.reports.Push(ports.OutputPresented{Output: o.conn.name, Flip: flip, Shown: o.shown, Queued: o.queued, Seen: seen, ChildReads: reads}) {
		21	+	o.mergedFlips++
21	o.log.Warn().Str("connector", o.conn.name).Msg("wayland is not reading output reports; flips merged")	22		o.log.Warn().Str("connector", o.conn.name).Msg("wayland is not reading output reports; flips merged")
22	}	23		}
23	}	24		}

M internal/adapters/headless/output.go +18 -6


@@ -113,6 +113,8 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
113	113		seen := map[ports.WindowID]uint64{}
114	114		// reports holds what the channel could not take yet, retried soon.
115	115		var reports presented.Queue
	116	+	// mergedFlips counts flips merged since the last stats line.
	117	+	mergedFlips := 0
116	118		var security ports.SecurityState
117	119		securityKnown := false
118	120		failRequests := func(reason error) {

@@ -312,6 +314,8 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
312	314		if err := r.Trim(clk.Now()); err != nil {
313	315		return fmt.Errorf("trim renderer: %w", err)
314	316		}
	317	+	opts.Log.Info().Str("output", opts.Name).Int("frames", frame).Int("merged_flips", mergedFlips).Msg("stats")
	318	+	mergedFlips = 0
315	319		continue
316	320		case s, ok := <-scenes:
317	321		if !ok {

@@ -398,7 +402,9 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
398	402		if !haveScene \|\| !dirty \|\| scene.Off {
399	403		// Contents not drawn are still read: report them. An output
400	404		// turned off draws nothing.
401		-	opts.report(&reports, nil, seen)
	405	+	if opts.report(&reports, nil, seen) {
	406	+	mergedFlips++
	407	+	}
402	408		continue
403	409		}
404	410		dirty = false

@@ -447,7 +453,9 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
447	453		if opts.Presented != nil {
448	454		_, reads, _ := pipeline.CapHiddenSeen(seen)
449	455		if len(reads) > 0 {
450		-	reports.Push(ports.OutputPresented{Output: opts.Name, Seen: seen, ChildReads: reads})
	456	+	if reports.Push(ports.OutputPresented{Output: opts.Name, Seen: seen, ChildReads: reads}) {
	457	+	mergedFlips++
	458	+	}
451	459		if reports.Drain(ctx, opts.Presented) != nil {
452	460		return nil
453	461		}

@@ -546,7 +554,9 @@ func Run(ctx context.Context, opts Options, scenes <-chan ports.Scene, contents
546	554		pipeline.EndGate(nil)
547	555		requests.List = capture.Waiting(requests.List, scene)
548	556		frame++
549		-	opts.report(&reports, flipInfo(scene, drawn, table.Kept), seen)
	557	+	if opts.report(&reports, flipInfo(scene, drawn, table.Kept), seen) {
	558	+	mergedFlips++
	559	+	}
550	560		if opts.ScreenshotDir != "" && !opts.protected() {
551	561		shot := r.Pixels()
552	562		if opts.protected() \|\| opts.Security != nil && opts.Security.Snapshot() != scene.Security {

@@ -618,14 +628,16 @@ func writePNGSecure(path string, img image.Image, security ports.SessionSecurity
618	628
619	629		// report queues what the output read, with flip for a drawn frame, and
620	630		// sends what the channel takes now; the rest is retried soon.
621		-	func (opts Options) report(q presented.Queue, flip ports.FlipInfo, seen map[ports.WindowID]uint64) {
	631	+	// It reports whether a flip was merged because wayland was not reading.
	632	+	func (opts Options) report(q presented.Queue, flip ports.FlipInfo, seen map[ports.WindowID]uint64) (merged bool) {
622	633		if opts.Presented == nil {
623		-	return
	634	+	return false
624	635		}
625		-	if q.Push(ports.OutputPresented{Output: opts.Name, Flip: flip, Seen: seen}) {
	636	+	if merged = q.Push(ports.OutputPresented{Output: opts.Name, Flip: flip, Seen: seen}); merged {
626	637		opts.Log.Warn().Str("output", opts.Name).Msg("wayland is not reading output reports; flips merged")
627	638		}
628	639		q.Flush(opts.Presented)
	640	+	return merged
629	641		}
630	642
631	643		// flush retries reports the channel could not take.

 	seen := map[ports.WindowID]uint64{}
 	// reports holds what the channel could not take yet, retried soon.
 	var reports presented.Queue
+	// mergedFlips counts flips merged since the last stats line.
+	mergedFlips := 0
 	var security ports.SecurityState
 	securityKnown := false
 	failRequests := func(reason error) {
 			if err := r.Trim(clk.Now()); err != nil {
 				return fmt.Errorf("trim renderer: %w", err)
 			}
+			opts.Log.Info().Str("output", opts.Name).Int("frames", frame).Int("merged_flips", mergedFlips).Msg("stats")
+			mergedFlips = 0
 			continue
 		case s, ok := <-scenes:
 			if !ok {
 		if !haveScene || !dirty || scene.Off {
 			// Contents not drawn are still read: report them. An output
 			// turned off draws nothing.
-			opts.report(&reports, nil, seen)
+			if opts.report(&reports, nil, seen) {
+				mergedFlips++
+			}
 			continue
 		}
 		dirty = false
 			if opts.Presented != nil {
 				_, reads, _ := pipeline.CapHiddenSeen(seen)
 				if len(reads) > 0 {
-					reports.Push(ports.OutputPresented{Output: opts.Name, Seen: seen, ChildReads: reads})
+					if reports.Push(ports.OutputPresented{Output: opts.Name, Seen: seen, ChildReads: reads}) {
+						mergedFlips++
+					}
 					if reports.Drain(ctx, opts.Presented) != nil {
 						return nil
 					}
 		pipeline.EndGate(nil)
 		requests.List = capture.Waiting(requests.List, scene)
 		frame++
-		opts.report(&reports, flipInfo(scene, drawn, table.Kept), seen)
+		if opts.report(&reports, flipInfo(scene, drawn, table.Kept), seen) {
+			mergedFlips++
+		}
 		if opts.ScreenshotDir != "" && !opts.protected() {
 			shot := r.Pixels()
 			if opts.protected() || opts.Security != nil && opts.Security.Snapshot() != scene.Security {
 // report queues what the output read, with flip for a drawn frame, and
 // sends what the channel takes now; the rest is retried soon.
-func (opts Options) report(q *presented.Queue, flip *ports.FlipInfo, seen map[ports.WindowID]uint64) {
+// It reports whether a flip was merged because wayland was not reading.
+func (opts Options) report(q *presented.Queue, flip *ports.FlipInfo, seen map[ports.WindowID]uint64) (merged bool) {
 	if opts.Presented == nil {
-		return
+		return false
 	}
-	if q.Push(ports.OutputPresented{Output: opts.Name, Flip: flip, Seen: seen}) {
+	if merged = q.Push(ports.OutputPresented{Output: opts.Name, Flip: flip, Seen: seen}); merged {
 		opts.Log.Warn().Str("output", opts.Name).Msg("wayland is not reading output reports; flips merged")
 	}
 	q.Flush(opts.Presented)
+	return merged
 }
 // flush retries reports the channel could not take.

M internal/adapters/headless/output_test.go +15 -1

@@ -1,6 +1,7 @@
1	1		package headless
2	2
3	3		import (
	4	+	"bytes"
4	5		"context"
5	6		"errors"
6	7		"image"

@@ -9,6 +10,7 @@ import (
9	10		"maps"
10	11		"os"
11	12		"path/filepath"
	13	+	"strings"
12	14		"sync"
13	15		"testing"
14	16		"time"

@@ -16,6 +18,7 @@ import (
16	18		"github.com/bnema/neferwl/internal/adapters/logging"
17	19		portsmocks "github.com/bnema/neferwl/internal/mocks/ports"
18	20		"github.com/bnema/neferwl/internal/ports"
	21	+	"github.com/bnema/zerowrap"
19	22		"github.com/stretchr/testify/mock"
20	23		)
21	24

@@ -214,8 +217,10 @@ func TestRunTrimsRendererOnTick(t *testing.T) {
214	217		return nil
215	218		}).Twice()
216	219		done := make(chan error, 1)
	220	+	var statsLog bytes.Buffer // written by Run's goroutine, read after it ends
	221	+	log := zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &statsLog})
217	222		go func() {
218		-	done <- Run(context.Background(), Options{Width: 2, Height: 2, Clock: clk, NewRenderer: func(int, int) (ports.Renderer, error) { return r, nil }}, nil, nil, nil, nil)
	223	+	done <- Run(context.Background(), Options{Width: 2, Height: 2, Clock: clk, Log: log, Name: "HEADLESS-1", NewRenderer: func(int, int) (ports.Renderer, error) { return r, nil }}, nil, nil, nil, nil)
219	224		}()
220	225		ticks <- now
221	226		if got := <-trimmed; !got.Equal(now) {

@@ -228,6 +233,15 @@ func TestRunTrimsRendererOnTick(t *testing.T) {
228	233		if s, _ := f.snapshot(); len(s) != 0 {
229	234		t.Fatalf("%d frames for a trim", len(s))
230	235		}
	236	+	// A trim tick that succeeded logs the periodic stats once.
	237	+	if got := strings.Count(statsLog.String(), `"message":"stats"`); got != 1 {
	238	+	t.Fatalf("%d stats entries: %s", got, statsLog.String())
	239	+	}
	240	+	for _, want := range []string{`"output":"HEADLESS-1"`, `"frames":0`, `"merged_flips":0`} {
	241	+	if !strings.Contains(statsLog.String(), want) {
	242	+	t.Fatalf("stats entry lacks %s: %s", want, statsLog.String())
	243	+	}
	244	+	}
231	245		}
232	246
233	247		func TestWritePNGAtomic(t *testing.T) {

 package headless
 import (
+	"bytes"
 	"context"
 	"errors"
 	"image"
 	"maps"
 	"os"
 	"path/filepath"
+	"strings"
 	"sync"
 	"testing"
 	"time"
 	"github.com/bnema/neferwl/internal/adapters/logging"
 	portsmocks "github.com/bnema/neferwl/internal/mocks/ports"
 	"github.com/bnema/neferwl/internal/ports"
+	"github.com/bnema/zerowrap"
 	"github.com/stretchr/testify/mock"
 )
 		return nil
 	}).Twice()
 	done := make(chan error, 1)
+	var statsLog bytes.Buffer // written by Run's goroutine, read after it ends
+	log := zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &statsLog})
 	go func() {
-		done <- Run(context.Background(), Options{Width: 2, Height: 2, Clock: clk, NewRenderer: func(int, int) (ports.Renderer, error) { return r, nil }}, nil, nil, nil, nil)
+		done <- Run(context.Background(), Options{Width: 2, Height: 2, Clock: clk, Log: log, Name: "HEADLESS-1", NewRenderer: func(int, int) (ports.Renderer, error) { return r, nil }}, nil, nil, nil, nil)
 	}()
 	ticks <- now
 	if got := <-trimmed; !got.Equal(now) {
 	if s, _ := f.snapshot(); len(s) != 0 {
 		t.Fatalf("%d frames for a trim", len(s))
 	}
+	// A trim tick that succeeded logs the periodic stats once.
+	if got := strings.Count(statsLog.String(), `"message":"stats"`); got != 1 {
+		t.Fatalf("%d stats entries: %s", got, statsLog.String())
+	}
+	for _, want := range []string{`"output":"HEADLESS-1"`, `"frames":0`, `"merged_flips":0`} {
+		if !strings.Contains(statsLog.String(), want) {
+			t.Fatalf("stats entry lacks %s: %s", want, statsLog.String())
+		}
+	}
 }
 func TestWritePNGAtomic(t *testing.T) {