feat(drm): report missed vblanks and flip delivery latency in output stats (#119)

* feat(ports): expose the pixels a renderer redrew since the last call

* feat(drm): report missed vblanks and flip delivery latency in output stats

* fix(drm): ignore idle gaps and normal fences in flip stats

* fix(drm): gate flip stats on when the frame was due

* fix(drm): exclude the VRR flip gap from commit delay

* refactor(drm): measure the VRR flip gap from the flip timestamp

commit: 41067c7814cf2ba31f2c0a37e6fa372f6366a666
author: bnema · 19d ago · 2026-10-03 19:46 UTC
committer: GitHub · 19d ago · 2026-10-03 19:46 UTC
parent: 6f4012a
signature: GPG UnverifiedB5690EEEBB952194 The key is unknown

15 files · +674 -38

M Makefile +1 -1


@@ -54,7 +54,7 @@ arch:
54	54		$(HOME)/go/bin/hexcheck -hexcheck.config .hexcheck.yaml -hexcheck.root . ./...
55	55		# Fast, mandatory guards for tiled content publications and SHM copies.
56	56		perf-check:
57		-	CGO_ENABLED=0 go test ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestOutputRoutingAllocations\|TestReportSeenAllocations\|TestFrameLifecycleTransitionsAllocations\|TestFullscreenShownAllocations\|TestFrameDecisionAllocations\|TestShownBySnapshotAllocations\|TestDueFramesAllocations\|TestRenderSteadyStateAllocations\|TestSceneWalkUnchangedTiledSHM\|TestTiledCommitPublishAllocations\|TestCapturedCommitApplyAllocations\|TestCapturedViewportApplyAllocations\|TestEffectiveInputEmptyTreeAllocations\|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1
	57	+	CGO_ENABLED=0 go test ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestOutputRoutingAllocations\|TestReportSeenAllocations\|TestFrameLifecycleTransitionsAllocations\|TestFullscreenShownAllocations\|TestFrameDecisionAllocations\|TestShownBySnapshotAllocations\|TestDueFramesAllocations\|TestRenderSteadyStateAllocations\|TestAccountFlipAllocations\|TestFlipDoneAllocations\|TestSceneWalkUnchangedTiledSHM\|TestTiledCommitPublishAllocations\|TestCapturedCommitApplyAllocations\|TestCapturedViewportApplyAllocations\|TestEffectiveInputEmptyTreeAllocations\|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1
58	58		check: vet test arch fakes-check perf-check
59	59
60	60		# Arch package of the committed HEAD (packaging/arch/PKGBUILD). Go modules


@@ -54,7 +54,7 @@ arch:
54		$(HOME)/go/bin/hexcheck -hexcheck.config .hexcheck.yaml -hexcheck.root . ./...	54		$(HOME)/go/bin/hexcheck -hexcheck.config .hexcheck.yaml -hexcheck.root . ./...
55		# Fast, mandatory guards for tiled content publications and SHM copies.	55		# Fast, mandatory guards for tiled content publications and SHM copies.
56		perf-check:	56		perf-check:
57	-	CGO_ENABLED=0 go test ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestOutputRoutingAllocations\|TestReportSeenAllocations\|TestFrameLifecycleTransitionsAllocations\|TestFullscreenShownAllocations\|TestFrameDecisionAllocations\|TestShownBySnapshotAllocations\|TestDueFramesAllocations\|TestRenderSteadyStateAllocations\|TestSceneWalkUnchangedTiledSHM\|TestTiledCommitPublishAllocations\|TestCapturedCommitApplyAllocations\|TestCapturedViewportApplyAllocations\|TestEffectiveInputEmptyTreeAllocations\|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1	57	+	CGO_ENABLED=0 go test ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestOutputRoutingAllocations\|TestReportSeenAllocations\|TestFrameLifecycleTransitionsAllocations\|TestFullscreenShownAllocations\|TestFrameDecisionAllocations\|TestShownBySnapshotAllocations\|TestDueFramesAllocations\|TestRenderSteadyStateAllocations\|TestAccountFlipAllocations\|TestFlipDoneAllocations\|TestSceneWalkUnchangedTiledSHM\|TestTiledCommitPublishAllocations\|TestCapturedCommitApplyAllocations\|TestCapturedViewportApplyAllocations\|TestEffectiveInputEmptyTreeAllocations\|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1
58		check: vet test arch fakes-check perf-check	58		check: vet test arch fakes-check perf-check
59			59
60		# Arch package of the committed HEAD (packaging/arch/PKGBUILD). Go modules	60		# Arch package of the committed HEAD (packaging/arch/PKGBUILD). Go modules

M docs/performance.md +12 -1


@@ -38,7 +38,18 @@ GODEBUG=gctrace=1 neferwl --backend=drm
38	38
39	39		`make tty` enables it on `localhost:6060` (`make tty PPROF=` disables it). `--pprof` also serves `/debug/pprof/profile` (CPU) and `/debug/pprof/trace` (scheduler and GC timeline for `go tool trace`). Escape analysis (`go build -gcflags=-m ./internal/adapters/vulkan`) shows why a value reaches the heap.
40	40
41		-	`slow flip` log entries (flip over 20 ms) carry `frame` (false: cursor or VRR state commit) and `vrr`; `input stats` shows coalesced pointer motion and the longest wait for core.
	41	+	Each output's `stats` entry (every 10 s) counts what happened since the previous one, from the kernel's flip timestamps, and starts over:
	42	+
	43	+	- `missed_vblanks`: frame flips that came over 1.5 refresh periods after the previous frame flip. An output renders only on change, so only a frame that was due counts: one wanted (a scene, content or capture change made it dirty) before, or less than one period after, the previous flip, so it was meant for the next vblank even if it was committed late. A frame wanted after an idle period is ignored. Not counted under VRR, where the period is not fixed.
	44	+	- `max_flip_interval_ms`: the longest interval between two flips of due frames (also under VRR, where the gate uses the mode's refresh period, the shortest one). The chain restarts after a modeset or a VRR change.
	45	+	- `max_commit_delay_ms`: for due frames, the longest time from when the frame was due (wanted, and not before the previous flip or the end of the deliberate `render.vrr-flip-gap`) to its commit. It is large when the commit came late: the previous flip's event was read late, or the CPU side of the composition was slow.
	46	+	- `max_flip_to_read_ms`: the longest time between a flip's kernel timestamp and the output goroutine handling its event, for the output's own commits.
	47	+	- `late_fences` (only with `--debug=drm-flip`, which reads the fence times): missed vblanks whose composition fence signalled after the vblank the frame targeted (the previous flip plus one period), so the GPU was not done in time. Not counted under VRR.
	48	+	- `redrawn_pixels`: target pixels the renderer drew; a damage-limited frame counts its damage, not the whole target.
	49	+
	50	+	Reading them together: missed vblanks with `late_fences` are a late GPU composition. Missed vblanks without late fences and with a large `max_commit_delay_ms` (usually next to a large `max_flip_to_read_ms`) are a late commit: the event reader or the CPU. Few `missed_vblanks` mean flips were on time only if `max_commit_delay_ms` is also small: a delayed commit can still make its vblank, and `max_flip_to_read_ms` alone says the event arrived late, not that the flip did.
	51	+
	52	+	`input stats` shows coalesced pointer motion and the longest wait for core.
42	53
43	54		`--debug=drm-flip` (or `make tty TTY_DEBUG=drm-flip`) logs every commit completion as a `flip` entry: `commit_to_flip_ms`, `flip_interval_ms` (between frame flips), `fence_ready_at_commit`, and, when the client fence reports its signal time, `commit_to_fence_ms` and `fence_to_flip_ms`. A negative `commit_to_fence_ms` means the client finished before the commit.
44	55


@@ -38,7 +38,18 @@ GODEBUG=gctrace=1 neferwl --backend=drm
38			38
39		`make tty` enables it on `localhost:6060` (`make tty PPROF=` disables it). `--pprof` also serves `/debug/pprof/profile` (CPU) and `/debug/pprof/trace` (scheduler and GC timeline for `go tool trace`). Escape analysis (`go build -gcflags=-m ./internal/adapters/vulkan`) shows why a value reaches the heap.	39		`make tty` enables it on `localhost:6060` (`make tty PPROF=` disables it). `--pprof` also serves `/debug/pprof/profile` (CPU) and `/debug/pprof/trace` (scheduler and GC timeline for `go tool trace`). Escape analysis (`go build -gcflags=-m ./internal/adapters/vulkan`) shows why a value reaches the heap.
40			40
41	-	`slow flip` log entries (flip over 20 ms) carry `frame` (false: cursor or VRR state commit) and `vrr`; `input stats` shows coalesced pointer motion and the longest wait for core.	41	+	Each output's `stats` entry (every 10 s) counts what happened since the previous one, from the kernel's flip timestamps, and starts over:
			42	+
			43	+	- `missed_vblanks`: frame flips that came over 1.5 refresh periods after the previous frame flip. An output renders only on change, so only a frame that was due counts: one wanted (a scene, content or capture change made it dirty) before, or less than one period after, the previous flip, so it was meant for the next vblank even if it was committed late. A frame wanted after an idle period is ignored. Not counted under VRR, where the period is not fixed.
			44	+	- `max_flip_interval_ms`: the longest interval between two flips of due frames (also under VRR, where the gate uses the mode's refresh period, the shortest one). The chain restarts after a modeset or a VRR change.
			45	+	- `max_commit_delay_ms`: for due frames, the longest time from when the frame was due (wanted, and not before the previous flip or the end of the deliberate `render.vrr-flip-gap`) to its commit. It is large when the commit came late: the previous flip's event was read late, or the CPU side of the composition was slow.
			46	+	- `max_flip_to_read_ms`: the longest time between a flip's kernel timestamp and the output goroutine handling its event, for the output's own commits.
			47	+	- `late_fences` (only with `--debug=drm-flip`, which reads the fence times): missed vblanks whose composition fence signalled after the vblank the frame targeted (the previous flip plus one period), so the GPU was not done in time. Not counted under VRR.
			48	+	- `redrawn_pixels`: target pixels the renderer drew; a damage-limited frame counts its damage, not the whole target.
			49	+
			50	+	Reading them together: missed vblanks with `late_fences` are a late GPU composition. Missed vblanks without late fences and with a large `max_commit_delay_ms` (usually next to a large `max_flip_to_read_ms`) are a late commit: the event reader or the CPU. Few `missed_vblanks` mean flips were on time only if `max_commit_delay_ms` is also small: a delayed commit can still make its vblank, and `max_flip_to_read_ms` alone says the event arrived late, not that the flip did.
			51	+
			52	+	`input stats` shows coalesced pointer motion and the longest wait for core.
42			53
43		`--debug=drm-flip` (or `make tty TTY_DEBUG=drm-flip`) logs every commit completion as a `flip` entry: `commit_to_flip_ms`, `flip_interval_ms` (between frame flips), `fence_ready_at_commit`, and, when the client fence reports its signal time, `commit_to_fence_ms` and `fence_to_flip_ms`. A negative `commit_to_fence_ms` means the client finished before the commit.	54		`--debug=drm-flip` (or `make tty TTY_DEBUG=drm-flip`) logs every commit completion as a `flip` entry: `commit_to_flip_ms`, `flip_interval_ms` (between frame flips), `fence_ready_at_commit`, and, when the client fence reports its signal time, `commit_to_fence_ms` and `fence_to_flip_ms`. A negative `commit_to_fence_ms` means the client finished before the commit.
44			55

A internal/adapters/drm/flip_stats.go +110 -0

@@ -0,0 +1,110 @@
	1	+	package drm
	2	+
	3	+	import "time"
	4	+
	5	+	// flipStats are the flip timing counters of one output, reported and
	6	+	// reset by the periodic stats entry. They are plain fields owned by the
	7	+	// output goroutine. All times are CLOCK_MONOTONIC (kernel flip
	8	+	// timestamps and userspace reads), so they tell a late composition from a
	9	+	// late read of the event (see accountFlip).
	10	+	type flipStats struct {
	11	+	// missedVblanks counts due frame flips whose kernel timestamp is over
	12	+	// 1.5 refresh periods after the previous frame flip (never under VRR,
	13	+	// where the period is not fixed).
	14	+	missedVblanks int
	15	+	// maxInterval is the longest time between two frame flips, of the
	16	+	// frames that were due.
	17	+	maxInterval time.Duration
	18	+	// maxCommitDelay is the longest time a due frame waited between the
	19	+	// moment it was due (wanted, the previous flip landed, or the VRR
	20	+	// flip gap ended) and its commit: late event read, slow composition.
	21	+	maxCommitDelay time.Duration
	22	+	// maxFlipToRead is the longest time between a flip's kernel timestamp
	23	+	// and the output reading its event: the event delivery latency.
	24	+	maxFlipToRead time.Duration
	25	+	// lateFences counts missed vblanks whose fences signalled after the
	26	+	// vblank the frame targeted (never under VRR). Fence times are only
	27	+	// read while flip tracing is on.
	28	+	lateFences int
	29	+	}
	30	+
	31	+	// nominalPeriod is the time between two vblanks at the mode's refresh
	32	+	// rate. Under VRR it is the shortest period: the fastest the output
	33	+	// flips.
	34	+	func (o *Output) nominalPeriod() time.Duration {
	35	+	return time.Duration(int64(time.Second) * 1000 / int64(max(1, o.mode.refreshMilli())))
	36	+	}
	37	+
	38	+	// refreshPeriod is the time between two vblanks of the current mode (0:
	39	+	// not fixed, VRR).
	40	+	func (o *Output) refreshPeriod() time.Duration {
	41	+	if o.vrrOn {
	42	+	return 0
	43	+	}
	44	+	return o.nominalPeriod()
	45	+	}
	46	+
	47	+	// setVRR records the VRR state. The flip interval chain restarts when it
	48	+	// changes: the period of the two states differs.
	49	+	func (o *Output) setVRR(on bool) {
	50	+	if o.vrrOn != on {
	51	+	o.lastFlipAt = 0
	52	+	}
	53	+	o.vrrOn = on
	54	+	}
	55	+
	56	+	// accountFlip counts the completion ev of a frame commit made at
	57	+	// commitAt for a frame due at wantedAt (0: unknown, the commit time; see
	58	+	// pendingFrame.dueAt). All times are CLOCK_MONOTONIC. fenceAt is when the
	59	+	// commit's fences signalled (0: none or unknown). It updates lastFlipAt
	60	+	// for frame flips and never allocates.
	61	+	//
	62	+	// An output renders only on change, so a gap after an idle period says
	63	+	// nothing about missed vblanks. The interval to the previous flip counts
	64	+	// only for a frame that was due: wanted less than one period after the
	65	+	// previous flip, so it was meant for the very next vblank, whenever it was
	66	+	// committed. A frame that waited for the previous flip's event or for its
	67	+	// composition is due as soon as it is wanted. Then:
	68	+	//
	69	+	// - a flip over 1.5 periods after the previous one missed a vblank
	70	+	// (never counted under VRR, where the period is not fixed);
	71	+	// - if it missed one and its fences signalled after the vblank it
	72	+	// targeted (the previous flip plus one period), the frame was late: a
	73	+	// late fence. A fence before that vblank is not;
	74	+	// - the commit delay is the time from when the frame was due (wanted,
	75	+	// and not before the previous flip) to its commit. A missed vblank
	76	+	// with a long commit delay and no late fence points at the commit
	77	+	// path: late event read, slow composition on the CPU.
	78	+	func (o *Output) accountFlip(ev flipEvent, frame bool, wantedAt, commitAt, fenceAt time.Duration) {
	79	+	if !frame {
	80	+	return
	81	+	}
	82	+	if wantedAt == 0 {
	83	+	wantedAt = commitAt
	84	+	}
	85	+	if prev := o.lastFlipAt; prev != 0 && wantedAt-prev < o.nominalPeriod() {
	86	+	s := &o.flipStats
	87	+	interval := ev.when - prev
	88	+	s.maxInterval = max(s.maxInterval, interval)
	89	+	s.maxCommitDelay = max(s.maxCommitDelay, commitAt-max(wantedAt, prev))
	90	+	if period := o.refreshPeriod(); period != 0 && 2interval > 3period {
	91	+	s.missedVblanks++
	92	+	if fenceAt != 0 && fenceAt > prev+period {
	93	+	s.lateFences++
	94	+	}
	95	+	}
	96	+	}
	97	+	o.lastFlipAt = ev.when
	98	+	}
	99	+
	100	+	// accountRead tracks the delivery latency of the event ev handled at now.
	101	+	func (o *Output) accountRead(ev flipEvent, now time.Duration) {
	102	+	o.flipStats.maxFlipToRead = max(o.flipStats.maxFlipToRead, now-ev.when)
	103	+	}
	104	+
	105	+	// takeFlipStats returns the counters and starts over.
	106	+	func (o *Output) takeFlipStats() flipStats {
	107	+	s := o.flipStats
	108	+	o.flipStats = flipStats{}
	109	+	return s
	110	+	}

@@ -0,0 +1,110 @@
	1	+	package drm
	2	+
	3	+	import "time"
	4	+
	5	+	// flipStats are the flip timing counters of one output, reported and
	6	+	// reset by the periodic stats entry. They are plain fields owned by the
	7	+	// output goroutine. All times are CLOCK_MONOTONIC (kernel flip
	8	+	// timestamps and userspace reads), so they tell a late composition from a
	9	+	// late read of the event (see accountFlip).
	10	+	type flipStats struct {
	11	+	// missedVblanks counts due frame flips whose kernel timestamp is over
	12	+	// 1.5 refresh periods after the previous frame flip (never under VRR,
	13	+	// where the period is not fixed).
	14	+	missedVblanks int
	15	+	// maxInterval is the longest time between two frame flips, of the
	16	+	// frames that were due.
	17	+	maxInterval time.Duration
	18	+	// maxCommitDelay is the longest time a due frame waited between the
	19	+	// moment it was due (wanted, the previous flip landed, or the VRR
	20	+	// flip gap ended) and its commit: late event read, slow composition.
	21	+	maxCommitDelay time.Duration
	22	+	// maxFlipToRead is the longest time between a flip's kernel timestamp
	23	+	// and the output reading its event: the event delivery latency.
	24	+	maxFlipToRead time.Duration
	25	+	// lateFences counts missed vblanks whose fences signalled after the
	26	+	// vblank the frame targeted (never under VRR). Fence times are only
	27	+	// read while flip tracing is on.
	28	+	lateFences int
	29	+	}
	30	+
	31	+	// nominalPeriod is the time between two vblanks at the mode's refresh
	32	+	// rate. Under VRR it is the shortest period: the fastest the output
	33	+	// flips.
	34	+	func (o *Output) nominalPeriod() time.Duration {
	35	+	return time.Duration(int64(time.Second) * 1000 / int64(max(1, o.mode.refreshMilli())))
	36	+	}
	37	+
	38	+	// refreshPeriod is the time between two vblanks of the current mode (0:
	39	+	// not fixed, VRR).
	40	+	func (o *Output) refreshPeriod() time.Duration {
	41	+	if o.vrrOn {
	42	+	return 0
	43	+	}
	44	+	return o.nominalPeriod()
	45	+	}
	46	+
	47	+	// setVRR records the VRR state. The flip interval chain restarts when it
	48	+	// changes: the period of the two states differs.
	49	+	func (o *Output) setVRR(on bool) {
	50	+	if o.vrrOn != on {
	51	+	o.lastFlipAt = 0
	52	+	}
	53	+	o.vrrOn = on
	54	+	}
	55	+
	56	+	// accountFlip counts the completion ev of a frame commit made at
	57	+	// commitAt for a frame due at wantedAt (0: unknown, the commit time; see
	58	+	// pendingFrame.dueAt). All times are CLOCK_MONOTONIC. fenceAt is when the
	59	+	// commit's fences signalled (0: none or unknown). It updates lastFlipAt
	60	+	// for frame flips and never allocates.
	61	+	//
	62	+	// An output renders only on change, so a gap after an idle period says
	63	+	// nothing about missed vblanks. The interval to the previous flip counts
	64	+	// only for a frame that was due: wanted less than one period after the
	65	+	// previous flip, so it was meant for the very next vblank, whenever it was
	66	+	// committed. A frame that waited for the previous flip's event or for its
	67	+	// composition is due as soon as it is wanted. Then:
	68	+	//
	69	+	// - a flip over 1.5 periods after the previous one missed a vblank
	70	+	// (never counted under VRR, where the period is not fixed);
	71	+	// - if it missed one and its fences signalled after the vblank it
	72	+	// targeted (the previous flip plus one period), the frame was late: a
	73	+	// late fence. A fence before that vblank is not;
	74	+	// - the commit delay is the time from when the frame was due (wanted,
	75	+	// and not before the previous flip) to its commit. A missed vblank
	76	+	// with a long commit delay and no late fence points at the commit
	77	+	// path: late event read, slow composition on the CPU.
	78	+	func (o *Output) accountFlip(ev flipEvent, frame bool, wantedAt, commitAt, fenceAt time.Duration) {
	79	+	if !frame {
	80	+	return
	81	+	}
	82	+	if wantedAt == 0 {
	83	+	wantedAt = commitAt
	84	+	}
	85	+	if prev := o.lastFlipAt; prev != 0 && wantedAt-prev < o.nominalPeriod() {
	86	+	s := &o.flipStats
	87	+	interval := ev.when - prev
	88	+	s.maxInterval = max(s.maxInterval, interval)
	89	+	s.maxCommitDelay = max(s.maxCommitDelay, commitAt-max(wantedAt, prev))
	90	+	if period := o.refreshPeriod(); period != 0 && 2interval > 3period {
	91	+	s.missedVblanks++
	92	+	if fenceAt != 0 && fenceAt > prev+period {
	93	+	s.lateFences++
	94	+	}
	95	+	}
	96	+	}
	97	+	o.lastFlipAt = ev.when
	98	+	}
	99	+
	100	+	// accountRead tracks the delivery latency of the event ev handled at now.
	101	+	func (o *Output) accountRead(ev flipEvent, now time.Duration) {
	102	+	o.flipStats.maxFlipToRead = max(o.flipStats.maxFlipToRead, now-ev.when)
	103	+	}
	104	+
	105	+	// takeFlipStats returns the counters and starts over.
	106	+	func (o *Output) takeFlipStats() flipStats {
	107	+	s := o.flipStats
	108	+	o.flipStats = flipStats{}
	109	+	return s
	110	+	}

A internal/adapters/drm/flip_stats_test.go +272 -0

@@ -0,0 +1,272 @@
	1	+	package drm
	2	+
	3	+	import (
	4	+	"bytes"
	5	+	"strings"
	6	+	"testing"
	7	+	"time"
	8	+
	9	+	"github.com/bnema/neferwl/internal/ports"
	10	+	"github.com/bnema/zerowrap"
	11	+	)
	12	+
	13	+	const period60 = 16_666_666 * time.Nanosecond // modeInfo{VRefresh: 60}
	14	+
	15	+	func flipAt(when time.Duration) flipEvent { return flipEvent{when: when} }
	16	+
	17	+	// p is the refresh period of the test output's 60 Hz mode.
	18	+	const p = period60
	19	+
	20	+	// The gate and the counters of accountFlip, one flip after a frame flip at
	21	+	// prev (1 s). due is the frame's due time: the later of wanted and gapEnd
	22	+	// (see pendingFrame.dueAt; both 0: the commit time).
	23	+	func TestAccountFlip(t *testing.T) {
	24	+	const prev = time.Second
	25	+	for _, tc := range []struct {
	26	+	name string
	27	+	vrr bool
	28	+	prev time.Duration // 0: no previous flip
	29	+	wanted, gapEnd time.Duration
	30	+	commit, when, fence time.Duration
	31	+	want flipStats
	32	+	wantLast time.Duration
	33	+	}{
	34	+	{name: "first flip has no interval", prev: 0, wanted: prev, commit: prev, when: prev + p, want: flipStats{}, wantLast: prev + p},
	35	+	{name: "on time", prev: prev, wanted: prev + p/4, commit: prev + p/2, when: prev + p, want: flipStats{maxInterval: p, maxCommitDelay: p/2 - p/4}},
	36	+	{name: "unknown wanted time", prev: prev, commit: prev + p/2, when: prev + p, want: flipStats{maxInterval: p}},
	37	+	{name: "just under 1.5 periods", prev: prev, wanted: prev, commit: prev + p/2, when: prev + p3/2 - 1, want: flipStats{maxInterval: p3/2 - 1, maxCommitDelay: p / 2}},
	38	+	{name: "two periods is a missed vblank", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2p, want: flipStats{missedVblanks: 1, maxInterval: 2 p, maxCommitDelay: p / 2}},
	39	+	{name: "idle gap is not counted", prev: prev, wanted: prev + time.Second, commit: prev + time.Second + p/2, when: prev + time.Second + p, want: flipStats{}},
	40	+	{name: "wanted one period after: not due", prev: prev, wanted: prev + p, commit: prev + p + p/2, when: prev + 5*p, want: flipStats{}},
	41	+	{name: "wanted just before one period: due", prev: prev, wanted: prev + p - 1, commit: prev + p + p/2, when: prev + 4p, want: flipStats{missedVblanks: 1, maxInterval: 4 p, maxCommitDelay: p/2 + 1}},
	42	+	{name: "delayed commit, wanted before the previous flip", prev: prev, wanted: prev - p/2, commit: prev + p + p/5, when: prev + 2*p, fence: prev + p/2,
	43	+	want: flipStats{missedVblanks: 1, maxInterval: 2 * p, maxCommitDelay: p + p/5}},
	44	+	{name: "normal frame: fence before its flip", prev: prev, wanted: prev + p/4, commit: prev + p/2, when: prev + p, fence: prev + p - 1,
	45	+	want: flipStats{maxInterval: p, maxCommitDelay: p/2 - p/4}},
	46	+	{name: "missed, fence unknown", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2p, want: flipStats{missedVblanks: 1, maxInterval: 2 p, maxCommitDelay: p / 2}},
	47	+	{name: "missed, fence at the targeted vblank", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2*p, fence: prev + p,
	48	+	want: flipStats{missedVblanks: 1, maxInterval: 2 * p, maxCommitDelay: p / 2}},
	49	+	{name: "missed, fence after the targeted vblank", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2*p, fence: prev + p + 1,
	50	+	want: flipStats{missedVblanks: 1, lateFences: 1, maxInterval: 2 * p, maxCommitDelay: p / 2}},
	51	+	{name: "VRR idle gap", vrr: true, prev: prev, wanted: prev + time.Second, commit: prev + time.Second + time.Millisecond, when: prev + time.Second + 2*time.Millisecond, want: flipStats{}},
	52	+	{name: "VRR back to back: no missed vblank, no late fence", vrr: true, prev: prev, wanted: prev, commit: prev + p/2, when: prev + 3p, fence: prev + 3p - 1,
	53	+	want: flipStats{maxInterval: 3 * p, maxCommitDelay: p / 2}},
	54	+	{name: "VRR flip gap is not a commit delay", vrr: true, prev: prev, wanted: prev, gapEnd: prev + 2time.Millisecond, commit: prev + 2time.Millisecond + 100time.Microsecond, when: prev + 3time.Millisecond,
	55	+	want: flipStats{maxInterval: 3 * time.Millisecond, maxCommitDelay: 100 * time.Microsecond}},
	56	+	{name: "wanted after the gap ended", vrr: true, prev: prev, wanted: prev + 5time.Millisecond, gapEnd: prev + 2time.Millisecond, commit: prev + 6time.Millisecond, when: prev + 7time.Millisecond,
	57	+	want: flipStats{maxInterval: 7 * time.Millisecond, maxCommitDelay: time.Millisecond}},
	58	+	} {
	59	+	t.Run(tc.name, func(t *testing.T) {
	60	+	o, _, _ := testOutput(t)
	61	+	o.vrrOn, o.lastFlipAt = tc.vrr, tc.prev
	62	+	f := pendingFrame{wantedAt: tc.wanted, gapEnd: tc.gapEnd}
	63	+	o.accountFlip(flipAt(tc.when), true, f.dueAt(), tc.commit, tc.fence)
	64	+	if o.flipStats != tc.want {
	65	+	t.Fatalf("stats %+v, want %+v", o.flipStats, tc.want)
	66	+	}
	67	+	wantLast := tc.wantLast
	68	+	if wantLast == 0 {
	69	+	wantLast = tc.when
	70	+	}
	71	+	if o.lastFlipAt != wantLast {
	72	+	t.Fatalf("last flip %s, want %s", o.lastFlipAt, wantLast)
	73	+	}
	74	+	})
	75	+	}
	76	+	}
	77	+
	78	+	// The gap end of the flip stats runs from the flip's kernel timestamp, the
	79	+	// commit gate from the time the event was read: an event read long after
	80	+	// the flip still shows as a commit delay.
	81	+	func TestStartFlipGapFromFlipTimestamp(t *testing.T) {
	82	+	o, _, _ := testOutput(t)
	83	+	gap := 2 * time.Millisecond
	84	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = gap, true, true
	85	+	flipped := time.Hour // CLOCK_MONOTONIC of the flip
	86	+	readAt := time.Unix(1000, 0)
	87	+	o.startFlipGap(pendingFrame{frame: true}, flipped, readAt)
	88	+	if o.flipGapAt != flipped+gap \|\| !o.flipGapUntil.Equal(readAt.Add(gap)) {
	89	+	t.Fatalf("gap at %s until %s", o.flipGapAt, o.flipGapUntil)
	90	+	}
	91	+	// The event was read 30 ms after the flip (> one period), the next
	92	+	// frame committed right after: the delay is not hidden in the gap.
	93	+	o.lastFlipAt = flipped
	94	+	f := pendingFrame{wantedAt: flipped + time.Millisecond, gapEnd: o.flipGapAt}
	95	+	o.accountFlip(flipAt(flipped+2p), true, f.dueAt(), flipped+30time.Millisecond, 0)
	96	+	if want := 30*time.Millisecond - gap; o.flipStats.maxCommitDelay != want {
	97	+	t.Fatalf("commit delay %s, want %s", o.flipStats.maxCommitDelay, want)
	98	+	}
	99	+	}
	100	+
	101	+	// The gap end set at a game frame's flip travels with the next frame
	102	+	// commit, which consumes it.
	103	+	func TestFlipGapEndReachesNextFrame(t *testing.T) {
	104	+	o, _, commits := testOutput(t)
	105	+	o.cursor = nil
	106	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = 2*time.Millisecond, true, true
	107	+	seen := map[ports.WindowID]uint64{}
	108	+	if err := o.commitFrame(70, nil, false, true, pendingFrame{}); err != nil {
	109	+	t.Fatal(err)
	110	+	}
	111	+	ev := eventOf((*commits)[0])
	112	+	ev.when = monotonic()
	113	+	o.completed(ev, seen)
	114	+	if o.flipGapAt != ev.when+2*time.Millisecond {
	115	+	t.Fatalf("gap end %s, flip at %s", o.flipGapAt, ev.when)
	116	+	}
	117	+	gap := o.flipGapAt
	118	+	if err := o.commitFrame(71, nil, false, true, pendingFrame{}); err != nil {
	119	+	t.Fatal(err)
	120	+	}
	121	+	if o.frame.pendingFrame.gapEnd != gap \|\| o.flipGapAt != 0 {
	122	+	t.Fatalf("gap end %s, left %s, want %s", o.frame.pendingFrame.gapEnd, o.flipGapAt, gap)
	123	+	}
	124	+	}
	125	+
	126	+	// A VRR change starts a new interval chain, in both directions.
	127	+	func TestSetVRRRestartsFlipInterval(t *testing.T) {
	128	+	o, _, _ := testOutput(t)
	129	+	o.lastFlipAt = time.Second
	130	+	o.setVRR(false)
	131	+	if o.lastFlipAt != time.Second {
	132	+	t.Fatal("unchanged state reset the chain")
	133	+	}
	134	+	o.setVRR(true)
	135	+	if o.lastFlipAt != 0 \|\| !o.vrrOn {
	136	+	t.Fatalf("vrr on: last %s", o.lastFlipAt)
	137	+	}
	138	+	o.lastFlipAt = time.Second
	139	+	o.setVRR(false)
	140	+	if o.lastFlipAt != 0 \|\| o.vrrOn {
	141	+	t.Fatalf("vrr off: last %s", o.lastFlipAt)
	142	+	}
	143	+	}
	144	+
	145	+	// A state commit (cursor, VRR) is neither a frame interval nor a frame.
	146	+	func TestAccountFlipStateCommit(t *testing.T) {
	147	+	o, _, _ := testOutput(t)
	148	+	o.lastFlipAt = time.Second
	149	+	o.accountFlip(flipAt(time.Second+3p), false, time.Second+p/2, time.Second+p/2, time.Second+3p)
	150	+	if s := o.flipStats; s != (flipStats{}) \|\| o.lastFlipAt != time.Second {
	151	+	t.Fatalf("stats %+v last %s", s, o.lastFlipAt)
	152	+	}
	153	+	}
	154	+
	155	+	func TestAccountReadMax(t *testing.T) {
	156	+	o, _, _ := testOutput(t)
	157	+	for _, d := range []time.Duration{2 * time.Millisecond, 25 * time.Millisecond, 5 * time.Millisecond} {
	158	+	o.accountRead(flipAt(time.Second), time.Second+d)
	159	+	}
	160	+	if got := o.flipStats.maxFlipToRead; got != 25*time.Millisecond {
	161	+	t.Fatalf("max flip to read %s", got)
	162	+	}
	163	+	}
	164	+
	165	+	func TestTakeFlipStatsResets(t *testing.T) {
	166	+	o, _, _ := testOutput(t)
	167	+	o.lastFlipAt = time.Second
	168	+	// Missed, with a fence after the targeted vblank.
	169	+	o.accountFlip(flipAt(time.Second+3p), true, time.Second, time.Second+p/2, time.Second+2p)
	170	+	o.accountRead(flipAt(time.Second), time.Second+time.Millisecond)
	171	+	o.accountFlip(flipAt(time.Second+4p), true, time.Second+3p, time.Second+3*p+p/2, 0)
	172	+	s := o.takeFlipStats()
	173	+	if s.missedVblanks != 1 \|\| s.lateFences != 1 \|\| s.maxInterval != 3*p \|\| s.maxCommitDelay != p/2 \|\| s.maxFlipToRead != time.Millisecond {
	174	+	t.Fatalf("taken %+v", s)
	175	+	}
	176	+	if o.flipStats != (flipStats{}) {
	177	+	t.Fatalf("not reset: %+v", o.flipStats)
	178	+	}
	179	+	// The interval chain survives the report.
	180	+	if o.lastFlipAt != time.Second+4*p {
	181	+	t.Fatalf("last flip %s", o.lastFlipAt)
	182	+	}
	183	+	}
	184	+
	185	+	// Every frame flip keeps lastFlipAt, traced or not, and our commit's
	186	+	// event delivery is measured.
	187	+	func TestCompletedKeepsLastFlipWithoutTrace(t *testing.T) {
	188	+	o, _, commits := testOutput(t)
	189	+	o.cursor = nil
	190	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	191	+	t.Fatal(err)
	192	+	}
	193	+	if !o.completed(flipEvent{crtc: tCrtc, user: (commits)[0].user, when: 5 time.Second}, map[ports.WindowID]uint64{}) {
	194	+	t.Fatal("not completed")
	195	+	}
	196	+	if o.lastFlipAt != 5*time.Second {
	197	+	t.Fatalf("last flip %s", o.lastFlipAt)
	198	+	}
	199	+	if o.flipStats.maxFlipToRead <= 0 {
	200	+	t.Fatalf("flip to read not measured: %+v", o.flipStats)
	201	+	}
	202	+	}
	203	+
	204	+	// The end of an EBUSY wait and a stale event are not deliveries of our
	205	+	// commit: they do not feed max_flip_to_read.
	206	+	func TestCompletedReadLatencyOnlyOurCommit(t *testing.T) {
	207	+	o, _, commits := testOutput(t)
	208	+	o.cursor = nil
	209	+	seen := map[ports.WindowID]uint64{}
	210	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	211	+	t.Fatal(err)
	212	+	}
	213	+	c := (*commits)[0]
	214	+	o.completed(flipEvent{crtc: tCrtc, user: c.user + 1<<userKindBits}, seen) // stale
	215	+	if o.flipStats.maxFlipToRead != 0 {
	216	+	t.Fatalf("stale event measured: %+v", o.flipStats)
	217	+	}
	218	+	o.frame.busy(time.Now())
	219	+	if !o.completed(flipEvent{crtc: tCrtc, user: 12345}, seen) \|\| o.flipStats.maxFlipToRead != 0 {
	220	+	t.Fatalf("EBUSY wait end measured: %+v", o.flipStats)
	221	+	}
	222	+	}
	223	+
	224	+	// With tracing on, completed still logs the interval since the previous
	225	+	// frame flip, and moves lastFlipAt after it.
	226	+	func TestCompletedTracesFlipInterval(t *testing.T) {
	227	+	o, _, commits := testOutput(t)
	228	+	o.cursor = nil
	229	+	o.traceFlips = true
	230	+	var log bytes.Buffer
	231	+	o.log = zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &log})
	232	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	233	+	t.Fatal(err)
	234	+	}
	235	+	when := monotonic()
	236	+	o.lastFlipAt = when - 10*time.Millisecond
	237	+	if !o.completed(flipEvent{crtc: tCrtc, user: (*commits)[0].user, when: when}, map[ports.WindowID]uint64{}) {
	238	+	t.Fatal("not completed")
	239	+	}
	240	+	if !strings.Contains(log.String(), `"flip_interval_ms":10`) \|\| o.lastFlipAt != when {
	241	+	t.Fatalf("last flip %s: %s", o.lastFlipAt, log.String())
	242	+	}
	243	+	}
	244	+
	245	+	func TestAccountFlipAllocations(t *testing.T) {
	246	+	o, _, _ := testOutput(t)
	247	+	at := time.Second
	248	+	if n := testing.AllocsPerRun(100, func() {
	249	+	at += 40 * time.Millisecond
	250	+	o.accountFlip(flipAt(at), true, at-35time.Millisecond, at-30time.Millisecond, at-20*time.Millisecond)
	251	+	o.accountFlip(flipAt(at), false, at, at, 0)
	252	+	o.accountRead(flipAt(at), at+time.Millisecond)
	253	+	_ = o.takeFlipStats()
	254	+	}); n != 0 {
	255	+	t.Fatalf("%v allocations", n)
	256	+	}
	257	+	}
	258	+
	259	+	// The completion accounting of a frame flip, tracing off, in steady state.
	260	+	// (completed itself reports the flip to wayland, which allocates.)
	261	+	func TestFlipDoneAllocations(t *testing.T) {
	262	+	o, _, _ := testOutput(t)
	263	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = time.Millisecond, true, true
	264	+	start := time.Now()
	265	+	at := time.Second
	266	+	if n := testing.AllocsPerRun(100, func() {
	267	+	at += 10 * time.Millisecond
	268	+	o.flipDone(flipAt(at), pendingFrame{frame: true, wantedAt: at - time.Millisecond}, start, true, false, 0)
	269	+	}); n != 0 {
	270	+	t.Fatalf("flipDone: %v allocations", n)
	271	+	}
	272	+	}

