1d16b83 fix(drm): keep a gap after each VRR game flip (#63) · neferwl

M Makefile +4 -2


@@ -2,17 +2,19 @@
2	2
3	3		# 0 runs until quit; set e.g. TTY_TIMEOUT=60s for a safety net.
4	4		TTY_TIMEOUT ?= 0
	5	+	comma := ,
5	6		# Go runtime profiles for tty runs; set PPROF= to disable.
6	7		PPROF ?= localhost:6060
7		-	RUNS := $(or $(XDG_STATE_HOME),$(HOME)/.local/state)/neferwl/runs
	8	+	RUNS := $(or $(XDG_STATE_HOME),$(HOME)/.local/state)/neferwl/runs/drm
8	9
9	10		# Build a fresh binary with the git revision embedded.
10	11		bin:
11	12		CGO_ENABLED=0 go build -o bin/neferwl ./cmd/neferwl
12	13
13	14		# Run on the current TTY. Quit: Ctrl+Alt+Backspace (or the quit bind).
	15	+	# TTY_DEBUG adds narrow categories, e.g. TTY_DEBUG=drm-flip.
14	16		tty: bin
15		-	./bin/neferwl --backend=drm --debug=all --timeout=$(TTY_TIMEOUT) $(if $(PPROF),--pprof=$(PPROF)); \
	17	+	./bin/neferwl --backend=drm --debug=all$(if $(TTY_DEBUG),$(comma)$(TTY_DEBUG)) --timeout=$(TTY_TIMEOUT) $(if $(PPROF),--pprof=$(PPROF)); \
16	18		echo "exit $$? - log: $(RUNS)/latest.log"
17	19
18	20		# Summarise the last run: lifecycle, warnings and errors.

 # 0 runs until quit; set e.g. TTY_TIMEOUT=60s for a safety net.
 TTY_TIMEOUT ?= 0
+comma := ,
 # Go runtime profiles for tty runs; set PPROF= to disable.
 PPROF ?= localhost:6060
-RUNS := $(or $(XDG_STATE_HOME),$(HOME)/.local/state)/neferwl/runs
+RUNS := $(or $(XDG_STATE_HOME),$(HOME)/.local/state)/neferwl/runs/drm
 # Build a fresh binary with the git revision embedded.
 bin:
 	CGO_ENABLED=0 go build -o bin/neferwl ./cmd/neferwl
 # Run on the current TTY. Quit: Ctrl+Alt+Backspace (or the quit bind).
+# TTY_DEBUG adds narrow categories, e.g. TTY_DEBUG=drm-flip.
 tty: bin
-	./bin/neferwl --backend=drm --debug=all --timeout=$(TTY_TIMEOUT) $(if $(PPROF),--pprof=$(PPROF)); \
+	./bin/neferwl --backend=drm --debug=all$(if $(TTY_DEBUG),$(comma)$(TTY_DEBUG)) --timeout=$(TTY_TIMEOUT) $(if $(PPROF),--pprof=$(PPROF)); \
 	echo "exit $$? - log: $(RUNS)/latest.log"
 # Summarise the last run: lifecycle, warnings and errors.

M cmd/neferwl/main.go +2 -2


@@ -144,7 +144,7 @@ func run() error {
144	144		noXwayland := flags.Bool("no-xwayland", false, "no X11 display for X11 apps")
145	145		headlessHDR := flags.Bool("headless-hdr", false, "test-only: report HDR on virtual outputs; fall back if Vulkan HDR unavailable")
146	146		timeout := flags.Duration("timeout", 0, "duration before exit (0 disables timeout)")
147		-	debugFlag := flags.String("debug", "", "debug components (comma-separated or all; input-motion logs every pointer motion)")
	147	+	debugFlag := flags.String("debug", "", "debug components (comma-separated or all; all leaves out drm-flip, input-motion and input-keys, which log every flip, pointer motion or key)")
148	148		configFlag := flags.String("config", "", "config path (empty uses XDG default)")
149	149		session := flags.Bool("session", false, "run as the login session: share WAYLAND_DISPLAY and DISPLAY with systemd and D-Bus user services; notify systemd when ready")
150	150		pprofAddr := flags.String("pprof", "", "serve Go runtime profiles (heap, CPU, trace) on this address, e.g. localhost:6060")

@@ -235,7 +235,7 @@ func run() error {
235	235		}
236	236		ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
237	237		defer stop()
238		-	ctx, closeLog, err := logging.Open(ctx, cfg.Log.Level, selected)
	238	+	ctx, closeLog, err := logging.Open(ctx, *backend, cfg.Log.Level, selected)
239	239		if err != nil {
240	240		fmt.Fprintln(os.Stderr, err)
241	241		return err


@@ -144,7 +144,7 @@ func run() error {
144		noXwayland := flags.Bool("no-xwayland", false, "no X11 display for X11 apps")	144		noXwayland := flags.Bool("no-xwayland", false, "no X11 display for X11 apps")
145		headlessHDR := flags.Bool("headless-hdr", false, "test-only: report HDR on virtual outputs; fall back if Vulkan HDR unavailable")	145		headlessHDR := flags.Bool("headless-hdr", false, "test-only: report HDR on virtual outputs; fall back if Vulkan HDR unavailable")
146		timeout := flags.Duration("timeout", 0, "duration before exit (0 disables timeout)")	146		timeout := flags.Duration("timeout", 0, "duration before exit (0 disables timeout)")
147	-	debugFlag := flags.String("debug", "", "debug components (comma-separated or all; input-motion logs every pointer motion)")	147	+	debugFlag := flags.String("debug", "", "debug components (comma-separated or all; all leaves out drm-flip, input-motion and input-keys, which log every flip, pointer motion or key)")
148		configFlag := flags.String("config", "", "config path (empty uses XDG default)")	148		configFlag := flags.String("config", "", "config path (empty uses XDG default)")
149		session := flags.Bool("session", false, "run as the login session: share WAYLAND_DISPLAY and DISPLAY with systemd and D-Bus user services; notify systemd when ready")	149		session := flags.Bool("session", false, "run as the login session: share WAYLAND_DISPLAY and DISPLAY with systemd and D-Bus user services; notify systemd when ready")
150		pprofAddr := flags.String("pprof", "", "serve Go runtime profiles (heap, CPU, trace) on this address, e.g. localhost:6060")	150		pprofAddr := flags.String("pprof", "", "serve Go runtime profiles (heap, CPU, trace) on this address, e.g. localhost:6060")

@@ -235,7 +235,7 @@ func run() error {
235		}	235		}
236		ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)	236		ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
237		defer stop()	237		defer stop()
238	-	ctx, closeLog, err := logging.Open(ctx, cfg.Log.Level, selected)	238	+	ctx, closeLog, err := logging.Open(ctx, *backend, cfg.Log.Level, selected)
239		if err != nil {	239		if err != nil {
240		fmt.Fprintln(os.Stderr, err)	240		fmt.Fprintln(os.Stderr, err)
241		return err	241		return err

M docs/config.md +1 -0


@@ -49,6 +49,7 @@ NeferWL reads `$XDG_CONFIG_HOME/neferwl/config` (or `~/.config/neferwl/config`).
49	49		\| `output.<name>.sdr-brightness` \| `203` \| How bright SDR desktop content appears in HDR, in nits (80–1000) \|
50	50		\| `render.direct-scanout` \| `on` \| Fullscreen buffers straight to the display \|
51	51		\| `render.tearing` / `render.vrr` \| `on` / `on` \| Tearing: games in direct scanout. VRR: any fullscreen window covering the output \|
	52	+	\| `render.vrr-flip-gap` \| `1ms` \| Under VRR, a game frame commits at least this long after the previous flip, so it does not wait for the panel's slowest refresh (0 to 10ms; `0` turns it off) \|
52	53		\| `performance.realtime` \| `on` \| Request real-time scheduling for output and input threads \|
53	54		\| `log.level` / `log.debug` \| `info` / empty \| Log level / debug components or `all` \|
54	55		\| `bind.<keys>` \| see below \| Action for a key combo; `none` removes a default \|


@@ -49,6 +49,7 @@ NeferWL reads `$XDG_CONFIG_HOME/neferwl/config` (or `~/.config/neferwl/config`).
49	\| `output.<name>.sdr-brightness` \| `203` \| How bright SDR desktop content appears in HDR, in nits (80–1000) \|	49		\| `output.<name>.sdr-brightness` \| `203` \| How bright SDR desktop content appears in HDR, in nits (80–1000) \|
50	\| `render.direct-scanout` \| `on` \| Fullscreen buffers straight to the display \|	50		\| `render.direct-scanout` \| `on` \| Fullscreen buffers straight to the display \|
51	\| `render.tearing` / `render.vrr` \| `on` / `on` \| Tearing: games in direct scanout. VRR: any fullscreen window covering the output \|	51		\| `render.tearing` / `render.vrr` \| `on` / `on` \| Tearing: games in direct scanout. VRR: any fullscreen window covering the output \|
		52	+	\| `render.vrr-flip-gap` \| `1ms` \| Under VRR, a game frame commits at least this long after the previous flip, so it does not wait for the panel's slowest refresh (0 to 10ms; `0` turns it off) \|
52	\| `performance.realtime` \| `on` \| Request real-time scheduling for output and input threads \|	53		\| `performance.realtime` \| `on` \| Request real-time scheduling for output and input threads \|
53	\| `log.level` / `log.debug` \| `info` / empty \| Log level / debug components or `all` \|	54		\| `log.level` / `log.debug` \| `info` / empty \| Log level / debug components or `all` \|
54	\| `bind.<keys>` \| see below \| Action for a key combo; `none` removes a default \|	55		\| `bind.<keys>` \| see below \| Action for a key combo; `none` removes a default \|

M docs/performance.md +5 -0


@@ -7,6 +7,7 @@ How NeferWL keeps its CPU and memory use low, how to measure it, and the referen
7	7		- No reflection on the FFI boundary. libwayland and Vulkan are called through `purego.Syscall6/Syscall15` (fixed arity, zero allocation) and C calls back into Go through `purego.NewCallbackInts`. The Vulkan dispatch tables are generated methods; the libwayland wrapper caches resource id, version and client, and precomputes request argument counts.
8	8		- No allocation per frame or per request on the steady-state path. Frame callbacks, presentation reports, DRM flips, Vulkan submissions and surface updates reuse owner-goroutine scratch or immutable snapshots. Surface updates (one per `wl_surface.commit`) are recycled once no queued update references them.
9	9		- Cursor rides on game frames under VRR. While a fullscreen game drives VRR, a cursor move waits for the game's next frame instead of its own commit: a cursor-only commit refreshes the panel at its slowest rate (~21 ms at 48 Hz) and delays the next game frame by as much. If the game stops drawing, the cursor still commits alone at 24 Hz.
	10	+	- Game frames keep a short gap after each VRR flip. On amdgpu, a flip committed right after the previous flip event can miss the early refresh and wait for the panel's slowest rate (~21 ms at 48 Hz); the next frame then lands at the same point, and the screen stays at 48 Hz while the game renders at 150 fps. Game frames under VRR therefore commit at least `render.vrr-flip-gap` (default 1 ms) after the previous flip. `internal/adapters/drm/vrr_flip_gap.go` has the measurements.
10	11		- Default GOGC. The Go live heap is a few MB (client buffers live in shared and GPU memory), so the runtime default `GOGC=100` with a 256 MiB soft limit gives 2 collections on the tiled playback test where `GOGC=50` gave 13. `GOGC` and `GOMEMLIMIT` from the environment win.
11	12
12	13		Output and input threads request real-time scheduling, and the Vulkan queue requests elevated priority. Both require CAP_SYS_NICE, which the Arch packages set on `/usr/bin/neferwl` at install. Apps launched by NeferWL inherit neither. Set `performance.realtime = false` to opt out. A binary built with `make bin` runs at normal priority unless you grant it: `sudo setcap cap_sys_nice+ep bin/neferwl`.

@@ -38,6 +39,10 @@ GODEBUG=gctrace=1 neferwl --backend=drm
38	39
39	40		`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.
40	41
	42	+	`--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.
	43	+
	44	+	Logs go to `$XDG_STATE_HOME/neferwl/runs/<backend>/`, one file per run with `latest.log` pointing at the newest; each backend keeps its last 20 runs, so headless test runs never rotate a DRM session's log away. `--debug=all` leaves out the per-event categories `drm-flip`, `input-motion` and `input-keys` (typed text); name them to turn them on.
	45	+
41	46		## Reference: 4K HDR tiled video playback
42	47
43	48		Workload: a browser playing 4K HDR video with 65 tiled subsurfaces committing every frame, DRM backend, `perf record -g` for 8 s. Percentages are the share of the process's own samples (inclusive).


@@ -7,6 +7,7 @@ How NeferWL keeps its CPU and memory use low, how to measure it, and the referen
7	- No reflection on the FFI boundary. libwayland and Vulkan are called through `purego.Syscall6/Syscall15` (fixed arity, zero allocation) and C calls back into Go through `purego.NewCallbackInts`. The Vulkan dispatch tables are generated methods; the libwayland wrapper caches resource id, version and client, and precomputes request argument counts.	7		- No reflection on the FFI boundary. libwayland and Vulkan are called through `purego.Syscall6/Syscall15` (fixed arity, zero allocation) and C calls back into Go through `purego.NewCallbackInts`. The Vulkan dispatch tables are generated methods; the libwayland wrapper caches resource id, version and client, and precomputes request argument counts.
8	- No allocation per frame or per request on the steady-state path. Frame callbacks, presentation reports, DRM flips, Vulkan submissions and surface updates reuse owner-goroutine scratch or immutable snapshots. Surface updates (one per `wl_surface.commit`) are recycled once no queued update references them.	8		- No allocation per frame or per request on the steady-state path. Frame callbacks, presentation reports, DRM flips, Vulkan submissions and surface updates reuse owner-goroutine scratch or immutable snapshots. Surface updates (one per `wl_surface.commit`) are recycled once no queued update references them.
9	- Cursor rides on game frames under VRR. While a fullscreen game drives VRR, a cursor move waits for the game's next frame instead of its own commit: a cursor-only commit refreshes the panel at its slowest rate (~21 ms at 48 Hz) and delays the next game frame by as much. If the game stops drawing, the cursor still commits alone at 24 Hz.	9		- Cursor rides on game frames under VRR. While a fullscreen game drives VRR, a cursor move waits for the game's next frame instead of its own commit: a cursor-only commit refreshes the panel at its slowest rate (~21 ms at 48 Hz) and delays the next game frame by as much. If the game stops drawing, the cursor still commits alone at 24 Hz.
		10	+	- Game frames keep a short gap after each VRR flip. On amdgpu, a flip committed right after the previous flip event can miss the early refresh and wait for the panel's slowest rate (~21 ms at 48 Hz); the next frame then lands at the same point, and the screen stays at 48 Hz while the game renders at 150 fps. Game frames under VRR therefore commit at least `render.vrr-flip-gap` (default 1 ms) after the previous flip. `internal/adapters/drm/vrr_flip_gap.go` has the measurements.
10	- Default GOGC. The Go live heap is a few MB (client buffers live in shared and GPU memory), so the runtime default `GOGC=100` with a 256 MiB soft limit gives 2 collections on the tiled playback test where `GOGC=50` gave 13. `GOGC` and `GOMEMLIMIT` from the environment win.	11		- Default GOGC. The Go live heap is a few MB (client buffers live in shared and GPU memory), so the runtime default `GOGC=100` with a 256 MiB soft limit gives 2 collections on the tiled playback test where `GOGC=50` gave 13. `GOGC` and `GOMEMLIMIT` from the environment win.
11		12
12	Output and input threads request real-time scheduling, and the Vulkan queue requests elevated priority. Both require CAP_SYS_NICE, which the Arch packages set on `/usr/bin/neferwl` at install. Apps launched by NeferWL inherit neither. Set `performance.realtime = false` to opt out. A binary built with `make bin` runs at normal priority unless you grant it: `sudo setcap cap_sys_nice+ep bin/neferwl`.	13		Output and input threads request real-time scheduling, and the Vulkan queue requests elevated priority. Both require CAP_SYS_NICE, which the Arch packages set on `/usr/bin/neferwl` at install. Apps launched by NeferWL inherit neither. Set `performance.realtime = false` to opt out. A binary built with `make bin` runs at normal priority unless you grant it: `sudo setcap cap_sys_nice+ep bin/neferwl`.

@@ -38,6 +39,10 @@ GODEBUG=gctrace=1 neferwl --backend=drm
38		39
39	`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.	40		`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.
40		41
		42	+	`--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.
		43	+
		44	+	Logs go to `$XDG_STATE_HOME/neferwl/runs/<backend>/`, one file per run with `latest.log` pointing at the newest; each backend keeps its last 20 runs, so headless test runs never rotate a DRM session's log away. `--debug=all` leaves out the per-event categories `drm-flip`, `input-motion` and `input-keys` (typed text); name them to turn them on.
		45	+
41	## Reference: 4K HDR tiled video playback	46		## Reference: 4K HDR tiled video playback
42		47
43	Workload: a browser playing 4K HDR video with 65 tiled subsurfaces committing every frame, DRM backend, `perf record -g` for 8 s. Percentages are the share of the process's own samples (inclusive).	48		Workload: a browser playing 4K HDR video with 65 tiled subsurfaces committing every frame, DRM backend, `perf record -g` for 8 s. Percentages are the share of the process's own samples (inclusive).

M internal/adapters/config/config.go +15 -0


@@ -13,11 +13,16 @@ import (
13	13		"sort"
14	14		"strconv"
15	15		"strings"
	16	+	"time"
16	17		"unicode"
17	18
18	19		"github.com/bnema/neferwl/internal/ports"
19	20		)
20	21
	22	+	// maxVRRFlipGap bounds render.vrr-flip-gap below one refresh of a slow
	23	+	// VRR panel (48 Hz: 20.8 ms).
	24	+	const maxVRRFlipGap = 10 * time.Millisecond
	25	+
21	26		// defaultBinds use the config syntax and go through the same parser as user binds.
22	27		var defaultBinds = []struct{ combo, action string }{
23	28		{"cmd+return", "spawn-terminal"},

@@ -135,6 +140,7 @@ func Defaults() ports.Config {
135	140		c.Render.DirectScanout = true
136	141		c.Render.Tearing = true
137	142		c.Render.VRR = true
	143	+	c.Render.VRRFlipGap = time.Millisecond
138	144		c.Performance.Realtime = true
139	145		c.Log.Level = "info"
140	146		c.Log.Debug = []string{}

@@ -577,6 +583,15 @@ func set(c *ports.Config, key, v string) error {
577	583		return err
578	584		}
579	585		c.Render.VRR = b
	586	+	case "render.vrr-flip-gap":
	587	+	d, err := time.ParseDuration(v)
	588	+	if v == "0" {
	589	+	d, err = 0, nil
	590	+	}
	591	+	if err != nil \|\| d < 0 \|\| d > maxVRRFlipGap {
	592	+	return fmt.Errorf("must be a duration between 0 and %s, e.g. 1ms", maxVRRFlipGap)
	593	+	}
	594	+	c.Render.VRRFlipGap = d
580	595		case "performance.realtime":
581	596		b, err := onOff(v)
582	597		if err != nil {


@@ -13,11 +13,16 @@ import (
13	"sort"	13		"sort"
14	"strconv"	14		"strconv"
15	"strings"	15		"strings"
		16	+	"time"
16	"unicode"	17		"unicode"
17		18
18	"github.com/bnema/neferwl/internal/ports"	19		"github.com/bnema/neferwl/internal/ports"
19	)	20		)
20		21
		22	+	// maxVRRFlipGap bounds render.vrr-flip-gap below one refresh of a slow
		23	+	// VRR panel (48 Hz: 20.8 ms).
		24	+	const maxVRRFlipGap = 10 * time.Millisecond
		25	+
21	// defaultBinds use the config syntax and go through the same parser as user binds.	26		// defaultBinds use the config syntax and go through the same parser as user binds.
22	var defaultBinds = []struct{ combo, action string }{	27		var defaultBinds = []struct{ combo, action string }{
23	{"cmd+return", "spawn-terminal"},	28		{"cmd+return", "spawn-terminal"},

@@ -135,6 +140,7 @@ func Defaults() ports.Config {
135	c.Render.DirectScanout = true	140		c.Render.DirectScanout = true
136	c.Render.Tearing = true	141		c.Render.Tearing = true
137	c.Render.VRR = true	142		c.Render.VRR = true
		143	+	c.Render.VRRFlipGap = time.Millisecond
138	c.Performance.Realtime = true	144		c.Performance.Realtime = true
139	c.Log.Level = "info"	145		c.Log.Level = "info"
140	c.Log.Debug = []string{}	146		c.Log.Debug = []string{}

@@ -577,6 +583,15 @@ func set(c *ports.Config, key, v string) error {
577	return err	583		return err
578	}	584		}
579	c.Render.VRR = b	585		c.Render.VRR = b
		586	+	case "render.vrr-flip-gap":
		587	+	d, err := time.ParseDuration(v)
		588	+	if v == "0" {
		589	+	d, err = 0, nil
		590	+	}
		591	+	if err != nil \|\| d < 0 \|\| d > maxVRRFlipGap {
		592	+	return fmt.Errorf("must be a duration between 0 and %s, e.g. 1ms", maxVRRFlipGap)
		593	+	}
		594	+	c.Render.VRRFlipGap = d
580	case "performance.realtime":	595		case "performance.realtime":
581	b, err := onOff(v)	596		b, err := onOff(v)
582	if err != nil {	597		if err != nil {

M internal/adapters/config/config_test.go +19 -0


@@ -6,6 +6,7 @@ import (
6	6		"reflect"
7	7		"strings"
8	8		"testing"
	9	+	"time"
9	10
10	11		"github.com/bnema/neferwl/internal/ports"
11	12		)

@@ -479,6 +480,24 @@ func TestStash(t *testing.T) {
479	480		}
480	481		}
481	482
	483	+	func TestVRRFlipGap(t *testing.T) {
	484	+	for _, tc := range []struct {
	485	+	value string
	486	+	want time.Duration
	487	+	warning bool
	488	+	}{
	489	+	{"0", 0, false}, {"0ms", 0, false}, {"500us", 500 * time.Microsecond, false}, {"2ms", 2 * time.Millisecond, false}, {"10ms", 10 * time.Millisecond, false},
	490	+	{"11ms", time.Millisecond, true}, {"-1ms", time.Millisecond, true}, {"1", time.Millisecond, true}, {"fast", time.Millisecond, true},
	491	+	} {
	492	+	t.Run(tc.value, func(t *testing.T) {
	493	+	c, warnings := parseString(t, "render.vrr-flip-gap = "+tc.value)
	494	+	if c.Render.VRRFlipGap != tc.want \|\| (len(warnings) != 0) != tc.warning {
	495	+	t.Fatalf("gap %v, warnings %v", c.Render.VRRFlipGap, warnings)
	496	+	}
	497	+	})
	498	+	}
	499	+	}
	500	+
482	501		func TestFloatingDim(t *testing.T) {
483	502		for _, tc := range []struct {
484	503		value string


@@ -6,6 +6,7 @@ import (
6	"reflect"	6		"reflect"
7	"strings"	7		"strings"
8	"testing"	8		"testing"
		9	+	"time"
9		10
10	"github.com/bnema/neferwl/internal/ports"	11		"github.com/bnema/neferwl/internal/ports"
11	)	12		)

@@ -479,6 +480,24 @@ func TestStash(t *testing.T) {
479	}	480		}
480	}	481		}
481		482
		483	+	func TestVRRFlipGap(t *testing.T) {
		484	+	for _, tc := range []struct {
		485	+	value string
		486	+	want time.Duration
		487	+	warning bool
		488	+	}{
		489	+	{"0", 0, false}, {"0ms", 0, false}, {"500us", 500 * time.Microsecond, false}, {"2ms", 2 * time.Millisecond, false}, {"10ms", 10 * time.Millisecond, false},
		490	+	{"11ms", time.Millisecond, true}, {"-1ms", time.Millisecond, true}, {"1", time.Millisecond, true}, {"fast", time.Millisecond, true},
		491	+	} {
		492	+	t.Run(tc.value, func(t *testing.T) {
		493	+	c, warnings := parseString(t, "render.vrr-flip-gap = "+tc.value)
		494	+	if c.Render.VRRFlipGap != tc.want \|\| (len(warnings) != 0) != tc.warning {
		495	+	t.Fatalf("gap %v, warnings %v", c.Render.VRRFlipGap, warnings)
		496	+	}
		497	+	})
		498	+	}
		499	+	}
		500	+
482	func TestFloatingDim(t *testing.T) {	501		func TestFloatingDim(t *testing.T) {
483	for _, tc := range []struct {	502		for _, tc := range []struct {
484	value string	503		value string

A internal/adapters/drm/flip_trace.go +102 -0

@@ -0,0 +1,102 @@
	1	+	package drm
	2	+
	3	+	import (
	4	+	"os"
	5	+	"runtime"
	6	+	"time"
	7	+	"unsafe"
	8	+
	9	+	"golang.org/x/sys/unix"
	10	+	)
	11	+
	12	+	// Flip tracing (--debug=drm-flip) logs every commit completion with the
	13	+	// times needed to tell a late client fence from a late flip: all times
	14	+	// are CLOCK_MONOTONIC, the clock of flip events and fence timestamps.
	15	+
	16	+	// SYNC_IOC_FILE_INFO = _IOWR('>', 4, struct sync_file_info)
	17	+	const ioctlSyncFileInfo = 0xc0383e04
	18	+
	19	+	// syncFileInfo is struct sync_file_info.
	20	+	type syncFileInfo struct {
	21	+	name [32]byte
	22	+	status int32
	23	+	flags uint32
	24	+	numFences uint32
	25	+	pad uint32
	26	+	fences uint64
	27	+	}
	28	+
	29	+	// syncFenceInfo is struct sync_fence_info.
	30	+	type syncFenceInfo struct {
	31	+	objName, driverName [32]byte
	32	+	status int32
	33	+	flags uint32
	34	+	timestampNs uint64
	35	+	}
	36	+
	37	+	// fenceSignalledAt is when every fence of the sync file f signalled
	38	+	// (0: not signalled yet or unknown).
	39	+	func fenceSignalledAt(f *os.File) time.Duration {
	40	+	info := syncFileInfo{}
	41	+	if ioctl(int(f.Fd()), ioctlSyncFileInfo, unsafe.Pointer(&info)) != nil \|\| info.numFences == 0 {
	42	+	return 0
	43	+	}
	44	+	fences := make([]syncFenceInfo, info.numFences)
	45	+	info.fences = uint64(uintptr(unsafe.Pointer(&fences[0])))
	46	+	err := ioctl(int(f.Fd()), ioctlSyncFileInfo, unsafe.Pointer(&info))
	47	+	runtime.KeepAlive(fences)
	48	+	if err != nil {
	49	+	return 0
	50	+	}
	51	+	var at uint64
	52	+	for _, fi := range fences {
	53	+	if fi.status != 1 {
	54	+	return 0
	55	+	}
	56	+	at = max(at, fi.timestampNs)
	57	+	}
	58	+	return time.Duration(at)
	59	+	}
	60	+
	61	+	// fencesSignalledAt is the latest signal time of fs (0: none, or one
	62	+	// unsignalled).
	63	+	func fencesSignalledAt(fs []*os.File) time.Duration {
	64	+	var at time.Duration
	65	+	for _, f := range fs {
	66	+	t := fenceSignalledAt(f)
	67	+	if t == 0 {
	68	+	return 0
	69	+	}
	70	+	at = max(at, t)
	71	+	}
	72	+	return at
	73	+	}
	74	+
	75	+	func monotonic() time.Duration {
	76	+	var ts unix.Timespec
	77	+	_ = unix.ClockGettime(unix.CLOCK_MONOTONIC, &ts)
	78	+	return time.Duration(ts.Nano())
	79	+	}
	80	+
	81	+	// traceFlip logs the completion ev of the commit f started at start.
	82	+	// 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)
	86	+	e := o.log.Debug().Str("connector", o.conn.name).Bool("frame", f.frame).Bool("async", f.async).Bool("vrr", o.vrrOn).
	87	+	Bool("direct", f.zeroCopy != 0).Uint32("seq", ev.seq).
	88	+	Float64("commit_to_flip_ms", ms(ev.when-commitAt)).Float64("flip_to_read_ms", ms(now-ev.when)).
	89	+	Int("fences", len(f.fences)).Bool("fence_ready_at_commit", f.fenceReady)
	90	+	if fenceAt != 0 {
	91	+	e = e.Float64("commit_to_fence_ms", ms(fenceAt-commitAt)).Float64("fence_to_flip_ms", ms(ev.when-fenceAt))
	92	+	}
	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
	98	+	}
	99	+	e.Msg("flip")
	100	+	}
	101	+
	102	+	func ms(d time.Duration) float64 { return float64(d) / float64(time.Millisecond) }

@@ -0,0 +1,102 @@
	1	+	package drm
	2	+
	3	+	import (
	4	+	"os"
	5	+	"runtime"
	6	+	"time"
	7	+	"unsafe"
	8	+
	9	+	"golang.org/x/sys/unix"
	10	+	)
	11	+
	12	+	// Flip tracing (--debug=drm-flip) logs every commit completion with the
	13	+	// times needed to tell a late client fence from a late flip: all times
	14	+	// are CLOCK_MONOTONIC, the clock of flip events and fence timestamps.
	15	+
	16	+	// SYNC_IOC_FILE_INFO = _IOWR('>', 4, struct sync_file_info)
	17	+	const ioctlSyncFileInfo = 0xc0383e04
	18	+
	19	+	// syncFileInfo is struct sync_file_info.
	20	+	type syncFileInfo struct {
	21	+	name [32]byte
	22	+	status int32
	23	+	flags uint32
	24	+	numFences uint32
	25	+	pad uint32
	26	+	fences uint64
	27	+	}
	28	+
	29	+	// syncFenceInfo is struct sync_fence_info.
	30	+	type syncFenceInfo struct {
	31	+	objName, driverName [32]byte
	32	+	status int32
	33	+	flags uint32
	34	+	timestampNs uint64
	35	+	}
	36	+
	37	+	// fenceSignalledAt is when every fence of the sync file f signalled
	38	+	// (0: not signalled yet or unknown).
	39	+	func fenceSignalledAt(f *os.File) time.Duration {
	40	+	info := syncFileInfo{}
	41	+	if ioctl(int(f.Fd()), ioctlSyncFileInfo, unsafe.Pointer(&info)) != nil \|\| info.numFences == 0 {
	42	+	return 0
	43	+	}
	44	+	fences := make([]syncFenceInfo, info.numFences)
	45	+	info.fences = uint64(uintptr(unsafe.Pointer(&fences[0])))
	46	+	err := ioctl(int(f.Fd()), ioctlSyncFileInfo, unsafe.Pointer(&info))
	47	+	runtime.KeepAlive(fences)
	48	+	if err != nil {
	49	+	return 0
	50	+	}
	51	+	var at uint64
	52	+	for _, fi := range fences {
	53	+	if fi.status != 1 {
	54	+	return 0
	55	+	}
	56	+	at = max(at, fi.timestampNs)
	57	+	}
	58	+	return time.Duration(at)
	59	+	}
	60	+
	61	+	// fencesSignalledAt is the latest signal time of fs (0: none, or one
	62	+	// unsignalled).
	63	+	func fencesSignalledAt(fs []*os.File) time.Duration {
	64	+	var at time.Duration
	65	+	for _, f := range fs {
	66	+	t := fenceSignalledAt(f)
	67	+	if t == 0 {
	68	+	return 0
	69	+	}
	70	+	at = max(at, t)
	71	+	}
	72	+	return at
	73	+	}
	74	+
	75	+	func monotonic() time.Duration {
	76	+	var ts unix.Timespec
	77	+	_ = unix.ClockGettime(unix.CLOCK_MONOTONIC, &ts)
	78	+	return time.Duration(ts.Nano())
	79	+	}
	80	+
	81	+	// traceFlip logs the completion ev of the commit f started at start.
	82	+	// 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)
	86	+	e := o.log.Debug().Str("connector", o.conn.name).Bool("frame", f.frame).Bool("async", f.async).Bool("vrr", o.vrrOn).
	87	+	Bool("direct", f.zeroCopy != 0).Uint32("seq", ev.seq).
	88	+	Float64("commit_to_flip_ms", ms(ev.when-commitAt)).Float64("flip_to_read_ms", ms(now-ev.when)).
	89	+	Int("fences", len(f.fences)).Bool("fence_ready_at_commit", f.fenceReady)
	90	+	if fenceAt != 0 {
	91	+	e = e.Float64("commit_to_fence_ms", ms(fenceAt-commitAt)).Float64("fence_to_flip_ms", ms(ev.when-fenceAt))
	92	+	}
	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
	98	+	}
	99	+	e.Msg("flip")
	100	+	}
	101	+
	102	+	func ms(d time.Duration) float64 { return float64(d) / float64(time.Millisecond) }

A internal/adapters/drm/flip_trace_test.go +58 -0

@@ -0,0 +1,58 @@
	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	+	"github.com/stretchr/testify/mock"
	12	+	)
	13	+
	14	+	// Only the event of our pending commit is traced: a stale event and the
	15	+	// event that ends an EBUSY wait are not.
	16	+	func TestTraceFlipsOnlyOurCommit(t *testing.T) {
	17	+	o, _, commits := testOutput(t)
	18	+	o.cursor = nil
	19	+	o.traceFlips = true
	20	+	var log bytes.Buffer
	21	+	o.log = zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &log})
	22	+	seen := map[ports.WindowID]uint64{}
	23	+	flips := func() int { return strings.Count(log.String(), `"message":"flip"`) }
	24	+
	25	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	26	+	t.Fatal(err)
	27	+	}
	28	+	c := (*commits)[0]
	29	+	stale := flipEvent{crtc: tCrtc, user: c.user + 1<<userKindBits}
	30	+	if o.completed(stale, seen) \|\| flips() != 0 {
	31	+	t.Fatalf("stale event traced: %s", log.String())
	32	+	}
	33	+	if !o.completed(flipEvent{crtc: tCrtc, user: c.user, when: time.Second}, seen) \|\| flips() != 1 {
	34	+	t.Fatalf("own commit not traced: %s", log.String())
	35	+	}
	36	+	if o.lastFlipAt != time.Second {
	37	+	t.Fatalf("last flip %s", o.lastFlipAt)
	38	+	}
	39	+
	40	+	o.frame.busy(time.Now())
	41	+	if !o.completed(flipEvent{crtc: tCrtc, user: 12345}, seen) \|\| flips() != 1 {
	42	+	t.Fatalf("EBUSY wait end traced: %s", log.String())
	43	+	}
	44	+	}
	45	+
	46	+	// A modeset starts a new flip interval: the time the output was inactive
	47	+	// is not reported as a frame interval.
	48	+	func TestModesetResetsFlipTrace(t *testing.T) {
	49	+	o, k, _ := testOutput(t)
	50	+	o.lastFlipAt = time.Second
	51	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil).Once()
	52	+	if err := o.modeset(); err != nil {
	53	+	t.Fatal(err)
	54	+	}
	55	+	if o.lastFlipAt != 0 {
	56	+	t.Fatalf("after modeset: last flip %s", o.lastFlipAt)
	57	+	}
	58	+	}

@@ -0,0 +1,58 @@
	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	+	"github.com/stretchr/testify/mock"
	12	+	)
	13	+
	14	+	// Only the event of our pending commit is traced: a stale event and the
	15	+	// event that ends an EBUSY wait are not.
	16	+	func TestTraceFlipsOnlyOurCommit(t *testing.T) {
	17	+	o, _, commits := testOutput(t)
	18	+	o.cursor = nil
	19	+	o.traceFlips = true
	20	+	var log bytes.Buffer
	21	+	o.log = zerowrap.New(zerowrap.Config{Level: "debug", Format: "json", Output: &log})
	22	+	seen := map[ports.WindowID]uint64{}
	23	+	flips := func() int { return strings.Count(log.String(), `"message":"flip"`) }
	24	+
	25	+	if err := o.commitFrame(70, nil, false, false, pendingFrame{}); err != nil {
	26	+	t.Fatal(err)
	27	+	}
	28	+	c := (*commits)[0]
	29	+	stale := flipEvent{crtc: tCrtc, user: c.user + 1<<userKindBits}
	30	+	if o.completed(stale, seen) \|\| flips() != 0 {
	31	+	t.Fatalf("stale event traced: %s", log.String())
	32	+	}
	33	+	if !o.completed(flipEvent{crtc: tCrtc, user: c.user, when: time.Second}, seen) \|\| flips() != 1 {
	34	+	t.Fatalf("own commit not traced: %s", log.String())
	35	+	}
	36	+	if o.lastFlipAt != time.Second {
	37	+	t.Fatalf("last flip %s", o.lastFlipAt)
	38	+	}
	39	+
	40	+	o.frame.busy(time.Now())
	41	+	if !o.completed(flipEvent{crtc: tCrtc, user: 12345}, seen) \|\| flips() != 1 {
	42	+	t.Fatalf("EBUSY wait end traced: %s", log.String())
	43	+	}
	44	+	}
	45	+
	46	+	// A modeset starts a new flip interval: the time the output was inactive
	47	+	// is not reported as a frame interval.
	48	+	func TestModesetResetsFlipTrace(t *testing.T) {
	49	+	o, k, _ := testOutput(t)
	50	+	o.lastFlipAt = time.Second
	51	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil).Once()
	52	+	if err := o.modeset(); err != nil {
	53	+	t.Fatal(err)
	54	+	}
	55	+	if o.lastFlipAt != 0 {
	56	+	t.Fatalf("after modeset: last flip %s", o.lastFlipAt)
	57	+	}
	58	+	}

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


@@ -35,6 +35,8 @@ type pendingFrame struct {
35	35		// the commit ends. composed is set when the frame was rendered.
36	36		fences []*os.File
37	37		composed bool
	38	+	// fenceReady: every fence had signalled at commit (flip tracing only).
	39	+	fenceReady bool
38	40		}
39	41
40	42		func (f *pendingFrame) closeFences() {

@@ -120,6 +122,12 @@ func (l *frameLifecycle) busy(now time.Time) bool {
120	122		return newRun
121	123		}
122	124
	125	+	// ours reports whether user is the event of the pending commit with a
	126	+	// known serial (not the end of an EBUSY wait).
	127	+	func (l *frameLifecycle) ours(user uint64) bool {
	128	+	return l.pending && l.pendingSerial != 0 && user>>userKindBits == l.pendingSerial
	129	+	}
	130	+
123	131		// flip consumes only the event for the pending commit; while waiting after
124	132		// EBUSY there is no known serial, so any CRTC event ends that wait. The
125	133		// returned start lets Output measure flip age after pending fences close.


@@ -35,6 +35,8 @@ type pendingFrame struct {
35	// the commit ends. composed is set when the frame was rendered.	35		// the commit ends. composed is set when the frame was rendered.
36	fences []*os.File	36		fences []*os.File
37	composed bool	37		composed bool
		38	+	// fenceReady: every fence had signalled at commit (flip tracing only).
		39	+	fenceReady bool
38	}	40		}
39		41
40	func (f *pendingFrame) closeFences() {	42		func (f *pendingFrame) closeFences() {

@@ -120,6 +122,12 @@ func (l *frameLifecycle) busy(now time.Time) bool {
120	return newRun	122		return newRun
121	}	123		}
122		124
		125	+	// ours reports whether user is the event of the pending commit with a
		126	+	// known serial (not the end of an EBUSY wait).
		127	+	func (l *frameLifecycle) ours(user uint64) bool {
		128	+	return l.pending && l.pendingSerial != 0 && user>>userKindBits == l.pendingSerial
		129	+	}
		130	+
123	// flip consumes only the event for the pending commit; while waiting after	131		// flip consumes only the event for the pending commit; while waiting after
124	// EBUSY there is no known serial, so any CRTC event ends that wait. The	132		// EBUSY there is no known serial, so any CRTC event ends that wait. The
125	// returned start lets Output measure flip age after pending fences close.	133		// returned start lets Output measure flip age after pending fences close.

M internal/adapters/drm/kms.go +7 -0


@@ -4,6 +4,7 @@ package drm
4	4		import (
5	5		"fmt"
6	6		"math"
	7	+	"time"
7	8		"unsafe"
8	9
9	10		"github.com/bnema/neferwl/internal/ports"

@@ -108,6 +109,12 @@ type Want struct {
108	109		Sampled []ports.DMABufFormat
109	110		// Device is the KMS device (dev_t) offered in scanout tranches.
110	111		Device uint64
	112	+	// TraceFlips logs each frame and commit completion with its timing
	113	+	// (--debug=drm-flip).
	114	+	TraceFlips bool
	115	+	// VRRFlipGap delays a game frame after the previous flip under VRR
	116	+	// (render.vrr-flip-gap, 0: off; see vrr_flip_gap.go).
	117	+	VRRFlipGap time.Duration
111	118		}
112	119
113	120		// HDRSettings is the requested HDR state and SDR reference white (nits).


@@ -4,6 +4,7 @@ package drm
4	import (	4		import (
5	"fmt"	5		"fmt"
6	"math"	6		"math"
		7	+	"time"
7	"unsafe"	8		"unsafe"
8		9
9	"github.com/bnema/neferwl/internal/ports"	10		"github.com/bnema/neferwl/internal/ports"

@@ -108,6 +109,12 @@ type Want struct {
108	Sampled []ports.DMABufFormat	109		Sampled []ports.DMABufFormat
109	// Device is the KMS device (dev_t) offered in scanout tranches.	110		// Device is the KMS device (dev_t) offered in scanout tranches.
110	Device uint64	111		Device uint64
		112	+	// TraceFlips logs each frame and commit completion with its timing
		113	+	// (--debug=drm-flip).
		114	+	TraceFlips bool
		115	+	// VRRFlipGap delays a game frame after the previous flip under VRR
		116	+	// (render.vrr-flip-gap, 0: off; see vrr_flip_gap.go).
		117	+	VRRFlipGap time.Duration
111	}	118		}
112		119
113	// HDRSettings is the requested HDR state and SDR reference white (nits).	120		// HDRSettings is the requested HDR state and SDR reference white (nits).

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


@@ -106,6 +106,15 @@ type Output struct {
106	106		// move waits for the next frame (see cursorWaits).
107	107		lastFrame time.Time
108	108		cursorHeld bool
	109	+	// traceFlips logs every completion with its timing; lastFlipAt is
	110	+	// the previous frame flip's kernel timestamp.
	111	+	traceFlips bool
	112	+	lastFlipAt time.Duration
	113	+	// vrrFlipGap is the minimum time between a game frame's flip event
	114	+	// and the next frame commit under VRR (render.vrr-flip-gap, 0: off);
	115	+	// flipGapUntil is when the next frame may commit. See vrr_flip_gap.go.
	116	+	vrrFlipGap time.Duration
	117	+	flipGapUntil time.Time
109	118		// wantOff is the latest Scene.Off: a client turned the display off.
110	119		// off: the CRTC is inactive for it. Every modeset (resume, recovery)
111	120		// follows wantOff, so a display turned off never lights up.

@@ -217,7 +226,7 @@ type CursorLoader func(c ports.CursorChange, scale float64, limit int) (ports.Cu
217	226		func newOutput(card Card, c connector, mode modeInfo, crtc uint32) (Output, error) {
218	227		log := card.log
219	228		pipe := slices.Index(card.crtcs, crtc)
220		-	o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1)}
	229	+	o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap}
221	230		var err error
222	231		if o.saved, err = getCrtc(card.fd, crtc); err != nil {
223	232		log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit")

@@ -384,6 +393,8 @@ func (o *Output) modeset() error {
384	393		}
385	394		o.modeBlob = blob
386	395		o.vrrOn, o.vrrGame, o.overlayOn, o.off = false, false, 0, o.wantOff
	396	+	// The gap and the traced flip interval belonged to the old state.
	397	+	o.flipGapUntil, o.lastFlipAt = time.Time{}, 0
387	398		o.contentValue, o.contentWanted = o.contentValues[0], o.contentValues[0]
388	399		o.planeRect = fullPlaneRect(o.Width(), o.Height())
389	400		if o.cursor != nil {

@@ -678,6 +689,9 @@ func (o Output) commitWithRect(fb uint32, fence os.File, async bool, vrr bool,
678	689		o.lastFrame, o.cursorHeld = time.Now(), false
679	690		f.frame, f.async = true, async
680	691		f.fences = dupFences(fence, ov.acquire)
	692	+	if o.traceFlips {
	693	+	f.fenceReady = signalled(f.fences)
	694	+	}
681	695		o.setAsync(async)
682	696		o.frame.begin(f, time.Now())
683	697		return nil

@@ -991,6 +1005,9 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
991	1005		vrrTimer := time.NewTimer(time.Hour)
992	1006		cursorTimer := time.NewTimer(time.Hour)
993	1007		o.frame.startTimer()
	1008	+	gapTimer := time.NewTimer(time.Hour)
	1009	+	gapTimer.Stop()
	1010	+	defer gapTimer.Stop()
994	1011		retryTimer.Stop()
995	1012		vrrTimer.Stop()
996	1013		cursorTimer.Stop()

@@ -1041,6 +1058,14 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
1041	1058		} else {
1042	1059		cursorTimer.Stop()
1043	1060		}
	1061	+	// A game frame waiting out the VRR flip gap commits when it ends.
	1062	+	var gapDue <-chan time.Time
	1063	+	if enabled && dirty && !o.frame.pendingCommit() && !o.flipGapUntil.IsZero() {
	1064	+	gapTimer.Reset(max(0, time.Until(o.flipGapUntil)))
	1065	+	gapDue = gapTimer.C
	1066	+	} else {
	1067	+	gapTimer.Stop()
	1068	+	}
1044	1069		// A commit whose event never comes must not stop the output.
1045	1070		stuck := o.frame.wait(enabled)
1046	1071		stateDirty := false

@@ -1067,6 +1092,7 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
1067	1092		stateDirty = true
1068	1093		case <-cursorWake:
1069	1094		stateDirty = true
	1095	+	case <-gapDue:
1070	1096		case <-ctx.Done():
1071	1097		return nil
1072	1098		case q := <-captures:

@@ -1191,6 +1217,12 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
1191	1217		}
1192	1218		continue
1193	1219		}
	1220	+	if !o.flipGapUntil.IsZero() {
	1221	+	if time.Now().Before(o.flipGapUntil) {
	1222	+	continue // gapDue commits it
	1223	+	}
	1224	+	o.flipGapUntil = time.Time{}
	1225	+	}
1194	1226		start := time.Now()
1195	1227		direct, err := o.submitFrame(ctx, r, scene, surfaces, seen, requests, captured)
1196	1228		requests = nil

@@ -1210,6 +1242,9 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend
1210	1242		}
1211	1243		dirty = false
1212	1244		frame++
	1245	+	if !o.traceFlips {
	1246	+	continue
	1247	+	}
1213	1248		o.log.Debug().Int("frame", frame).Uint64("seq", scene.Seq).Int("windows", len(scene.Windows)).Bool("direct", direct).Dur("took", time.Since(start)).Msg("frame")
1214	1249		}
1215	1250		}

@@ -1238,10 +1273,21 @@ func (o Output) commitFailed(err error, enabled bool) bool {
1238	1273		// reported with its kernel timestamp. It reports false for an event of
1239	1274		// another commit, which is dropped.
1240	1275		func (o *Output) completed(ev flipEvent, seen map[ports.WindowID]uint64) bool {
	1276	+	// Only a commit of ours is traced: not a stale event, nor the end of
	1277	+	// an EBUSY wait. Its fences are read before flip closes them.
	1278	+	trace := o.traceFlips && o.frame.ours(ev.user)
	1279	+	var fenceAt time.Duration
	1280	+	if trace {
	1281	+	fenceAt = fencesSignalledAt(o.frame.pendingFrame.fences)
	1282	+	}
1241	1283		f, start, ok := o.frame.flip(ev.user)
1242	1284		if !ok {
1243	1285		return false
1244	1286		}
	1287	+	if trace {
	1288	+	o.traceFlip(ev, f, start, fenceAt)
	1289	+	}
	1290	+	o.startFlipGap(f)
1245	1291		if age := time.Since(start); age > 20*time.Millisecond {
1246	1292		o.log.Info().Dur("flip_ms", age).Bool("frame", f.frame).Bool("vrr", o.vrrOn).Str("connector", o.conn.name).Msg("slow flip")
1247	1293		}

@@ -1282,7 +1328,11 @@ func (o *Output) setCursor(r ports.Renderer, load CursorLoader, c ports.CursorCh
1282	1328		o.log.Warn().Err(err).Msg("cursor")
1283	1329		return
1284	1330		}
1285		-	o.log.Debug().Float64("scale", scale).Str("shape", c.Shape).Bool("client", c.Image != nil).Int("w", img.W).Int("h", img.H).Msg("cursor image")
	1331	+	if c.Image != nil {
	1332	+	// Client cursors (games) reload on every change: too many to log.
	1333	+	return
	1334	+	}
	1335	+	o.log.Debug().Float64("scale", scale).Str("shape", c.Shape).Int("w", img.W).Int("h", img.H).Msg("cursor image")
1286	1336		}
1287	1337
1288	1338		// maxUnsent bounds reports waiting for wayland; past it the oldest flip is

 	// move waits for the next frame (see cursorWaits).
 	lastFrame  time.Time
 	cursorHeld bool
+	// traceFlips logs every completion with its timing; lastFlipAt is
+	// the previous frame flip's kernel timestamp.
+	traceFlips bool
+	lastFlipAt 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.
+	vrrFlipGap   time.Duration
+	flipGapUntil time.Time
 	// 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.
 func newOutput(card *Card, c connector, mode modeInfo, crtc uint32) (*Output, error) {
 	log := card.log
 	pipe := slices.Index(card.crtcs, crtc)
-	o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1)}
+	o := &Output{k: card.k, flipped: card.flips[crtc], frame: frameLifecycle{serials: &card.serials}, formats: card.formats, sampled: card.want.Sampled, device: card.want.Device, crtc: crtc, conn: c, mode: mode, log: log, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap}
 	var err error
 	if o.saved, err = getCrtc(card.fd, crtc); err != nil {
 		log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit")
 	}
 	o.modeBlob = blob
 	o.vrrOn, o.vrrGame, o.overlayOn, o.off = false, false, 0, o.wantOff
+	// The gap and the traced flip interval belonged to the old state.
+	o.flipGapUntil, o.lastFlipAt = time.Time{}, 0
 	o.contentValue, o.contentWanted = o.contentValues[0], o.contentValues[0]
 	o.planeRect = fullPlaneRect(o.Width(), o.Height())
 	if o.cursor != nil {
 	o.lastFrame, o.cursorHeld = time.Now(), false
 	f.frame, f.async = true, async
 	f.fences = dupFences(fence, ov.acquire)
+	if o.traceFlips {
+		f.fenceReady = signalled(f.fences)
+	}
 	o.setAsync(async)
 	o.frame.begin(f, time.Now())
 	return nil
 	vrrTimer := time.NewTimer(time.Hour)
 	cursorTimer := time.NewTimer(time.Hour)
 	o.frame.startTimer()
+	gapTimer := time.NewTimer(time.Hour)
+	gapTimer.Stop()
+	defer gapTimer.Stop()
 	retryTimer.Stop()
 	vrrTimer.Stop()
 	cursorTimer.Stop()
 		} else {
 			cursorTimer.Stop()
 		}
+		// A game frame waiting out the VRR flip gap commits when it ends.
+		var gapDue <-chan time.Time
+		if enabled && dirty && !o.frame.pendingCommit() && !o.flipGapUntil.IsZero() {
+			gapTimer.Reset(max(0, time.Until(o.flipGapUntil)))
+			gapDue = gapTimer.C
+		} else {
+			gapTimer.Stop()
+		}
 		// A commit whose event never comes must not stop the output.
 		stuck := o.frame.wait(enabled)
 		stateDirty := false
 			stateDirty = true
 		case <-cursorWake:
 			stateDirty = true
+		case <-gapDue:
 		case <-ctx.Done():
 			return nil
 		case q := <-captures:
 			}
 			continue
 		}
+		if !o.flipGapUntil.IsZero() {
+			if time.Now().Before(o.flipGapUntil) {
+				continue // gapDue commits it
+			}
+			o.flipGapUntil = time.Time{}
+		}
 		start := time.Now()
 		direct, err := o.submitFrame(ctx, r, scene, surfaces, seen, requests, captured)
 		requests = nil
 		}
 		dirty = false
 		frame++
+		if !o.traceFlips {
+			continue
+		}
 		o.log.Debug().Int("frame", frame).Uint64("seq", scene.Seq).Int("windows", len(scene.Windows)).Bool("direct", direct).Dur("took", time.Since(start)).Msg("frame")
 	}
 }
 // 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)
+	var fenceAt time.Duration
+	if trace {
+		fenceAt = fencesSignalledAt(o.frame.pendingFrame.fences)
+	}
 	f, start, ok := o.frame.flip(ev.user)
 	if !ok {
 		return false
 	}
+	if trace {
+		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")
 	}
 		o.log.Warn().Err(err).Msg("cursor")
 		return
 	}
-	o.log.Debug().Float64("scale", scale).Str("shape", c.Shape).Bool("client", c.Image != nil).Int("w", img.W).Int("h", img.H).Msg("cursor image")
+	if c.Image != nil {
+		// Client cursors (games) reload on every change: too many to log.
+		return
+	}
+	o.log.Debug().Float64("scale", scale).Str("shape", c.Shape).Int("w", img.W).Int("h", img.H).Msg("cursor image")
 }
 // maxUnsent bounds reports waiting for wayland; past it the oldest flip is

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


@@ -31,6 +31,7 @@ type commitRec struct {
31	31		req atomicReq
32	32		flags uint32
33	33		user uint64
	34	+	at time.Time // when the commit was made
34	35		}
35	36
36	37		// testOutput returns an output on a mocked kms that records commits;

@@ -49,7 +50,7 @@ func testOutputMu(t testing.T, errs ...error) (Output, mockkms, []commitRec,
49	50		k.EXPECT().commit(mock.Anything, mock.Anything, mock.Anything).RunAndReturn(func(r *atomicReq, flags uint32, user uint64) error {
50	51		commitMu.Lock()
51	52		defer commitMu.Unlock()
52		-	c := commitRec{flags: flags, user: user}
	53	+	c := commitRec{flags: flags, user: user, at: time.Now()}
53	54		c.req.objs = append([]uint32(nil), r.objs...)
54	55		for _, ps := range r.props {
55	56		c.req.props = append(c.req.props, append([]propValue(nil), ps...))

 	req   atomicReq
 	flags uint32
 	user  uint64
+	at    time.Time // when the commit was made
 }
 // testOutput returns an output on a mocked kms that records commits;
 	k.EXPECT().commit(mock.Anything, mock.Anything, mock.Anything).RunAndReturn(func(r *atomicReq, flags uint32, user uint64) error {
 		commitMu.Lock()
 		defer commitMu.Unlock()
-		c := commitRec{flags: flags, user: user}
+		c := commitRec{flags: flags, user: user, at: time.Now()}
 		c.req.objs = append([]uint32(nil), r.objs...)
 		for _, ps := range r.props {
 			c.req.props = append(c.req.props, append([]propValue(nil), ps...))

A internal/adapters/drm/vrr_flip_gap.go +52 -0

@@ -0,0 +1,52 @@
	1	+	package drm
	2	+
	3	+	import "time"
	4	+
	5	+	// VRR flip gap: a workaround for game frames that hit the panel's slowest
	6	+	// refresh while the game renders fast.
	7	+	//
	8	+	// Symptom: fullscreen game, direct scanout, VRR on, 120-165 fps. Now and
	9	+	// then, runs of 5 to 30 consecutive flips each take ~20.8 ms: the panel's
	10	+	// maximum VRR frame time (1/48 Hz on a 48-165 Hz panel). The game's FPS
	11	+	// counter stays steady, but the screen visibly drops to 48 Hz for a
	12	+	// fraction of a second.
	13	+	//
	14	+	// Root cause, measured with --debug=drm-flip on amdgpu (DP, 48-165 Hz):
	15	+	// - the client's acquire fence had already signalled at commit, and
	16	+	// the atomic ioctl returned at once: neither the game nor our commit
	17	+	// path is late;
	18	+	// - every slow flip was committed within ~0.3 ms after the previous
	19	+	// flip event, i.e. right at the start of the next refresh cycle;
	20	+	// - the flip event then comes ~20.8 ms after the commit: the flip
	21	+	// misses the early-refresh window and the display only refreshes when
	22	+	// the VRR timeout forces it (vtotal at the minimum rate);
	23	+	// - since Output.Run commits the next frame as soon as that late event
	24	+	// arrives, the next commit lands at the same point of the cycle, and
	25	+	// the output stays locked at the minimum rate until the game's timing
	26	+	// drifts.
	27	+	//
	28	+	// Why the kernel misses these flips is not established (amdgpu DC VRR
	29	+	// flip programming around vblank is the likely place). What is measured:
	30	+	// committing the next game frame a short time after the flip event keeps
	31	+	// it out of that window. With a 1 ms gap a 3-minute run had 0 slow flips
	32	+	// in gameplay, against bursts of up to 30 without it and ~10 isolated
	33	+	// slow flips per minute with a 2 ms delay applied only after a slow flip.
	34	+	// The cost is at most the gap of added latency per frame, well under one
	35	+	// 165 Hz refresh (6 ms), and it applies only while VRR runs for a game.
	36	+	//
	37	+	// render.vrr-flip-gap sets the gap (default 1 ms, 0 turns the workaround
	38	+	// off); drop it once the driver no longer needs it.
	39	+
	40	+	// startFlipGap is called on each completed commit f: after a game frame's
	41	+	// flip under VRR, the next frame waits vrrFlipGap before it commits. A
	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) {
	45	+	if !f.frame {
	46	+	return
	47	+	}
	48	+	o.flipGapUntil = time.Time{}
	49	+	if o.vrrFlipGap > 0 && o.vrrOn && o.vrrGame {
	50	+	o.flipGapUntil = time.Now().Add(o.vrrFlipGap)
	51	+	}
	52	+	}

@@ -0,0 +1,52 @@
	1	+	package drm
	2	+
	3	+	import "time"
	4	+
	5	+	// VRR flip gap: a workaround for game frames that hit the panel's slowest
	6	+	// refresh while the game renders fast.
	7	+	//
	8	+	// Symptom: fullscreen game, direct scanout, VRR on, 120-165 fps. Now and
	9	+	// then, runs of 5 to 30 consecutive flips each take ~20.8 ms: the panel's
	10	+	// maximum VRR frame time (1/48 Hz on a 48-165 Hz panel). The game's FPS
	11	+	// counter stays steady, but the screen visibly drops to 48 Hz for a
	12	+	// fraction of a second.
	13	+	//
	14	+	// Root cause, measured with --debug=drm-flip on amdgpu (DP, 48-165 Hz):
	15	+	// - the client's acquire fence had already signalled at commit, and
	16	+	// the atomic ioctl returned at once: neither the game nor our commit
	17	+	// path is late;
	18	+	// - every slow flip was committed within ~0.3 ms after the previous
	19	+	// flip event, i.e. right at the start of the next refresh cycle;
	20	+	// - the flip event then comes ~20.8 ms after the commit: the flip
	21	+	// misses the early-refresh window and the display only refreshes when
	22	+	// the VRR timeout forces it (vtotal at the minimum rate);
	23	+	// - since Output.Run commits the next frame as soon as that late event
	24	+	// arrives, the next commit lands at the same point of the cycle, and
	25	+	// the output stays locked at the minimum rate until the game's timing
	26	+	// drifts.
	27	+	//
	28	+	// Why the kernel misses these flips is not established (amdgpu DC VRR
	29	+	// flip programming around vblank is the likely place). What is measured:
	30	+	// committing the next game frame a short time after the flip event keeps
	31	+	// it out of that window. With a 1 ms gap a 3-minute run had 0 slow flips
	32	+	// in gameplay, against bursts of up to 30 without it and ~10 isolated
	33	+	// slow flips per minute with a 2 ms delay applied only after a slow flip.
	34	+	// The cost is at most the gap of added latency per frame, well under one
	35	+	// 165 Hz refresh (6 ms), and it applies only while VRR runs for a game.
	36	+	//
	37	+	// render.vrr-flip-gap sets the gap (default 1 ms, 0 turns the workaround
	38	+	// off); drop it once the driver no longer needs it.
	39	+
	40	+	// startFlipGap is called on each completed commit f: after a game frame's
	41	+	// flip under VRR, the next frame waits vrrFlipGap before it commits. A
	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) {
	45	+	if !f.frame {
	46	+	return
	47	+	}
	48	+	o.flipGapUntil = time.Time{}
	49	+	if o.vrrFlipGap > 0 && o.vrrOn && o.vrrGame {
	50	+	o.flipGapUntil = time.Now().Add(o.vrrFlipGap)
	51	+	}
	52	+	}

A internal/adapters/drm/vrr_flip_gap_test.go +145 -0

@@ -0,0 +1,145 @@
	1	+	package drm
	2	+
	3	+	import (
	4	+	"context"
	5	+	"os"
	6	+	"testing"
	7	+	"time"
	8	+
	9	+	portsmocks "github.com/bnema/neferwl/internal/mocks/ports"
	10	+	"github.com/bnema/neferwl/internal/ports"
	11	+	"github.com/stretchr/testify/mock"
	12	+	)
	13	+
	14	+	// The gap starts only after a game frame's flip under VRR.
	15	+	func TestStartFlipGap(t *testing.T) {
	16	+	for _, tc := range []struct {
	17	+	name string
	18	+	gap time.Duration
	19	+	frame, vrr, game bool
	20	+	want bool
	21	+	}{
	22	+	{"game frame under VRR", time.Millisecond, true, true, true, true},
	23	+	{"gap off", 0, true, true, true, false},
	24	+	{"state commit keeps the gap", time.Millisecond, false, true, true, true},
	25	+	{"state commit keeps no gap", time.Millisecond, false, false, false, false},
	26	+	{"VRR off", time.Millisecond, true, false, true, false},
	27	+	{"desktop under VRR hold", time.Millisecond, true, true, false, false},
	28	+	} {
	29	+	// A gap is pending from the last game frame when it applies.
	30	+	pending := time.Time{}
	31	+	if tc.vrr && tc.game {
	32	+	pending = time.Now().Add(time.Hour)
	33	+	}
	34	+	o := &Output{vrrFlipGap: tc.gap, vrrOn: tc.vrr, vrrGame: tc.game, flipGapUntil: pending}
	35	+	o.startFlipGap(pendingFrame{frame: tc.frame})
	36	+	if got := !o.flipGapUntil.IsZero(); got != tc.want {
	37	+	t.Errorf("%s: gap started %v, want %v", tc.name, got, tc.want)
	38	+	}
	39	+	}
	40	+	}
	41	+
	42	+	// A cursor commit that completes inside the gap does not end it.
	43	+	func TestStateCommitKeepsFlipGap(t *testing.T) {
	44	+	o, _, commits := testOutput(t)
	45	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = time.Hour, true, true
	46	+	seen := map[ports.WindowID]uint64{}
	47	+	if err := o.commitFrame(70, nil, false, true, pendingFrame{}); err != nil {
	48	+	t.Fatal(err)
	49	+	}
	50	+	o.completed(eventOf((*commits)[0]), seen)
	51	+	gap := o.flipGapUntil
	52	+	if gap.IsZero() {
	53	+	t.Fatal("no gap after a game frame")
	54	+	}
	55	+	o.cursor.image = true
	56	+	o.lastFrame = time.Time{} // the cursor commits alone
	57	+	o.cursor.Move(3, 3)
	58	+	if err := o.commitState(o.stateVRR()); err != nil \|\| len(*commits) != 2 {
	59	+	t.Fatalf("cursor commit: %v, %d commits", err, len(*commits))
	60	+	}
	61	+	o.completed(eventOf((*commits)[1]), seen)
	62	+	if o.flipGapUntil != gap {
	63	+	t.Fatalf("gap %v after a cursor commit, want %v", o.flipGapUntil, gap)
	64	+	}
	65	+	}
	66	+
	67	+	// A modeset drops a pending gap: it belonged to the old display state.
	68	+	func TestModesetClearsFlipGap(t *testing.T) {
	69	+	o, k, _ := testOutput(t)
	70	+	o.flipGapUntil = time.Now().Add(time.Hour)
	71	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil).Once()
	72	+	if err := o.modeset(); err != nil {
	73	+	t.Fatal(err)
	74	+	}
	75	+	if !o.flipGapUntil.IsZero() {
	76	+	t.Fatalf("gap until %v after modeset", o.flipGapUntil)
	77	+	}
	78	+	}
	79	+
	80	+	// Run commits the next game frame no sooner than the gap after the flip
	81	+	// event, then commits it on its own when the gap ends.
	82	+	func TestRunWaitsVRRFlipGap(t *testing.T) {
	83	+	o, k, commits, commitMu := testOutputMu(t)
	84	+	o.cursor, o.tearing = nil, false
	85	+	o.vrrFlipGap = 30 * time.Millisecond
	86	+	flips := make(chan flipEvent, 1)
	87	+	o.flipped = flips
	88	+	r := portsmocks.NewMockRenderer(t)
	89	+	pipeBuf := func() ports.DMABuf {
	90	+	f, w, _ := os.Pipe()
	91	+	w.Close()
	92	+	return ports.DMABuf{Planes: []ports.DMABufPlane{{File: f}}}
	93	+	}
	94	+	r.EXPECT().SetHDR(float64(0)).Return().Maybe()
	95	+	r.EXPECT().ExportTargets(2, mock.Anything).Return([]ports.DMABuf{pipeBuf(), pipeBuf()}, nil).Once()
	96	+	r.EXPECT().UseTarget(mock.Anything).Return()
	97	+	r.EXPECT().Render(mock.Anything, mock.Anything).Return(nil, nil)
	98	+	r.EXPECT().Close().Return().Once()
	99	+	k.EXPECT().addFB(mock.Anything, uint32(fourccXRGB)).Return(70, nil).Twice()
	100	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil)
	101	+	k.EXPECT().destroyBlob(mock.Anything).Return(nil).Maybe()
	102	+	k.EXPECT().rmFB(mock.Anything).Return(nil).Maybe()
	103	+	frames := func() (commitRec, int) {
	104	+	commitMu.Lock()
	105	+	defer commitMu.Unlock()
	106	+	n, last := 0, commitRec{}
	107	+	for _, c := range *commits {
	108	+	if c.user&3 == userFrame {
	109	+	n, last = n+1, c
	110	+	}
	111	+	}
	112	+	return last, n
	113	+	}
	114	+	scenes := make(chan ports.Scene, 1)
	115	+	ctx, cancel := context.WithCancel(context.Background())
	116	+	done := make(chan error, 1)
	117	+	go func() {
	118	+	done <- o.Run(ctx, func(int, int) (ports.Renderer, error) { return r, nil }, nil, make(chan bool), scenes, nil, nil, make(chan ports.OutputPresented, 8), nil, nil)
	119	+	}()
	120	+	// A composed fullscreen window: a game frame under VRR.
	121	+	game := ports.Scene{OutputWidth: 200, OutputHeight: 100,
	122	+	Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 200, H: 100}, Fullscreen: true}},
	123	+	Layers: []ports.SceneLayer{{ID: 5, Layer: ports.LayerOverlay, Rect: ports.Rect{W: 10, H: 10}}}}
	124	+	scenes <- game
	125	+	waitFor(t, func() bool { _, n := frames(); return n == 1 })
	126	+	last, _ := frames()
	127	+	// The next frame is already waiting when the flip arrives.
	128	+	game.Seq = 1
	129	+	scenes <- game
	130	+	flips <- flipEvent{crtc: tCrtc, user: last.user, when: time.Second, seq: 1}
	131	+	// Run handles the flip after it is sent: its commit is at least the
	132	+	// gap after this point, whatever the scheduling delay.
	133	+	sent := time.Now()
	134	+	waitFor(t, func() bool { _, n := frames(); return n == 2 })
	135	+	commitMu.Lock()
	136	+	second := (commits)[len(commits)-1].at
	137	+	commitMu.Unlock()
	138	+	if waited := second.Sub(sent); waited < o.vrrFlipGap-time.Millisecond {
	139	+	t.Fatalf("next frame committed %s after the flip, gap %s", waited, o.vrrFlipGap)
	140	+	}
	141	+	cancel()
	142	+	if err := <-done; err != nil {
	143	+	t.Fatal(err)
	144	+	}
	145	+	}

@@ -0,0 +1,145 @@
	1	+	package drm
	2	+
	3	+	import (
	4	+	"context"
	5	+	"os"
	6	+	"testing"
	7	+	"time"
	8	+
	9	+	portsmocks "github.com/bnema/neferwl/internal/mocks/ports"
	10	+	"github.com/bnema/neferwl/internal/ports"
	11	+	"github.com/stretchr/testify/mock"
	12	+	)
	13	+
	14	+	// The gap starts only after a game frame's flip under VRR.
	15	+	func TestStartFlipGap(t *testing.T) {
	16	+	for _, tc := range []struct {
	17	+	name string
	18	+	gap time.Duration
	19	+	frame, vrr, game bool
	20	+	want bool
	21	+	}{
	22	+	{"game frame under VRR", time.Millisecond, true, true, true, true},
	23	+	{"gap off", 0, true, true, true, false},
	24	+	{"state commit keeps the gap", time.Millisecond, false, true, true, true},
	25	+	{"state commit keeps no gap", time.Millisecond, false, false, false, false},
	26	+	{"VRR off", time.Millisecond, true, false, true, false},
	27	+	{"desktop under VRR hold", time.Millisecond, true, true, false, false},
	28	+	} {
	29	+	// A gap is pending from the last game frame when it applies.
	30	+	pending := time.Time{}
	31	+	if tc.vrr && tc.game {
	32	+	pending = time.Now().Add(time.Hour)
	33	+	}
	34	+	o := &Output{vrrFlipGap: tc.gap, vrrOn: tc.vrr, vrrGame: tc.game, flipGapUntil: pending}
	35	+	o.startFlipGap(pendingFrame{frame: tc.frame})
	36	+	if got := !o.flipGapUntil.IsZero(); got != tc.want {
	37	+	t.Errorf("%s: gap started %v, want %v", tc.name, got, tc.want)
	38	+	}
	39	+	}
	40	+	}
	41	+
	42	+	// A cursor commit that completes inside the gap does not end it.
	43	+	func TestStateCommitKeepsFlipGap(t *testing.T) {
	44	+	o, _, commits := testOutput(t)
	45	+	o.vrrFlipGap, o.vrrOn, o.vrrGame = time.Hour, true, true
	46	+	seen := map[ports.WindowID]uint64{}
	47	+	if err := o.commitFrame(70, nil, false, true, pendingFrame{}); err != nil {
	48	+	t.Fatal(err)
	49	+	}
	50	+	o.completed(eventOf((*commits)[0]), seen)
	51	+	gap := o.flipGapUntil
	52	+	if gap.IsZero() {
	53	+	t.Fatal("no gap after a game frame")
	54	+	}
	55	+	o.cursor.image = true
	56	+	o.lastFrame = time.Time{} // the cursor commits alone
	57	+	o.cursor.Move(3, 3)
	58	+	if err := o.commitState(o.stateVRR()); err != nil \|\| len(*commits) != 2 {
	59	+	t.Fatalf("cursor commit: %v, %d commits", err, len(*commits))
	60	+	}
	61	+	o.completed(eventOf((*commits)[1]), seen)
	62	+	if o.flipGapUntil != gap {
	63	+	t.Fatalf("gap %v after a cursor commit, want %v", o.flipGapUntil, gap)
	64	+	}
	65	+	}
	66	+
	67	+	// A modeset drops a pending gap: it belonged to the old display state.
	68	+	func TestModesetClearsFlipGap(t *testing.T) {
	69	+	o, k, _ := testOutput(t)
	70	+	o.flipGapUntil = time.Now().Add(time.Hour)
	71	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil).Once()
	72	+	if err := o.modeset(); err != nil {
	73	+	t.Fatal(err)
	74	+	}
	75	+	if !o.flipGapUntil.IsZero() {
	76	+	t.Fatalf("gap until %v after modeset", o.flipGapUntil)
	77	+	}
	78	+	}
	79	+
	80	+	// Run commits the next game frame no sooner than the gap after the flip
	81	+	// event, then commits it on its own when the gap ends.
	82	+	func TestRunWaitsVRRFlipGap(t *testing.T) {
	83	+	o, k, commits, commitMu := testOutputMu(t)
	84	+	o.cursor, o.tearing = nil, false
	85	+	o.vrrFlipGap = 30 * time.Millisecond
	86	+	flips := make(chan flipEvent, 1)
	87	+	o.flipped = flips
	88	+	r := portsmocks.NewMockRenderer(t)
	89	+	pipeBuf := func() ports.DMABuf {
	90	+	f, w, _ := os.Pipe()
	91	+	w.Close()
	92	+	return ports.DMABuf{Planes: []ports.DMABufPlane{{File: f}}}
	93	+	}
	94	+	r.EXPECT().SetHDR(float64(0)).Return().Maybe()
	95	+	r.EXPECT().ExportTargets(2, mock.Anything).Return([]ports.DMABuf{pipeBuf(), pipeBuf()}, nil).Once()
	96	+	r.EXPECT().UseTarget(mock.Anything).Return()
	97	+	r.EXPECT().Render(mock.Anything, mock.Anything).Return(nil, nil)
	98	+	r.EXPECT().Close().Return().Once()
	99	+	k.EXPECT().addFB(mock.Anything, uint32(fourccXRGB)).Return(70, nil).Twice()
	100	+	k.EXPECT().createBlob(mock.Anything).Return(99, nil)
	101	+	k.EXPECT().destroyBlob(mock.Anything).Return(nil).Maybe()
	102	+	k.EXPECT().rmFB(mock.Anything).Return(nil).Maybe()
	103	+	frames := func() (commitRec, int) {
	104	+	commitMu.Lock()
	105	+	defer commitMu.Unlock()
	106	+	n, last := 0, commitRec{}
	107	+	for _, c := range *commits {
	108	+	if c.user&3 == userFrame {
	109	+	n, last = n+1, c
	110	+	}
	111	+	}
	112	+	return last, n
	113	+	}
	114	+	scenes := make(chan ports.Scene, 1)
	115	+	ctx, cancel := context.WithCancel(context.Background())
	116	+	done := make(chan error, 1)
	117	+	go func() {
	118	+	done <- o.Run(ctx, func(int, int) (ports.Renderer, error) { return r, nil }, nil, make(chan bool), scenes, nil, nil, make(chan ports.OutputPresented, 8), nil, nil)
	119	+	}()
	120	+	// A composed fullscreen window: a game frame under VRR.
	121	+	game := ports.Scene{OutputWidth: 200, OutputHeight: 100,
	122	+	Windows: []ports.SceneWindow{{ID: 1, Rect: ports.Rect{W: 200, H: 100}, Fullscreen: true}},
	123	+	Layers: []ports.SceneLayer{{ID: 5, Layer: ports.LayerOverlay, Rect: ports.Rect{W: 10, H: 10}}}}
	124	+	scenes <- game
	125	+	waitFor(t, func() bool { _, n := frames(); return n == 1 })
	126	+	last, _ := frames()
	127	+	// The next frame is already waiting when the flip arrives.
	128	+	game.Seq = 1
	129	+	scenes <- game
	130	+	flips <- flipEvent{crtc: tCrtc, user: last.user, when: time.Second, seq: 1}
	131	+	// Run handles the flip after it is sent: its commit is at least the
	132	+	// gap after this point, whatever the scheduling delay.
	133	+	sent := time.Now()
	134	+	waitFor(t, func() bool { _, n := frames(); return n == 2 })
	135	+	commitMu.Lock()
	136	+	second := (commits)[len(commits)-1].at
	137	+	commitMu.Unlock()
	138	+	if waited := second.Sub(sent); waited < o.vrrFlipGap-time.Millisecond {
	139	+	t.Fatalf("next frame committed %s after the flip, gap %s", waited, o.vrrFlipGap)
	140	+	}
	141	+	cancel()
	142	+	if err := <-done; err != nil {
	143	+	t.Fatal(err)
	144	+	}
	145	+	}

M internal/adapters/libinput/libinput.go +6 -1


@@ -207,6 +207,9 @@ type Options struct {
207	207		// LogMotion logs every pointer motion (--debug=input-motion); motions
208	208		// are otherwise only counted in the input stats.
209	209		LogMotion bool
	210	+	// LogKeys logs every key (--debug=input-keys): typed text, off by
	211	+	// default.
	212	+	LogKeys bool
210	213		}
211	214
212	215		// statsEvery is how often Run logs input throughput.

@@ -447,7 +450,9 @@ func translate(ev uintptr, opts Options, p pointer, in inputState) (ports.Inpu
447	450		k := keyboardEvent(ev)
448	451		code, pressed := keyboardKey(k), keyboardState(k) == 1
449	452		ke := opts.Keymap.Key(code, pressed, msec(keyboardUsec(k)))
450		-	log.Debug().Uint32("code", code).Str("keysym", ke.Keysym).Bool("pressed", pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")
	453	+	if opts.LogKeys {
	454	+	log.Debug().Uint32("code", code).Str("keysym", ke.Keysym).Bool("pressed", pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")
	455	+	}
451	456		switch action, vt := hotkey(ke); action {
452	457		case hotkeyQuit:
453	458		log.Warn().Str("reason", "emergency-key").Msg("quit")

 	// LogMotion logs every pointer motion (--debug=input-motion); motions
 	// are otherwise only counted in the input stats.
 	LogMotion bool
+	// LogKeys logs every key (--debug=input-keys): typed text, off by
+	// default.
+	LogKeys bool
 }
 // statsEvery is how often Run logs input throughput.
 		k := keyboardEvent(ev)
 		code, pressed := keyboardKey(k), keyboardState(k) == 1
 		ke := opts.Keymap.Key(code, pressed, msec(keyboardUsec(k)))
-		log.Debug().Uint32("code", code).Str("keysym", ke.Keysym).Bool("pressed", pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")
+		if opts.LogKeys {
+			log.Debug().Uint32("code", code).Str("keysym", ke.Keysym).Bool("pressed", pressed).Uint8("mods", uint8(ke.Mods)).Msg("key")
+		}
 		switch action, vt := hotkey(ke); action {
 		case hotkeyQuit:
 			log.Warn().Str("reason", "emergency-key").Msg("quit")

M internal/adapters/wayland/cursor.go +3 -1


@@ -140,8 +140,10 @@ func (s *Server) setCursor(c ports.CursorChange) {
140	140		if s.channels.Cursors == nil {
141	141		return
142	142		}
143		-	s.log.Debug().Str("shape", c.Shape).Bool("client", c.Image != nil).Bool("hidden", c.Hidden).Msg("cursor")
144	143		s.cursorMu.Lock()
	144	+	if c.Image == nil && (c.Shape != s.cursorLatest.Shape \|\| c.Hidden != s.cursorLatest.Hidden \|\| s.cursorLatest.Image != nil) {
	145	+	s.log.Debug().Str("shape", c.Shape).Bool("hidden", c.Hidden).Msg("cursor")
	146	+	}
145	147		s.cursorLatest, s.cursorQueued = c, true
146	148		s.cursorMu.Unlock()
147	149		select {

 	if s.channels.Cursors == nil {
 		return
 	}
-	s.log.Debug().Str("shape", c.Shape).Bool("client", c.Image != nil).Bool("hidden", c.Hidden).Msg("cursor")
 	s.cursorMu.Lock()
+	if c.Image == nil && (c.Shape != s.cursorLatest.Shape || c.Hidden != s.cursorLatest.Hidden || s.cursorLatest.Image != nil) {
+		s.log.Debug().Str("shape", c.Shape).Bool("hidden", c.Hidden).Msg("cursor")
+	}
 	s.cursorLatest, s.cursorQueued = c, true
 	s.cursorMu.Unlock()
 	select {

M internal/app/app.go +2 -1


@@ -200,7 +200,7 @@ func run(ctx context.Context, opts Options, inject func(chan<- ports.InputEvent)
200	200		log.Warn().Str("component", "sched").Err(err).Msg("input scheduling")
201	201		}
202	202		}
203		-	return libinput.Run(ctx, libinput.Options{Seat: hw.seat, SeatName: hw.seat.Name(), Keymap: km, Keymaps: keymaps, Layout: layout, Layouts: layouts, Constraints: constraints, Touchpad: opts.Config.Touchpad, Touchpads: touchpads, Active: hw.seat.Subscribe(), MoveCursor: curs.move, Log: logging.For(ctx, "input"), LogMotion: logging.Enabled(ctx, "input-motion")}, input)
	203	+	return libinput.Run(ctx, libinput.Options{Seat: hw.seat, SeatName: hw.seat.Name(), Keymap: km, Keymaps: keymaps, Layout: layout, Layouts: layouts, Constraints: constraints, Touchpad: opts.Config.Touchpad, Touchpads: touchpads, Active: hw.seat.Subscribe(), MoveCursor: curs.move, Log: logging.For(ctx, "input"), LogMotion: logging.Enabled(ctx, "input-motion"), LogKeys: logging.Enabled(ctx, "input-keys")}, input)
204	204		})
205	205		return
206	206		}

@@ -265,6 +265,7 @@ func run(ctx context.Context, opts Options, inject func(chan<- ports.InputEvent)
265	265		want := func(cfg ports.Config) drm.Want {
266	266		w := wantFromConfig(cfg)
267	267		w.Sampled = dmabuf.Formats
	268	+	w.TraceFlips = logging.Enabled(ctx, "drm-flip")
268	269		return w
269	270		}
270	271		return hw.runOutputs(ctx, want, opts.Config, apply, outputIO, curs, newRenderer, logging.For(ctx, "drm"))

 						log.Warn().Str("component", "sched").Err(err).Msg("input scheduling")
 					}
 				}
-				return libinput.Run(ctx, libinput.Options{Seat: hw.seat, SeatName: hw.seat.Name(), Keymap: km, Keymaps: keymaps, Layout: layout, Layouts: layouts, Constraints: constraints, Touchpad: opts.Config.Touchpad, Touchpads: touchpads, Active: hw.seat.Subscribe(), MoveCursor: curs.move, Log: logging.For(ctx, "input"), LogMotion: logging.Enabled(ctx, "input-motion")}, input)
+				return libinput.Run(ctx, libinput.Options{Seat: hw.seat, SeatName: hw.seat.Name(), Keymap: km, Keymaps: keymaps, Layout: layout, Layouts: layouts, Constraints: constraints, Touchpad: opts.Config.Touchpad, Touchpads: touchpads, Active: hw.seat.Subscribe(), MoveCursor: curs.move, Log: logging.For(ctx, "input"), LogMotion: logging.Enabled(ctx, "input-motion"), LogKeys: logging.Enabled(ctx, "input-keys")}, input)
 			})
 			return
 		}
 				want := func(cfg ports.Config) drm.Want {
 					w := wantFromConfig(cfg)
 					w.Sampled = dmabuf.Formats
+					w.TraceFlips = logging.Enabled(ctx, "drm-flip")
 					return w
 				}
 				return hw.runOutputs(ctx, want, opts.Config, apply, outputIO, curs, newRenderer, logging.For(ctx, "drm"))

M internal/app/drm.go +2 -1


@@ -81,6 +81,7 @@ func openDRM(ctx context.Context, cfg ports.Config) (*drmBackend, error) {
81	81		return nil, fmt.Errorf("open seat: %w", err)
82	82		}
83	83		want := wantFromConfig(cfg)
	84	+	want.TraceFlips = logging.Enabled(ctx, "drm-flip")
84	85		paths, _ := filepath.Glob("/dev/dri/card[0-9]*")
85	86		sort.Strings(paths)
86	87		b := &drmBackend{seat: s, clock: clock.System{}}

@@ -112,7 +113,7 @@ func openDRM(ctx context.Context, cfg ports.Config) (*drmBackend, error) {
112	113		// wantFromConfig turns output.<name> and render.* entries into connector choices.
113	114		func wantFromConfig(cfg ports.Config) drm.Want {
114	115		r := cfg.Render
115		-	want := drm.Want{Disabled: map[string]bool{}, Modes: map[string][3]float64{}, HDR: map[string]drm.HDRSettings{}, NoScanout: !r.DirectScanout, NoTearing: !r.Tearing, NoVRR: !r.VRR}
	116	+	want := drm.Want{Disabled: map[string]bool{}, Modes: map[string][3]float64{}, HDR: map[string]drm.HDRSettings{}, NoScanout: !r.DirectScanout, NoTearing: !r.Tearing, NoVRR: !r.VRR, VRRFlipGap: r.VRRFlipGap}
116	117		for _, o := range cfg.Outputs {
117	118		nits := o.SDRBrightness
118	119		if nits == 0 {

 		return nil, fmt.Errorf("open seat: %w", err)
 	}
 	want := wantFromConfig(cfg)
+	want.TraceFlips = logging.Enabled(ctx, "drm-flip")
 	paths, _ := filepath.Glob("/dev/dri/card[0-9]*")
 	sort.Strings(paths)
 	b := &drmBackend{seat: s, clock: clock.System{}}
 // wantFromConfig turns output.<name> and render.* entries into connector choices.
 func wantFromConfig(cfg ports.Config) drm.Want {
 	r := cfg.Render
-	want := drm.Want{Disabled: map[string]bool{}, Modes: map[string][3]float64{}, HDR: map[string]drm.HDRSettings{}, NoScanout: !r.DirectScanout, NoTearing: !r.Tearing, NoVRR: !r.VRR}
+	want := drm.Want{Disabled: map[string]bool{}, Modes: map[string][3]float64{}, HDR: map[string]drm.HDRSettings{}, NoScanout: !r.DirectScanout, NoTearing: !r.Tearing, NoVRR: !r.VRR, VRRFlipGap: r.VRRFlipGap}
 	for _, o := range cfg.Outputs {
 		nits := o.SDRBrightness
 		if nits == 0 {

M internal/app/drm_test.go +3 -2


@@ -2,6 +2,7 @@ package app
2	2
3	3		import (
4	4		"testing"
	5	+	"time"
5	6
6	7		"github.com/bnema/neferwl/internal/adapters/drm"
7	8		"github.com/bnema/neferwl/internal/ports"

@@ -9,9 +10,9 @@ import (
9	10
10	11		func TestWantFromConfig(t *testing.T) {
11	12		cfg := ports.Config{Outputs: []ports.OutputConfig{{Name: "eDP-1", Scale: 2, ScaleOnly: true, HDR: true, SDRBrightness: 350}, {Name: "HDMI-A-1", Mode: "1920x1080@60"}, {Name: "DP-3", Off: true}}}
12		-	cfg.Render.DirectScanout, cfg.Render.VRR = true, true
	13	+	cfg.Render.DirectScanout, cfg.Render.VRR, cfg.Render.VRRFlipGap = true, true, 2*time.Millisecond
13	14		want := wantFromConfig(cfg)
14		-	if m := want.Modes["HDMI-A-1"]; m != [3]float64{1920, 1080, 60} \|\| !want.Disabled["DP-3"] \|\| len(want.Modes) != 1 \|\| want.NoScanout \|\| !want.NoTearing \|\| want.NoVRR \|\| want.HDR["eDP-1"] != (drm.HDRSettings{Enabled: true, SDRBrightness: 350}) \|\| want.HDR["HDMI-A-1"].SDRBrightness != 203 {
	15	+	if m := want.Modes["HDMI-A-1"]; m != [3]float64{1920, 1080, 60} \|\| want.VRRFlipGap != 2*time.Millisecond \|\| !want.Disabled["DP-3"] \|\| len(want.Modes) != 1 \|\| want.NoScanout \|\| !want.NoTearing \|\| want.NoVRR \|\| want.HDR["eDP-1"] != (drm.HDRSettings{Enabled: true, SDRBrightness: 350}) \|\| want.HDR["HDMI-A-1"].SDRBrightness != 203 {
15	16		t.Fatalf("%+v", want)
16	17		}
17	18		}

 import (
 	"testing"
+	"time"
 	"github.com/bnema/neferwl/internal/adapters/drm"
 	"github.com/bnema/neferwl/internal/ports"
 func TestWantFromConfig(t *testing.T) {
 	cfg := ports.Config{Outputs: []ports.OutputConfig{{Name: "eDP-1", Scale: 2, ScaleOnly: true, HDR: true, SDRBrightness: 350}, {Name: "HDMI-A-1", Mode: "1920x1080@60"}, {Name: "DP-3", Off: true}}}
-	cfg.Render.DirectScanout, cfg.Render.VRR = true, true
+	cfg.Render.DirectScanout, cfg.Render.VRR, cfg.Render.VRRFlipGap = true, true, 2*time.Millisecond
 	want := wantFromConfig(cfg)
-	if m := want.Modes["HDMI-A-1"]; m != [3]float64{1920, 1080, 60} || !want.Disabled["DP-3"] || len(want.Modes) != 1 || want.NoScanout || !want.NoTearing || want.NoVRR || want.HDR["eDP-1"] != (drm.HDRSettings{Enabled: true, SDRBrightness: 350}) || want.HDR["HDMI-A-1"].SDRBrightness != 203 {
+	if m := want.Modes["HDMI-A-1"]; m != [3]float64{1920, 1080, 60} || want.VRRFlipGap != 2*time.Millisecond || !want.Disabled["DP-3"] || len(want.Modes) != 1 || want.NoScanout || !want.NoTearing || want.NoVRR || want.HDR["eDP-1"] != (drm.HDRSettings{Enabled: true, SDRBrightness: 350}) || want.HDR["HDMI-A-1"].SDRBrightness != 203 {
 		t.Fatalf("%+v", want)
 	}
 }

M internal/logging/logging.go +10 -7


@@ -21,9 +21,10 @@ var components = map[string]bool{
21	21		}
22	22
23	23		// categories are debug switches narrower than a component, only on when
24		-	// named: "all" leaves them off (input-motion logs every pointer motion).
25		-	// Naming one turns on debug for its component.
26		-	var categories = map[string]string{"input-motion": "input"}
	24	+	// named: "all" leaves them off. input-motion logs every pointer motion,
	25	+	// input-keys every key (typed text), drm-flip every frame and commit
	26	+	// completion with its timing. Naming one turns on debug for its component.
	27	+	var categories = map[string]string{"input-motion": "input", "input-keys": "input", "drm-flip": "drm"}
27	28
28	29		type debugKey struct{}
29	30		type levelKey struct{}

@@ -50,10 +51,12 @@ func ParseDebug(value string) (map[string]bool, error) {
50	51		// keepRuns is how many per-run log files Open retains.
51	52		const keepRuns = 20
52	53
53		-	// Open creates runs/<timestamp>.log, points runs/latest.log at it, prunes old runs
54		-	// and attaches the logger to ctx.
	54	+	// Open creates runs/<backend>/<timestamp>.log, points latest.log in that
	55	+	// directory at it, prunes old runs of that backend and attaches the logger
	56	+	// to ctx. Each backend keeps its own runs: headless test runs never rotate
	57	+	// a DRM session's log away.
55	58		// The caller must invoke close after all logging is complete.
56		-	func Open(ctx context.Context, level, debug string) (context.Context, func() error, error) {
	59	+	func Open(ctx context.Context, backend, level, debug string) (context.Context, func() error, error) {
57	60		selected, err := ParseDebug(debug)
58	61		if err != nil {
59	62		return nil, nil, err

@@ -66,7 +69,7 @@ func Open(ctx context.Context, level, debug string) (context.Context, func() err
66	69		}
67	70		state = filepath.Join(home, ".local", "state")
68	71		}
69		-	dir := filepath.Join(state, "neferwl", "runs")
	72	+	dir := filepath.Join(state, "neferwl", "runs", backend)
70	73		if err := os.MkdirAll(dir, 0o700); err != nil {
71	74		return nil, nil, err
72	75		}

 }
 // categories are debug switches narrower than a component, only on when
-// named: "all" leaves them off (input-motion logs every pointer motion).
+// named: "all" leaves them off. input-motion logs every pointer motion,
-// Naming one turns on debug for its component.
+// input-keys every key (typed text), drm-flip every frame and commit
-var categories = map[string]string{"input-motion": "input"}
+// completion with its timing. Naming one turns on debug for its component.
+var categories = map[string]string{"input-motion": "input", "input-keys": "input", "drm-flip": "drm"}
 type debugKey struct{}
 type levelKey struct{}
 // keepRuns is how many per-run log files Open retains.
 const keepRuns = 20
-// Open creates runs/<timestamp>.log, points runs/latest.log at it, prunes old runs
+// Open creates runs/<backend>/<timestamp>.log, points latest.log in that
-// and attaches the logger to ctx.
+// directory at it, prunes old runs of that backend and attaches the logger
+// to ctx. Each backend keeps its own runs: headless test runs never rotate
+// a DRM session's log away.
 // The caller must invoke close after all logging is complete.
-func Open(ctx context.Context, level, debug string) (context.Context, func() error, error) {
+func Open(ctx context.Context, backend, level, debug string) (context.Context, func() error, error) {
 	selected, err := ParseDebug(debug)
 	if err != nil {
 		return nil, nil, err
 		}
 		state = filepath.Join(home, ".local", "state")
 	}
-	dir := filepath.Join(state, "neferwl", "runs")
+	dir := filepath.Join(state, "neferwl", "runs", backend)
 	if err := os.MkdirAll(dir, 0o700); err != nil {
 		return nil, nil, err
 	}

M internal/logging/logging_test.go +47 -15


@@ -34,11 +34,11 @@ func TestParseDebug(t *testing.T) {
34	34
35	35		func TestComponentLevelsAndRotation(t *testing.T) {
36	36		t.Setenv("XDG_STATE_HOME", t.TempDir())
37		-	dir := filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs")
	37	+	dir := filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm")
38	38		path := filepath.Join(dir, "latest.log")
39	39		for run := 0; run < keepRuns+2; run++ {
40	40		time.Sleep(2 * time.Millisecond) // distinct millisecond timestamps
41		-	ctx, closeLog, err := Open(context.Background(), "info", "core")
	41	+	ctx, closeLog, err := Open(context.Background(), "drm", "info", "core")
42	42		if err != nil {
43	43		t.Fatal(err)
44	44		}

@@ -84,10 +84,39 @@ func splitLines(data []byte) [][]byte {
84	84		return lines
85	85		}
86	86
	87	+	// Headless runs rotate in their own directory: they never prune a DRM run.
	88	+	func TestBackendsRotateSeparately(t *testing.T) {
	89	+	t.Setenv("XDG_STATE_HOME", t.TempDir())
	90	+	runs := filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs")
	91	+	open := func(backend string) {
	92	+	time.Sleep(2 * time.Millisecond) // distinct millisecond timestamps
	93	+	_, closeLog, err := Open(context.Background(), backend, "info", "")
	94	+	if err != nil {
	95	+	t.Fatal(err)
	96	+	}
	97	+	if err := closeLog(); err != nil {
	98	+	t.Fatal(err)
	99	+	}
	100	+	}
	101	+	open("drm")
	102	+	for range keepRuns + 2 {
	103	+	open("headless")
	104	+	}
	105	+	if drm, _ := filepath.Glob(filepath.Join(runs, "drm", "2*.log")); len(drm) != 1 {
	106	+	t.Fatalf("drm runs %v", drm)
	107	+	}
	108	+	if _, err := os.Stat(filepath.Join(runs, "drm", "latest.log")); err != nil {
	109	+	t.Fatal(err)
	110	+	}
	111	+	if headless, _ := filepath.Glob(filepath.Join(runs, "headless", "2*.log")); len(headless) != keepRuns {
	112	+	t.Fatalf("kept %d headless runs", len(headless))
	113	+	}
	114	+	}
	115	+
87	116		// A category alone raises its component to debug, so its lines are written.
88	117		func TestCategoryEnablesComponentDebug(t *testing.T) {
89	118		t.Setenv("XDG_STATE_HOME", t.TempDir())
90		-	ctx, closeLog, err := Open(context.Background(), "info", "input-motion")
	119	+	ctx, closeLog, err := Open(context.Background(), "drm", "info", "input-motion")
91	120		if err != nil {
92	121		t.Fatal(err)
93	122		}

@@ -97,7 +126,7 @@ func TestCategoryEnablesComponentDebug(t *testing.T) {
97	126		if err := closeLog(); err != nil {
98	127		t.Fatal(err)
99	128		}
100		-	data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "latest.log"))
	129	+	data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log"))
101	130		if err != nil {
102	131		t.Fatal(err)
103	132		}

@@ -108,17 +137,20 @@ func TestCategoryEnablesComponentDebug(t *testing.T) {
108	137
109	138		// Narrow categories are on only when named, never through "all".
110	139		func TestEnabledCategories(t *testing.T) {
111		-	for _, tc := range []struct {
112		-	debug string
113		-	want bool
114		-	}{{"all", false}, {"input", false}, {"input-motion", true}, {"all,input-motion", true}} {
115		-	sel, err := ParseDebug(tc.debug)
116		-	if err != nil {
117		-	t.Fatal(err)
118		-	}
119		-	ctx := context.WithValue(context.Background(), debugKey{}, debugSet(sel))
120		-	if got := Enabled(ctx, "input-motion"); got != tc.want {
121		-	t.Errorf("%q: %v", tc.debug, got)
	140	+	for _, category := range []string{"input-motion", "input-keys", "drm-flip"} {
	141	+	component := categories[category]
	142	+	for _, tc := range []struct {
	143	+	debug string
	144	+	want bool
	145	+	}{{"all", false}, {component, false}, {category, true}, {"all," + category, true}} {
	146	+	sel, err := ParseDebug(tc.debug)
	147	+	if err != nil {
	148	+	t.Fatal(err)
	149	+	}
	150	+	ctx := context.WithValue(context.Background(), debugKey{}, debugSet(sel))
	151	+	if got := Enabled(ctx, category); got != tc.want {
	152	+	t.Errorf("%s with %q: %v", category, tc.debug, got)
	153	+	}
122	154		}
123	155		}
124	156		}

 func TestComponentLevelsAndRotation(t *testing.T) {
 	t.Setenv("XDG_STATE_HOME", t.TempDir())
-	dir := filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs")
+	dir := filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm")
 	path := filepath.Join(dir, "latest.log")
 	for run := 0; run < keepRuns+2; run++ {
 		time.Sleep(2 * time.Millisecond) // distinct millisecond timestamps
-		ctx, closeLog, err := Open(context.Background(), "info", "core")
+		ctx, closeLog, err := Open(context.Background(), "drm", "info", "core")
 		if err != nil {
 			t.Fatal(err)
 		}
 	return lines
 }
+// Headless runs rotate in their own directory: they never prune a DRM run.
+func TestBackendsRotateSeparately(t *testing.T) {
+	t.Setenv("XDG_STATE_HOME", t.TempDir())
+	runs := filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs")
+	open := func(backend string) {
+		time.Sleep(2 * time.Millisecond) // distinct millisecond timestamps
+		_, closeLog, err := Open(context.Background(), backend, "info", "")
+		if err != nil {
+			t.Fatal(err)
+		}
+		if err := closeLog(); err != nil {
+			t.Fatal(err)
+		}
+	}
+	open("drm")
+	for range keepRuns + 2 {
+		open("headless")
+	}
+	if drm, _ := filepath.Glob(filepath.Join(runs, "drm", "2*.log")); len(drm) != 1 {
+		t.Fatalf("drm runs %v", drm)
+	}
+	if _, err := os.Stat(filepath.Join(runs, "drm", "latest.log")); err != nil {
+		t.Fatal(err)
+	}
+	if headless, _ := filepath.Glob(filepath.Join(runs, "headless", "2*.log")); len(headless) != keepRuns {
+		t.Fatalf("kept %d headless runs", len(headless))
+	}
+}
 // A category alone raises its component to debug, so its lines are written.
 func TestCategoryEnablesComponentDebug(t *testing.T) {
 	t.Setenv("XDG_STATE_HOME", t.TempDir())
-	ctx, closeLog, err := Open(context.Background(), "info", "input-motion")
+	ctx, closeLog, err := Open(context.Background(), "drm", "info", "input-motion")
 	if err != nil {
 		t.Fatal(err)
 	}
 	if err := closeLog(); err != nil {
 		t.Fatal(err)
 	}
-	data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "latest.log"))
+	data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log"))
 	if err != nil {
 		t.Fatal(err)
 	}
 // Narrow categories are on only when named, never through "all".
 func TestEnabledCategories(t *testing.T) {
-	for _, tc := range []struct {
+	for _, category := range []string{"input-motion", "input-keys", "drm-flip"} {
-		debug string
+		component := categories[category]
-		want  bool
+		for _, tc := range []struct {
-	}{{"all", false}, {"input", false}, {"input-motion", true}, {"all,input-motion", true}} {
+			debug string
-		sel, err := ParseDebug(tc.debug)
+			want  bool
-		if err != nil {
+		}{{"all", false}, {component, false}, {category, true}, {"all," + category, true}} {
-			t.Fatal(err)
+			sel, err := ParseDebug(tc.debug)
-		}
+			if err != nil {
-		ctx := context.WithValue(context.Background(), debugKey{}, debugSet(sel))
+				t.Fatal(err)
-		if got := Enabled(ctx, "input-motion"); got != tc.want {
+			}
-			t.Errorf("%q: %v", tc.debug, got)
+			ctx := context.WithValue(context.Background(), debugKey{}, debugSet(sel))
+			if got := Enabled(ctx, category); got != tc.want {
+				t.Errorf("%s with %q: %v", category, tc.debug, got)
+			}
 		}
 	}
 }

M internal/ports/config.go +8 -1

@@ -1,6 +1,9 @@
1	1		package ports
2	2
3		-	import "image"
	3	+	import (
	4	+	"image"
	5	+	"time"
	6	+	)
4	7
5	8		// DefaultSDRBrightness is the BT.2408 SDR reference white in HDR, in nits.
6	9		const DefaultSDRBrightness = 203

@@ -113,6 +116,10 @@ type Config struct {
113	116		// Tearing honours wp_tearing_control_v1 in direct scanout; VRR
114	117		// turns variable refresh on while a buffer is scanned out.
115	118		Tearing, VRR bool
	119	+	// VRRFlipGap is the minimum time between a game frame's flip and
	120	+	// the next frame commit under VRR (0: off). It works around
	121	+	// flips that land at the panel's slowest refresh.
	122	+	VRRFlipGap time.Duration
116	123		}
117	124		Performance struct{ Realtime bool }
118	125		Log struct {

 package ports
-import "image"
+import (
+	"image"
+	"time"
+)
 // DefaultSDRBrightness is the BT.2408 SDR reference white in HDR, in nits.
 const DefaultSDRBrightness = 203
 		// Tearing honours wp_tearing_control_v1 in direct scanout; VRR
 		// turns variable refresh on while a buffer is scanned out.
 		Tearing, VRR bool
+		// VRRFlipGap is the minimum time between a game frame's flip and
+		// the next frame commit under VRR (0: off). It works around
+		// flips that land at the panel's slowest refresh.
+		VRRFlipGap time.Duration
 	}
 	Performance struct{ Realtime bool }
 	Log         struct {