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