@@ -0,0 +1,272 @@
	1	+	package drm
	2	+
	3	+	import (
	4	+	"bytes"
	5	+	"strings"
	6	+	"testing"
	7	+	"time"
	8	+
	9	+	"github.com/bnema/neferwl/internal/ports"
	10	+	"github.com/bnema/zerowrap"
	11	+	)
	12	+
	13	+	const period60 = 16_666_666 * time.Nanosecond // modeInfo{VRefresh: 60}
	14	+
	15	+	func flipAt(when time.Duration) flipEvent { return flipEvent{when: when} }
	16	+
	17	+	// p is the refresh period of the test output's 60 Hz mode.
	18	+	const p = period60
	19	+
	20	+	// The gate and the counters of accountFlip, one flip after a frame flip at
	21	+	// prev (1 s). due is the frame's due time: the later of wanted and gapEnd
	22	+	// (see pendingFrame.dueAt; both 0: the commit time).
	23	+	func TestAccountFlip(t *testing.T) {
	24	+	const prev = time.Second
	25	+	for _, tc := range []struct {
	26	+	name string
	27	+	vrr bool
	28	+	prev time.Duration // 0: no previous flip
	29	+	wanted, gapEnd time.Duration
	30	+	commit, when, fence time.Duration
	31	+	want flipStats
	32	+	wantLast time.Duration
	33	+	}{
	34	+	{name: "first flip has no interval", prev: 0, wanted: prev, commit: prev, when: prev + p, want: flipStats{}, wantLast: prev + p},
	35	+	{name: "on time", prev: prev, wanted: prev + p/4, commit: prev + p/2, when: prev + p, want: flipStats{maxInterval: p, maxCommitDelay: p/2 - p/4}},
	36	+	{name: "unknown wanted time", prev: prev, commit: prev + p/2, when: prev + p, want: flipStats{maxInterval: p}},
	37	+	{name: "just under 1.5 periods", prev: prev, wanted: prev, commit: prev + p/2, when: prev + p3/2 - 1, want: flipStats{maxInterval: p3/2 - 1, maxCommitDelay: p / 2}},
	38	+	{name: "two periods is a missed vblank", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2p, want: flipStats{missedVblanks: 1, maxInterval: 2 p, maxCommitDelay: p / 2}},
	39	+	{name: "idle gap is not counted", prev: prev, wanted: prev + time.Second, commit: prev + time.Second + p/2, when: prev + time.Second + p, want: flipStats{}},
	40	+	{name: "wanted one period after: not due", prev: prev, wanted: prev + p, commit: prev + p + p/2, when: prev + 5*p, want: flipStats{}},
	41	+	{name: "wanted just before one period: due", prev: prev, wanted: prev + p - 1, commit: prev + p + p/2, when: prev + 4p, want: flipStats{missedVblanks: 1, maxInterval: 4 p, maxCommitDelay: p/2 + 1}},
	42	+	{name: "delayed commit, wanted before the previous flip", prev: prev, wanted: prev - p/2, commit: prev + p + p/5, when: prev + 2*p, fence: prev + p/2,
	43	+	want: flipStats{missedVblanks: 1, maxInterval: 2 * p, maxCommitDelay: p + p/5}},
	44	+	{name: "normal frame: fence before its flip", prev: prev, wanted: prev + p/4, commit: prev + p/2, when: prev + p, fence: prev + p - 1,
	45	+	want: flipStats{maxInterval: p, maxCommitDelay: p/2 - p/4}},
	46	+	{name: "missed, fence unknown", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2p, want: flipStats{missedVblanks: 1, maxInterval: 2 p, maxCommitDelay: p / 2}},
	47	+	{name: "missed, fence at the targeted vblank", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2*p, fence: prev + p,
	48	+	want: flipStats{missedVblanks: 1, maxInterval: 2 * p, maxCommitDelay: p / 2}},
	49	+	{name: "missed, fence after the targeted vblank", prev: prev, wanted: prev, commit: prev + p/2, when: prev + 2*p, fence: prev + p + 1,
	50	+	want: flipStats{missedVblanks: 1, lateFences: 1, maxInterval: 2 * p, maxCommitDelay: p / 2}},
	51	+	{name: "VRR idle gap", vrr: true, prev: prev, wanted: prev + time.Second, commit: prev + time.Second + time.Millisecond, when: prev + time.Second + 2*time.Millisecond, want: flipStats{}},
	52	+	{name: "VRR back to back: no missed vblank, no late fence", vrr: true, prev: prev, wanted: prev, commit: prev + p/2, when: prev + 3p, fence: prev + 3p - 1,
	53	+	want: flipStats{maxInterval: 3 * p, maxCommitDelay: p / 2}},
	54	+	{name: "VRR flip gap is not a commit delay", vrr: true, prev: prev, wanted: prev, gapEnd: prev + 2time.Millisecond, commit: prev + 2time.Millisecond + 100time.Microsecond, when: prev + 3time.Millisecond,
	55	+	want: flipStats{maxInterval: 3 * time.Millisecond, maxCommitDelay: 100 * time.Microsecond}},
	56	+	{name: "wanted after the gap ended", vrr: true, prev: prev, wanted: prev + 5time.Millisecond, gapEnd: prev + 2time.Millisecond, commit: prev + 6time.Millisecond, when: prev + 7time.Millisecond,
	57	+	want: flipStats{maxInterval: 7 * time.Millisecond, maxCommitDelay: time.Millisecond}},
	58	+	} {
	59	+	t.Run(tc.name, func(t *testing.T) {
	60	+	o, _, _ := testOutput(t)
	61	+	o.vrrOn, o.lastFlipAt = tc.vrr, tc.prev
	62	+	f := pendingFrame{wantedAt: tc.wanted, gapEnd: tc.gapEnd}
	63	+	o.accountFlip(flipAt(tc.when), true, f.dueAt(), tc.commit, tc.fence)
	64	+	if o.flipStats != tc.want {
	65	+	t.Fatalf("stats %+v, want %+v", o.flipStats, tc.want)
	66	+	}
	67	+	wantLast := tc.wantLast
	68	+	if wantLast == 0 {
	69	+	wantLast = tc.when
	70	+	}
	71	+	if o.lastFlipAt != wantLast {
	72	+	t.Fatalf("last flip %s, want %s", o.lastFlipAt, wantLast)
	73	+	}
	74	+	})
	75	+	}
	76	+	}
	77	+
	78	+	// The gap end of the flip stats runs from the flip's kernel timestamp, the
	79	+	// commit gate from the time the event was read: an event read long after
	80	+	// the flip still shows as a commit delay.
	81	+	func TestStartFlipGapFromFlipTimestamp(t *testing.T) {
	82	+	o, _, _ := testOutput(t)
	83	+	gap := 2 * time.Millisecond
	84	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = gap, true, true
	85	+	flipped := time.Hour // CLOCK_MONOTONIC of the flip
	86	+	readAt := time.Unix(1000, 0)
	87	+	o.startFlipGap(pendingFrame{frame: true}, flipped, readAt)
	88	+	if o.flipGapAt != flipped+gap \|\| !o.flipGapUntil.Equal(readAt.Add(gap)) {
	89	+	t.Fatalf("gap at %s until %s", o.flipGapAt, o.flipGapUntil)
	90	+	}
	91	+	// The event was read 30 ms after the flip (> one period), the next
	92	+	// frame committed right after: the delay is not hidden in the gap.
	93	+	o.lastFlipAt = flipped
	94	+	f := pendingFrame{wantedAt: flipped + time.Millisecond, gapEnd: o.flipGapAt}
	95	+	o.accountFlip(flipAt(flipped+2p), true, f.dueAt(), flipped+30time.Millisecond, 0)
	96	+	if want := 30*time.Millisecond - gap; o.flipStats.maxCommitDelay != want {
	97	+	t.Fatalf("commit delay %s, want %s", o.flipStats.maxCommitDelay, want)
	98	+	}
	99	+	}
	100	+
	101	+	// The gap end set at a game frame's flip travels with the next frame
	102	+	// commit, which consumes it.
	103	+	func TestFlipGapEndReachesNextFrame(t *testing.T) {
	104	+	o, _, commits := testOutput(t)
	105	+	o.cursor = nil
	106	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = 2*time.Millisecond, true, true
	107	+	seen := map[ports.WindowID]uint64{}
	108	+	if err := o.commitFrame(70, nil, false, true, pendingFrame{}); err != nil {
	109	+	t.Fatal(err)
	110	+	}
	111	+	ev := eventOf((*commits)[0])
	112	+	ev.when = monotonic()
	113	+	o.completed(ev, seen)
	114	+	if o.flipGapAt != ev.when+2*time.Millisecond {
	115	+	t.Fatalf("gap end %s, flip at %s", o.flipGapAt, ev.when)
	116	+	}
	117	+	gap := o.flipGapAt
	118	+	if err := o.commitFrame(71, nil, false, true, pendingFrame{}); err != nil {
	119	+	t.Fatal(err)
	120	+	}
	121	+	if o.frame.pendingFrame.gapEnd != gap \|\| o.flipGapAt != 0 {
	122	+	t.Fatalf("gap end %s, left %s, want %s", o.frame.pendingFrame.gapEnd, o.flipGapAt, gap)
	123	+	}
	124	+	}
	125	+
	126	+	// A VRR change starts a new interval chain, in both directions.
	127	+	func TestSetVRRRestartsFlipInterval(t *testing.T) {
	128	+	o, _, _ := testOutput(t)
	129	+	o.lastFlipAt = time.Second
	130	+	o.setVRR(false)
	131	+	if o.lastFlipAt != time.Second {
	132	+	t.Fatal("unchanged state reset the chain")
	133	+	}
	134	+	o.setVRR(true)
	135	+	if o.lastFlipAt != 0 \|\| !o.vrrOn {
	136	+	t.Fatalf("vrr on: last %s", o.lastFlipAt)
	137	+	}
	138	+	o.lastFlipAt = time.Second
	139	+	o.setVRR(false)
	140	+	if o.lastFlipAt != 0 \|\| o.vrrOn {
	141	+	t.Fatalf("vrr off: last %s", o.lastFlipAt)
	142	+	}
	143	+	}
	144	+
	145	+	// A state commit (cursor, VRR) is neither a frame interval nor a frame.
	146	+	func TestAccountFlipStateCommit(t *testing.T) {
	147	+	o, _, _ := testOutput(t)
	148	+	o.lastFlipAt = time.Second
	149	+	o.accountFlip(flipAt(time.Second+3p), false, time.Second+p/2, time.Second+p/2, time.Second+3p)
	150	+	if s := o.flipStats; s != (flipStats{}) \|\| o.lastFlipAt != time.Second {
	151	+	t.Fatalf("stats %+v last %s", s, o.lastFlipAt)
	152	+	}
	153	+	}
	154	+
	155	+	func TestAccountReadMax(t *testing.T) {
	156	+	o, _, _ := testOutput(t)
	157	+	for _, d := range []time.Duration{2 * time.Millisecond, 25 * time.Millisecond, 5 * time.Millisecond} {
	158	+	o.accountRead(flipAt(time.Second), time.Second+d)
	159	+	}
	160	+	if got := o.flipStats.maxFlipToRead; got != 25*time.Millisecond {
	161	+	t.Fatalf("max flip to read %s", got)
	162	+	}
	163	+	}
	164	+
	165	+	func TestTakeFlipStatsResets(t *testing.T) {
	166	+	o, _, _ := testOutput(t)
	167	+	o.lastFlipAt = time.Second
	168	+	// Missed, with a fence after the targeted vblank.
	169	+	o.accountFlip(flipAt(time.Second+3p), true, time.Second, time.Second+p/2, time.Second+2p)
	170	+	o.accountRead(flipAt(time.Second), time.Second+time.Millisecond)
	171	+	o.accountFlip(flipAt(time.Second+4p), true, time.Second+3p, time.Second+3*p+p/2, 0)
	172	+	s := o.takeFlipStats()
	173	+	if s.missedVblanks != 1 \|\| s.lateFences != 1 \|\| s.maxInterval != 3*p \|\| s.maxCommitDelay != p/2 \|\| s.maxFlipToRead != time.Millisecond {
	174	+	t.Fatalf("taken %+v", s)
	175	+	}
	176	+	if o.flipStats != (flipStats{}) {
	177	+	t.Fatalf("not reset: %+v", o.flipStats)
	178	+	}
	179	+	// The interval chain survives the report.
	180	+	if o.lastFlipAt != time.Second+4*p {
	181	+	t.Fatalf("last flip %s", o.lastFlipAt)
	182	+	}
	183	+	}
	184	+
	185	+	// Every frame flip keeps lastFlipAt, traced or not, and our commit's
	186	+	// event delivery is measured.
	187	+	func TestCompletedKeepsLastFlipWithoutTrace(t *testing.T) {
	188	+	o, _, commits := testOutput(t)
	189	+	o.cursor = nil
	190	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	191	+	t.Fatal(err)
	192	+	}
	193	+	if !o.completed(flipEvent{crtc: tCrtc, user: (commits)[0].user, when: 5 time.Second}, map[ports.WindowID]uint64{}) {
	194	+	t.Fatal("not completed")
	195	+	}
	196	+	if o.lastFlipAt != 5*time.Second {
	197	+	t.Fatalf("last flip %s", o.lastFlipAt)
	198	+	}
	199	+	if o.flipStats.maxFlipToRead <= 0 {
	200	+	t.Fatalf("flip to read not measured: %+v", o.flipStats)
	201	+	}
	202	+	}
	203	+
	204	+	// The end of an EBUSY wait and a stale event are not deliveries of our
	205	+	// commit: they do not feed max_flip_to_read.
	206	+	func TestCompletedReadLatencyOnlyOurCommit(t *testing.T) {
	207	+	o, _, commits := testOutput(t)
	208	+	o.cursor = nil
	209	+	seen := map[ports.WindowID]uint64{}
	210	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	211	+	t.Fatal(err)
	212	+	}
	213	+	c := (*commits)[0]
	214	+	o.completed(flipEvent{crtc: tCrtc, user: c.user + 1<<userKindBits}, seen) // stale
	215	+	if o.flipStats.maxFlipToRead != 0 {
	216	+	t.Fatalf("stale event measured: %+v", o.flipStats)
	217	+	}
	218	+	o.frame.busy(time.Now())
	219	+	if !o.completed(flipEvent{crtc: tCrtc, user: 12345}, seen) \|\| o.flipStats.maxFlipToRead != 0 {
	220	+	t.Fatalf("EBUSY wait end measured: %+v", o.flipStats)
	221	+	}
	222	+	}
	223	+
	224	+	// With tracing on, completed still logs the interval since the previous
	225	+	// frame flip, and moves lastFlipAt after it.
	226	+	func TestCompletedTracesFlipInterval(t *testing.T) {
	227	+	o, _, commits := testOutput(t)
	228	+	o.cursor = nil
	229	+	o.traceFlips = true
	230	+	var log bytes.Buffer
	231	+	o.log = zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &log})
	232	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	233	+	t.Fatal(err)
	234	+	}
	235	+	when := monotonic()
	236	+	o.lastFlipAt = when - 10*time.Millisecond
	237	+	if !o.completed(flipEvent{crtc: tCrtc, user: (*commits)[0].user, when: when}, map[ports.WindowID]uint64{}) {
	238	+	t.Fatal("not completed")
	239	+	}
	240	+	if !strings.Contains(log.String(), `"flip_interval_ms":10`) \|\| o.lastFlipAt != when {
	241	+	t.Fatalf("last flip %s: %s", o.lastFlipAt, log.String())
	242	+	}
	243	+	}
	244	+
	245	+	func TestAccountFlipAllocations(t *testing.T) {
	246	+	o, _, _ := testOutput(t)
	247	+	at := time.Second
	248	+	if n := testing.AllocsPerRun(100, func() {
	249	+	at += 40 * time.Millisecond
	250	+	o.accountFlip(flipAt(at), true, at-35time.Millisecond, at-30time.Millisecond, at-20*time.Millisecond)
	251	+	o.accountFlip(flipAt(at), false, at, at, 0)
	252	+	o.accountRead(flipAt(at), at+time.Millisecond)
	253	+	_ = o.takeFlipStats()
	254	+	}); n != 0 {
	255	+	t.Fatalf("%v allocations", n)
	256	+	}
	257	+	}
	258	+
	259	+	// The completion accounting of a frame flip, tracing off, in steady state.
	260	+	// (completed itself reports the flip to wayland, which allocates.)
	261	+	func TestFlipDoneAllocations(t *testing.T) {
	262	+	o, _, _ := testOutput(t)
	263	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = time.Millisecond, true, true
	264	+	start := time.Now()
	265	+	at := time.Second
	266	+	if n := testing.AllocsPerRun(100, func() {
	267	+	at += 10 * time.Millisecond
	268	+	o.flipDone(flipAt(at), pendingFrame{frame: true, wantedAt: at - time.Millisecond}, start, true, false, 0)
	269	+	}); n != 0 {
	270	+	t.Fatalf("flipDone: %v allocations", n)
	271	+	}
	272	+	}

M internal/adapters/drm/flip_trace.go +5 -9


@@ -78,11 +78,10 @@ func monotonic() time.Duration {
78	78		return time.Duration(ts.Nano())
79	79		}
80	80
81		-	// traceFlip logs the completion ev of the commit f started at start.
	81	+	// traceFlip logs the completion ev of the commit f made at commitAt and
	82	+	// handled at now. prev is the previous frame flip's timestamp (0: none).
82	83		// fenceAt is when its fences signalled (0: none or unknown).
83		-	func (o *Output) traceFlip(ev flipEvent, f pendingFrame, start time.Time, fenceAt time.Duration) {
84		-	now := monotonic()
85		-	commitAt := now - time.Since(start)
	84	+	func (o *Output) traceFlip(ev flipEvent, f pendingFrame, commitAt, now, prev, fenceAt time.Duration) {
86	85		e := o.log.Debug().Str("connector", o.conn.name).Bool("frame", f.frame).Bool("async", f.async).Bool("vrr", o.vrrOn).
87	86		Bool("direct", f.zeroCopy != 0).Uint32("seq", ev.seq).
88	87		Float64("commit_to_flip_ms", ms(ev.when-commitAt)).Float64("flip_to_read_ms", ms(now-ev.when)).

@@ -90,11 +89,8 @@ func (o *Output) traceFlip(ev flipEvent, f pendingFrame, start time.Time, fenceA
90	89		if fenceAt != 0 {
91	90		e = e.Float64("commit_to_fence_ms", ms(fenceAt-commitAt)).Float64("fence_to_flip_ms", ms(ev.when-fenceAt))
92	91		}
93		-	if f.frame {
94		-	if o.lastFlipAt != 0 {
95		-	e = e.Float64("flip_interval_ms", ms(ev.when-o.lastFlipAt))
96		-	}
97		-	o.lastFlipAt = ev.when
	92	+	if f.frame && prev != 0 {
	93	+	e = e.Float64("flip_interval_ms", ms(ev.when-prev))
98	94		}
99	95		e.Msg("flip")
100	96		}

 	return time.Duration(ts.Nano())
 }
-// traceFlip logs the completion ev of the commit f started at start.
+// traceFlip logs the completion ev of the commit f made at commitAt and
+// handled at now. prev is the previous frame flip's timestamp (0: none).
 // fenceAt is when its fences signalled (0: none or unknown).
-func (o *Output) traceFlip(ev flipEvent, f pendingFrame, start time.Time, fenceAt time.Duration) {
+func (o *Output) traceFlip(ev flipEvent, f pendingFrame, commitAt, now, prev, fenceAt time.Duration) {
-	now := monotonic()
-	commitAt := now - time.Since(start)
 	e := o.log.Debug().Str("connector", o.conn.name).Bool("frame", f.frame).Bool("async", f.async).Bool("vrr", o.vrrOn).
 		Bool("direct", f.zeroCopy != 0).Uint32("seq", ev.seq).
 		Float64("commit_to_flip_ms", ms(ev.when-commitAt)).Float64("flip_to_read_ms", ms(now-ev.when)).
 	if fenceAt != 0 {
 		e = e.Float64("commit_to_fence_ms", ms(fenceAt-commitAt)).Float64("fence_to_flip_ms", ms(ev.when-fenceAt))
 	}
-	if f.frame {
+	if f.frame && prev != 0 {
-		if o.lastFlipAt != 0 {
+		e = e.Float64("flip_interval_ms", ms(ev.when-prev))
-			e = e.Float64("flip_interval_ms", ms(ev.when-o.lastFlipAt))
-		}
-		o.lastFlipAt = ev.when
 	}
 	e.Msg("flip")
 }

M internal/adapters/drm/frame_lifecycle.go +9 -0


@@ -38,8 +38,17 @@ type pendingFrame struct {
38	38		composed bool
39	39		// fenceReady: every fence had signalled at commit (flip tracing only).
40	40		fenceReady bool
	41	+	// wantedAt is when the frame was first wanted (CLOCK_MONOTONIC, 0:
	42	+	// unknown), for the flip stats.
	43	+	wantedAt time.Duration
	44	+	// gapEnd is when the VRR flip gap that held the frame ended (0: none).
	45	+	gapEnd time.Duration
41	46		}
42	47
	48	+	// dueAt is when the frame could first commit: wanted, and after the
	49	+	// deliberate VRR flip gap (0: unknown).
	50	+	func (f *pendingFrame) dueAt() time.Duration { return max(f.wantedAt, f.gapEnd) }
	51	+
43	52		func (f *pendingFrame) closeFences() {
44	53		for _, fd := range f.fences {
45	54		fd.Close()


@@ -38,8 +38,17 @@ type pendingFrame struct {
38	composed bool	38		composed bool
39	// fenceReady: every fence had signalled at commit (flip tracing only).	39		// fenceReady: every fence had signalled at commit (flip tracing only).
40	fenceReady bool	40		fenceReady bool
		41	+	// wantedAt is when the frame was first wanted (CLOCK_MONOTONIC, 0:
		42	+	// unknown), for the flip stats.
		43	+	wantedAt time.Duration
		44	+	// gapEnd is when the VRR flip gap that held the frame ended (0: none).
		45	+	gapEnd time.Duration
41	}	46		}
42		47
		48	+	// dueAt is when the frame could first commit: wanted, and after the
		49	+	// deliberate VRR flip gap (0: unknown).
		50	+	func (f *pendingFrame) dueAt() time.Duration { return max(f.wantedAt, f.gapEnd) }
		51	+
43	func (f *pendingFrame) closeFences() {	52		func (f *pendingFrame) closeFences() {
44	for _, fd := range f.fences {	53		for _, fd := range f.fences {
45	fd.Close()	54		fd.Close()

M internal/adapters/drm/output.go +56 -20


@@ -122,14 +122,26 @@ type Output struct {
122	122		lastFrame time.Time
123	123		cursorHeld bool
124	124		// traceFlips logs every completion with its timing; lastFlipAt is
125		-	// the previous frame flip's kernel timestamp.
	125	+	// the previous frame flip's kernel timestamp (always kept).
	126	+	// flipStats are reported and reset with the periodic stats. wantedAt
	127	+	// is when the output first needed a frame since the last frame commit
	128	+	// (0: none), taken by the commit into pendingFrame.
126	129		traceFlips bool
127	130		lastFlipAt time.Duration
	131	+	flipStats flipStats
	132	+	wantedAt time.Duration
128	133		// vrrFlipGap is the minimum time between a game frame's flip event
129	134		// and the next frame commit under VRR (render.vrr-flip-gap, 0: off);
130		-	// flipGapUntil is when the next frame may commit. See vrr_flip_gap.go.
	135	+	// flipGapUntil is when the next frame may commit: the gap from the
	136	+	// time the flip event was read, as the workaround was measured. See
	137	+	// vrr_flip_gap.go.
131	138		vrrFlipGap time.Duration
132	139		flipGapUntil time.Time
	140	+	// flipGapAt is the end of the gap from the flip's kernel timestamp
	141	+	// (CLOCK_MONOTONIC), kept until the frame it held commits. It differs
	142	+	// from flipGapUntil on purpose: the flip stats must not hide a late
	143	+	// read of the event inside the gap.
	144	+	flipGapAt time.Duration
133	145		// wantOff is the latest Scene.Off: a client turned the display off.
134	146		// off: the CRTC is inactive for it. Every modeset (resume, recovery)
135	147		// follows wantOff, so a display turned off never lights up.

@@ -378,8 +390,8 @@ func (o *Output) modesetImage(fb uint32, active bool) error {
378	390		}
379	391		o.modeBlob = blob
380	392		o.vrrOn, o.vrrGame, o.overlayOn, o.off = false, false, 0, !active
381		-	// The gap and the traced flip interval belonged to the old state.
382		-	o.flipGapUntil, o.lastFlipAt = time.Time{}, 0
	393	+	// The gap and the flip interval belonged to the old state.
	394	+	o.flipGapUntil, o.flipGapAt, o.lastFlipAt = time.Time{}, 0, 0
383	395		o.contentValue, o.contentWanted = o.contentValues[0], o.contentValues[0]
384	396		o.planeRect = fullPlaneRect(o.Width(), o.Height())
385	397		if o.cursor != nil {

@@ -416,7 +428,8 @@ func (o *Output) powerOff() error {
416	428		if err := o.k.commit(req, atomicAllowModes, 0); err != nil {
417	429		return fmt.Errorf("power off: %w", err)
418	430		}
419		-	o.off, o.vrrOn, o.vrrGame = true, false, false
	431	+	o.off, o.vrrGame = true, false
	432	+	o.setVRR(false)
420	433		o.contentValue, o.contentWanted = o.contentValues[0], o.contentValues[0]
421	434		o.log.Info().Str("connector", o.conn.name).Msg("power off")
422	435		// An inactive output offers neither HDR nor direct scanout.

@@ -605,7 +618,7 @@ func (o Output) commitWithRect(fb uint32, fence os.File, async bool, vrr bool,
605	618		if o.vrrOn != vrr {
606	619		o.log.Info().Bool("vrr", vrr).Str("connector", o.conn.name).Msg("vrr")
607	620		}
608		-	o.vrrOn = vrr
	621	+	o.setVRR(vrr)
609	622		}
610	623		if o.cursor != nil {
611	624		// An async commit leaves the cursor plane as applied.

@@ -618,6 +631,8 @@ func (o Output) commitWithRect(fb uint32, fence os.File, async bool, vrr bool,
618	631		o.planeRect = rect
619	632		o.lastFrame, o.cursorHeld = time.Now(), false
620	633		f.frame, f.async = true, async
	634	+	f.wantedAt, o.wantedAt = o.wantedAt, 0
	635	+	f.gapEnd, o.flipGapAt = o.flipGapAt, 0
621	636		f.fences = dupFences(fence, ov.acquire)
622	637		if o.traceFlips {
623	638		f.fenceReady = signalled(f.fences)

@@ -714,7 +729,7 @@ func (o *Output) commitState(vrr bool) error {
714	729		if vrr != o.vrrOn {
715	730		o.log.Info().Bool("vrr", vrr).Str("connector", o.conn.name).Msg("vrr")
716	731		}
717		-	o.vrrOn = vrr
	732	+	o.setVRR(vrr)
718	733		o.contentValue = o.contentWanted
719	734		o.frame.begin(pendingFrame{}, time.Now())
720	735		return nil

@@ -1002,6 +1017,7 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
1002	1017		for {
1003	1018		if o.observeSecurity() \|\| haveScene && !o.sceneCurrent(scene) {
1004	1019		scene, haveScene, dirty = ports.Scene{}, false, false
	1020	+	o.wantedAt = 0
1005	1021		want, cursorScale, cursorTransform = ports.CursorChange{}, -1, 0
1006	1022		if o.cursor != nil {
1007	1023		o.cursor.image, o.cursor.later = false, nil

@@ -1276,8 +1292,20 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
1276	1292		cs := o.cursor.TakeStats()
1277	1293		ev = ev.Int("cursor_moves", cs.Moves).Int("cursor_commits", cs.Commits)
1278	1294		}
	1295	+	fs := o.takeFlipStats()
	1296	+	ev = ev.Int("missed_vblanks", fs.missedVblanks).Float64("max_flip_interval_ms", ms(fs.maxInterval))
	1297	+	ev = ev.Float64("max_commit_delay_ms", ms(fs.maxCommitDelay)).Float64("max_flip_to_read_ms", ms(fs.maxFlipToRead))
	1298	+	ev = ev.Int("redrawn_pixels", r.TakeRedrawn())
	1299	+	if o.traceFlips {
	1300	+	ev = ev.Int("late_fences", fs.lateFences)
	1301	+	}
1279	1302		ev.Msg("stats")
1280	1303		}
	1304	+	// A frame wanted while the previous one is in flight is due at
	1305	+	// that flip: accountFlip never counts it before.
	1306	+	if dirty && haveScene && o.wantedAt == 0 {
	1307	+	o.wantedAt = monotonic()
	1308	+	}
1281	1309		o.observeSecurity()
1282	1310		if haveScene && !o.sceneCurrent(scene) {
1283	1311		continue

@@ -1418,13 +1446,31 @@ func (o Output) commitFailed(err error, enabled bool) bool {
1418	1446		return false
1419	1447		}
1420	1448
	1449	+	// flipDone times the completion ev of the commit f made at start: the
	1450	+	// flip stats, the flip trace and the VRR flip gap. It never allocates
	1451	+	// with tracing off.
	1452	+	func (o *Output) flipDone(ev flipEvent, f pendingFrame, start time.Time, ours, trace bool, fenceAt time.Duration) {
	1453	+	readAt := time.Now()
	1454	+	now := monotonic()
	1455	+	commitAt := now - readAt.Sub(start)
	1456	+	if ours {
	1457	+	o.accountRead(ev, now)
	1458	+	}
	1459	+	if trace {
	1460	+	o.traceFlip(ev, f, commitAt, now, o.lastFlipAt, fenceAt)
	1461	+	}
	1462	+	o.accountFlip(ev, f.frame, f.dueAt(), commitAt, fenceAt)
	1463	+	o.startFlipGap(f, ev.when, readAt)
	1464	+	}
	1465	+
1421	1466		// completed handles the event of the pending commit: a flipped frame is
1422	1467		// reported with its kernel timestamp. It reports false for an event of
1423	1468		// another commit, which is dropped.
1424	1469		func (o *Output) completed(ev flipEvent, seen map[ports.WindowID]uint64) bool {
1425	1470		// Only a commit of ours is traced: not a stale event, nor the end of
1426	1471		// an EBUSY wait. Its fences are read before flip closes them.
1427		-	trace := o.traceFlips && o.frame.ours(ev.user)
	1472	+	ours := o.frame.ours(ev.user)
	1473	+	trace := o.traceFlips && ours
1428	1474		var fenceAt time.Duration
1429	1475		if trace {
1430	1476		fenceAt = fencesSignalledAt(o.frame.pendingFrame.fences)

@@ -1433,13 +1479,7 @@ func (o *Output) completed(ev flipEvent, seen map[ports.WindowID]uint64) bool {
1433	1479		if !ok {
1434	1480		return false
1435	1481		}
1436		-	if trace {
1437		-	o.traceFlip(ev, f, start, fenceAt)
1438		-	}
1439		-	o.startFlipGap(f)
1440		-	if age := time.Since(start); age > 20*time.Millisecond {
1441		-	o.log.Info().Dur("flip_ms", age).Bool("frame", f.frame).Bool("vrr", o.vrrOn).Str("connector", o.conn.name).Msg("slow flip")
1442		-	}
	1482	+	o.flipDone(ev, f, start, ours, trace, fenceAt)
1443	1483		if o.cursor != nil {
1444	1484		o.cursor.landed()
1445	1485		}

@@ -1456,11 +1496,7 @@ func (o *Output) completed(ev flipEvent, seen map[ports.WindowID]uint64) bool {
1456	1496		if o.queued == f.queued {
1457	1497		o.queued = 0
1458	1498		}
1459		-	refresh := time.Duration(0)
1460		-	if !o.vrrOn {
1461		-	refresh = time.Duration(int64(time.Second) * 1000 / int64(max(1, o.mode.refreshMilli())))
1462		-	}
1463		-	o.report(&ports.FlipInfo{When: ev.when, Seq: uint64(ev.seq), Refresh: refresh, ZeroCopy: f.zeroCopy, Async: f.async, HardwareClock: true, Shows: f.shows}, seen)
	1499	+	o.report(&ports.FlipInfo{When: ev.when, Seq: uint64(ev.seq), Refresh: o.refreshPeriod(), ZeroCopy: f.zeroCopy, Async: f.async, HardwareClock: true, Shows: f.shows}, seen)
1464	1500		return true
1465	1501		}
1466	1502

 	lastFrame  time.Time
 	cursorHeld bool
 	// traceFlips logs every completion with its timing; lastFlipAt is
-	// the previous frame flip's kernel timestamp.
+	// the previous frame flip's kernel timestamp (always kept).
+	// flipStats are reported and reset with the periodic stats. wantedAt
+	// is when the output first needed a frame since the last frame commit
+	// (0: none), taken by the commit into pendingFrame.
 	traceFlips bool
 	lastFlipAt time.Duration
+	flipStats  flipStats
+	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. See vrr_flip_gap.go.
+	// flipGapUntil is when the next frame may commit: the gap from the
+	// time the flip event was read, as the workaround was measured. See
+	// vrr_flip_gap.go.
 	vrrFlipGap   time.Duration
 	flipGapUntil time.Time
+	// flipGapAt is the end of the gap from the flip's kernel timestamp
+	// (CLOCK_MONOTONIC), kept until the frame it held commits. It differs
+	// from flipGapUntil on purpose: the flip stats must not hide a late
+	// read of the event inside the gap.
+	flipGapAt time.Duration
 	// wantOff is the latest Scene.Off: a client turned the display off.
 	// off: the CRTC is inactive for it. Every modeset (resume, recovery)
 	// follows wantOff, so a display turned off never lights up.
 	}
 	o.modeBlob = blob
 	o.vrrOn, o.vrrGame, o.overlayOn, o.off = false, false, 0, !active
-	// The gap and the traced flip interval belonged to the old state.
+	// The gap and the flip interval belonged to the old state.
-	o.flipGapUntil, o.lastFlipAt = time.Time{}, 0
+	o.flipGapUntil, o.flipGapAt, o.lastFlipAt = time.Time{}, 0, 0
 	o.contentValue, o.contentWanted = o.contentValues[0], o.contentValues[0]
 	o.planeRect = fullPlaneRect(o.Width(), o.Height())
 	if o.cursor != nil {
 	if err := o.k.commit(req, atomicAllowModes, 0); err != nil {
 		return fmt.Errorf("power off: %w", err)
 	}
-	o.off, o.vrrOn, o.vrrGame = true, false, false
+	o.off, o.vrrGame = true, false
+	o.setVRR(false)
 	o.contentValue, o.contentWanted = o.contentValues[0], o.contentValues[0]
 	o.log.Info().Str("connector", o.conn.name).Msg("power off")
 	// An inactive output offers neither HDR nor direct scanout.
 		if o.vrrOn != vrr {
 			o.log.Info().Bool("vrr", vrr).Str("connector", o.conn.name).Msg("vrr")
 		}
-		o.vrrOn = vrr
+		o.setVRR(vrr)
 	}
 	if o.cursor != nil {
 		// An async commit leaves the cursor plane as applied.
 	o.planeRect = rect
 	o.lastFrame, o.cursorHeld = time.Now(), false
 	f.frame, f.async = true, async
+	f.wantedAt, o.wantedAt = o.wantedAt, 0
+	f.gapEnd, o.flipGapAt = o.flipGapAt, 0
 	f.fences = dupFences(fence, ov.acquire)
 	if o.traceFlips {
 		f.fenceReady = signalled(f.fences)
 	if vrr != o.vrrOn {
 		o.log.Info().Bool("vrr", vrr).Str("connector", o.conn.name).Msg("vrr")
 	}
-	o.vrrOn = vrr
+	o.setVRR(vrr)
 	o.contentValue = o.contentWanted
 	o.frame.begin(pendingFrame{}, time.Now())
 	return nil
 	for {
 		if o.observeSecurity() || haveScene && !o.sceneCurrent(scene) {
 			scene, haveScene, dirty = ports.Scene{}, false, false
+			o.wantedAt = 0
 			want, cursorScale, cursorTransform = ports.CursorChange{}, -1, 0
 			if o.cursor != nil {
 				o.cursor.image, o.cursor.later = false, nil
 				cs := o.cursor.TakeStats()
 				ev = ev.Int("cursor_moves", cs.Moves).Int("cursor_commits", cs.Commits)
 			}
+			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())
+			if o.traceFlips {
+				ev = ev.Int("late_fences", fs.lateFences)
+			}
 			ev.Msg("stats")
 		}
+		// A frame wanted while the previous one is in flight is due at
+		// that flip: accountFlip never counts it before.
+		if dirty && haveScene && o.wantedAt == 0 {
+			o.wantedAt = monotonic()
+		}
 		o.observeSecurity()
 		if haveScene && !o.sceneCurrent(scene) {
 			continue
 	return false
 }
+// flipDone times the completion ev of the commit f made at start: the
+// flip stats, the flip trace and the VRR flip gap. It never allocates
+// with tracing off.
+func (o *Output) flipDone(ev flipEvent, f pendingFrame, start time.Time, ours, trace bool, fenceAt time.Duration) {
+	readAt := time.Now()
+	now := monotonic()
+	commitAt := now - readAt.Sub(start)
+	if ours {
+		o.accountRead(ev, now)
+	}
+	if trace {
+		o.traceFlip(ev, f, commitAt, now, o.lastFlipAt, fenceAt)
+	}
+	o.accountFlip(ev, f.frame, f.dueAt(), commitAt, fenceAt)
+	o.startFlipGap(f, ev.when, readAt)
+}
 // completed handles the event of the pending commit: a flipped frame is
 // reported with its kernel timestamp. It reports false for an event of
 // another commit, which is dropped.
 func (o *Output) completed(ev flipEvent, seen map[ports.WindowID]uint64) bool {
 	// Only a commit of ours is traced: not a stale event, nor the end of
 	// an EBUSY wait. Its fences are read before flip closes them.
-	trace := o.traceFlips && o.frame.ours(ev.user)
+	ours := o.frame.ours(ev.user)
+	trace := o.traceFlips && ours
 	var fenceAt time.Duration
 	if trace {
 		fenceAt = fencesSignalledAt(o.frame.pendingFrame.fences)
 	if !ok {
 		return false
 	}
-	if trace {
+	o.flipDone(ev, f, start, ours, trace, fenceAt)
-		o.traceFlip(ev, f, start, fenceAt)
-	}
-	o.startFlipGap(f)
-	if age := time.Since(start); age > 20*time.Millisecond {
-		o.log.Info().Dur("flip_ms", age).Bool("frame", f.frame).Bool("vrr", o.vrrOn).Str("connector", o.conn.name).Msg("slow flip")
-	}
 	if o.cursor != nil {
 		o.cursor.landed()
 	}
 	if o.queued == f.queued {
 		o.queued = 0
 	}
-	refresh := time.Duration(0)
+	o.report(&ports.FlipInfo{When: ev.when, Seq: uint64(ev.seq), Refresh: o.refreshPeriod(), ZeroCopy: f.zeroCopy, Async: f.async, HardwareClock: true, Shows: f.shows}, seen)
-	if !o.vrrOn {
-		refresh = time.Duration(int64(time.Second) * 1000 / int64(max(1, o.mode.refreshMilli())))
-	}
-	o.report(&ports.FlipInfo{When: ev.when, Seq: uint64(ev.seq), Refresh: refresh, ZeroCopy: f.zeroCopy, Async: f.async, HardwareClock: true, Shows: f.shows}, seen)
 	return true
 }

M internal/adapters/drm/output_test.go +129 -0

@@ -1,10 +1,12 @@
1	1		package drm
2	2
3	3		import (
	4	+	"bytes"
4	5		"context"
5	6		"errors"
6	7		"image"
7	8		"os"
	9	+	"strings"
8	10		"sync"
9	11		"sync/atomic"
10	12		"testing"

@@ -732,6 +734,10 @@ func TestRunTrimsRendererOnStatsTick(t *testing.T) {
732	734		r := portsmocks.NewMockRenderer(t)
733	735		r.EXPECT().SetHDR(float64(0)).Return().Maybe()
734	736		r.EXPECT().Close().Return().Once()
	737	+	r.EXPECT().TakeRedrawn().Return(1234).Once()
	738	+	var statsLog bytes.Buffer // written by Run's goroutine, read after it ends
	739	+	o.log = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &statsLog})
	740	+	o.flipStats = flipStats{missedVblanks: 3, maxInterval: 50 * time.Millisecond, maxFlipToRead: 25 * time.Millisecond, lateFences: 2}
735	741		trimmed := make(chan struct{}, 2)
736	742		failure := os.ErrInvalid
737	743		calls := 0 // Run's goroutine only

@@ -757,6 +763,15 @@ func TestRunTrimsRendererOnStatsTick(t *testing.T) {
757	763		if err := <-done; !errors.Is(err, failure) {
758	764		t.Fatalf("run: %v", err)
759	765		}
	766	+	// Reported once, then reset. late_fences needs flip tracing.
	767	+	for _, want := range []string{`"message":"stats"`, `"missed_vblanks":3`, `"max_flip_interval_ms":50`, `"max_flip_to_read_ms":25`, `"redrawn_pixels":1234`} {
	768	+	if !strings.Contains(statsLog.String(), want) {
	769	+	t.Fatalf("stats entry lacks %s: %s", want, statsLog.String())
	770	+	}
	771	+	}
	772	+	if strings.Contains(statsLog.String(), "late_fences") \|\| o.flipStats != (flipStats{}) {
	773	+	t.Fatalf("late fences untraced or stats not reset: %s %+v", statsLog.String(), o.flipStats)
	774	+	}
760	775		}
761	776
762	777		// A render failure must complete captures queued before the first frame.

@@ -922,3 +937,117 @@ func TestRunPanicReportsReadinessError(t *testing.T) {
922	937		}()
923	938		o.Run(context.Background(), func(int, int) (ports.Renderer, error) { panic("renderer panic") }, nil, nil, nil, nil, nil, nil, nil, nil)
924	939		}
	940	+
	941	+	// stampRun starts Run on an output with unbuffered scene and content
	942	+	// channels: a send completes once Run took the message, and the next send
	943	+	// once it went round its loop again, which is the sync point for what the
	944	+	// loop did with the first.
	945	+	type stampRun struct {
	946	+	o *Output
	947	+	scenes chan ports.Scene
	948	+	contents chan ports.SurfaceContent
	949	+	flips chan flipEvent
	950	+	wake chan ports.SecurityState
	951	+	state *atomic.Uint64
	952	+	frameCommit func() int
	953	+	lastCommit func() commitRec
	954	+	stop func()
	955	+	}
	956	+
	957	+	func startStampRun(t testing.T) stampRun {
	958	+	o, k, commits, commitMu := testOutputMu(t)
	959	+	o.cursor, o.tearing = nil, false
	960	+	sr := &stampRun{o: o, scenes: make(chan ports.Scene), contents: make(chan ports.SurfaceContent), flips: make(chan flipEvent, 1), wake: make(chan ports.SecurityState, 1), state: &atomic.Uint64{}}
	961	+	o.flipped = sr.flips
	962	+	securityGate(t, o, sr.state)
	963	+	o.SecurityChanges = sr.wake
	964	+	r := portsmocks.NewMockRenderer(t)
	965	+	pipeBuf := func() ports.DMABuf {
	966	+	f, w, _ := os.Pipe()
	967	+	w.Close()
	968	+	return ports.DMABuf{Planes: []ports.DMABufPlane{{File: f}}}
	969	+	}
	970	+	r.EXPECT().SetHDR(float64(0)).Return().Maybe()
	971	+	r.EXPECT().ExportTargets(2, mock.Anything).Return([]ports.DMABuf{pipeBuf(), pipeBuf()}, nil).Once()
	972	+	r.EXPECT().UseTarget(mock.Anything).Return()
	973	+	r.EXPECT().Render(mock.Anything, mock.Anything).Return(nil, nil)
	974	+	r.EXPECT().Close().Return().Once()
	975	+	k.EXPECT().addFB(mock.Anything, uint32(fourccXRGB)).Return(70, nil).Twice()
	976	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil)
	977	+	k.EXPECT().destroyBlob(mock.Anything).Return(nil).Maybe()
	978	+	k.EXPECT().rmFB(mock.Anything).Return(nil).Maybe()
	979	+	sr.frameCommit = func() int {
	980	+	commitMu.Lock()
	981	+	defer commitMu.Unlock()
	982	+	n := 0
	983	+	for _, c := range *commits {
	984	+	if c.user&3 == userFrame {
	985	+	n++
	986	+	}
	987	+	}
	988	+	return n
	989	+	}
	990	+	sr.lastCommit = func() commitRec {
	991	+	commitMu.Lock()
	992	+	defer commitMu.Unlock()
	993	+	return (commits)[len(commits)-1]
	994	+	}
	995	+	ctx, cancel := context.WithCancel(context.Background())
	996	+	done := make(chan error, 1)
	997	+	go func() {
	998	+	done <- o.Run(ctx, func(int, int) (ports.Renderer, error) { return r, nil }, nil, make(chan bool), sr.scenes, sr.contents, nil, make(chan ports.OutputPresented, 8), nil, nil)
	999	+	}()
	1000	+	// stop ends Run: its state is ours to read afterwards.
	1001	+	sr.stop = func() {
	1002	+	cancel()
	1003	+	if err := <-done; err != nil {
	1004	+	t.Fatal(err)
	1005	+	}
	1006	+	}
	1007	+	return sr
	1008	+	}
	1009	+
	1010	+	// Run: a frame wanted while the previous one is in flight is stamped when
	1011	+	// it becomes dirty, and the commit that follows takes the stamp.
	1012	+	func TestRunStampsWhenFrameWasWanted(t *testing.T) {
	1013	+	sr := startStampRun(t)
	1014	+	scene := ports.Scene{OutputWidth: 200, OutputHeight: 100, Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 10, H: 10}}}}
	1015	+	sr.scenes <- scene
	1016	+	waitFor(t, func() bool { return sr.frameCommit() == 1 })
	1017	+	// Frame 1 is in flight: a new scene arrives and waits.
	1018	+	last := sr.lastCommit()
	1019	+	scene.Seq = 2
	1020	+	before := monotonic()
	1021	+	sr.scenes <- scene
	1022	+	sr.contents <- ports.SurfaceContent{ID: 1, Seq: 1, SHM: &ports.SHMBuffer{}} // Run went round its loop
	1023	+	flipSent := monotonic()
	1024	+	sr.flips <- flipEvent{crtc: tCrtc, user: last.user, when: time.Second, seq: 1}
	1025	+	waitFor(t, func() bool { return sr.frameCommit() == 2 })
	1026	+	sr.stop()
	1027	+	if sr.o.wantedAt != 0 {
	1028	+	t.Fatalf("stamp left after the commit: %s", sr.o.wantedAt)
	1029	+	}
	1030	+	f := sr.o.frame.pendingFrame
	1031	+	if !f.frame \|\| f.wantedAt < before \|\| f.wantedAt >= flipSent {
	1032	+	t.Fatalf("second frame (%v) wanted at %s, scene sent at %s, flip sent at %s", f.frame, f.wantedAt, before, flipSent)
	1033	+	}
	1034	+	}
	1035	+
	1036	+	// A change of security state drops the scene, and with it the stamp of
	1037	+	// the frame it wanted.
	1038	+	func TestRunSecurityResetClearsWantedAt(t *testing.T) {
	1039	+	sr := startStampRun(t)
	1040	+	scene := ports.Scene{OutputWidth: 200, OutputHeight: 100, Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 10, H: 10}}}}
	1041	+	sr.scenes <- scene
	1042	+	waitFor(t, func() bool { return sr.frameCommit() == 1 })
	1043	+	scene.Seq = 2
	1044	+	sr.scenes <- scene
	1045	+	sr.contents <- ports.SurfaceContent{ID: 1, Seq: 1, SHM: &ports.SHMBuffer{}} // stamped by now
	1046	+	sr.state.Store(2) // a new security generation, not protected
	1047	+	sr.wake <- ports.SecurityState{}
	1048	+	sr.contents <- ports.SurfaceContent{ID: 1, Seq: 2, SHM: &ports.SHMBuffer{}} // Run went round and reset
	1049	+	sr.stop()
	1050	+	if sr.o.wantedAt != 0 {
	1051	+	t.Fatalf("stamp kept across the security reset: %s", sr.o.wantedAt)
	1052	+	}
	1053	+	}

@@ -1,10 +1,12 @@
1	package drm	1		package drm
2		2
3	import (	3		import (
		4	+	"bytes"
4	"context"	5		"context"
5	"errors"	6		"errors"
6	"image"	7		"image"
7	"os"	8		"os"
		9	+	"strings"
8	"sync"	10		"sync"
9	"sync/atomic"	11		"sync/atomic"
10	"testing"	12		"testing"

@@ -732,6 +734,10 @@ func TestRunTrimsRendererOnStatsTick(t *testing.T) {
732	r := portsmocks.NewMockRenderer(t)	734		r := portsmocks.NewMockRenderer(t)
733	r.EXPECT().SetHDR(float64(0)).Return().Maybe()	735		r.EXPECT().SetHDR(float64(0)).Return().Maybe()
734	r.EXPECT().Close().Return().Once()	736		r.EXPECT().Close().Return().Once()
		737	+	r.EXPECT().TakeRedrawn().Return(1234).Once()
		738	+	var statsLog bytes.Buffer // written by Run's goroutine, read after it ends
		739	+	o.log = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &statsLog})
		740	+	o.flipStats = flipStats{missedVblanks: 3, maxInterval: 50 * time.Millisecond, maxFlipToRead: 25 * time.Millisecond, lateFences: 2}
735	trimmed := make(chan struct{}, 2)	741		trimmed := make(chan struct{}, 2)
736	failure := os.ErrInvalid	742		failure := os.ErrInvalid
737	calls := 0 // Run's goroutine only	743		calls := 0 // Run's goroutine only

@@ -757,6 +763,15 @@ func TestRunTrimsRendererOnStatsTick(t *testing.T) {
757	if err := <-done; !errors.Is(err, failure) {	763		if err := <-done; !errors.Is(err, failure) {
758	t.Fatalf("run: %v", err)	764		t.Fatalf("run: %v", err)
759	}	765		}
		766	+	// Reported once, then reset. late_fences needs flip tracing.
		767	+	for _, want := range []string{`"message":"stats"`, `"missed_vblanks":3`, `"max_flip_interval_ms":50`, `"max_flip_to_read_ms":25`, `"redrawn_pixels":1234`} {
		768	+	if !strings.Contains(statsLog.String(), want) {
		769	+	t.Fatalf("stats entry lacks %s: %s", want, statsLog.String())
		770	+	}
		771	+	}
		772	+	if strings.Contains(statsLog.String(), "late_fences") \|\| o.flipStats != (flipStats{}) {
		773	+	t.Fatalf("late fences untraced or stats not reset: %s %+v", statsLog.String(), o.flipStats)
		774	+	}
760	}	775		}
761		776
762	// A render failure must complete captures queued before the first frame.	777		// A render failure must complete captures queued before the first frame.

@@ -922,3 +937,117 @@ func TestRunPanicReportsReadinessError(t *testing.T) {
922	}()	937		}()
923	o.Run(context.Background(), func(int, int) (ports.Renderer, error) { panic("renderer panic") }, nil, nil, nil, nil, nil, nil, nil, nil)	938		o.Run(context.Background(), func(int, int) (ports.Renderer, error) { panic("renderer panic") }, nil, nil, nil, nil, nil, nil, nil, nil)
924	}	939		}
		940	+
		941	+	// stampRun starts Run on an output with unbuffered scene and content
		942	+	// channels: a send completes once Run took the message, and the next send
		943	+	// once it went round its loop again, which is the sync point for what the
		944	+	// loop did with the first.
		945	+	type stampRun struct {
		946	+	o *Output
		947	+	scenes chan ports.Scene
		948	+	contents chan ports.SurfaceContent
		949	+	flips chan flipEvent
		950	+	wake chan ports.SecurityState
		951	+	state *atomic.Uint64
		952	+	frameCommit func() int
		953	+	lastCommit func() commitRec
		954	+	stop func()
		955	+	}
		956	+
		957	+	func startStampRun(t testing.T) stampRun {
		958	+	o, k, commits, commitMu := testOutputMu(t)
		959	+	o.cursor, o.tearing = nil, false
		960	+	sr := &stampRun{o: o, scenes: make(chan ports.Scene), contents: make(chan ports.SurfaceContent), flips: make(chan flipEvent, 1), wake: make(chan ports.SecurityState, 1), state: &atomic.Uint64{}}
		961	+	o.flipped = sr.flips
		962	+	securityGate(t, o, sr.state)
		963	+	o.SecurityChanges = sr.wake
		964	+	r := portsmocks.NewMockRenderer(t)
		965	+	pipeBuf := func() ports.DMABuf {
		966	+	f, w, _ := os.Pipe()
		967	+	w.Close()
		968	+	return ports.DMABuf{Planes: []ports.DMABufPlane{{File: f}}}
		969	+	}
		970	+	r.EXPECT().SetHDR(float64(0)).Return().Maybe()
		971	+	r.EXPECT().ExportTargets(2, mock.Anything).Return([]ports.DMABuf{pipeBuf(), pipeBuf()}, nil).Once()
		972	+	r.EXPECT().UseTarget(mock.Anything).Return()
		973	+	r.EXPECT().Render(mock.Anything, mock.Anything).Return(nil, nil)
		974	+	r.EXPECT().Close().Return().Once()
		975	+	k.EXPECT().addFB(mock.Anything, uint32(fourccXRGB)).Return(70, nil).Twice()
		976	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil)
		977	+	k.EXPECT().destroyBlob(mock.Anything).Return(nil).Maybe()
		978	+	k.EXPECT().rmFB(mock.Anything).Return(nil).Maybe()
		979	+	sr.frameCommit = func() int {
		980	+	commitMu.Lock()
		981	+	defer commitMu.Unlock()
		982	+	n := 0
		983	+	for _, c := range *commits {
		984	+	if c.user&3 == userFrame {
		985	+	n++
		986	+	}
		987	+	}
		988	+	return n
		989	+	}
		990	+	sr.lastCommit = func() commitRec {
		991	+	commitMu.Lock()
		992	+	defer commitMu.Unlock()
		993	+	return (commits)[len(commits)-1]
		994	+	}
		995	+	ctx, cancel := context.WithCancel(context.Background())
		996	+	done := make(chan error, 1)
		997	+	go func() {
		998	+	done <- o.Run(ctx, func(int, int) (ports.Renderer, error) { return r, nil }, nil, make(chan bool), sr.scenes, sr.contents, nil, make(chan ports.OutputPresented, 8), nil, nil)
		999	+	}()
		1000	+	// stop ends Run: its state is ours to read afterwards.
		1001	+	sr.stop = func() {
		1002	+	cancel()
		1003	+	if err := <-done; err != nil {
		1004	+	t.Fatal(err)
		1005	+	}
		1006	+	}
		1007	+	return sr
		1008	+	}
		1009	+
		1010	+	// Run: a frame wanted while the previous one is in flight is stamped when
		1011	+	// it becomes dirty, and the commit that follows takes the stamp.
		1012	+	func TestRunStampsWhenFrameWasWanted(t *testing.T) {
		1013	+	sr := startStampRun(t)
		1014	+	scene := ports.Scene{OutputWidth: 200, OutputHeight: 100, Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 10, H: 10}}}}
		1015	+	sr.scenes <- scene
		1016	+	waitFor(t, func() bool { return sr.frameCommit() == 1 })
		1017	+	// Frame 1 is in flight: a new scene arrives and waits.
		1018	+	last := sr.lastCommit()
		1019	+	scene.Seq = 2
		1020	+	before := monotonic()
		1021	+	sr.scenes <- scene
		1022	+	sr.contents <- ports.SurfaceContent{ID: 1, Seq: 1, SHM: &ports.SHMBuffer{}} // Run went round its loop
		1023	+	flipSent := monotonic()
		1024	+	sr.flips <- flipEvent{crtc: tCrtc, user: last.user, when: time.Second, seq: 1}
		1025	+	waitFor(t, func() bool { return sr.frameCommit() == 2 })
		1026	+	sr.stop()
		1027	+	if sr.o.wantedAt != 0 {
		1028	+	t.Fatalf("stamp left after the commit: %s", sr.o.wantedAt)
		1029	+	}
		1030	+	f := sr.o.frame.pendingFrame
		1031	+	if !f.frame \|\| f.wantedAt < before \|\| f.wantedAt >= flipSent {
		1032	+	t.Fatalf("second frame (%v) wanted at %s, scene sent at %s, flip sent at %s", f.frame, f.wantedAt, before, flipSent)
		1033	+	}
		1034	+	}
		1035	+
		1036	+	// A change of security state drops the scene, and with it the stamp of
		1037	+	// the frame it wanted.
		1038	+	func TestRunSecurityResetClearsWantedAt(t *testing.T) {
		1039	+	sr := startStampRun(t)
		1040	+	scene := ports.Scene{OutputWidth: 200, OutputHeight: 100, Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 10, H: 10}}}}
		1041	+	sr.scenes <- scene
		1042	+	waitFor(t, func() bool { return sr.frameCommit() == 1 })
		1043	+	scene.Seq = 2
		1044	+	sr.scenes <- scene
		1045	+	sr.contents <- ports.SurfaceContent{ID: 1, Seq: 1, SHM: &ports.SHMBuffer{}} // stamped by now
		1046	+	sr.state.Store(2) // a new security generation, not protected
		1047	+	sr.wake <- ports.SecurityState{}
		1048	+	sr.contents <- ports.SurfaceContent{ID: 1, Seq: 2, SHM: &ports.SHMBuffer{}} // Run went round and reset
		1049	+	sr.stop()
		1050	+	if sr.o.wantedAt != 0 {
		1051	+	t.Fatalf("stamp kept across the security reset: %s", sr.o.wantedAt)
		1052	+	}
		1053	+	}

M internal/adapters/drm/protection.go +2 -1


@@ -97,7 +97,8 @@ func (o *Output) disableProtected() error {
97	97		_ = o.k.destroyBlob(o.modeBlob) // MODE_ID is 0 now: nothing references it
98	98		o.modeBlob = 0
99	99		}
100		-	o.off, o.vrrOn, o.vrrGame, o.overlayOn = true, false, false, 0
	100	+	o.off, o.vrrGame, o.overlayOn = true, false, 0
	101	+	o.setVRR(false)
101	102		o.sendFormats()
102	103		o.shown, o.queued = 0, 0
103	104		if o.cursor != nil {

 		_ = o.k.destroyBlob(o.modeBlob) // MODE_ID is 0 now: nothing references it
 		o.modeBlob = 0
 	}
-	o.off, o.vrrOn, o.vrrGame, o.overlayOn = true, false, false, 0
+	o.off, o.vrrGame, o.overlayOn = true, false, 0
+	o.setVRR(false)
 	o.sendFormats()
 	o.shown, o.queued = 0, 0
 	if o.cursor != nil {

M internal/adapters/drm/vrr_flip_gap.go +8 -4


@@ -40,13 +40,17 @@ import "time"
40	40		// startFlipGap is called on each completed commit f: after a game frame's
41	41		// flip under VRR, the next frame waits vrrFlipGap before it commits. A
42	42		// state commit (cursor, VRR toggle) completing inside the gap keeps it:
43		-	// the next frame still follows the last frame flip.
44		-	func (o *Output) startFlipGap(f pendingFrame) {
	43	+	// the next frame still follows the last frame flip. The commit gate runs
	44	+	// from readAt, when the event was read (what the workaround was measured
	45	+	// with); the flip stats' gap end runs from when, the flip's kernel
	46	+	// timestamp, so a late read of the event still shows as a commit delay.
	47	+	func (o *Output) startFlipGap(f pendingFrame, when time.Duration, readAt time.Time) {
45	48		if !f.frame {
46	49		return
47	50		}
48		-	o.flipGapUntil = time.Time{}
	51	+	o.flipGapUntil, o.flipGapAt = time.Time{}, 0
49	52		if o.vrrFlipGap > 0 && o.vrrOn && o.vrrGame {
50		-	o.flipGapUntil = time.Now().Add(o.vrrFlipGap)
	53	+	o.flipGapUntil = readAt.Add(o.vrrFlipGap)
	54	+	o.flipGapAt = when + o.vrrFlipGap
51	55		}
52	56		}

 // startFlipGap is called on each completed commit f: after a game frame's
 // flip under VRR, the next frame waits vrrFlipGap before it commits. A
 // state commit (cursor, VRR toggle) completing inside the gap keeps it:
-// the next frame still follows the last frame flip.
+// the next frame still follows the last frame flip. The commit gate runs
-func (o *Output) startFlipGap(f pendingFrame) {
+// from readAt, when the event was read (what the workaround was measured
+// with); the flip stats' gap end runs from when, the flip's kernel
+// timestamp, so a late read of the event still shows as a commit delay.
+func (o *Output) startFlipGap(f pendingFrame, when time.Duration, readAt time.Time) {
 	if !f.frame {
 		return
 	}
-	o.flipGapUntil = time.Time{}
+	o.flipGapUntil, o.flipGapAt = time.Time{}, 0
 	if o.vrrFlipGap > 0 && o.vrrOn && o.vrrGame {
-		o.flipGapUntil = time.Now().Add(o.vrrFlipGap)
+		o.flipGapUntil = readAt.Add(o.vrrFlipGap)
+		o.flipGapAt = when + o.vrrFlipGap
 	}
 }

M internal/adapters/drm/vrr_flip_gap_test.go +1 -1


@@ -32,7 +32,7 @@ func TestStartFlipGap(t *testing.T) {
32	32		pending = time.Now().Add(time.Hour)
33	33		}
34	34		o := &Output{vrrFlipGap: tc.gap, vrrOn: tc.vrr, vrrGame: tc.game, flipGapUntil: pending}
35		-	o.startFlipGap(pendingFrame{frame: tc.frame})
	35	+	o.startFlipGap(pendingFrame{frame: tc.frame}, monotonic(), time.Now())
36	36		if got := !o.flipGapUntil.IsZero(); got != tc.want {
37	37		t.Errorf("%s: gap started %v, want %v", tc.name, got, tc.want)
38	38		}


@@ -32,7 +32,7 @@ func TestStartFlipGap(t *testing.T) {
32		pending = time.Now().Add(time.Hour)	32		pending = time.Now().Add(time.Hour)
33		}	33		}
34		o := &Output{vrrFlipGap: tc.gap, vrrOn: tc.vrr, vrrGame: tc.game, flipGapUntil: pending}	34		o := &Output{vrrFlipGap: tc.gap, vrrOn: tc.vrr, vrrGame: tc.game, flipGapUntil: pending}
35	-	o.startFlipGap(pendingFrame{frame: tc.frame})	35	+	o.startFlipGap(pendingFrame{frame: tc.frame}, monotonic(), time.Now())
36		if got := !o.flipGapUntil.IsZero(); got != tc.want {	36		if got := !o.flipGapUntil.IsZero(); got != tc.want {
37		t.Errorf("%s: gap started %v, want %v", tc.name, got, tc.want)	37		t.Errorf("%s: gap started %v, want %v", tc.name, got, tc.want)
38		}	38		}

A internal/adapters/vulkan/redrawn_test.go +13 -0

@@ -0,0 +1,13 @@
	1	+	package vulkan
	2	+
	3	+	import "testing"
	4	+
	5	+	func TestTakeRedrawnResets(t *testing.T) {
	6	+	r := &Renderer{redrawn: 4096}
	7	+	if got := r.TakeRedrawn(); got != 4096 {
	8	+	t.Fatalf("taken %d", got)
	9	+	}
	10	+	if got := r.TakeRedrawn(); got != 0 {
	11	+	t.Fatalf("after reset %d", got)
	12	+	}
	13	+	}

@@ -0,0 +1,13 @@
	1	+	package vulkan
	2	+
	3	+	import "testing"
	4	+
	5	+	func TestTakeRedrawnResets(t *testing.T) {
	6	+	r := &Renderer{redrawn: 4096}
	7	+	if got := r.TakeRedrawn(); got != 4096 {
	8	+	t.Fatalf("taken %d", got)
	9	+	}
	10	+	if got := r.TakeRedrawn(); got != 0 {
	11	+	t.Fatalf("after reset %d", got)
	12	+	}
	13	+	}

M internal/adapters/vulkan/renderer.go +9 -1


@@ -72,7 +72,7 @@ type Renderer struct {
72	72		copied int
73	73		// marks date the frames for Trim's wall-clock eviction (trim.go).
74	74		marks []trimMark
75		-	// redrawn counts the target pixels drawn, for tests.
	75	+	// redrawn counts the target pixels drawn (TakeRedrawn).
76	76		redrawn int
77	77		// cursors are the exported cursor images (CursorBuffers).
78	78		cursors [2]*cursorImage

@@ -325,6 +325,14 @@ func (r *Renderer) findMemoryType(bits uint32, props vk.MemoryPropertyFlags) (ui
325	325		// It is diagnostic only and must be read by the renderer's owner goroutine.
326	326		func (r *Renderer) CopiedBytes() int { return r.copied }
327	327
	328	+	// TakeRedrawn returns the target pixels drawn since the last call and
	329	+	// resets the count.
	330	+	func (r *Renderer) TakeRedrawn() int {
	331	+	n := r.redrawn
	332	+	r.redrawn = 0
	333	+	return n
	334	+	}
	335	+
328	336		// QueuePriority is the global priority the queue got: realtime, high or
329	337		// default.
330	338		func (r *Renderer) QueuePriority() string { return r.queuePriority }

 	copied int
 	// marks date the frames for Trim's wall-clock eviction (trim.go).
 	marks []trimMark
-	// redrawn counts the target pixels drawn, for tests.
+	// redrawn counts the target pixels drawn (TakeRedrawn).
 	redrawn int
 	// cursors are the exported cursor images (CursorBuffers).
 	cursors [2]*cursorImage
 // It is diagnostic only and must be read by the renderer's owner goroutine.
 func (r *Renderer) CopiedBytes() int { return r.copied }
+// TakeRedrawn returns the target pixels drawn since the last call and
+// resets the count.
+func (r *Renderer) TakeRedrawn() int {
+	n := r.redrawn
+	r.redrawn = 0
+	return n
+}
 // QueuePriority is the global priority the queue got: realtime, high or
 // default.
 func (r *Renderer) QueuePriority() string { return r.queuePriority }

M internal/mocks/ports/devices_mock.go +44 -0


@@ -606,6 +606,50 @@ func (_c MockRenderer_SetHDR_Call) RunAndReturn(run func(sdrNits float64)) Moc
606	606		return _c
607	607		}
608	608
	609	+	// TakeRedrawn provides a mock function for the type MockRenderer
	610	+	func (_mock *MockRenderer) TakeRedrawn() int {
	611	+	ret := _mock.Called()
	612	+
	613	+	if len(ret) == 0 {
	614	+	panic("no return value specified for TakeRedrawn")
	615	+	}
	616	+
	617	+	var r0 int
	618	+	if returnFunc, ok := ret.Get(0).(func() int); ok {
	619	+	r0 = returnFunc()
	620	+	} else {
	621	+	r0 = ret.Get(0).(int)
	622	+	}
	623	+	return r0
	624	+	}
	625	+
	626	+	// MockRenderer_TakeRedrawn_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'TakeRedrawn'
	627	+	type MockRenderer_TakeRedrawn_Call struct {
	628	+	*mock.Call
	629	+	}
	630	+
	631	+	// TakeRedrawn is a helper method to define mock.On call
	632	+	func (_e MockRenderer_Expecter) TakeRedrawn() MockRenderer_TakeRedrawn_Call {
	633	+	return &MockRenderer_TakeRedrawn_Call{Call: _e.mock.On("TakeRedrawn")}
	634	+	}
	635	+
	636	+	func (_c MockRenderer_TakeRedrawn_Call) Run(run func()) MockRenderer_TakeRedrawn_Call {
	637	+	_c.Call.Run(func(args mock.Arguments) {
	638	+	run()
	639	+	})
	640	+	return _c
	641	+	}
	642	+
	643	+	func (_c MockRenderer_TakeRedrawn_Call) Return(n int) MockRenderer_TakeRedrawn_Call {
	644	+	_c.Call.Return(n)
	645	+	return _c
	646	+	}
	647	+
	648	+	func (_c MockRenderer_TakeRedrawn_Call) RunAndReturn(run func() int) MockRenderer_TakeRedrawn_Call {
	649	+	_c.Call.Return(run)
	650	+	return _c
	651	+	}
	652	+
609	653		// Trim provides a mock function for the type MockRenderer
610	654		func (_mock *MockRenderer) Trim(now time.Time) error {
611	655		ret := _mock.Called(now)


@@ -606,6 +606,50 @@ func (_c MockRenderer_SetHDR_Call) RunAndReturn(run func(sdrNits float64)) Moc
606	return _c	606		return _c
607	}	607		}
608		608
		609	+	// TakeRedrawn provides a mock function for the type MockRenderer
		610	+	func (_mock *MockRenderer) TakeRedrawn() int {
		611	+	ret := _mock.Called()
		612	+
		613	+	if len(ret) == 0 {
		614	+	panic("no return value specified for TakeRedrawn")
		615	+	}
		616	+
		617	+	var r0 int
		618	+	if returnFunc, ok := ret.Get(0).(func() int); ok {
		619	+	r0 = returnFunc()
		620	+	} else {
		621	+	r0 = ret.Get(0).(int)
		622	+	}
		623	+	return r0
		624	+	}
		625	+
		626	+	// MockRenderer_TakeRedrawn_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'TakeRedrawn'
		627	+	type MockRenderer_TakeRedrawn_Call struct {
		628	+	*mock.Call
		629	+	}
		630	+
		631	+	// TakeRedrawn is a helper method to define mock.On call
		632	+	func (_e MockRenderer_Expecter) TakeRedrawn() MockRenderer_TakeRedrawn_Call {
		633	+	return &MockRenderer_TakeRedrawn_Call{Call: _e.mock.On("TakeRedrawn")}
		634	+	}
		635	+
		636	+	func (_c MockRenderer_TakeRedrawn_Call) Run(run func()) MockRenderer_TakeRedrawn_Call {
		637	+	_c.Call.Run(func(args mock.Arguments) {
		638	+	run()
		639	+	})
		640	+	return _c
		641	+	}
		642	+
		643	+	func (_c MockRenderer_TakeRedrawn_Call) Return(n int) MockRenderer_TakeRedrawn_Call {
		644	+	_c.Call.Return(n)
		645	+	return _c
		646	+	}
		647	+
		648	+	func (_c MockRenderer_TakeRedrawn_Call) RunAndReturn(run func() int) MockRenderer_TakeRedrawn_Call {
		649	+	_c.Call.Return(run)
		650	+	return _c
		651	+	}
		652	+
609	// Trim provides a mock function for the type MockRenderer	653		// Trim provides a mock function for the type MockRenderer
610	func (_mock *MockRenderer) Trim(now time.Time) error {	654		func (_mock *MockRenderer) Trim(now time.Time) error {
611	ret := _mock.Called(now)	655		ret := _mock.Called(now)

M internal/ports/devices.go +3 -0


@@ -74,6 +74,9 @@ type Renderer interface {
74	74		// finished frames held, without rendering. Outputs call it
75	75		// periodically: an idle output renders no frame to free them.
76	76		Trim(now time.Time) error
	77	+	// TakeRedrawn returns the target pixels drawn since the last call
	78	+	// (damage-limited frames count their damage only) and starts over.
	79	+	TakeRedrawn() int
77	80		Close()
78	81		}
79	82


@@ -74,6 +74,9 @@ type Renderer interface {
74	// finished frames held, without rendering. Outputs call it	74		// finished frames held, without rendering. Outputs call it
75	// periodically: an idle output renders no frame to free them.	75		// periodically: an idle output renders no frame to free them.
76	Trim(now time.Time) error	76		Trim(now time.Time) error
		77	+	// TakeRedrawn returns the target pixels drawn since the last call
		78	+	// (damage-limited frames count their damage only) and starts over.
		79	+	TakeRedrawn() int
77	Close()	80		Close()
78	}	81		}
79		82