Merge pull request 'perf: quiet idle CPU, DRM master retry and stall watchdog' (#37) from perf/idle-cpu-watchdog into main
Reviewed-on: https://git.bnema.dev/bnema/neferwl/pulls/37
26 files · +1348 -161
M Makefile +1 -1
| @@ -69,7 +69,7 @@ adapter-imports: | |||
| 69 | 69 | [ -z "$$bad" ] || { echo "$$bad"; echo 'adapter imports another adapter: use ports or a shared library (Makefile ADAPTER_LIBS)' >&2; exit 1; } | |
| 70 | 70 | # Fast, mandatory guards for tiled content publications and SHM copies. | |
| 71 | 71 | perf-check: | |
| 72 | - | CGO_ENABLED=0 go test ./internal/core ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestAnimateAllocations|TestPublishAllocations|TestPublishSubscribersAllocations|TestPublishStashSlideAllocations|TestPublishOverviewAllocations|TestPublishLeavingAllocations|TestOutputRoutingAllocations|TestReportSeenAllocations|TestFrameLifecycleTransitionsAllocations|TestFullscreenShownAllocations|TestFrameDecisionAllocations|TestCommitFrameAllocations|TestColorPipelineAllocations|TestShownBySnapshotAllocations|TestMRUNoteFocusDoesNotAllocateWhenSettled|TestDueFramesAllocations|TestRenderSteadyStateAllocations|TestSceneOpaqueRegionAllocations|TestSceneDeltaAllocations|TestAccountFlipAllocations|TestFlipDoneAllocations|TestSceneWalkUnchangedTiledSHM|TestTiledCommitPublishAllocations|TestCapturedCommitApplyAllocations|TestCapturedViewportApplyAllocations|TestEffectiveInputEmptyTreeAllocations|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1 | |
| 72 | + | CGO_ENABLED=0 go test ./internal/core ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestAnimateAllocations|TestPublishAllocations|TestPublishSubscribersAllocations|TestPublishStashSlideAllocations|TestPublishOverviewAllocations|TestPublishLeavingAllocations|TestOutputRoutingAllocations|TestReportSeenAllocations|TestFrameLifecycleTransitionsAllocations|TestFullscreenShownAllocations|TestFrameDecisionAllocations|TestCommitFrameAllocations|TestColorPipelineAllocations|TestShownBySnapshotAllocations|TestMRUNoteFocusDoesNotAllocateWhenSettled|TestDueFramesAllocations|TestRenderSteadyStateAllocations|TestSceneOpaqueRegionAllocations|TestSceneDeltaAllocations|TestAccountFlipAllocations|TestFlipDoneAllocations|TestSceneWalkUnchangedTiledSHM|TestTiledCommitPublishAllocations|TestCapturedCommitApplyAllocations|TestCapturedViewportApplyAllocations|TestEffectiveInputEmptyTreeAllocations|TestHeadlessTiledSHMCallbackAndCopyBudget|TestReleaseHeldAllocations|TestCommitDamageAllocations|TestEmitContentAllocations)$$' -count=1 | |
| 73 | 73 | check: vet test arch fakes-check log-check perf-check | |
| 74 | 74 | ||
| 75 | 75 | # On-demand SDR/HDR colour check with examples/testpattern on a headless | |
| @@ -69,7 +69,7 @@ adapter-imports: | |||||
| 69 | [ -z "$$bad" ] || { echo "$$bad"; echo 'adapter imports another adapter: use ports or a shared library (Makefile ADAPTER_LIBS)' >&2; exit 1; } | 69 | [ -z "$$bad" ] || { echo "$$bad"; echo 'adapter imports another adapter: use ports or a shared library (Makefile ADAPTER_LIBS)' >&2; exit 1; } | ||
| 70 | # Fast, mandatory guards for tiled content publications and SHM copies. | 70 | # Fast, mandatory guards for tiled content publications and SHM copies. | ||
| 71 | perf-check: | 71 | perf-check: | ||
| 72 | - | CGO_ENABLED=0 go test ./internal/core ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestAnimateAllocations|TestPublishAllocations|TestPublishSubscribersAllocations|TestPublishStashSlideAllocations|TestPublishOverviewAllocations|TestPublishLeavingAllocations|TestOutputRoutingAllocations|TestReportSeenAllocations|TestFrameLifecycleTransitionsAllocations|TestFullscreenShownAllocations|TestFrameDecisionAllocations|TestCommitFrameAllocations|TestColorPipelineAllocations|TestShownBySnapshotAllocations|TestMRUNoteFocusDoesNotAllocateWhenSettled|TestDueFramesAllocations|TestRenderSteadyStateAllocations|TestSceneOpaqueRegionAllocations|TestSceneDeltaAllocations|TestAccountFlipAllocations|TestFlipDoneAllocations|TestSceneWalkUnchangedTiledSHM|TestTiledCommitPublishAllocations|TestCapturedCommitApplyAllocations|TestCapturedViewportApplyAllocations|TestEffectiveInputEmptyTreeAllocations|TestHeadlessTiledSHMCallbackAndCopyBudget)$$' -count=1 | 72 | + | CGO_ENABLED=0 go test ./internal/core ./internal/app ./internal/adapters/drm ./internal/adapters/vulkan ./internal/adapters/wayland -run '^(TestAnimateAllocations|TestPublishAllocations|TestPublishSubscribersAllocations|TestPublishStashSlideAllocations|TestPublishOverviewAllocations|TestPublishLeavingAllocations|TestOutputRoutingAllocations|TestReportSeenAllocations|TestFrameLifecycleTransitionsAllocations|TestFullscreenShownAllocations|TestFrameDecisionAllocations|TestCommitFrameAllocations|TestColorPipelineAllocations|TestShownBySnapshotAllocations|TestMRUNoteFocusDoesNotAllocateWhenSettled|TestDueFramesAllocations|TestRenderSteadyStateAllocations|TestSceneOpaqueRegionAllocations|TestSceneDeltaAllocations|TestAccountFlipAllocations|TestFlipDoneAllocations|TestSceneWalkUnchangedTiledSHM|TestTiledCommitPublishAllocations|TestCapturedCommitApplyAllocations|TestCapturedViewportApplyAllocations|TestEffectiveInputEmptyTreeAllocations|TestHeadlessTiledSHMCallbackAndCopyBudget|TestReleaseHeldAllocations|TestCommitDamageAllocations|TestEmitContentAllocations)$$' -count=1 |
| 73 | check: vet test arch fakes-check log-check perf-check | 73 | check: vet test arch fakes-check log-check perf-check | ||
| 74 | 74 | ||||
| 75 | # On-demand SDR/HDR colour check with examples/testpattern on a headless | 75 | # On-demand SDR/HDR colour check with examples/testpattern on a headless | ||
M internal/adapters/drm/output.go +113 -37
| @@ -78,6 +78,8 @@ type Output struct { | |||
| 78 | 78 | // seatDisable carries a request to leave the planes on Bypass before | |
| 79 | 79 | // the seat is disabled (PrepareSeatDisable); Run answers it. | |
| 80 | 80 | seatDisable chan chan struct{} | |
| 81 | + | // ping carries watchdog probes (Ping); Run answers each one. | |
| 82 | + | ping chan chan struct{} | |
| 81 | 83 | // fbs are the two renderer images frames alternate between, back the | |
| 82 | 84 | // one the next frame draws into (ADR 014: zero copy). | |
| 83 | 85 | fbs [2]uint32 | |
| @@ -206,7 +208,7 @@ type CursorLoader func(c ports.CursorChange, scale float64, t ports.BufferTransf | |||
| 206 | 208 | func newOutput(card *Card, c connector, mode modeInfo, crtc uint32) (*Output, error) { | |
| 207 | 209 | log := card.log | |
| 208 | 210 | pipe := slices.Index(card.crtcs, crtc) | |
| 209 | - | 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, renderLog: card.renderLog, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap} | |
| 211 | + | 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, renderLog: card.renderLog, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), ping: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap} | |
| 210 | 212 | var err error | |
| 211 | 213 | if o.saved, err = getCrtc(card.fd, crtc); err != nil { | |
| 212 | 214 | log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit") | |
| @@ -319,6 +321,21 @@ func cursorSize(fd int) int { | |||
| 319 | 321 | // Cursor is the hardware cursor, or nil when the CRTC has no cursor plane. | |
| 320 | 322 | func (o *Output) Cursor() *Cursor { return o.cursor } | |
| 321 | 323 | ||
| 324 | + | // Ping returns once Run handled a probe, or once ctx ends: the watchdog | |
| 325 | + | // uses it to detect a stuck output loop. | |
| 326 | + | func (o *Output) Ping(ctx context.Context) { | |
| 327 | + | ack := make(chan struct{}) | |
| 328 | + | select { | |
| 329 | + | case o.ping <- ack: | |
| 330 | + | case <-ctx.Done(): | |
| 331 | + | return | |
| 332 | + | } | |
| 333 | + | select { | |
| 334 | + | case <-ack: | |
| 335 | + | case <-ctx.Done(): | |
| 336 | + | } | |
| 337 | + | } | |
| 338 | + | ||
| 322 | 339 | // Info describes the output for core and clients. Unknown EDID fields are empty. | |
| 323 | 340 | func (o *Output) Info() ports.OutputInfo { | |
| 324 | 341 | known := func(v string) string { | |
| @@ -1098,6 +1115,64 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||
| 1098 | 1115 | cursorWake = o.cursor.wake | |
| 1099 | 1116 | } | |
| 1100 | 1117 | securityChanges := o.SecurityChanges | |
| 1118 | + | reacquireTimer := time.NewTimer(time.Hour) | |
| 1119 | + | reacquireTimer.Stop() | |
| 1120 | + | defer reacquireTimer.Stop() | |
| 1121 | + | var reacquire masterRetry | |
| 1122 | + | // refuse records an enable refused for lack of DRM master. | |
| 1123 | + | refuseMaster := func(err error) { | |
| 1124 | + | if reacquire.refused(err, enabled, time.Now()) { | |
| 1125 | + | o.log.Warn().Err(err).Str("connector", o.conn.name).Int("attempts", masterRetryLimit).Msg("DRM master not back; output stays off until the next seat change") | |
| 1126 | + | } | |
| 1127 | + | } | |
| 1128 | + | // setActive applies a seat change. skip reports that the loop must | |
| 1129 | + | // go on without touching the frame state (refused or protected). | |
| 1130 | + | setActive := func(on bool) (skip bool, err error) { | |
| 1131 | + | o.observeSecurity() | |
| 1132 | + | if o.protected { | |
| 1133 | + | o.invalidateSecurity() | |
| 1134 | + | enabled = on | |
| 1135 | + | if on && o.fbs[0] == 0 { | |
| 1136 | + | if err := o.showImages(r, imagesDriver, nil); err != nil { | |
| 1137 | + | if !o.commitFailed(err, &enabled) { | |
| 1138 | + | return true, err | |
| 1139 | + | } | |
| 1140 | + | refuseMaster(err) | |
| 1141 | + | return true, nil | |
| 1142 | + | } | |
| 1143 | + | } | |
| 1144 | + | // With images, the protected modeset runs at the top of the | |
| 1145 | + | // loop (prepareSecurity): it ends or reschedules the retry. | |
| 1146 | + | return true, nil | |
| 1147 | + | } | |
| 1148 | + | // Modeset on every enable: a fast disable+enable can coalesce to one true. | |
| 1149 | + | if on { | |
| 1150 | + | enabled = true // this enable may supersede a previous master loss | |
| 1151 | + | var err error | |
| 1152 | + | if o.fbs[0] == 0 { | |
| 1153 | + | err = o.showImages(r, imagesDriver, nil) | |
| 1154 | + | } else { | |
| 1155 | + | err = o.modeset() | |
| 1156 | + | } | |
| 1157 | + | if err != nil { | |
| 1158 | + | if !o.commitFailed(err, &enabled) { | |
| 1159 | + | return true, err | |
| 1160 | + | } | |
| 1161 | + | refuseMaster(err) | |
| 1162 | + | return true, nil // epoch retry or wait disabled for master reacquisition | |
| 1163 | + | } | |
| 1164 | + | reacquire.done() | |
| 1165 | + | o.observeSecurity() | |
| 1166 | + | if o.protected { | |
| 1167 | + | return true, nil | |
| 1168 | + | } | |
| 1169 | + | o.probeAsync(r) | |
| 1170 | + | dirty = haveScene | |
| 1171 | + | } | |
| 1172 | + | enabled = on | |
| 1173 | + | o.log.Info().Bool("enabled", on).Msg("output") | |
| 1174 | + | return false, nil | |
| 1175 | + | } | |
| 1101 | 1176 | for { | |
| 1102 | 1177 | if o.observeSecurity() || haveScene && !o.sceneCurrent(scene) { | |
| 1103 | 1178 | scene, haveScene, dirty = ports.Scene{}, false, false | |
| @@ -1118,6 +1193,11 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||
| 1118 | 1193 | if !o.commitFailed(err, &enabled) { | |
| 1119 | 1194 | return err | |
| 1120 | 1195 | } | |
| 1196 | + | // A lock screen refused for lack of DRM master after a VT | |
| 1197 | + | // switch is retried like an ordinary enable. | |
| 1198 | + | refuseMaster(err) | |
| 1199 | + | } else { | |
| 1200 | + | reacquire.done() | |
| 1121 | 1201 | } | |
| 1122 | 1202 | // Recheck immediately: a takeover during the clear needs its own | |
| 1123 | 1203 | // transaction, not another scene or wake to make progress. | |
| @@ -1203,6 +1283,14 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||
| 1203 | 1283 | } else { | |
| 1204 | 1284 | protectTimer.Stop() | |
| 1205 | 1285 | } | |
| 1286 | + | // An enable refused for lack of DRM master is retried on time. | |
| 1287 | + | var reacquireDue <-chan time.Time | |
| 1288 | + | if d, ok := reacquire.next(time.Now()); ok { | |
| 1289 | + | reacquireTimer.Reset(d) | |
| 1290 | + | reacquireDue = reacquireTimer.C | |
| 1291 | + | } else { | |
| 1292 | + | reacquireTimer.Stop() | |
| 1293 | + | } | |
| 1206 | 1294 | // A commit whose event never comes must not stop the output. | |
| 1207 | 1295 | stuck := o.frame.wait(enabled) | |
| 1208 | 1296 | stateDirty := false | |
| @@ -1260,52 +1348,40 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||
| 1260 | 1348 | refuse = capture.ErrOutputOff | |
| 1261 | 1349 | } | |
| 1262 | 1350 | dirty = requests.Admit(q, refuse, scene, haveScene) || dirty | |
| 1351 | + | case ack := <-o.ping: | |
| 1352 | + | close(ack) | |
| 1353 | + | continue | |
| 1263 | 1354 | case ack := <-o.seatDisable: | |
| 1264 | 1355 | o.bypassForSeatDisable() | |
| 1265 | 1356 | // The seat is about to be disabled: no frame may select the | |
| 1266 | - | // pipeline again before the next enable (a modeset). | |
| 1357 | + | // pipeline again before the next enable (a modeset), not even a | |
| 1358 | + | // retried one. | |
| 1359 | + | reacquire.done() | |
| 1267 | 1360 | enabled = false | |
| 1268 | 1361 | ack <- struct{}{} | |
| 1269 | 1362 | continue | |
| 1270 | 1363 | case on := <-active: | |
| 1271 | - | o.observeSecurity() | |
| 1272 | - | if o.protected { | |
| 1273 | - | o.invalidateSecurity() | |
| 1274 | - | enabled = on | |
| 1275 | - | if on && o.fbs[0] == 0 { | |
| 1276 | - | if err := o.showImages(r, imagesDriver, nil); err != nil { | |
| 1277 | - | if !o.commitFailed(err, &enabled) { | |
| 1278 | - | return err | |
| 1279 | - | } | |
| 1280 | - | } | |
| 1281 | - | } | |
| 1364 | + | reacquire.done() | |
| 1365 | + | skip, err := setActive(on) | |
| 1366 | + | if err != nil { | |
| 1367 | + | return err | |
| 1368 | + | } | |
| 1369 | + | if skip { | |
| 1282 | 1370 | continue | |
| 1283 | 1371 | } | |
| 1284 | - | // Modeset on every enable: a fast disable+enable can coalesce to one true. | |
| 1285 | - | if on { | |
| 1286 | - | enabled = true // this enable may supersede a previous master loss | |
| 1287 | - | var err error | |
| 1288 | - | if o.fbs[0] == 0 { | |
| 1289 | - | err = o.showImages(r, imagesDriver, nil) | |
| 1290 | - | } else { | |
| 1291 | - | err = o.modeset() | |
| 1292 | - | } | |
| 1293 | - | if err != nil { | |
| 1294 | - | if !o.commitFailed(err, &enabled) { | |
| 1295 | - | return err | |
| 1296 | - | } | |
| 1297 | - | continue // epoch retry or wait disabled for master reacquisition | |
| 1298 | - | } | |
| 1299 | - | o.observeSecurity() | |
| 1300 | - | if o.protected { | |
| 1301 | - | continue | |
| 1302 | - | } | |
| 1303 | - | o.probeAsync(r) | |
| 1304 | - | dirty = haveScene | |
| 1305 | - | stateDirty = true | |
| 1372 | + | stateDirty = on | |
| 1373 | + | case <-reacquireDue: | |
| 1374 | + | // The seat reported active before the kernel gave DRM master | |
| 1375 | + | // back: the enable modeset was refused. Try it again. | |
| 1376 | + | reacquire.fire() | |
| 1377 | + | skip, err := setActive(true) | |
| 1378 | + | if err != nil { | |
| 1379 | + | return err | |
| 1306 | 1380 | } | |
| 1307 | - | enabled = on | |
| 1308 | - | o.log.Info().Bool("enabled", on).Msg("output") | |
| 1381 | + | if skip { | |
| 1382 | + | continue | |
| 1383 | + | } | |
| 1384 | + | stateDirty = true | |
| 1309 | 1385 | case ev := <-o.flipped: | |
| 1310 | 1386 | o.observeSecurity() | |
| 1311 | 1387 | if !o.completed(ev, seen) { | |
| @@ -78,6 +78,8 @@ type Output struct { | |||||
| 78 | // seatDisable carries a request to leave the planes on Bypass before | 78 | // seatDisable carries a request to leave the planes on Bypass before | ||
| 79 | // the seat is disabled (PrepareSeatDisable); Run answers it. | 79 | // the seat is disabled (PrepareSeatDisable); Run answers it. | ||
| 80 | seatDisable chan chan struct{} | 80 | seatDisable chan chan struct{} | ||
| 81 | + | // ping carries watchdog probes (Ping); Run answers each one. | |||
| 82 | + | ping chan chan struct{} | |||
| 81 | // fbs are the two renderer images frames alternate between, back the | 83 | // fbs are the two renderer images frames alternate between, back the | ||
| 82 | // one the next frame draws into (ADR 014: zero copy). | 84 | // one the next frame draws into (ADR 014: zero copy). | ||
| 83 | fbs [2]uint32 | 85 | fbs [2]uint32 | ||
| @@ -206,7 +208,7 @@ type CursorLoader func(c ports.CursorChange, scale float64, t ports.BufferTransf | |||||
| 206 | func newOutput(card *Card, c connector, mode modeInfo, crtc uint32) (*Output, error) { | 208 | func newOutput(card *Card, c connector, mode modeInfo, crtc uint32) (*Output, error) { | ||
| 207 | log := card.log | 209 | log := card.log | ||
| 208 | pipe := slices.Index(card.crtcs, crtc) | 210 | pipe := slices.Index(card.crtcs, crtc) | ||
| 209 | - | 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, renderLog: card.renderLog, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap} | 211 | + | 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, renderLog: card.renderLog, monitor: readMonitor(card.path, c.name), scanout: !card.want.NoScanout, clientFBs: map[uint64]*clientFB{}, reason: "start", ready: make(chan error, 1), seatDisable: make(chan chan struct{}), ping: make(chan chan struct{}), traceFlips: card.want.TraceFlips, vrrFlipGap: card.want.VRRFlipGap} |
| 210 | var err error | 212 | var err error | ||
| 211 | if o.saved, err = getCrtc(card.fd, crtc); err != nil { | 213 | if o.saved, err = getCrtc(card.fd, crtc); err != nil { | ||
| 212 | log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit") | 214 | log.Warn().Err(err).Uint32("crtc", crtc).Msg("save crtc; it will not be restored on exit") | ||
| @@ -319,6 +321,21 @@ func cursorSize(fd int) int { | |||||
| 319 | // Cursor is the hardware cursor, or nil when the CRTC has no cursor plane. | 321 | // Cursor is the hardware cursor, or nil when the CRTC has no cursor plane. | ||
| 320 | func (o *Output) Cursor() *Cursor { return o.cursor } | 322 | func (o *Output) Cursor() *Cursor { return o.cursor } | ||
| 321 | 323 | ||||
| 324 | + | // Ping returns once Run handled a probe, or once ctx ends: the watchdog | |||
| 325 | + | // uses it to detect a stuck output loop. | |||
| 326 | + | func (o *Output) Ping(ctx context.Context) { | |||
| 327 | + | ack := make(chan struct{}) | |||
| 328 | + | select { | |||
| 329 | + | case o.ping <- ack: | |||
| 330 | + | case <-ctx.Done(): | |||
| 331 | + | return | |||
| 332 | + | } | |||
| 333 | + | select { | |||
| 334 | + | case <-ack: | |||
| 335 | + | case <-ctx.Done(): | |||
| 336 | + | } | |||
| 337 | + | } | |||
| 338 | + | ||||
| 322 | // Info describes the output for core and clients. Unknown EDID fields are empty. | 339 | // Info describes the output for core and clients. Unknown EDID fields are empty. | ||
| 323 | func (o *Output) Info() ports.OutputInfo { | 340 | func (o *Output) Info() ports.OutputInfo { | ||
| 324 | known := func(v string) string { | 341 | known := func(v string) string { | ||
| @@ -1098,6 +1115,64 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||||
| 1098 | cursorWake = o.cursor.wake | 1115 | cursorWake = o.cursor.wake | ||
| 1099 | } | 1116 | } | ||
| 1100 | securityChanges := o.SecurityChanges | 1117 | securityChanges := o.SecurityChanges | ||
| 1118 | + | reacquireTimer := time.NewTimer(time.Hour) | |||
| 1119 | + | reacquireTimer.Stop() | |||
| 1120 | + | defer reacquireTimer.Stop() | |||
| 1121 | + | var reacquire masterRetry | |||
| 1122 | + | // refuse records an enable refused for lack of DRM master. | |||
| 1123 | + | refuseMaster := func(err error) { | |||
| 1124 | + | if reacquire.refused(err, enabled, time.Now()) { | |||
| 1125 | + | o.log.Warn().Err(err).Str("connector", o.conn.name).Int("attempts", masterRetryLimit).Msg("DRM master not back; output stays off until the next seat change") | |||
| 1126 | + | } | |||
| 1127 | + | } | |||
| 1128 | + | // setActive applies a seat change. skip reports that the loop must | |||
| 1129 | + | // go on without touching the frame state (refused or protected). | |||
| 1130 | + | setActive := func(on bool) (skip bool, err error) { | |||
| 1131 | + | o.observeSecurity() | |||
| 1132 | + | if o.protected { | |||
| 1133 | + | o.invalidateSecurity() | |||
| 1134 | + | enabled = on | |||
| 1135 | + | if on && o.fbs[0] == 0 { | |||
| 1136 | + | if err := o.showImages(r, imagesDriver, nil); err != nil { | |||
| 1137 | + | if !o.commitFailed(err, &enabled) { | |||
| 1138 | + | return true, err | |||
| 1139 | + | } | |||
| 1140 | + | refuseMaster(err) | |||
| 1141 | + | return true, nil | |||
| 1142 | + | } | |||
| 1143 | + | } | |||
| 1144 | + | // With images, the protected modeset runs at the top of the | |||
| 1145 | + | // loop (prepareSecurity): it ends or reschedules the retry. | |||
| 1146 | + | return true, nil | |||
| 1147 | + | } | |||
| 1148 | + | // Modeset on every enable: a fast disable+enable can coalesce to one true. | |||
| 1149 | + | if on { | |||
| 1150 | + | enabled = true // this enable may supersede a previous master loss | |||
| 1151 | + | var err error | |||
| 1152 | + | if o.fbs[0] == 0 { | |||
| 1153 | + | err = o.showImages(r, imagesDriver, nil) | |||
| 1154 | + | } else { | |||
| 1155 | + | err = o.modeset() | |||
| 1156 | + | } | |||
| 1157 | + | if err != nil { | |||
| 1158 | + | if !o.commitFailed(err, &enabled) { | |||
| 1159 | + | return true, err | |||
| 1160 | + | } | |||
| 1161 | + | refuseMaster(err) | |||
| 1162 | + | return true, nil // epoch retry or wait disabled for master reacquisition | |||
| 1163 | + | } | |||
| 1164 | + | reacquire.done() | |||
| 1165 | + | o.observeSecurity() | |||
| 1166 | + | if o.protected { | |||
| 1167 | + | return true, nil | |||
| 1168 | + | } | |||
| 1169 | + | o.probeAsync(r) | |||
| 1170 | + | dirty = haveScene | |||
| 1171 | + | } | |||
| 1172 | + | enabled = on | |||
| 1173 | + | o.log.Info().Bool("enabled", on).Msg("output") | |||
| 1174 | + | return false, nil | |||
| 1175 | + | } | |||
| 1101 | for { | 1176 | for { | ||
| 1102 | if o.observeSecurity() || haveScene && !o.sceneCurrent(scene) { | 1177 | if o.observeSecurity() || haveScene && !o.sceneCurrent(scene) { | ||
| 1103 | scene, haveScene, dirty = ports.Scene{}, false, false | 1178 | scene, haveScene, dirty = ports.Scene{}, false, false | ||
| @@ -1118,6 +1193,11 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||||
| 1118 | if !o.commitFailed(err, &enabled) { | 1193 | if !o.commitFailed(err, &enabled) { | ||
| 1119 | return err | 1194 | return err | ||
| 1120 | } | 1195 | } | ||
| 1196 | + | // A lock screen refused for lack of DRM master after a VT | |||
| 1197 | + | // switch is retried like an ordinary enable. | |||
| 1198 | + | refuseMaster(err) | |||
| 1199 | + | } else { | |||
| 1200 | + | reacquire.done() | |||
| 1121 | } | 1201 | } | ||
| 1122 | // Recheck immediately: a takeover during the clear needs its own | 1202 | // Recheck immediately: a takeover during the clear needs its own | ||
| 1123 | // transaction, not another scene or wake to make progress. | 1203 | // transaction, not another scene or wake to make progress. | ||
| @@ -1203,6 +1283,14 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||||
| 1203 | } else { | 1283 | } else { | ||
| 1204 | protectTimer.Stop() | 1284 | protectTimer.Stop() | ||
| 1205 | } | 1285 | } | ||
| 1286 | + | // An enable refused for lack of DRM master is retried on time. | |||
| 1287 | + | var reacquireDue <-chan time.Time | |||
| 1288 | + | if d, ok := reacquire.next(time.Now()); ok { | |||
| 1289 | + | reacquireTimer.Reset(d) | |||
| 1290 | + | reacquireDue = reacquireTimer.C | |||
| 1291 | + | } else { | |||
| 1292 | + | reacquireTimer.Stop() | |||
| 1293 | + | } | |||
| 1206 | // A commit whose event never comes must not stop the output. | 1294 | // A commit whose event never comes must not stop the output. | ||
| 1207 | stuck := o.frame.wait(enabled) | 1295 | stuck := o.frame.wait(enabled) | ||
| 1208 | stateDirty := false | 1296 | stateDirty := false | ||
| @@ -1260,52 +1348,40 @@ func (o *Output) Run(ctx context.Context, newRenderer func(w, h int) (ports.Rend | |||||
| 1260 | refuse = capture.ErrOutputOff | 1348 | refuse = capture.ErrOutputOff | ||
| 1261 | } | 1349 | } | ||
| 1262 | dirty = requests.Admit(q, refuse, scene, haveScene) || dirty | 1350 | dirty = requests.Admit(q, refuse, scene, haveScene) || dirty | ||
| 1351 | + | case ack := <-o.ping: | |||
| 1352 | + | close(ack) | |||
| 1353 | + | continue | |||
| 1263 | case ack := <-o.seatDisable: | 1354 | case ack := <-o.seatDisable: | ||
| 1264 | o.bypassForSeatDisable() | 1355 | o.bypassForSeatDisable() | ||
| 1265 | // The seat is about to be disabled: no frame may select the | 1356 | // The seat is about to be disabled: no frame may select the | ||
| 1266 | - | // pipeline again before the next enable (a modeset). | 1357 | + | // pipeline again before the next enable (a modeset), not even a |
| 1358 | + | // retried one. | |||
| 1359 | + | reacquire.done() | |||
| 1267 | enabled = false | 1360 | enabled = false | ||
| 1268 | ack <- struct{}{} | 1361 | ack <- struct{}{} | ||
| 1269 | continue | 1362 | continue | ||
| 1270 | case on := <-active: | 1363 | case on := <-active: | ||
| 1271 | - | o.observeSecurity() | 1364 | + | reacquire.done() |
| 1272 | - | if o.protected { | 1365 | + | skip, err := setActive(on) |
| 1273 | - | o.invalidateSecurity() | 1366 | + | if err != nil { |
| 1274 | - | enabled = on | 1367 | + | return err |
| 1275 | - | if on && o.fbs[0] == 0 { | 1368 | + | } |
| 1276 | - | if err := o.showImages(r, imagesDriver, nil); err != nil { | 1369 | + | if skip { |
| 1277 | - | if !o.commitFailed(err, &enabled) { | |||
| 1278 | - | return err | |||
| 1279 | - | } | |||
| 1280 | - | } | |||
| 1281 | - | } | |||
| 1282 | continue | 1370 | continue | ||
| 1283 | } | 1371 | } | ||
| 1284 | - | // Modeset on every enable: a fast disable+enable can coalesce to one true. | 1372 | + | stateDirty = on |
| 1285 | - | if on { | 1373 | + | case <-reacquireDue: |
| 1286 | - | enabled = true // this enable may supersede a previous master loss | 1374 | + | // The seat reported active before the kernel gave DRM master |
| 1287 | - | var err error | 1375 | + | // back: the enable modeset was refused. Try it again. |
| 1288 | - | if o.fbs[0] == 0 { | 1376 | + | reacquire.fire() |
| 1289 | - | err = o.showImages(r, imagesDriver, nil) | 1377 | + | skip, err := setActive(true) |
| 1290 | - | } else { | 1378 | + | if err != nil { |
| 1291 | - | err = o.modeset() | 1379 | + | return err |
| 1292 | - | } | |||
| 1293 | - | if err != nil { | |||
| 1294 | - | if !o.commitFailed(err, &enabled) { | |||
| 1295 | - | return err | |||
| 1296 | - | } | |||
| 1297 | - | continue // epoch retry or wait disabled for master reacquisition | |||
| 1298 | - | } | |||
| 1299 | - | o.observeSecurity() | |||
| 1300 | - | if o.protected { | |||
| 1301 | - | continue | |||
| 1302 | - | } | |||
| 1303 | - | o.probeAsync(r) | |||
| 1304 | - | dirty = haveScene | |||
| 1305 | - | stateDirty = true | |||
| 1306 | } | 1380 | } | ||
| 1307 | - | enabled = on | 1381 | + | if skip { |
| 1308 | - | o.log.Info().Bool("enabled", on).Msg("output") | 1382 | + | continue |
| 1383 | + | } | |||
| 1384 | + | stateDirty = true | |||
| 1309 | case ev := <-o.flipped: | 1385 | case ev := <-o.flipped: | ||
| 1310 | o.observeSecurity() | 1386 | o.observeSecurity() | ||
| 1311 | if !o.completed(ev, seen) { | 1387 | if !o.completed(ev, seen) { | ||
A internal/adapters/drm/reacquire.go +56 -0
| @@ -0,0 +1,56 @@ | |||
| 1 | + | package drm | |
| 2 | + | ||
| 3 | + | import "time" | |
| 4 | + | ||
| 5 | + | // masterRetry retries an enable modeset that the kernel refused because | |
| 6 | + | // DRM master was not back yet. The seat can report the session active | |
| 7 | + | // before the kernel hands master back; without a retry the output stays | |
| 8 | + | // dark until the next VT switch. | |
| 9 | + | // | |
| 10 | + | // The retry has a fixed deadline: the output loop wakes for many other | |
| 11 | + | // events (pings, cursor, reports) and must not push it back on each one. | |
| 12 | + | type masterRetry struct { | |
| 13 | + | pending bool | |
| 14 | + | due time.Time | |
| 15 | + | attempts int | |
| 16 | + | } | |
| 17 | + | ||
| 18 | + | const ( | |
| 19 | + | masterRetryFirst = 20 * time.Millisecond | |
| 20 | + | masterRetryMax = time.Second | |
| 21 | + | // masterRetryLimit bounds the retries of one enable (about 35 s). | |
| 22 | + | masterRetryLimit = 40 | |
| 23 | + | ) | |
| 24 | + | ||
| 25 | + | // refused records an enable refused with err at now; only a lost master | |
| 26 | + | // is retried, and enabled stays false until a retry succeeds. It reports | |
| 27 | + | // that the retries are exhausted. | |
| 28 | + | func (m *masterRetry) refused(err error, enabled bool, now time.Time) (gaveUp bool) { | |
| 29 | + | if !lostMaster(err) || enabled { | |
| 30 | + | return false | |
| 31 | + | } | |
| 32 | + | if m.attempts >= masterRetryLimit { | |
| 33 | + | m.pending = false | |
| 34 | + | return true | |
| 35 | + | } | |
| 36 | + | m.pending = true | |
| 37 | + | m.due = now.Add(min(masterRetryFirst<<min(m.attempts, 6), masterRetryMax)) | |
| 38 | + | return false | |
| 39 | + | } | |
| 40 | + | ||
| 41 | + | // fire starts an attempt: the retry is pending again only if it is refused. | |
| 42 | + | func (m *masterRetry) fire() { | |
| 43 | + | m.pending = false | |
| 44 | + | m.attempts++ | |
| 45 | + | } | |
| 46 | + | ||
| 47 | + | // done ends the retry: the enable succeeded or the seat changed. | |
| 48 | + | func (m *masterRetry) done() { *m = masterRetry{} } | |
| 49 | + | ||
| 50 | + | // next is the time left before the next attempt, if one is due. | |
| 51 | + | func (m *masterRetry) next(now time.Time) (time.Duration, bool) { | |
| 52 | + | if !m.pending { | |
| 53 | + | return 0, false | |
| 54 | + | } | |
| 55 | + | return max(0, m.due.Sub(now)), true | |
| 56 | + | } | |
| @@ -0,0 +1,56 @@ | |||||
| 1 | + | package drm | |||
| 2 | + | ||||
| 3 | + | import "time" | |||
| 4 | + | ||||
| 5 | + | // masterRetry retries an enable modeset that the kernel refused because | |||
| 6 | + | // DRM master was not back yet. The seat can report the session active | |||
| 7 | + | // before the kernel hands master back; without a retry the output stays | |||
| 8 | + | // dark until the next VT switch. | |||
| 9 | + | // | |||
| 10 | + | // The retry has a fixed deadline: the output loop wakes for many other | |||
| 11 | + | // events (pings, cursor, reports) and must not push it back on each one. | |||
| 12 | + | type masterRetry struct { | |||
| 13 | + | pending bool | |||
| 14 | + | due time.Time | |||
| 15 | + | attempts int | |||
| 16 | + | } | |||
| 17 | + | ||||
| 18 | + | const ( | |||
| 19 | + | masterRetryFirst = 20 * time.Millisecond | |||
| 20 | + | masterRetryMax = time.Second | |||
| 21 | + | // masterRetryLimit bounds the retries of one enable (about 35 s). | |||
| 22 | + | masterRetryLimit = 40 | |||
| 23 | + | ) | |||
| 24 | + | ||||
| 25 | + | // refused records an enable refused with err at now; only a lost master | |||
| 26 | + | // is retried, and enabled stays false until a retry succeeds. It reports | |||
| 27 | + | // that the retries are exhausted. | |||
| 28 | + | func (m *masterRetry) refused(err error, enabled bool, now time.Time) (gaveUp bool) { | |||
| 29 | + | if !lostMaster(err) || enabled { | |||
| 30 | + | return false | |||
| 31 | + | } | |||
| 32 | + | if m.attempts >= masterRetryLimit { | |||
| 33 | + | m.pending = false | |||
| 34 | + | return true | |||
| 35 | + | } | |||
| 36 | + | m.pending = true | |||
| 37 | + | m.due = now.Add(min(masterRetryFirst<<min(m.attempts, 6), masterRetryMax)) | |||
| 38 | + | return false | |||
| 39 | + | } | |||
| 40 | + | ||||
| 41 | + | // fire starts an attempt: the retry is pending again only if it is refused. | |||
| 42 | + | func (m *masterRetry) fire() { | |||
| 43 | + | m.pending = false | |||
| 44 | + | m.attempts++ | |||
| 45 | + | } | |||
| 46 | + | ||||
| 47 | + | // done ends the retry: the enable succeeded or the seat changed. | |||
| 48 | + | func (m *masterRetry) done() { *m = masterRetry{} } | |||
| 49 | + | ||||
| 50 | + | // next is the time left before the next attempt, if one is due. | |||
| 51 | + | func (m *masterRetry) next(now time.Time) (time.Duration, bool) { | |||
| 52 | + | if !m.pending { | |||
| 53 | + | return 0, false | |||
| 54 | + | } | |||
| 55 | + | return max(0, m.due.Sub(now)), true | |||
| 56 | + | } | |||
A internal/adapters/drm/reacquire_test.go +184 -0
| @@ -0,0 +1,184 @@ | |||
| 1 | + | package drm | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "context" | |
| 5 | + | "errors" | |
| 6 | + | "sync" | |
| 7 | + | "testing" | |
| 8 | + | "testing/synctest" | |
| 9 | + | "time" | |
| 10 | + | ||
| 11 | + | portsmocks "github.com/bnema/neferwl/internal/mocks/ports" | |
| 12 | + | "github.com/bnema/neferwl/internal/ports" | |
| 13 | + | "github.com/stretchr/testify/mock" | |
| 14 | + | "golang.org/x/sys/unix" | |
| 15 | + | ) | |
| 16 | + | ||
| 17 | + | func TestMasterRetryBackoff(t *testing.T) { | |
| 18 | + | var m masterRetry | |
| 19 | + | now := time.Unix(0, 0) | |
| 20 | + | if _, ok := m.next(now); ok { | |
| 21 | + | t.Fatal("retry due before a refusal") | |
| 22 | + | } | |
| 23 | + | if m.refused(unix.EBUSY, false, now); m.pending { | |
| 24 | + | t.Fatal("a busy refusal is retried by the busy path, not here") | |
| 25 | + | } | |
| 26 | + | if m.refused(unix.EACCES, true, now); m.pending { | |
| 27 | + | t.Fatal("an enabled output is not retried") | |
| 28 | + | } | |
| 29 | + | m.refused(unix.EACCES, false, now) | |
| 30 | + | // The deadline is fixed: asking later leaves less, never more. | |
| 31 | + | if d, ok := m.next(now); !ok || d != masterRetryFirst { | |
| 32 | + | t.Fatalf("first retry %v %v", d, ok) | |
| 33 | + | } | |
| 34 | + | if d, _ := m.next(now.Add(masterRetryFirst / 2)); d != masterRetryFirst/2 { | |
| 35 | + | t.Fatalf("half-way %v", d) | |
| 36 | + | } | |
| 37 | + | if d, _ := m.next(now.Add(time.Hour)); d != 0 { | |
| 38 | + | t.Fatalf("overdue %v", d) | |
| 39 | + | } | |
| 40 | + | m.fire() | |
| 41 | + | if _, ok := m.next(now); ok { | |
| 42 | + | t.Fatal("pending while an attempt runs") | |
| 43 | + | } | |
| 44 | + | m.attempts = 30 | |
| 45 | + | m.refused(unix.EPERM, false, now) | |
| 46 | + | if d, _ := m.next(now); d != masterRetryMax { | |
| 47 | + | t.Fatalf("capped retry %v", d) | |
| 48 | + | } | |
| 49 | + | m.attempts = masterRetryLimit | |
| 50 | + | if !m.refused(unix.EACCES, false, now) || m.pending { | |
| 51 | + | t.Fatal("retries past the limit") | |
| 52 | + | } | |
| 53 | + | m.done() | |
| 54 | + | if _, ok := m.next(now); ok || m.attempts != 0 { | |
| 55 | + | t.Fatal("retry after done") | |
| 56 | + | } | |
| 57 | + | } | |
| 58 | + | ||
| 59 | + | // retryHarness runs an output whose enable modesets the kernel refuses | |
| 60 | + | // (lost master) until allow is called. | |
| 61 | + | type retryHarness struct { | |
| 62 | + | o *Output | |
| 63 | + | active chan bool | |
| 64 | + | modesets func() int | |
| 65 | + | allow func() | |
| 66 | + | stop func() | |
| 67 | + | } | |
| 68 | + | ||
| 69 | + | func newRetryHarness(t *testing.T) retryHarness { | |
| 70 | + | t.Helper() | |
| 71 | + | var mu sync.Mutex | |
| 72 | + | refuse := true | |
| 73 | + | o, k, commits, commitMu := testOutputRules(t, func(_ *atomicReq, flags uint32) error { | |
| 74 | + | mu.Lock() | |
| 75 | + | defer mu.Unlock() | |
| 76 | + | if refuse && flags&atomicAllowModes != 0 && flags&atomicTestOnly == 0 { | |
| 77 | + | return unix.EACCES | |
| 78 | + | } | |
| 79 | + | return nil | |
| 80 | + | }) | |
| 81 | + | o.cursor, o.tearing = nil, false | |
| 82 | + | r := portsmocks.NewMockRenderer(t) | |
| 83 | + | r.EXPECT().SetHDR(mock.Anything).Return().Maybe() | |
| 84 | + | r.EXPECT().UseTarget(mock.Anything).Return().Maybe() | |
| 85 | + | r.EXPECT().Render(mock.Anything, mock.Anything).Return(nil, nil).Maybe() | |
| 86 | + | r.EXPECT().Close().Return().Once() | |
| 87 | + | // The 10 s stats tick runs in long tests. | |
| 88 | + | r.EXPECT().Trim(mock.Anything).Return(nil).Maybe() | |
| 89 | + | r.EXPECT().TakeRedrawn().Return(0).Maybe() | |
| 90 | + | k.EXPECT().createBlob(mock.Anything).Return(99, nil).Maybe() | |
| 91 | + | k.EXPECT().destroyBlob(mock.Anything).Return(nil).Maybe() | |
| 92 | + | k.EXPECT().rmFB(mock.Anything).Return(nil).Maybe() | |
| 93 | + | o.ping = make(chan chan struct{}) | |
| 94 | + | active := make(chan bool, 1) | |
| 95 | + | active <- false | |
| 96 | + | ctx, cancel := context.WithCancel(context.Background()) | |
| 97 | + | done := make(chan error, 1) | |
| 98 | + | go func() { | |
| 99 | + | done <- o.Run(ctx, func(int, int) (ports.Renderer, error) { return r, nil }, nil, active, nil, nil, nil, make(chan ports.OutputPresented, 1), nil, nil) | |
| 100 | + | }() | |
| 101 | + | synctest.Wait() | |
| 102 | + | return retryHarness{ | |
| 103 | + | o: o, active: active, | |
| 104 | + | modesets: func() int { | |
| 105 | + | commitMu.Lock() | |
| 106 | + | defer commitMu.Unlock() | |
| 107 | + | n := 0 | |
| 108 | + | for _, c := range *commits { | |
| 109 | + | if c.flags&atomicAllowModes != 0 && c.flags&atomicTestOnly == 0 { | |
| 110 | + | n++ | |
| 111 | + | } | |
| 112 | + | } | |
| 113 | + | return n | |
| 114 | + | }, | |
| 115 | + | allow: func() { mu.Lock(); refuse = false; mu.Unlock() }, | |
| 116 | + | stop: func() { | |
| 117 | + | cancel() | |
| 118 | + | if err := <-done; err != nil && !errors.Is(err, context.Canceled) { | |
| 119 | + | t.Fatal(err) | |
| 120 | + | } | |
| 121 | + | }, | |
| 122 | + | } | |
| 123 | + | } | |
| 124 | + | ||
| 125 | + | // The seat reports active before the kernel gives DRM master back: the | |
| 126 | + | // enable modeset is refused, then retried until it succeeds, without a | |
| 127 | + | // second seat change, even while other events (watchdog pings) keep | |
| 128 | + | // waking the loop faster than the backoff. | |
| 129 | + | func TestEnableRefusedForMasterIsRetried(t *testing.T) { | |
| 130 | + | synctest.Test(t, func(t *testing.T) { | |
| 131 | + | h := newRetryHarness(t) | |
| 132 | + | h.active <- true | |
| 133 | + | synctest.Wait() | |
| 134 | + | if n := h.modesets(); n != 1 { | |
| 135 | + | t.Fatalf("%d modesets after the refused enable", n) | |
| 136 | + | } | |
| 137 | + | // Let the backoff grow past the ping period. | |
| 138 | + | pingFor := func(d time.Duration) { | |
| 139 | + | for end := time.Now().Add(d); time.Now().Before(end); { | |
| 140 | + | time.Sleep(100 * time.Millisecond) | |
| 141 | + | h.o.Ping(context.Background()) | |
| 142 | + | } | |
| 143 | + | synctest.Wait() | |
| 144 | + | } | |
| 145 | + | pingFor(3 * time.Second) | |
| 146 | + | before := h.modesets() | |
| 147 | + | if before < 6 { | |
| 148 | + | t.Fatalf("%d modesets in 3 s of pings: the retry was pushed back", before) | |
| 149 | + | } | |
| 150 | + | h.allow() | |
| 151 | + | pingFor(2 * masterRetryMax) | |
| 152 | + | after := h.modesets() | |
| 153 | + | if after != before+1 { | |
| 154 | + | t.Fatalf("%d modesets before success, %d after", before, after) | |
| 155 | + | } | |
| 156 | + | // Once enabled, nothing retries any more. | |
| 157 | + | pingFor(2 * masterRetryMax) | |
| 158 | + | if n := h.modesets(); n != after { | |
| 159 | + | t.Fatalf("%d modesets after success", n) | |
| 160 | + | } | |
| 161 | + | h.stop() | |
| 162 | + | }) | |
| 163 | + | } | |
| 164 | + | ||
| 165 | + | // A seat disable ends a pending retry: no modeset may follow the plane | |
| 166 | + | // reset before the next enable. | |
| 167 | + | func TestSeatDisableCancelsMasterRetry(t *testing.T) { | |
| 168 | + | synctest.Test(t, func(t *testing.T) { | |
| 169 | + | h := newRetryHarness(t) | |
| 170 | + | h.active <- true | |
| 171 | + | synctest.Wait() | |
| 172 | + | ack := make(chan struct{}) | |
| 173 | + | h.o.seatDisable <- ack | |
| 174 | + | <-ack | |
| 175 | + | synctest.Wait() | |
| 176 | + | n := h.modesets() | |
| 177 | + | time.Sleep(10 * masterRetryMax) | |
| 178 | + | synctest.Wait() | |
| 179 | + | if got := h.modesets(); got != n { | |
| 180 | + | t.Fatalf("%d modesets after the seat disable, want %d", got, n) | |
| 181 | + | } | |
| 182 | + | h.stop() | |
| 183 | + | }) | |
| 184 | + | } | |
| @@ -0,0 +1,184 @@ | |||||
| 1 | + | package drm | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "context" | |||
| 5 | + | "errors" | |||
| 6 | + | "sync" | |||
| 7 | + | "testing" | |||
| 8 | + | "testing/synctest" | |||
| 9 | + | "time" | |||
| 10 | + | ||||
| 11 | + | portsmocks "github.com/bnema/neferwl/internal/mocks/ports" | |||
| 12 | + | "github.com/bnema/neferwl/internal/ports" | |||
| 13 | + | "github.com/stretchr/testify/mock" | |||
| 14 | + | "golang.org/x/sys/unix" | |||
| 15 | + | ) | |||
| 16 | + | ||||
| 17 | + | func TestMasterRetryBackoff(t *testing.T) { | |||
| 18 | + | var m masterRetry | |||
| 19 | + | now := time.Unix(0, 0) | |||
| 20 | + | if _, ok := m.next(now); ok { | |||
| 21 | + | t.Fatal("retry due before a refusal") | |||
| 22 | + | } | |||
| 23 | + | if m.refused(unix.EBUSY, false, now); m.pending { | |||
| 24 | + | t.Fatal("a busy refusal is retried by the busy path, not here") | |||
| 25 | + | } | |||
| 26 | + | if m.refused(unix.EACCES, true, now); m.pending { | |||
| 27 | + | t.Fatal("an enabled output is not retried") | |||
| 28 | + | } | |||
| 29 | + | m.refused(unix.EACCES, false, now) | |||
| 30 | + | // The deadline is fixed: asking later leaves less, never more. | |||
| 31 | + | if d, ok := m.next(now); !ok || d != masterRetryFirst { | |||
| 32 | + | t.Fatalf("first retry %v %v", d, ok) | |||
| 33 | + | } | |||
| 34 | + | if d, _ := m.next(now.Add(masterRetryFirst / 2)); d != masterRetryFirst/2 { | |||
| 35 | + | t.Fatalf("half-way %v", d) | |||
| 36 | + | } | |||
| 37 | + | if d, _ := m.next(now.Add(time.Hour)); d != 0 { | |||
| 38 | + | t.Fatalf("overdue %v", d) | |||
| 39 | + | } | |||
| 40 | + | m.fire() | |||
| 41 | + | if _, ok := m.next(now); ok { | |||
| 42 | + | t.Fatal("pending while an attempt runs") | |||
| 43 | + | } | |||
| 44 | + | m.attempts = 30 | |||
| 45 | + | m.refused(unix.EPERM, false, now) | |||
| 46 | + | if d, _ := m.next(now); d != masterRetryMax { | |||
| 47 | + | t.Fatalf("capped retry %v", d) | |||
| 48 | + | } | |||
| 49 | + | m.attempts = masterRetryLimit | |||
| 50 | + | if !m.refused(unix.EACCES, false, now) || m.pending { | |||
| 51 | + | t.Fatal("retries past the limit") | |||
| 52 | + | } | |||
| 53 | + | m.done() | |||
| 54 | + | if _, ok := m.next(now); ok || m.attempts != 0 { | |||
| 55 | + | t.Fatal("retry after done") | |||
| 56 | + | } | |||
| 57 | + | } | |||
| 58 | + | ||||
| 59 | + | // retryHarness runs an output whose enable modesets the kernel refuses | |||
| 60 | + | // (lost master) until allow is called. | |||
| 61 | + | type retryHarness struct { | |||
| 62 | + | o *Output | |||
| 63 | + | active chan bool | |||
| 64 | + | modesets func() int | |||
| 65 | + | allow func() | |||
| 66 | + | stop func() | |||
| 67 | + | } | |||
| 68 | + | ||||
| 69 | + | func newRetryHarness(t *testing.T) retryHarness { | |||
| 70 | + | t.Helper() | |||
| 71 | + | var mu sync.Mutex | |||
| 72 | + | refuse := true | |||
| 73 | + | o, k, commits, commitMu := testOutputRules(t, func(_ *atomicReq, flags uint32) error { | |||
| 74 | + | mu.Lock() | |||
| 75 | + | defer mu.Unlock() | |||
| 76 | + | if refuse && flags&atomicAllowModes != 0 && flags&atomicTestOnly == 0 { | |||
| 77 | + | return unix.EACCES | |||
| 78 | + | } | |||
| 79 | + | return nil | |||
| 80 | + | }) | |||
| 81 | + | o.cursor, o.tearing = nil, false | |||
| 82 | + | r := portsmocks.NewMockRenderer(t) | |||
| 83 | + | r.EXPECT().SetHDR(mock.Anything).Return().Maybe() | |||
| 84 | + | r.EXPECT().UseTarget(mock.Anything).Return().Maybe() | |||
| 85 | + | r.EXPECT().Render(mock.Anything, mock.Anything).Return(nil, nil).Maybe() | |||
| 86 | + | r.EXPECT().Close().Return().Once() | |||
| 87 | + | // The 10 s stats tick runs in long tests. | |||
| 88 | + | r.EXPECT().Trim(mock.Anything).Return(nil).Maybe() | |||
| 89 | + | r.EXPECT().TakeRedrawn().Return(0).Maybe() | |||
| 90 | + | k.EXPECT().createBlob(mock.Anything).Return(99, nil).Maybe() | |||
| 91 | + | k.EXPECT().destroyBlob(mock.Anything).Return(nil).Maybe() | |||
| 92 | + | k.EXPECT().rmFB(mock.Anything).Return(nil).Maybe() | |||
| 93 | + | o.ping = make(chan chan struct{}) | |||
| 94 | + | active := make(chan bool, 1) | |||
| 95 | + | active <- false | |||
| 96 | + | ctx, cancel := context.WithCancel(context.Background()) | |||
| 97 | + | done := make(chan error, 1) | |||
| 98 | + | go func() { | |||
| 99 | + | done <- o.Run(ctx, func(int, int) (ports.Renderer, error) { return r, nil }, nil, active, nil, nil, nil, make(chan ports.OutputPresented, 1), nil, nil) | |||
| 100 | + | }() | |||
| 101 | + | synctest.Wait() | |||
| 102 | + | return retryHarness{ | |||
| 103 | + | o: o, active: active, | |||
| 104 | + | modesets: func() int { | |||
| 105 | + | commitMu.Lock() | |||
| 106 | + | defer commitMu.Unlock() | |||
| 107 | + | n := 0 | |||
| 108 | + | for _, c := range *commits { | |||
| 109 | + | if c.flags&atomicAllowModes != 0 && c.flags&atomicTestOnly == 0 { | |||
| 110 | + | n++ | |||
| 111 | + | } | |||
| 112 | + | } | |||
| 113 | + | return n | |||
| 114 | + | }, | |||
| 115 | + | allow: func() { mu.Lock(); refuse = false; mu.Unlock() }, | |||
| 116 | + | stop: func() { | |||
| 117 | + | cancel() | |||
| 118 | + | if err := <-done; err != nil && !errors.Is(err, context.Canceled) { | |||
| 119 | + | t.Fatal(err) | |||
| 120 | + | } | |||
| 121 | + | }, | |||
| 122 | + | } | |||
| 123 | + | } | |||
| 124 | + | ||||
| 125 | + | // The seat reports active before the kernel gives DRM master back: the | |||
| 126 | + | // enable modeset is refused, then retried until it succeeds, without a | |||
| 127 | + | // second seat change, even while other events (watchdog pings) keep | |||
| 128 | + | // waking the loop faster than the backoff. | |||
| 129 | + | func TestEnableRefusedForMasterIsRetried(t *testing.T) { | |||
| 130 | + | synctest.Test(t, func(t *testing.T) { | |||
| 131 | + | h := newRetryHarness(t) | |||
| 132 | + | h.active <- true | |||
| 133 | + | synctest.Wait() | |||
| 134 | + | if n := h.modesets(); n != 1 { | |||
| 135 | + | t.Fatalf("%d modesets after the refused enable", n) | |||
| 136 | + | } | |||
| 137 | + | // Let the backoff grow past the ping period. | |||
| 138 | + | pingFor := func(d time.Duration) { | |||
| 139 | + | for end := time.Now().Add(d); time.Now().Before(end); { | |||
| 140 | + | time.Sleep(100 * time.Millisecond) | |||
| 141 | + | h.o.Ping(context.Background()) | |||
| 142 | + | } | |||
| 143 | + | synctest.Wait() | |||
| 144 | + | } | |||
| 145 | + | pingFor(3 * time.Second) | |||
| 146 | + | before := h.modesets() | |||
| 147 | + | if before < 6 { | |||
| 148 | + | t.Fatalf("%d modesets in 3 s of pings: the retry was pushed back", before) | |||
| 149 | + | } | |||
| 150 | + | h.allow() | |||
| 151 | + | pingFor(2 * masterRetryMax) | |||
| 152 | + | after := h.modesets() | |||
| 153 | + | if after != before+1 { | |||
| 154 | + | t.Fatalf("%d modesets before success, %d after", before, after) | |||
| 155 | + | } | |||
| 156 | + | // Once enabled, nothing retries any more. | |||
| 157 | + | pingFor(2 * masterRetryMax) | |||
| 158 | + | if n := h.modesets(); n != after { | |||
| 159 | + | t.Fatalf("%d modesets after success", n) | |||
| 160 | + | } | |||
| 161 | + | h.stop() | |||
| 162 | + | }) | |||
| 163 | + | } | |||
| 164 | + | ||||
| 165 | + | // A seat disable ends a pending retry: no modeset may follow the plane | |||
| 166 | + | // reset before the next enable. | |||
| 167 | + | func TestSeatDisableCancelsMasterRetry(t *testing.T) { | |||
| 168 | + | synctest.Test(t, func(t *testing.T) { | |||
| 169 | + | h := newRetryHarness(t) | |||
| 170 | + | h.active <- true | |||
| 171 | + | synctest.Wait() | |||
| 172 | + | ack := make(chan struct{}) | |||
| 173 | + | h.o.seatDisable <- ack | |||
| 174 | + | <-ack | |||
| 175 | + | synctest.Wait() | |||
| 176 | + | n := h.modesets() | |||
| 177 | + | time.Sleep(10 * masterRetryMax) | |||
| 178 | + | synctest.Wait() | |||
| 179 | + | if got := h.modesets(); got != n { | |||
| 180 | + | t.Fatalf("%d modesets after the seat disable, want %d", got, n) | |||
| 181 | + | } | |||
| 182 | + | h.stop() | |||
| 183 | + | }) | |||
| 184 | + | } | |||
M internal/adapters/drm/security_resume_test.go +26 -19
| @@ -16,13 +16,23 @@ import ( | |||
| 16 | 16 | func TestSecurityUnlockedResumeUsesOwnerRetry(t *testing.T) { | |
| 17 | 17 | for _, stage := range []string{"engage-during-request", "master-loss"} { | |
| 18 | 18 | t.Run(stage, func(t *testing.T) { | |
| 19 | - | var failures []error | |
| 19 | + | var state atomic.Uint64 | |
| 20 | + | var rule func(*atomicReq, uint32) error | |
| 20 | 21 | if stage == "master-loss" { | |
| 21 | - | failures = []error{unix.EACCES} | |
| 22 | + | // The lock engages as the kernel refuses the first enable for | |
| 23 | + | // lack of master: the retry must be a protected modeset. | |
| 24 | + | refused := false | |
| 25 | + | rule = func(*atomicReq, uint32) error { | |
| 26 | + | if refused { | |
| 27 | + | return nil | |
| 28 | + | } | |
| 29 | + | refused = true | |
| 30 | + | state.Store(3) | |
| 31 | + | return unix.EACCES | |
| 32 | + | } | |
| 22 | 33 | } | |
| 23 | - | o, k, commits, mu := testOutputMu(t, failures...) | |
| 34 | + | o, k, commits, mu := testOutputRules(t, rule) | |
| 24 | 35 | o.cursor, o.tearing = nil, false | |
| 25 | - | var state atomic.Uint64 | |
| 26 | 36 | securityGate(t, o, &state) | |
| 27 | 37 | events := make(chan ports.SecurityBackendEvent, 4) | |
| 28 | 38 | o.SecurityEvents = events | |
| @@ -55,22 +65,11 @@ func TestSecurityUnlockedResumeUsesOwnerRetry(t *testing.T) { | |||
| 55 | 65 | }() | |
| 56 | 66 | active <- true | |
| 57 | 67 | if stage == "master-loss" { | |
| 58 | - | waitFor(t, func() bool { mu.Lock(); defer mu.Unlock(); return len(*commits) == 1 }) | |
| 59 | - | state.Store(3) | |
| 68 | + | waitFor(t, func() bool { mu.Lock(); defer mu.Unlock(); return len(*commits) >= 1 }) | |
| 60 | 69 | wake <- ports.SecurityState{} | |
| 61 | - | select { | |
| 62 | - | case ev := <-events: | |
| 63 | - | if _, ok := ev.(ports.SecurityOutputProof); ok { | |
| 64 | - | t.Fatal("master loss forged proof") | |
| 65 | - | } | |
| 66 | - | case <-time.After(20 * time.Millisecond): | |
| 67 | - | } | |
| 68 | - | select { | |
| 69 | - | case err := <-done: | |
| 70 | - | t.Fatalf("resume stopped owner: %v", err) | |
| 71 | - | default: | |
| 72 | - | } | |
| 73 | - | active <- true // only real seat reacquisition permits preparation | |
| 70 | + | // The seat reported active before master came back: the owner | |
| 71 | + | // retries the protected modeset itself, with no second seat | |
| 72 | + | // event. The proof below must follow that successful retry. | |
| 74 | 73 | } | |
| 75 | 74 | for { | |
| 76 | 75 | select { | |
| @@ -79,6 +78,14 @@ func TestSecurityUnlockedResumeUsesOwnerRetry(t *testing.T) { | |||
| 79 | 78 | if p.Proof.Generation != 1 || p.Proof.Instance != 77 { | |
| 80 | 79 | t.Fatalf("proof %+v", p) | |
| 81 | 80 | } | |
| 81 | + | if stage == "master-loss" { | |
| 82 | + | mu.Lock() | |
| 83 | + | n := len(*commits) | |
| 84 | + | mu.Unlock() | |
| 85 | + | if n < 2 { | |
| 86 | + | t.Fatal("master loss forged proof: no successful retry") | |
| 87 | + | } | |
| 88 | + | } | |
| 82 | 89 | cancel() | |
| 83 | 90 | if err := <-done; err != nil { | |
| 84 | 91 | t.Fatal(err) | |
| @@ -16,13 +16,23 @@ import ( | |||||
| 16 | func TestSecurityUnlockedResumeUsesOwnerRetry(t *testing.T) { | 16 | func TestSecurityUnlockedResumeUsesOwnerRetry(t *testing.T) { | ||
| 17 | for _, stage := range []string{"engage-during-request", "master-loss"} { | 17 | for _, stage := range []string{"engage-during-request", "master-loss"} { | ||
| 18 | t.Run(stage, func(t *testing.T) { | 18 | t.Run(stage, func(t *testing.T) { | ||
| 19 | - | var failures []error | 19 | + | var state atomic.Uint64 |
| 20 | + | var rule func(*atomicReq, uint32) error | |||
| 20 | if stage == "master-loss" { | 21 | if stage == "master-loss" { | ||
| 21 | - | failures = []error{unix.EACCES} | 22 | + | // The lock engages as the kernel refuses the first enable for |
| 23 | + | // lack of master: the retry must be a protected modeset. | |||
| 24 | + | refused := false | |||
| 25 | + | rule = func(*atomicReq, uint32) error { | |||
| 26 | + | if refused { | |||
| 27 | + | return nil | |||
| 28 | + | } | |||
| 29 | + | refused = true | |||
| 30 | + | state.Store(3) | |||
| 31 | + | return unix.EACCES | |||
| 32 | + | } | |||
| 22 | } | 33 | } | ||
| 23 | - | o, k, commits, mu := testOutputMu(t, failures...) | 34 | + | o, k, commits, mu := testOutputRules(t, rule) |
| 24 | o.cursor, o.tearing = nil, false | 35 | o.cursor, o.tearing = nil, false | ||
| 25 | - | var state atomic.Uint64 | |||
| 26 | securityGate(t, o, &state) | 36 | securityGate(t, o, &state) | ||
| 27 | events := make(chan ports.SecurityBackendEvent, 4) | 37 | events := make(chan ports.SecurityBackendEvent, 4) | ||
| 28 | o.SecurityEvents = events | 38 | o.SecurityEvents = events | ||
| @@ -55,22 +65,11 @@ func TestSecurityUnlockedResumeUsesOwnerRetry(t *testing.T) { | |||||
| 55 | }() | 65 | }() | ||
| 56 | active <- true | 66 | active <- true | ||
| 57 | if stage == "master-loss" { | 67 | if stage == "master-loss" { | ||
| 58 | - | waitFor(t, func() bool { mu.Lock(); defer mu.Unlock(); return len(*commits) == 1 }) | 68 | + | waitFor(t, func() bool { mu.Lock(); defer mu.Unlock(); return len(*commits) >= 1 }) |
| 59 | - | state.Store(3) | |||
| 60 | wake <- ports.SecurityState{} | 69 | wake <- ports.SecurityState{} | ||
| 61 | - | select { | 70 | + | // The seat reported active before master came back: the owner |
| 62 | - | case ev := <-events: | 71 | + | // retries the protected modeset itself, with no second seat |
| 63 | - | if _, ok := ev.(ports.SecurityOutputProof); ok { | 72 | + | // event. The proof below must follow that successful retry. |
| 64 | - | t.Fatal("master loss forged proof") | |||
| 65 | - | } | |||
| 66 | - | case <-time.After(20 * time.Millisecond): | |||
| 67 | - | } | |||
| 68 | - | select { | |||
| 69 | - | case err := <-done: | |||
| 70 | - | t.Fatalf("resume stopped owner: %v", err) | |||
| 71 | - | default: | |||
| 72 | - | } | |||
| 73 | - | active <- true // only real seat reacquisition permits preparation | |||
| 74 | } | 73 | } | ||
| 75 | for { | 74 | for { | ||
| 76 | select { | 75 | select { | ||
| @@ -79,6 +78,14 @@ func TestSecurityUnlockedResumeUsesOwnerRetry(t *testing.T) { | |||||
| 79 | if p.Proof.Generation != 1 || p.Proof.Instance != 77 { | 78 | if p.Proof.Generation != 1 || p.Proof.Instance != 77 { | ||
| 80 | t.Fatalf("proof %+v", p) | 79 | t.Fatalf("proof %+v", p) | ||
| 81 | } | 80 | } | ||
| 81 | + | if stage == "master-loss" { | |||
| 82 | + | mu.Lock() | |||
| 83 | + | n := len(*commits) | |||
| 84 | + | mu.Unlock() | |||
| 85 | + | if n < 2 { | |||
| 86 | + | t.Fatal("master loss forged proof: no successful retry") | |||
| 87 | + | } | |||
| 88 | + | } | |||
| 82 | cancel() | 89 | cancel() | ||
| 83 | if err := <-done; err != nil { | 90 | if err := <-done; err != nil { | ||
| 84 | t.Fatal(err) | 91 | t.Fatal(err) | ||
M internal/adapters/logging/logging.go +88 -11
| @@ -4,14 +4,18 @@ package logging | |||
| 4 | 4 | import ( | |
| 5 | 5 | "context" | |
| 6 | 6 | "fmt" | |
| 7 | + | "io" | |
| 7 | 8 | "os" | |
| 8 | 9 | "path/filepath" | |
| 10 | + | runtimedebug "runtime/debug" | |
| 9 | 11 | "sort" | |
| 10 | 12 | "strings" | |
| 13 | + | "sync" | |
| 11 | 14 | "time" | |
| 12 | 15 | ||
| 13 | 16 | "github.com/bnema/zerowrap" | |
| 14 | 17 | "github.com/rs/zerolog" | |
| 18 | + | "github.com/rs/zerolog/diode" | |
| 15 | 19 | "golang.org/x/term" | |
| 16 | 20 | ) | |
| 17 | 21 | ||
| @@ -29,6 +33,7 @@ var categories = map[string]string{"input-motion": "input", "input-keys": "input | |||
| 29 | 33 | ||
| 30 | 34 | type debugKey struct{} | |
| 31 | 35 | type levelKey struct{} | |
| 36 | + | type dirKey struct{} | |
| 32 | 37 | type debugSet map[string]bool | |
| 33 | 38 | ||
| 34 | 39 | func ParseDebug(value string) (map[string]bool, error) { | |
| @@ -56,8 +61,9 @@ const keepRuns = 20 | |||
| 56 | 61 | // directory at it, prunes old runs of that backend and attaches the logger | |
| 57 | 62 | // to ctx. Each backend keeps its own runs: headless test runs never rotate | |
| 58 | 63 | // a DRM session's log away. | |
| 59 | - | // The caller must invoke close after all logging is complete. | |
| 60 | - | func Open(ctx context.Context, backend, level, debug string) (context.Context, func() error, error) { | |
| 64 | + | // The caller must invoke close after all logging is complete; crashed | |
| 65 | + | // keeps the crash file for a panic about to be re-raised. | |
| 66 | + | func Open(ctx context.Context, backend, level, debug string) (context.Context, func(crashed bool) error, error) { | |
| 61 | 67 | selected, err := ParseDebug(debug) | |
| 62 | 68 | if err != nil { | |
| 63 | 69 | return nil, nil, err | |
| @@ -85,23 +91,88 @@ func Open(ctx context.Context, backend, level, debug string) (context.Context, f | |||
| 85 | 91 | _ = file.Close() | |
| 86 | 92 | return nil, nil, err | |
| 87 | 93 | } | |
| 94 | + | // Queued entries are lost on a fatal crash: the runtime's own report | |
| 95 | + | // (panic and every stack) goes to its own file, besides stderr. A clean | |
| 96 | + | // Close removes it while still empty. Created before pruneRuns so | |
| 97 | + | // crash files rotate like logs. | |
| 98 | + | crashPath := filepath.Join(dir, strings.TrimSuffix(name, ".log")+".crash") | |
| 99 | + | if crash, err := os.OpenFile(crashPath, os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0o600); err == nil { | |
| 100 | + | _ = runtimedebug.SetCrashOutput(crash, runtimedebug.CrashOptions{}) | |
| 101 | + | _ = crash.Close() // SetCrashOutput keeps its own duplicate | |
| 102 | + | } else { | |
| 103 | + | crashPath = "" | |
| 104 | + | } | |
| 88 | 105 | pruneRuns(dir) | |
| 89 | - | var output = zerowrap.Config{Level: level, Format: "json", Output: file} | |
| 106 | + | // Hide Close from the diode: asyncWriter closes the file once. | |
| 107 | + | var sink io.Writer = struct{ io.Writer }{file} | |
| 90 | 108 | if term.IsTerminal(int(os.Stderr.Fd())) { | |
| 91 | - | output.Output = &consoleAndFile{file: file} | |
| 109 | + | sink = &consoleAndFile{file: file} | |
| 92 | 110 | } | |
| 93 | - | ctx = zerowrap.WithCtx(ctx, zerowrap.New(output)) | |
| 111 | + | w := newAsyncWriter(sink, file, crashPath) | |
| 112 | + | ctx = zerowrap.WithCtx(ctx, zerowrap.New(zerowrap.Config{Level: level, Format: "json", Output: w})) | |
| 94 | 113 | ctx = context.WithValue(ctx, debugKey{}, debugSet(selected)) | |
| 95 | 114 | ctx = context.WithValue(ctx, levelKey{}, level) | |
| 96 | - | return ctx, file.Close, nil | |
| 115 | + | ctx = context.WithValue(ctx, dirKey{}, dir) | |
| 116 | + | return ctx, func(crashed bool) error { | |
| 117 | + | if !crashed { | |
| 118 | + | w.Clean() | |
| 119 | + | } | |
| 120 | + | return w.Close() | |
| 121 | + | }, nil | |
| 122 | + | } | |
| 123 | + | ||
| 124 | + | // logQueue is how many entries may wait for the disk. Past it, entries are | |
| 125 | + | // dropped (and counted on stderr) rather than blocking the logging | |
| 126 | + | // goroutine: input, outputs and the display must never wait on a slow disk. | |
| 127 | + | const logQueue = 8192 | |
| 128 | + | ||
| 129 | + | // newAsyncWriter writes entries to w from its own goroutine. Close drains | |
| 130 | + | // what is queued, then closes c. | |
| 131 | + | func newAsyncWriter(w io.Writer, c io.Closer, crashPath string) *asyncWriter { | |
| 132 | + | d := diode.NewWriter(w, logQueue, 0, func(missed int) { | |
| 133 | + | fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed) | |
| 134 | + | }) | |
| 135 | + | return &asyncWriter{Writer: d, closer: c, crashPath: crashPath} | |
| 136 | + | } | |
| 137 | + | ||
| 138 | + | type asyncWriter struct { | |
| 139 | + | diode.Writer | |
| 140 | + | closer io.Closer | |
| 141 | + | crashPath string | |
| 142 | + | once sync.Once | |
| 143 | + | err error | |
| 144 | + | } | |
| 145 | + | ||
| 146 | + | // Close drains the queue and closes the file once. | |
| 147 | + | func (a *asyncWriter) Close() error { | |
| 148 | + | a.once.Do(func() { | |
| 149 | + | _ = a.Writer.Close() // drains the queue | |
| 150 | + | a.err = a.closer.Close() | |
| 151 | + | }) | |
| 152 | + | return a.err | |
| 153 | + | } | |
| 154 | + | ||
| 155 | + | // Clean ends a run that did not crash: the crash output is released and | |
| 156 | + | // the crash file removed while still empty. | |
| 157 | + | func (a *asyncWriter) Clean() { | |
| 158 | + | if a.crashPath == "" { | |
| 159 | + | return | |
| 160 | + | } | |
| 161 | + | _ = runtimedebug.SetCrashOutput(nil, runtimedebug.CrashOptions{}) | |
| 162 | + | if fi, err := os.Stat(a.crashPath); err == nil && fi.Size() == 0 { | |
| 163 | + | _ = os.Remove(a.crashPath) | |
| 164 | + | } | |
| 97 | 165 | } | |
| 98 | 166 | ||
| 99 | 167 | func pruneRuns(dir string) { | |
| 100 | - | runs, _ := filepath.Glob(filepath.Join(dir, "2*.log")) | |
| 101 | - | sort.Strings(runs) | |
| 102 | - | for len(runs) > keepRuns { | |
| 103 | - | _ = os.Remove(runs[0]) | |
| 104 | - | runs = runs[1:] | |
| 168 | + | // Watchdog stall dumps (stall-<time>-<loop>.txt) rotate like runs. | |
| 169 | + | for _, pattern := range []string{"2*.log", "2*.crash", "stall-*.txt"} { | |
| 170 | + | runs, _ := filepath.Glob(filepath.Join(dir, pattern)) | |
| 171 | + | sort.Strings(runs) | |
| 172 | + | for len(runs) > keepRuns { | |
| 173 | + | _ = os.Remove(runs[0]) | |
| 174 | + | runs = runs[1:] | |
| 175 | + | } | |
| 105 | 176 | } | |
| 106 | 177 | } | |
| 107 | 178 | ||
| @@ -113,6 +184,12 @@ func (w *consoleAndFile) Write(p []byte) (int, error) { | |||
| 113 | 184 | return w.file.Write(p) | |
| 114 | 185 | } | |
| 115 | 186 | ||
| 187 | + | // Dir is the directory of the run log Open created, or "" without one. | |
| 188 | + | func Dir(ctx context.Context) string { | |
| 189 | + | dir, _ := ctx.Value(dirKey{}).(string) | |
| 190 | + | return dir | |
| 191 | + | } | |
| 192 | + | ||
| 116 | 193 | // Enabled reports whether a debug category was named in --debug. | |
| 117 | 194 | func Enabled(ctx context.Context, category string) bool { | |
| 118 | 195 | selected, _ := ctx.Value(debugKey{}).(debugSet) | |
| @@ -4,14 +4,18 @@ package logging | |||||
| 4 | import ( | 4 | import ( | ||
| 5 | "context" | 5 | "context" | ||
| 6 | "fmt" | 6 | "fmt" | ||
| 7 | + | "io" | |||
| 7 | "os" | 8 | "os" | ||
| 8 | "path/filepath" | 9 | "path/filepath" | ||
| 10 | + | runtimedebug "runtime/debug" | |||
| 9 | "sort" | 11 | "sort" | ||
| 10 | "strings" | 12 | "strings" | ||
| 13 | + | "sync" | |||
| 11 | "time" | 14 | "time" | ||
| 12 | 15 | ||||
| 13 | "github.com/bnema/zerowrap" | 16 | "github.com/bnema/zerowrap" | ||
| 14 | "github.com/rs/zerolog" | 17 | "github.com/rs/zerolog" | ||
| 18 | + | "github.com/rs/zerolog/diode" | |||
| 15 | "golang.org/x/term" | 19 | "golang.org/x/term" | ||
| 16 | ) | 20 | ) | ||
| 17 | 21 | ||||
| @@ -29,6 +33,7 @@ var categories = map[string]string{"input-motion": "input", "input-keys": "input | |||||
| 29 | 33 | ||||
| 30 | type debugKey struct{} | 34 | type debugKey struct{} | ||
| 31 | type levelKey struct{} | 35 | type levelKey struct{} | ||
| 36 | + | type dirKey struct{} | |||
| 32 | type debugSet map[string]bool | 37 | type debugSet map[string]bool | ||
| 33 | 38 | ||||
| 34 | func ParseDebug(value string) (map[string]bool, error) { | 39 | func ParseDebug(value string) (map[string]bool, error) { | ||
| @@ -56,8 +61,9 @@ const keepRuns = 20 | |||||
| 56 | // directory at it, prunes old runs of that backend and attaches the logger | 61 | // directory at it, prunes old runs of that backend and attaches the logger | ||
| 57 | // to ctx. Each backend keeps its own runs: headless test runs never rotate | 62 | // to ctx. Each backend keeps its own runs: headless test runs never rotate | ||
| 58 | // a DRM session's log away. | 63 | // a DRM session's log away. | ||
| 59 | - | // The caller must invoke close after all logging is complete. | 64 | + | // The caller must invoke close after all logging is complete; crashed |
| 60 | - | func Open(ctx context.Context, backend, level, debug string) (context.Context, func() error, error) { | 65 | + | // keeps the crash file for a panic about to be re-raised. |
| 66 | + | func Open(ctx context.Context, backend, level, debug string) (context.Context, func(crashed bool) error, error) { | |||
| 61 | selected, err := ParseDebug(debug) | 67 | selected, err := ParseDebug(debug) | ||
| 62 | if err != nil { | 68 | if err != nil { | ||
| 63 | return nil, nil, err | 69 | return nil, nil, err | ||
| @@ -85,23 +91,88 @@ func Open(ctx context.Context, backend, level, debug string) (context.Context, f | |||||
| 85 | _ = file.Close() | 91 | _ = file.Close() | ||
| 86 | return nil, nil, err | 92 | return nil, nil, err | ||
| 87 | } | 93 | } | ||
| 94 | + | // Queued entries are lost on a fatal crash: the runtime's own report | |||
| 95 | + | // (panic and every stack) goes to its own file, besides stderr. A clean | |||
| 96 | + | // Close removes it while still empty. Created before pruneRuns so | |||
| 97 | + | // crash files rotate like logs. | |||
| 98 | + | crashPath := filepath.Join(dir, strings.TrimSuffix(name, ".log")+".crash") | |||
| 99 | + | if crash, err := os.OpenFile(crashPath, os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0o600); err == nil { | |||
| 100 | + | _ = runtimedebug.SetCrashOutput(crash, runtimedebug.CrashOptions{}) | |||
| 101 | + | _ = crash.Close() // SetCrashOutput keeps its own duplicate | |||
| 102 | + | } else { | |||
| 103 | + | crashPath = "" | |||
| 104 | + | } | |||
| 88 | pruneRuns(dir) | 105 | pruneRuns(dir) | ||
| 89 | - | var output = zerowrap.Config{Level: level, Format: "json", Output: file} | 106 | + | // Hide Close from the diode: asyncWriter closes the file once. |
| 107 | + | var sink io.Writer = struct{ io.Writer }{file} | |||
| 90 | if term.IsTerminal(int(os.Stderr.Fd())) { | 108 | if term.IsTerminal(int(os.Stderr.Fd())) { | ||
| 91 | - | output.Output = &consoleAndFile{file: file} | 109 | + | sink = &consoleAndFile{file: file} |
| 92 | } | 110 | } | ||
| 93 | - | ctx = zerowrap.WithCtx(ctx, zerowrap.New(output)) | 111 | + | w := newAsyncWriter(sink, file, crashPath) |
| 112 | + | ctx = zerowrap.WithCtx(ctx, zerowrap.New(zerowrap.Config{Level: level, Format: "json", Output: w})) | |||
| 94 | ctx = context.WithValue(ctx, debugKey{}, debugSet(selected)) | 113 | ctx = context.WithValue(ctx, debugKey{}, debugSet(selected)) | ||
| 95 | ctx = context.WithValue(ctx, levelKey{}, level) | 114 | ctx = context.WithValue(ctx, levelKey{}, level) | ||
| 96 | - | return ctx, file.Close, nil | 115 | + | ctx = context.WithValue(ctx, dirKey{}, dir) |
| 116 | + | return ctx, func(crashed bool) error { | |||
| 117 | + | if !crashed { | |||
| 118 | + | w.Clean() | |||
| 119 | + | } | |||
| 120 | + | return w.Close() | |||
| 121 | + | }, nil | |||
| 122 | + | } | |||
| 123 | + | ||||
| 124 | + | // logQueue is how many entries may wait for the disk. Past it, entries are | |||
| 125 | + | // dropped (and counted on stderr) rather than blocking the logging | |||
| 126 | + | // goroutine: input, outputs and the display must never wait on a slow disk. | |||
| 127 | + | const logQueue = 8192 | |||
| 128 | + | ||||
| 129 | + | // newAsyncWriter writes entries to w from its own goroutine. Close drains | |||
| 130 | + | // what is queued, then closes c. | |||
| 131 | + | func newAsyncWriter(w io.Writer, c io.Closer, crashPath string) *asyncWriter { | |||
| 132 | + | d := diode.NewWriter(w, logQueue, 0, func(missed int) { | |||
| 133 | + | fmt.Fprintf(os.Stderr, "neferwl: %d log entries dropped: disk too slow\n", missed) | |||
| 134 | + | }) | |||
| 135 | + | return &asyncWriter{Writer: d, closer: c, crashPath: crashPath} | |||
| 136 | + | } | |||
| 137 | + | ||||
| 138 | + | type asyncWriter struct { | |||
| 139 | + | diode.Writer | |||
| 140 | + | closer io.Closer | |||
| 141 | + | crashPath string | |||
| 142 | + | once sync.Once | |||
| 143 | + | err error | |||
| 144 | + | } | |||
| 145 | + | ||||
| 146 | + | // Close drains the queue and closes the file once. | |||
| 147 | + | func (a *asyncWriter) Close() error { | |||
| 148 | + | a.once.Do(func() { | |||
| 149 | + | _ = a.Writer.Close() // drains the queue | |||
| 150 | + | a.err = a.closer.Close() | |||
| 151 | + | }) | |||
| 152 | + | return a.err | |||
| 153 | + | } | |||
| 154 | + | ||||
| 155 | + | // Clean ends a run that did not crash: the crash output is released and | |||
| 156 | + | // the crash file removed while still empty. | |||
| 157 | + | func (a *asyncWriter) Clean() { | |||
| 158 | + | if a.crashPath == "" { | |||
| 159 | + | return | |||
| 160 | + | } | |||
| 161 | + | _ = runtimedebug.SetCrashOutput(nil, runtimedebug.CrashOptions{}) | |||
| 162 | + | if fi, err := os.Stat(a.crashPath); err == nil && fi.Size() == 0 { | |||
| 163 | + | _ = os.Remove(a.crashPath) | |||
| 164 | + | } | |||
| 97 | } | 165 | } | ||
| 98 | 166 | ||||
| 99 | func pruneRuns(dir string) { | 167 | func pruneRuns(dir string) { | ||
| 100 | - | runs, _ := filepath.Glob(filepath.Join(dir, "2*.log")) | 168 | + | // Watchdog stall dumps (stall-<time>-<loop>.txt) rotate like runs. |
| 101 | - | sort.Strings(runs) | 169 | + | for _, pattern := range []string{"2*.log", "2*.crash", "stall-*.txt"} { |
| 102 | - | for len(runs) > keepRuns { | 170 | + | runs, _ := filepath.Glob(filepath.Join(dir, pattern)) |
| 103 | - | _ = os.Remove(runs[0]) | 171 | + | sort.Strings(runs) |
| 104 | - | runs = runs[1:] | 172 | + | for len(runs) > keepRuns { |
| 173 | + | _ = os.Remove(runs[0]) | |||
| 174 | + | runs = runs[1:] | |||
| 175 | + | } | |||
| 105 | } | 176 | } | ||
| 106 | } | 177 | } | ||
| 107 | 178 | ||||
| @@ -113,6 +184,12 @@ func (w *consoleAndFile) Write(p []byte) (int, error) { | |||||
| 113 | return w.file.Write(p) | 184 | return w.file.Write(p) | ||
| 114 | } | 185 | } | ||
| 115 | 186 | ||||
| 187 | + | // Dir is the directory of the run log Open created, or "" without one. | |||
| 188 | + | func Dir(ctx context.Context) string { | |||
| 189 | + | dir, _ := ctx.Value(dirKey{}).(string) | |||
| 190 | + | return dir | |||
| 191 | + | } | |||
| 192 | + | ||||
| 116 | // Enabled reports whether a debug category was named in --debug. | 193 | // Enabled reports whether a debug category was named in --debug. | ||
| 117 | func Enabled(ctx context.Context, category string) bool { | 194 | func Enabled(ctx context.Context, category string) bool { | ||
| 118 | selected, _ := ctx.Value(debugKey{}).(debugSet) | 195 | selected, _ := ctx.Value(debugKey{}).(debugSet) | ||
M internal/adapters/logging/logging_test.go +34 -3
| @@ -4,6 +4,7 @@ import ( | |||
| 4 | 4 | "bytes" | |
| 5 | 5 | "context" | |
| 6 | 6 | "encoding/json" | |
| 7 | + | "io" | |
| 7 | 8 | "os" | |
| 8 | 9 | "path/filepath" | |
| 9 | 10 | "testing" | |
| @@ -47,7 +48,7 @@ func TestComponentLevelsAndRotation(t *testing.T) { | |||
| 47 | 48 | core.Debug().Msg("visible") | |
| 48 | 49 | app.Debug().Msg("hidden") | |
| 49 | 50 | app.Info().Msg("startup") | |
| 50 | - | if err := closeLog(); err != nil { | |
| 51 | + | if err := closeLog(false); err != nil { | |
| 51 | 52 | t.Fatal(err) | |
| 52 | 53 | } | |
| 53 | 54 | data, err := os.ReadFile(path) | |
| @@ -72,6 +73,10 @@ func TestComponentLevelsAndRotation(t *testing.T) { | |||
| 72 | 73 | if len(runs) != keepRuns { | |
| 73 | 74 | t.Fatalf("kept %d runs, want %d", len(runs), keepRuns) | |
| 74 | 75 | } | |
| 76 | + | // A clean run leaves no empty crash file behind. | |
| 77 | + | if crashes, _ := filepath.Glob(filepath.Join(dir, "2*.crash")); len(crashes) != 0 { | |
| 78 | + | t.Fatalf("empty crash files kept: %v", crashes) | |
| 79 | + | } | |
| 75 | 80 | } | |
| 76 | 81 | ||
| 77 | 82 | func splitLines(data []byte) [][]byte { | |
| @@ -94,7 +99,7 @@ func TestBackendsRotateSeparately(t *testing.T) { | |||
| 94 | 99 | if err != nil { | |
| 95 | 100 | t.Fatal(err) | |
| 96 | 101 | } | |
| 97 | - | if err := closeLog(); err != nil { | |
| 102 | + | if err := closeLog(false); err != nil { | |
| 98 | 103 | t.Fatal(err) | |
| 99 | 104 | } | |
| 100 | 105 | } | |
| @@ -123,7 +128,7 @@ func TestCategoryEnablesComponentDebug(t *testing.T) { | |||
| 123 | 128 | input, core := For(ctx, "input"), For(ctx, "core") | |
| 124 | 129 | input.Debug().Msg("motion") | |
| 125 | 130 | core.Debug().Msg("hidden") | |
| 126 | - | if err := closeLog(); err != nil { | |
| 131 | + | if err := closeLog(false); err != nil { | |
| 127 | 132 | t.Fatal(err) | |
| 128 | 133 | } | |
| 129 | 134 | data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log")) | |
| @@ -135,6 +140,32 @@ func TestCategoryEnablesComponentDebug(t *testing.T) { | |||
| 135 | 140 | } | |
| 136 | 141 | } | |
| 137 | 142 | ||
| 143 | + | // A disk that stops answering must not block the goroutine that logs: | |
| 144 | + | // input and outputs log from their own loops. | |
| 145 | + | func TestLogWriteNeverBlocksOnSlowDisk(t *testing.T) { | |
| 146 | + | r, pw, err := os.Pipe() // nobody reads: writes block once the pipe is full | |
| 147 | + | if err != nil { | |
| 148 | + | t.Fatal(err) | |
| 149 | + | } | |
| 150 | + | defer r.Close() | |
| 151 | + | w := newAsyncWriter(struct{ io.Writer }{pw}, pw, "") | |
| 152 | + | line := bytes.Repeat([]byte{'x'}, 1024) | |
| 153 | + | done := make(chan struct{}) | |
| 154 | + | go func() { | |
| 155 | + | defer close(done) | |
| 156 | + | for range 4 * logQueue { // far past the pipe buffer and the queue | |
| 157 | + | _, _ = w.Write(line) | |
| 158 | + | } | |
| 159 | + | }() | |
| 160 | + | select { | |
| 161 | + | case <-done: | |
| 162 | + | case <-time.After(5 * time.Second): | |
| 163 | + | t.Fatal("log write blocked on a stuck disk") | |
| 164 | + | } | |
| 165 | + | r.Close() // unblock the writer so Close can drain and return | |
| 166 | + | _ = w.Close() | |
| 167 | + | } | |
| 168 | + | ||
| 138 | 169 | // Narrow categories are on only when named, never through "all". | |
| 139 | 170 | func TestEnabledCategories(t *testing.T) { | |
| 140 | 171 | for _, category := range []string{"input-motion", "input-keys", "drm-flip"} { | |
| @@ -4,6 +4,7 @@ import ( | |||||
| 4 | "bytes" | 4 | "bytes" | ||
| 5 | "context" | 5 | "context" | ||
| 6 | "encoding/json" | 6 | "encoding/json" | ||
| 7 | + | "io" | |||
| 7 | "os" | 8 | "os" | ||
| 8 | "path/filepath" | 9 | "path/filepath" | ||
| 9 | "testing" | 10 | "testing" | ||
| @@ -47,7 +48,7 @@ func TestComponentLevelsAndRotation(t *testing.T) { | |||||
| 47 | core.Debug().Msg("visible") | 48 | core.Debug().Msg("visible") | ||
| 48 | app.Debug().Msg("hidden") | 49 | app.Debug().Msg("hidden") | ||
| 49 | app.Info().Msg("startup") | 50 | app.Info().Msg("startup") | ||
| 50 | - | if err := closeLog(); err != nil { | 51 | + | if err := closeLog(false); err != nil { |
| 51 | t.Fatal(err) | 52 | t.Fatal(err) | ||
| 52 | } | 53 | } | ||
| 53 | data, err := os.ReadFile(path) | 54 | data, err := os.ReadFile(path) | ||
| @@ -72,6 +73,10 @@ func TestComponentLevelsAndRotation(t *testing.T) { | |||||
| 72 | if len(runs) != keepRuns { | 73 | if len(runs) != keepRuns { | ||
| 73 | t.Fatalf("kept %d runs, want %d", len(runs), keepRuns) | 74 | t.Fatalf("kept %d runs, want %d", len(runs), keepRuns) | ||
| 74 | } | 75 | } | ||
| 76 | + | // A clean run leaves no empty crash file behind. | |||
| 77 | + | if crashes, _ := filepath.Glob(filepath.Join(dir, "2*.crash")); len(crashes) != 0 { | |||
| 78 | + | t.Fatalf("empty crash files kept: %v", crashes) | |||
| 79 | + | } | |||
| 75 | } | 80 | } | ||
| 76 | 81 | ||||
| 77 | func splitLines(data []byte) [][]byte { | 82 | func splitLines(data []byte) [][]byte { | ||
| @@ -94,7 +99,7 @@ func TestBackendsRotateSeparately(t *testing.T) { | |||||
| 94 | if err != nil { | 99 | if err != nil { | ||
| 95 | t.Fatal(err) | 100 | t.Fatal(err) | ||
| 96 | } | 101 | } | ||
| 97 | - | if err := closeLog(); err != nil { | 102 | + | if err := closeLog(false); err != nil { |
| 98 | t.Fatal(err) | 103 | t.Fatal(err) | ||
| 99 | } | 104 | } | ||
| 100 | } | 105 | } | ||
| @@ -123,7 +128,7 @@ func TestCategoryEnablesComponentDebug(t *testing.T) { | |||||
| 123 | input, core := For(ctx, "input"), For(ctx, "core") | 128 | input, core := For(ctx, "input"), For(ctx, "core") | ||
| 124 | input.Debug().Msg("motion") | 129 | input.Debug().Msg("motion") | ||
| 125 | core.Debug().Msg("hidden") | 130 | core.Debug().Msg("hidden") | ||
| 126 | - | if err := closeLog(); err != nil { | 131 | + | if err := closeLog(false); err != nil { |
| 127 | t.Fatal(err) | 132 | t.Fatal(err) | ||
| 128 | } | 133 | } | ||
| 129 | data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log")) | 134 | data, err := os.ReadFile(filepath.Join(os.Getenv("XDG_STATE_HOME"), "neferwl", "runs", "drm", "latest.log")) | ||
| @@ -135,6 +140,32 @@ func TestCategoryEnablesComponentDebug(t *testing.T) { | |||||
| 135 | } | 140 | } | ||
| 136 | } | 141 | } | ||
| 137 | 142 | ||||
| 143 | + | // A disk that stops answering must not block the goroutine that logs: | |||
| 144 | + | // input and outputs log from their own loops. | |||
| 145 | + | func TestLogWriteNeverBlocksOnSlowDisk(t *testing.T) { | |||
| 146 | + | r, pw, err := os.Pipe() // nobody reads: writes block once the pipe is full | |||
| 147 | + | if err != nil { | |||
| 148 | + | t.Fatal(err) | |||
| 149 | + | } | |||
| 150 | + | defer r.Close() | |||
| 151 | + | w := newAsyncWriter(struct{ io.Writer }{pw}, pw, "") | |||
| 152 | + | line := bytes.Repeat([]byte{'x'}, 1024) | |||
| 153 | + | done := make(chan struct{}) | |||
| 154 | + | go func() { | |||
| 155 | + | defer close(done) | |||
| 156 | + | for range 4 * logQueue { // far past the pipe buffer and the queue | |||
| 157 | + | _, _ = w.Write(line) | |||
| 158 | + | } | |||
| 159 | + | }() | |||
| 160 | + | select { | |||
| 161 | + | case <-done: | |||
| 162 | + | case <-time.After(5 * time.Second): | |||
| 163 | + | t.Fatal("log write blocked on a stuck disk") | |||
| 164 | + | } | |||
| 165 | + | r.Close() // unblock the writer so Close can drain and return | |||
| 166 | + | _ = w.Close() | |||
| 167 | + | } | |||
| 168 | + | ||||
| 138 | // Narrow categories are on only when named, never through "all". | 169 | // Narrow categories are on only when named, never through "all". | ||
| 139 | func TestEnabledCategories(t *testing.T) { | 170 | func TestEnabledCategories(t *testing.T) { | ||
| 140 | for _, category := range []string{"input-motion", "input-keys", "drm-flip"} { | 171 | for _, category := range []string{"input-motion", "input-keys", "drm-flip"} { | ||
M internal/adapters/vulkan/damage.go +49 -9
| @@ -27,6 +27,8 @@ type damageRegion struct { | |||
| 27 | 27 | drawn map[ports.WindowID]heldWindow | |
| 28 | 28 | // rects is scratch for a content's damage rects (reused across frames). | |
| 29 | 29 | rects []ports.Rect | |
| 30 | + | // why counts the reasons of full redraws (the renderer's; nil: none). | |
| 31 | + | why *fullRedraws | |
| 30 | 32 | } | |
| 31 | 33 | ||
| 32 | 34 | // heldWindow is a window a target holds: its content Seq and rect. | |
| @@ -46,6 +48,7 @@ func newDamage(tg *target, s ports.Scene, bounds image.Rectangle) *damageRegion | |||
| 46 | 48 | // one keeps all but what sceneDelta finds changed. | |
| 47 | 49 | func (d *damageRegion) hold(tg *target, s ports.Scene) { | |
| 48 | 50 | if !tg.valid || s.Seq == 0 { | |
| 51 | + | d.why.count(fullTarget) | |
| 49 | 52 | return | |
| 50 | 53 | } | |
| 51 | 54 | if tg.sceneSeq == s.Seq { | |
| @@ -64,6 +67,8 @@ func (d *damageRegion) hold(tg *target, s ports.Scene) { | |||
| 64 | 67 | limit := d.bound.Dx() * d.bound.Dy() * 9 / 10 | |
| 65 | 68 | if area, ok := sceneDelta(tg.scene, s, phys, limit); ok { | |
| 66 | 69 | d.held, d.area = tg, area | |
| 70 | + | } else { | |
| 71 | + | d.why.count(fullScene) | |
| 67 | 72 | } | |
| 68 | 73 | } | |
| 69 | 74 | ||
| @@ -78,7 +83,7 @@ func (r *Renderer) frameDamage(tg *target, s ports.Scene, bounds image.Rectangle | |||
| 78 | 83 | r.damageDrawn = make(map[ports.WindowID]heldWindow) | |
| 79 | 84 | } | |
| 80 | 85 | clear(r.damageDrawn) | |
| 81 | - | r.damage = damageRegion{seen: r.damageSeen, drawn: r.damageDrawn, bound: bounds, rects: r.damage.rects[:0]} | |
| 86 | + | r.damage = damageRegion{seen: r.damageSeen, drawn: r.damageDrawn, bound: bounds, rects: r.damage.rects[:0], why: &r.fullRedraws} | |
| 82 | 87 | r.damage.hold(tg, s) | |
| 83 | 88 | return &r.damage | |
| 84 | 89 | } | |
| @@ -108,16 +113,51 @@ func (d *damageRegion) window(id ports.WindowID, c ports.SurfaceContent, rect im | |||
| 108 | 113 | if ok && held == c.Seq { | |
| 109 | 114 | return | |
| 110 | 115 | } | |
| 111 | - | if !ok || c.Empty() || len(c.Children) > 0 { | |
| 112 | - | d.add(rect) | |
| 113 | - | return | |
| 116 | + | switch { | |
| 117 | + | case !ok: | |
| 118 | + | d.why.count(fullNewWindow) | |
| 119 | + | case c.Empty(): | |
| 120 | + | d.why.count(fullEmpty) | |
| 121 | + | case len(c.Children) > 0: | |
| 122 | + | d.why.count(fullChildren) | |
| 123 | + | default: | |
| 124 | + | var known bool | |
| 125 | + | d.rects, known = c.AppendDamageSince(d.rects[:0], held) | |
| 126 | + | if known { | |
| 127 | + | return // mapped by content, called next | |
| 128 | + | } | |
| 129 | + | d.why.count(fullHistory) | |
| 114 | 130 | } | |
| 115 | - | var known bool | |
| 116 | - | d.rects, known = c.AppendDamageSince(d.rects[:0], held) | |
| 117 | - | if !known { | |
| 118 | - | d.add(rect) | |
| 131 | + | d.add(rect) | |
| 132 | + | } | |
| 133 | + | ||
| 134 | + | // fullReason is why a whole target or window rect is redrawn. | |
| 135 | + | type fullReason int | |
| 136 | + | ||
| 137 | + | const ( | |
| 138 | + | fullTarget fullReason = iota // target never drawn, or an unnumbered scene | |
| 139 | + | fullScene // the scene changed past sceneDelta | |
| 140 | + | fullNewWindow // the target never held the window | |
| 141 | + | fullEmpty // the window has no content | |
| 142 | + | fullChildren // the window has subsurfaces | |
| 143 | + | fullHistory // the damage history does not reach the held content | |
| 144 | + | fullReasons | |
| 145 | + | ) | |
| 146 | + | ||
| 147 | + | // fullRedraws counts full redraws by reason since the last take. | |
| 148 | + | type fullRedraws [fullReasons]int | |
| 149 | + | ||
| 150 | + | func (f *fullRedraws) count(r fullReason) { | |
| 151 | + | if f != nil { | |
| 152 | + | f[r]++ | |
| 119 | 153 | } | |
| 120 | - | // Otherwise mapped by content, called next: nothing more here. | |
| 154 | + | } | |
| 155 | + | ||
| 156 | + | // take returns the counts and resets them. | |
| 157 | + | func (f *fullRedraws) take() fullRedraws { | |
| 158 | + | n := *f | |
| 159 | + | *f = fullRedraws{} | |
| 160 | + | return n | |
| 121 | 161 | } | |
| 122 | 162 | ||
| 123 | 163 | // content maps a root surface's buffer damage onto full (where its w×h | |
| @@ -27,6 +27,8 @@ type damageRegion struct { | |||||
| 27 | drawn map[ports.WindowID]heldWindow | 27 | drawn map[ports.WindowID]heldWindow | ||
| 28 | // rects is scratch for a content's damage rects (reused across frames). | 28 | // rects is scratch for a content's damage rects (reused across frames). | ||
| 29 | rects []ports.Rect | 29 | rects []ports.Rect | ||
| 30 | + | // why counts the reasons of full redraws (the renderer's; nil: none). | |||
| 31 | + | why *fullRedraws | |||
| 30 | } | 32 | } | ||
| 31 | 33 | ||||
| 32 | // heldWindow is a window a target holds: its content Seq and rect. | 34 | // heldWindow is a window a target holds: its content Seq and rect. | ||
| @@ -46,6 +48,7 @@ func newDamage(tg *target, s ports.Scene, bounds image.Rectangle) *damageRegion | |||||
| 46 | // one keeps all but what sceneDelta finds changed. | 48 | // one keeps all but what sceneDelta finds changed. | ||
| 47 | func (d *damageRegion) hold(tg *target, s ports.Scene) { | 49 | func (d *damageRegion) hold(tg *target, s ports.Scene) { | ||
| 48 | if !tg.valid || s.Seq == 0 { | 50 | if !tg.valid || s.Seq == 0 { | ||
| 51 | + | d.why.count(fullTarget) | |||
| 49 | return | 52 | return | ||
| 50 | } | 53 | } | ||
| 51 | if tg.sceneSeq == s.Seq { | 54 | if tg.sceneSeq == s.Seq { | ||
| @@ -64,6 +67,8 @@ func (d *damageRegion) hold(tg *target, s ports.Scene) { | |||||
| 64 | limit := d.bound.Dx() * d.bound.Dy() * 9 / 10 | 67 | limit := d.bound.Dx() * d.bound.Dy() * 9 / 10 | ||
| 65 | if area, ok := sceneDelta(tg.scene, s, phys, limit); ok { | 68 | if area, ok := sceneDelta(tg.scene, s, phys, limit); ok { | ||
| 66 | d.held, d.area = tg, area | 69 | d.held, d.area = tg, area | ||
| 70 | + | } else { | |||
| 71 | + | d.why.count(fullScene) | |||
| 67 | } | 72 | } | ||
| 68 | } | 73 | } | ||
| 69 | 74 | ||||
| @@ -78,7 +83,7 @@ func (r *Renderer) frameDamage(tg *target, s ports.Scene, bounds image.Rectangle | |||||
| 78 | r.damageDrawn = make(map[ports.WindowID]heldWindow) | 83 | r.damageDrawn = make(map[ports.WindowID]heldWindow) | ||
| 79 | } | 84 | } | ||
| 80 | clear(r.damageDrawn) | 85 | clear(r.damageDrawn) | ||
| 81 | - | r.damage = damageRegion{seen: r.damageSeen, drawn: r.damageDrawn, bound: bounds, rects: r.damage.rects[:0]} | 86 | + | r.damage = damageRegion{seen: r.damageSeen, drawn: r.damageDrawn, bound: bounds, rects: r.damage.rects[:0], why: &r.fullRedraws} |
| 82 | r.damage.hold(tg, s) | 87 | r.damage.hold(tg, s) | ||
| 83 | return &r.damage | 88 | return &r.damage | ||
| 84 | } | 89 | } | ||
| @@ -108,16 +113,51 @@ func (d *damageRegion) window(id ports.WindowID, c ports.SurfaceContent, rect im | |||||
| 108 | if ok && held == c.Seq { | 113 | if ok && held == c.Seq { | ||
| 109 | return | 114 | return | ||
| 110 | } | 115 | } | ||
| 111 | - | if !ok || c.Empty() || len(c.Children) > 0 { | 116 | + | switch { |
| 112 | - | d.add(rect) | 117 | + | case !ok: |
| 113 | - | return | 118 | + | d.why.count(fullNewWindow) |
| 119 | + | case c.Empty(): | |||
| 120 | + | d.why.count(fullEmpty) | |||
| 121 | + | case len(c.Children) > 0: | |||
| 122 | + | d.why.count(fullChildren) | |||
| 123 | + | default: | |||
| 124 | + | var known bool | |||
| 125 | + | d.rects, known = c.AppendDamageSince(d.rects[:0], held) | |||
| 126 | + | if known { | |||
| 127 | + | return // mapped by content, called next | |||
| 128 | + | } | |||
| 129 | + | d.why.count(fullHistory) | |||
| 114 | } | 130 | } | ||
| 115 | - | var known bool | 131 | + | d.add(rect) |
| 116 | - | d.rects, known = c.AppendDamageSince(d.rects[:0], held) | 132 | + | } |
| 117 | - | if !known { | 133 | + | |
| 118 | - | d.add(rect) | 134 | + | // fullReason is why a whole target or window rect is redrawn. |
| 135 | + | type fullReason int | |||
| 136 | + | ||||
| 137 | + | const ( | |||
| 138 | + | fullTarget fullReason = iota // target never drawn, or an unnumbered scene | |||
| 139 | + | fullScene // the scene changed past sceneDelta | |||
| 140 | + | fullNewWindow // the target never held the window | |||
| 141 | + | fullEmpty // the window has no content | |||
| 142 | + | fullChildren // the window has subsurfaces | |||
| 143 | + | fullHistory // the damage history does not reach the held content | |||
| 144 | + | fullReasons | |||
| 145 | + | ) | |||
| 146 | + | ||||
| 147 | + | // fullRedraws counts full redraws by reason since the last take. | |||
| 148 | + | type fullRedraws [fullReasons]int | |||
| 149 | + | ||||
| 150 | + | func (f *fullRedraws) count(r fullReason) { | |||
| 151 | + | if f != nil { | |||
| 152 | + | f[r]++ | |||
| 119 | } | 153 | } | ||
| 120 | - | // Otherwise mapped by content, called next: nothing more here. | 154 | + | } |
| 155 | + | ||||
| 156 | + | // take returns the counts and resets them. | |||
| 157 | + | func (f *fullRedraws) take() fullRedraws { | |||
| 158 | + | n := *f | |||
| 159 | + | *f = fullRedraws{} | |||
| 160 | + | return n | |||
| 121 | } | 161 | } | ||
| 122 | 162 | ||||
| 123 | // content maps a root surface's buffer damage onto full (where its w×h | 163 | // content maps a root surface's buffer damage onto full (where its w×h | ||
A internal/adapters/vulkan/fullredraw_test.go +39 -0
| @@ -0,0 +1,39 @@ | |||
| 1 | + | package vulkan | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "image" | |
| 5 | + | "testing" | |
| 6 | + | ||
| 7 | + | "github.com/bnema/neferwl/internal/ports" | |
| 8 | + | ) | |
| 9 | + | ||
| 10 | + | // Each whole-window redraw is counted under its reason, so the stats tell | |
| 11 | + | // a client claiming full damage from a history too short. | |
| 12 | + | func TestFullRedrawReasons(t *testing.T) { | |
| 13 | + | rect := image.Rect(0, 0, 10, 10) | |
| 14 | + | held := &target{valid: true, windows: map[ports.WindowID]heldWindow{1: {seq: 1, rect: rect}}} | |
| 15 | + | var why fullRedraws | |
| 16 | + | d := &damageRegion{held: held, seen: map[ports.WindowID]bool{}, drawn: map[ports.WindowID]heldWindow{}, bound: rect, why: &why} | |
| 17 | + | pixels := ports.SurfaceContent{Width: 10, Height: 10, SHM: &ports.SHMBuffer{}} | |
| 18 | + | ||
| 19 | + | known := pixels | |
| 20 | + | known.ID, known.Seq = 1, 2 | |
| 21 | + | known.DamageHistory = []ports.SeqDamage{{Seq: 2, Rects: []ports.Rect{{W: 1, H: 1}}}} | |
| 22 | + | d.window(1, known, rect) | |
| 23 | + | if why != (fullRedraws{}) { | |
| 24 | + | t.Fatalf("partial damage counted as full: %v", why) | |
| 25 | + | } | |
| 26 | + | ||
| 27 | + | d.seen = map[ports.WindowID]bool{} | |
| 28 | + | gap := pixels | |
| 29 | + | gap.ID, gap.Seq = 1, 9 | |
| 30 | + | gap.DamageHistory = []ports.SeqDamage{{Seq: 9, Rects: []ports.Rect{{W: 1, H: 1}}}} | |
| 31 | + | d.window(1, gap, rect) | |
| 32 | + | d.window(2, gap, rect) | |
| 33 | + | if why[fullHistory] != 1 || why[fullNewWindow] != 1 { | |
| 34 | + | t.Fatalf("reasons %v", why) | |
| 35 | + | } | |
| 36 | + | if got := why.take(); got[fullHistory] != 1 || why != (fullRedraws{}) { | |
| 37 | + | t.Fatalf("take %v left %v", got, why) | |
| 38 | + | } | |
| 39 | + | } | |
| @@ -0,0 +1,39 @@ | |||||
| 1 | + | package vulkan | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "image" | |||
| 5 | + | "testing" | |||
| 6 | + | ||||
| 7 | + | "github.com/bnema/neferwl/internal/ports" | |||
| 8 | + | ) | |||
| 9 | + | ||||
| 10 | + | // Each whole-window redraw is counted under its reason, so the stats tell | |||
| 11 | + | // a client claiming full damage from a history too short. | |||
| 12 | + | func TestFullRedrawReasons(t *testing.T) { | |||
| 13 | + | rect := image.Rect(0, 0, 10, 10) | |||
| 14 | + | held := &target{valid: true, windows: map[ports.WindowID]heldWindow{1: {seq: 1, rect: rect}}} | |||
| 15 | + | var why fullRedraws | |||
| 16 | + | d := &damageRegion{held: held, seen: map[ports.WindowID]bool{}, drawn: map[ports.WindowID]heldWindow{}, bound: rect, why: &why} | |||
| 17 | + | pixels := ports.SurfaceContent{Width: 10, Height: 10, SHM: &ports.SHMBuffer{}} | |||
| 18 | + | ||||
| 19 | + | known := pixels | |||
| 20 | + | known.ID, known.Seq = 1, 2 | |||
| 21 | + | known.DamageHistory = []ports.SeqDamage{{Seq: 2, Rects: []ports.Rect{{W: 1, H: 1}}}} | |||
| 22 | + | d.window(1, known, rect) | |||
| 23 | + | if why != (fullRedraws{}) { | |||
| 24 | + | t.Fatalf("partial damage counted as full: %v", why) | |||
| 25 | + | } | |||
| 26 | + | ||||
| 27 | + | d.seen = map[ports.WindowID]bool{} | |||
| 28 | + | gap := pixels | |||
| 29 | + | gap.ID, gap.Seq = 1, 9 | |||
| 30 | + | gap.DamageHistory = []ports.SeqDamage{{Seq: 9, Rects: []ports.Rect{{W: 1, H: 1}}}} | |||
| 31 | + | d.window(1, gap, rect) | |||
| 32 | + | d.window(2, gap, rect) | |||
| 33 | + | if why[fullHistory] != 1 || why[fullNewWindow] != 1 { | |||
| 34 | + | t.Fatalf("reasons %v", why) | |||
| 35 | + | } | |||
| 36 | + | if got := why.take(); got[fullHistory] != 1 || why != (fullRedraws{}) { | |||
| 37 | + | t.Fatalf("take %v left %v", got, why) | |||
| 38 | + | } | |||
| 39 | + | } | |||
M internal/adapters/vulkan/renderer.go +7 -0
| @@ -89,6 +89,9 @@ type Renderer struct { | |||
| 89 | 89 | marks []trimMark | |
| 90 | 90 | // redrawn counts the target pixels drawn (TakeRedrawn). | |
| 91 | 91 | redrawn int | |
| 92 | + | // fullRedraws counts why whole targets or windows were redrawn; each | |
| 93 | + | // TakeRedrawn logs and resets it. | |
| 94 | + | fullRedraws fullRedraws | |
| 92 | 95 | // cursors are the exported cursor images (CursorBuffers). | |
| 93 | 96 | cursors [2]*cursorImage | |
| 94 | 97 | // compose draws every frame (compose.go); maxRange bounds one | |
| @@ -345,6 +348,10 @@ func (r *Renderer) CopiedBytes() int { return r.copied } | |||
| 345 | 348 | func (r *Renderer) TakeRedrawn() int { | |
| 346 | 349 | n := r.redrawn | |
| 347 | 350 | r.redrawn = 0 | |
| 351 | + | if f := r.fullRedraws.take(); f != (fullRedraws{}) { | |
| 352 | + | r.log.Debug().Int("target", f[fullTarget]).Int("scene", f[fullScene]).Int("new_window", f[fullNewWindow]). | |
| 353 | + | Int("empty", f[fullEmpty]).Int("children", f[fullChildren]).Int("history", f[fullHistory]).Msg("full redraws") | |
| 354 | + | } | |
| 348 | 355 | return n | |
| 349 | 356 | } | |
| 350 | 357 | ||
| @@ -89,6 +89,9 @@ type Renderer struct { | |||||
| 89 | marks []trimMark | 89 | marks []trimMark | ||
| 90 | // redrawn counts the target pixels drawn (TakeRedrawn). | 90 | // redrawn counts the target pixels drawn (TakeRedrawn). | ||
| 91 | redrawn int | 91 | redrawn int | ||
| 92 | + | // fullRedraws counts why whole targets or windows were redrawn; each | |||
| 93 | + | // TakeRedrawn logs and resets it. | |||
| 94 | + | fullRedraws fullRedraws | |||
| 92 | // cursors are the exported cursor images (CursorBuffers). | 95 | // cursors are the exported cursor images (CursorBuffers). | ||
| 93 | cursors [2]*cursorImage | 96 | cursors [2]*cursorImage | ||
| 94 | // compose draws every frame (compose.go); maxRange bounds one | 97 | // compose draws every frame (compose.go); maxRange bounds one | ||
| @@ -345,6 +348,10 @@ func (r *Renderer) CopiedBytes() int { return r.copied } | |||||
| 345 | func (r *Renderer) TakeRedrawn() int { | 348 | func (r *Renderer) TakeRedrawn() int { | ||
| 346 | n := r.redrawn | 349 | n := r.redrawn | ||
| 347 | r.redrawn = 0 | 350 | r.redrawn = 0 | ||
| 351 | + | if f := r.fullRedraws.take(); f != (fullRedraws{}) { | |||
| 352 | + | r.log.Debug().Int("target", f[fullTarget]).Int("scene", f[fullScene]).Int("new_window", f[fullNewWindow]). | |||
| 353 | + | Int("empty", f[fullEmpty]).Int("children", f[fullChildren]).Int("history", f[fullHistory]).Msg("full redraws") | |||
| 354 | + | } | |||
| 348 | return n | 355 | return n | ||
| 349 | } | 356 | } | ||
| 350 | 357 | ||||
A internal/adapters/watchdog/watchdog.go +117 -0
| @@ -0,0 +1,117 @@ | |||
| 1 | + | // Package watchdog writes every goroutine stack to a file when a probed | |
| 2 | + | // owner loop stops answering, so a frozen session leaves the exact place | |
| 3 | + | // it is stuck on disk. | |
| 4 | + | package watchdog | |
| 5 | + | ||
| 6 | + | import ( | |
| 7 | + | "context" | |
| 8 | + | "fmt" | |
| 9 | + | "os" | |
| 10 | + | "path/filepath" | |
| 11 | + | "runtime/pprof" | |
| 12 | + | "sync" | |
| 13 | + | "time" | |
| 14 | + | ||
| 15 | + | "github.com/bnema/zerowrap" | |
| 16 | + | ) | |
| 17 | + | ||
| 18 | + | // Probe asks an owner loop to run an empty task: Ping returns once the | |
| 19 | + | // loop ran it. A loop that is stuck never returns. | |
| 20 | + | type Probe struct { | |
| 21 | + | Name string | |
| 22 | + | Ping func() | |
| 23 | + | } | |
| 24 | + | ||
| 25 | + | // Options set how often the probes run and how long a loop may take. | |
| 26 | + | type Options struct { | |
| 27 | + | Dir string // where stall dumps go (the run log directory) | |
| 28 | + | Every time.Duration // between two probes of a loop | |
| 29 | + | Timeout time.Duration // a probe slower than this is a stall | |
| 30 | + | Log zerowrap.Logger | |
| 31 | + | } | |
| 32 | + | ||
| 33 | + | // Run probes each loop probes returns until ctx ends; the set may change | |
| 34 | + | // between ticks (outputs come and go). On a stall it writes one dump per | |
| 35 | + | // stall: a loop must answer again before it is dumped again. Every Ping | |
| 36 | + | // must return once ctx ends: Run waits for the probes in flight. | |
| 37 | + | func Run(ctx context.Context, probes func() []Probe, o Options) { | |
| 38 | + | var inflight sync.WaitGroup | |
| 39 | + | defer inflight.Wait() | |
| 40 | + | type state struct { | |
| 41 | + | answer chan struct{} // the probe in flight, nil when none | |
| 42 | + | since time.Time | |
| 43 | + | stalled bool | |
| 44 | + | seen bool | |
| 45 | + | } | |
| 46 | + | states := map[string]*state{} | |
| 47 | + | tick := time.NewTicker(o.Every) | |
| 48 | + | defer tick.Stop() | |
| 49 | + | for { | |
| 50 | + | select { | |
| 51 | + | case <-ctx.Done(): | |
| 52 | + | return | |
| 53 | + | case now := <-tick.C: | |
| 54 | + | for _, s := range states { | |
| 55 | + | s.seen = false | |
| 56 | + | } | |
| 57 | + | for _, p := range probes() { | |
| 58 | + | s := states[p.Name] | |
| 59 | + | if s == nil { | |
| 60 | + | s = &state{} | |
| 61 | + | states[p.Name] = s | |
| 62 | + | } | |
| 63 | + | s.seen = true | |
| 64 | + | if s.answer != nil { | |
| 65 | + | select { | |
| 66 | + | case <-s.answer: | |
| 67 | + | if s.stalled { | |
| 68 | + | o.Log.Warn().Str("loop", p.Name).Dur("after", now.Sub(s.since)).Msg("loop answers again") | |
| 69 | + | } | |
| 70 | + | s.answer, s.stalled = nil, false | |
| 71 | + | default: | |
| 72 | + | if !s.stalled && now.Sub(s.since) >= o.Timeout { | |
| 73 | + | s.stalled = true | |
| 74 | + | path, err := dump(o.Dir, p.Name, now) | |
| 75 | + | o.Log.Error().Err(err).Str("loop", p.Name).Dur("waited", now.Sub(s.since)).Str("dump", path).Msg("loop stalled") | |
| 76 | + | } | |
| 77 | + | continue // one probe in flight per loop | |
| 78 | + | } | |
| 79 | + | } | |
| 80 | + | answer := make(chan struct{}) | |
| 81 | + | s.answer, s.since = answer, now | |
| 82 | + | inflight.Go(func() { p.Ping(); close(answer) }) | |
| 83 | + | } | |
| 84 | + | // A loop that left (an unplugged output) is forgotten; its | |
| 85 | + | // probe goroutine ends with the loop's context. | |
| 86 | + | for name, s := range states { | |
| 87 | + | if !s.seen { | |
| 88 | + | delete(states, name) | |
| 89 | + | } | |
| 90 | + | } | |
| 91 | + | } | |
| 92 | + | } | |
| 93 | + | } | |
| 94 | + | ||
| 95 | + | // dump writes every goroutine stack to dir and syncs it: a frozen machine | |
| 96 | + | // is often force rebooted, which loses what the page cache still holds. | |
| 97 | + | func dump(dir, name string, now time.Time) (string, error) { | |
| 98 | + | path := filepath.Join(dir, fmt.Sprintf("stall-%s-%s.txt", now.Format("20060102-150405.000"), name)) | |
| 99 | + | f, err := os.OpenFile(path, os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0o600) | |
| 100 | + | if err != nil { | |
| 101 | + | return path, err | |
| 102 | + | } | |
| 103 | + | fmt.Fprintf(f, "loop %q stopped answering at %s\n\n", name, now.Format(time.RFC3339Nano)) | |
| 104 | + | werr := pprof.Lookup("goroutine").WriteTo(f, 2) | |
| 105 | + | serr := f.Sync() | |
| 106 | + | cerr := f.Close() | |
| 107 | + | if d, err := os.Open(dir); err == nil { | |
| 108 | + | _ = d.Sync() | |
| 109 | + | _ = d.Close() | |
| 110 | + | } | |
| 111 | + | for _, err := range []error{werr, serr, cerr} { | |
| 112 | + | if err != nil { | |
| 113 | + | return path, err | |
| 114 | + | } | |
| 115 | + | } | |
| 116 | + | return path, nil | |
| 117 | + | } | |
| @@ -0,0 +1,117 @@ | |||||
| 1 | + | // Package watchdog writes every goroutine stack to a file when a probed | |||
| 2 | + | // owner loop stops answering, so a frozen session leaves the exact place | |||
| 3 | + | // it is stuck on disk. | |||
| 4 | + | package watchdog | |||
| 5 | + | ||||
| 6 | + | import ( | |||
| 7 | + | "context" | |||
| 8 | + | "fmt" | |||
| 9 | + | "os" | |||
| 10 | + | "path/filepath" | |||
| 11 | + | "runtime/pprof" | |||
| 12 | + | "sync" | |||
| 13 | + | "time" | |||
| 14 | + | ||||
| 15 | + | "github.com/bnema/zerowrap" | |||
| 16 | + | ) | |||
| 17 | + | ||||
| 18 | + | // Probe asks an owner loop to run an empty task: Ping returns once the | |||
| 19 | + | // loop ran it. A loop that is stuck never returns. | |||
| 20 | + | type Probe struct { | |||
| 21 | + | Name string | |||
| 22 | + | Ping func() | |||
| 23 | + | } | |||
| 24 | + | ||||
| 25 | + | // Options set how often the probes run and how long a loop may take. | |||
| 26 | + | type Options struct { | |||
| 27 | + | Dir string // where stall dumps go (the run log directory) | |||
| 28 | + | Every time.Duration // between two probes of a loop | |||
| 29 | + | Timeout time.Duration // a probe slower than this is a stall | |||
| 30 | + | Log zerowrap.Logger | |||
| 31 | + | } | |||
| 32 | + | ||||
| 33 | + | // Run probes each loop probes returns until ctx ends; the set may change | |||
| 34 | + | // between ticks (outputs come and go). On a stall it writes one dump per | |||
| 35 | + | // stall: a loop must answer again before it is dumped again. Every Ping | |||
| 36 | + | // must return once ctx ends: Run waits for the probes in flight. | |||
| 37 | + | func Run(ctx context.Context, probes func() []Probe, o Options) { | |||
| 38 | + | var inflight sync.WaitGroup | |||
| 39 | + | defer inflight.Wait() | |||
| 40 | + | type state struct { | |||
| 41 | + | answer chan struct{} // the probe in flight, nil when none | |||
| 42 | + | since time.Time | |||
| 43 | + | stalled bool | |||
| 44 | + | seen bool | |||
| 45 | + | } | |||
| 46 | + | states := map[string]*state{} | |||
| 47 | + | tick := time.NewTicker(o.Every) | |||
| 48 | + | defer tick.Stop() | |||
| 49 | + | for { | |||
| 50 | + | select { | |||
| 51 | + | case <-ctx.Done(): | |||
| 52 | + | return | |||
| 53 | + | case now := <-tick.C: | |||
| 54 | + | for _, s := range states { | |||
| 55 | + | s.seen = false | |||
| 56 | + | } | |||
| 57 | + | for _, p := range probes() { | |||
| 58 | + | s := states[p.Name] | |||
| 59 | + | if s == nil { | |||
| 60 | + | s = &state{} | |||
| 61 | + | states[p.Name] = s | |||
| 62 | + | } | |||
| 63 | + | s.seen = true | |||
| 64 | + | if s.answer != nil { | |||
| 65 | + | select { | |||
| 66 | + | case <-s.answer: | |||
| 67 | + | if s.stalled { | |||
| 68 | + | o.Log.Warn().Str("loop", p.Name).Dur("after", now.Sub(s.since)).Msg("loop answers again") | |||
| 69 | + | } | |||
| 70 | + | s.answer, s.stalled = nil, false | |||
| 71 | + | default: | |||
| 72 | + | if !s.stalled && now.Sub(s.since) >= o.Timeout { | |||
| 73 | + | s.stalled = true | |||
| 74 | + | path, err := dump(o.Dir, p.Name, now) | |||
| 75 | + | o.Log.Error().Err(err).Str("loop", p.Name).Dur("waited", now.Sub(s.since)).Str("dump", path).Msg("loop stalled") | |||
| 76 | + | } | |||
| 77 | + | continue // one probe in flight per loop | |||
| 78 | + | } | |||
| 79 | + | } | |||
| 80 | + | answer := make(chan struct{}) | |||
| 81 | + | s.answer, s.since = answer, now | |||
| 82 | + | inflight.Go(func() { p.Ping(); close(answer) }) | |||
| 83 | + | } | |||
| 84 | + | // A loop that left (an unplugged output) is forgotten; its | |||
| 85 | + | // probe goroutine ends with the loop's context. | |||
| 86 | + | for name, s := range states { | |||
| 87 | + | if !s.seen { | |||
| 88 | + | delete(states, name) | |||
| 89 | + | } | |||
| 90 | + | } | |||
| 91 | + | } | |||
| 92 | + | } | |||
| 93 | + | } | |||
| 94 | + | ||||
| 95 | + | // dump writes every goroutine stack to dir and syncs it: a frozen machine | |||
| 96 | + | // is often force rebooted, which loses what the page cache still holds. | |||
| 97 | + | func dump(dir, name string, now time.Time) (string, error) { | |||
| 98 | + | path := filepath.Join(dir, fmt.Sprintf("stall-%s-%s.txt", now.Format("20060102-150405.000"), name)) | |||
| 99 | + | f, err := os.OpenFile(path, os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0o600) | |||
| 100 | + | if err != nil { | |||
| 101 | + | return path, err | |||
| 102 | + | } | |||
| 103 | + | fmt.Fprintf(f, "loop %q stopped answering at %s\n\n", name, now.Format(time.RFC3339Nano)) | |||
| 104 | + | werr := pprof.Lookup("goroutine").WriteTo(f, 2) | |||
| 105 | + | serr := f.Sync() | |||
| 106 | + | cerr := f.Close() | |||
| 107 | + | if d, err := os.Open(dir); err == nil { | |||
| 108 | + | _ = d.Sync() | |||
| 109 | + | _ = d.Close() | |||
| 110 | + | } | |||
| 111 | + | for _, err := range []error{werr, serr, cerr} { | |||
| 112 | + | if err != nil { | |||
| 113 | + | return path, err | |||
| 114 | + | } | |||
| 115 | + | } | |||
| 116 | + | return path, nil | |||
| 117 | + | } | |||
A internal/adapters/watchdog/watchdog_test.go +77 -0
| @@ -0,0 +1,77 @@ | |||
| 1 | + | package watchdog | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "context" | |
| 5 | + | "os" | |
| 6 | + | "path/filepath" | |
| 7 | + | "strings" | |
| 8 | + | "sync/atomic" | |
| 9 | + | "testing" | |
| 10 | + | "testing/synctest" | |
| 11 | + | "time" | |
| 12 | + | ||
| 13 | + | "github.com/bnema/zerowrap" | |
| 14 | + | ) | |
| 15 | + | ||
| 16 | + | // stuckOwnerLoop blocks like an owner goroutine that never reaches its | |
| 17 | + | // select again; the dump must name it. | |
| 18 | + | func stuckOwnerLoop(ctx context.Context, release <-chan struct{}) { | |
| 19 | + | select { | |
| 20 | + | case <-release: | |
| 21 | + | case <-ctx.Done(): | |
| 22 | + | } | |
| 23 | + | } | |
| 24 | + | ||
| 25 | + | func TestStalledLoopIsDumpedOnce(t *testing.T) { | |
| 26 | + | dir := t.TempDir() | |
| 27 | + | synctest.Test(t, func(t *testing.T) { | |
| 28 | + | ctx, cancel := context.WithCancel(context.Background()) | |
| 29 | + | release := make(chan struct{}) | |
| 30 | + | var answered atomic.Int32 | |
| 31 | + | probes := func() []Probe { | |
| 32 | + | return []Probe{ | |
| 33 | + | {Name: "stuck", Ping: func() { stuckOwnerLoop(ctx, release) }}, | |
| 34 | + | {Name: "fine", Ping: func() { answered.Add(1) }}, | |
| 35 | + | } | |
| 36 | + | } | |
| 37 | + | done := make(chan struct{}) | |
| 38 | + | go func() { | |
| 39 | + | defer close(done) | |
| 40 | + | Run(ctx, probes, Options{Dir: dir, Every: 10 * time.Millisecond, Timeout: 50 * time.Millisecond, Log: zerowrap.Default()}) | |
| 41 | + | }() | |
| 42 | + | dumps := func() []string { | |
| 43 | + | m, _ := filepath.Glob(filepath.Join(dir, "stall-*.txt")) | |
| 44 | + | return m | |
| 45 | + | } | |
| 46 | + | time.Sleep(40 * time.Millisecond) | |
| 47 | + | synctest.Wait() | |
| 48 | + | if d := dumps(); len(d) != 0 { | |
| 49 | + | t.Fatalf("dumped before the timeout: %v", d) | |
| 50 | + | } | |
| 51 | + | time.Sleep(30 * time.Millisecond) | |
| 52 | + | synctest.Wait() | |
| 53 | + | d := dumps() | |
| 54 | + | if len(d) != 1 || !strings.HasSuffix(d[0], "-stuck.txt") { | |
| 55 | + | t.Fatalf("dumps %v", d) | |
| 56 | + | } | |
| 57 | + | // Still stuck: no second dump. | |
| 58 | + | time.Sleep(time.Second) | |
| 59 | + | synctest.Wait() | |
| 60 | + | if again := dumps(); len(again) != 1 { | |
| 61 | + | t.Fatalf("dumps after the first %v", again) | |
| 62 | + | } | |
| 63 | + | data, err := os.ReadFile(d[0]) | |
| 64 | + | if err != nil { | |
| 65 | + | t.Fatal(err) | |
| 66 | + | } | |
| 67 | + | if !strings.Contains(string(data), "stuckOwnerLoop") { | |
| 68 | + | t.Fatalf("dump does not name the stuck function:\n%s", data) | |
| 69 | + | } | |
| 70 | + | if n := answered.Load(); n < 50 { | |
| 71 | + | t.Fatalf("a healthy loop was probed %d times in 1 s", n) | |
| 72 | + | } | |
| 73 | + | // Run waits for its probes: a stuck one ends with ctx. | |
| 74 | + | cancel() | |
| 75 | + | <-done | |
| 76 | + | }) | |
| 77 | + | } | |
| @@ -0,0 +1,77 @@ | |||||
| 1 | + | package watchdog | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "context" | |||
| 5 | + | "os" | |||
| 6 | + | "path/filepath" | |||
| 7 | + | "strings" | |||
| 8 | + | "sync/atomic" | |||
| 9 | + | "testing" | |||
| 10 | + | "testing/synctest" | |||
| 11 | + | "time" | |||
| 12 | + | ||||
| 13 | + | "github.com/bnema/zerowrap" | |||
| 14 | + | ) | |||
| 15 | + | ||||
| 16 | + | // stuckOwnerLoop blocks like an owner goroutine that never reaches its | |||
| 17 | + | // select again; the dump must name it. | |||
| 18 | + | func stuckOwnerLoop(ctx context.Context, release <-chan struct{}) { | |||
| 19 | + | select { | |||
| 20 | + | case <-release: | |||
| 21 | + | case <-ctx.Done(): | |||
| 22 | + | } | |||
| 23 | + | } | |||
| 24 | + | ||||
| 25 | + | func TestStalledLoopIsDumpedOnce(t *testing.T) { | |||
| 26 | + | dir := t.TempDir() | |||
| 27 | + | synctest.Test(t, func(t *testing.T) { | |||
| 28 | + | ctx, cancel := context.WithCancel(context.Background()) | |||
| 29 | + | release := make(chan struct{}) | |||
| 30 | + | var answered atomic.Int32 | |||
| 31 | + | probes := func() []Probe { | |||
| 32 | + | return []Probe{ | |||
| 33 | + | {Name: "stuck", Ping: func() { stuckOwnerLoop(ctx, release) }}, | |||
| 34 | + | {Name: "fine", Ping: func() { answered.Add(1) }}, | |||
| 35 | + | } | |||
| 36 | + | } | |||
| 37 | + | done := make(chan struct{}) | |||
| 38 | + | go func() { | |||
| 39 | + | defer close(done) | |||
| 40 | + | Run(ctx, probes, Options{Dir: dir, Every: 10 * time.Millisecond, Timeout: 50 * time.Millisecond, Log: zerowrap.Default()}) | |||
| 41 | + | }() | |||
| 42 | + | dumps := func() []string { | |||
| 43 | + | m, _ := filepath.Glob(filepath.Join(dir, "stall-*.txt")) | |||
| 44 | + | return m | |||
| 45 | + | } | |||
| 46 | + | time.Sleep(40 * time.Millisecond) | |||
| 47 | + | synctest.Wait() | |||
| 48 | + | if d := dumps(); len(d) != 0 { | |||
| 49 | + | t.Fatalf("dumped before the timeout: %v", d) | |||
| 50 | + | } | |||
| 51 | + | time.Sleep(30 * time.Millisecond) | |||
| 52 | + | synctest.Wait() | |||
| 53 | + | d := dumps() | |||
| 54 | + | if len(d) != 1 || !strings.HasSuffix(d[0], "-stuck.txt") { | |||
| 55 | + | t.Fatalf("dumps %v", d) | |||
| 56 | + | } | |||
| 57 | + | // Still stuck: no second dump. | |||
| 58 | + | time.Sleep(time.Second) | |||
| 59 | + | synctest.Wait() | |||
| 60 | + | if again := dumps(); len(again) != 1 { | |||
| 61 | + | t.Fatalf("dumps after the first %v", again) | |||
| 62 | + | } | |||
| 63 | + | data, err := os.ReadFile(d[0]) | |||
| 64 | + | if err != nil { | |||
| 65 | + | t.Fatal(err) | |||
| 66 | + | } | |||
| 67 | + | if !strings.Contains(string(data), "stuckOwnerLoop") { | |||
| 68 | + | t.Fatalf("dump does not name the stuck function:\n%s", data) | |||
| 69 | + | } | |||
| 70 | + | if n := answered.Load(); n < 50 { | |||
| 71 | + | t.Fatalf("a healthy loop was probed %d times in 1 s", n) | |||
| 72 | + | } | |||
| 73 | + | // Run waits for its probes: a stuck one ends with ctx. | |||
| 74 | + | cancel() | |||
| 75 | + | <-done | |||
| 76 | + | }) | |||
| 77 | + | } | |||
A internal/adapters/wayland/alloc_hotpath_test.go +153 -0
| @@ -0,0 +1,153 @@ | |||
| 1 | + | package wayland | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "context" | |
| 5 | + | "testing" | |
| 6 | + | "time" | |
| 7 | + | ||
| 8 | + | "github.com/bnema/neferwl/internal/ports" | |
| 9 | + | "github.com/stretchr/testify/mock" | |
| 10 | + | ) | |
| 11 | + | ||
| 12 | + | // The steady-state hot paths that run for every frame or commit allocate | |
| 13 | + | // nothing (or one pooled object per damage-history generation). | |
| 14 | + | ||
| 15 | + | func TestReleaseHeldAllocations(t *testing.T) { | |
| 16 | + | out := &output{place: ports.OutputPlacement{Info: ports.OutputInfo{Name: "DP-2", RefreshMilli: 60000}}} | |
| 17 | + | s := &Server{outputs: []*output{out}, reports: map[string]ports.OutputPresented{}} | |
| 18 | + | reports := []ports.OutputPresented{{Output: "DP-2", Seen: map[ports.WindowID]uint64{1: 1}}} | |
| 19 | + | now := time.Unix(100, 0) | |
| 20 | + | s.releaseHeld(now, reports) | |
| 21 | + | if allocs := testing.AllocsPerRun(100, func() { s.releaseHeld(now, reports) }); allocs != 0 { | |
| 22 | + | t.Errorf("releaseHeld: %.1f allocs, want 0", allocs) | |
| 23 | + | } | |
| 24 | + | } | |
| 25 | + | ||
| 26 | + | func TestCommitDamageAllocations(t *testing.T) { | |
| 27 | + | srv := &Server{fifoSurfaces: map[*surface]struct{}{}, frameReady: make(chan struct{}, 1)} | |
| 28 | + | surf := &surface{server: srv} | |
| 29 | + | commit := func() { | |
| 30 | + | surf.Damage(nil, 0, 0, 4, 4) | |
| 31 | + | surf.DamageBuffer(nil, 1, 1, 2, 2) | |
| 32 | + | surf.queueUpdate() | |
| 33 | + | surf.queue[0].applyGraph() | |
| 34 | + | } | |
| 35 | + | commit() | |
| 36 | + | if allocs := testing.AllocsPerRun(100, commit); allocs != 0 { | |
| 37 | + | t.Errorf("damage requests + queueUpdate + apply: %.1f allocs, want 0", allocs) | |
| 38 | + | } | |
| 39 | + | // The queued update keeps its rects while the next commit collects its own. | |
| 40 | + | surf.Damage(nil, 0, 0, 1, 1) | |
| 41 | + | surf.queueUpdate() | |
| 42 | + | first := surf.queue[0] | |
| 43 | + | surf.Damage(nil, 5, 5, 2, 2) | |
| 44 | + | if len(first.damage) != 1 || first.damage[0].W != 1 || len(surf.next.damage) != 1 || surf.next.damage[0].W != 2 { | |
| 45 | + | t.Fatalf("damage shared between commits: queued %v pending %v", first.damage, surf.next.damage) | |
| 46 | + | } | |
| 47 | + | surf.queueUpdate() | |
| 48 | + | if second := surf.queue[1]; len(second.damage) != 1 || second.damage[0].W != 2 || first.damage[0].W != 1 { | |
| 49 | + | t.Fatalf("damage mixed up: %v %v", first.damage, second.damage) | |
| 50 | + | } | |
| 51 | + | } | |
| 52 | + | ||
| 53 | + | // An explicit-sync commit moves its points into the update: the commit | |
| 54 | + | // itself allocates no commitSync, and a pending one is not overwritten. | |
| 55 | + | func TestCommitSyncStorageIsPerUpdate(t *testing.T) { | |
| 56 | + | dev := newMocksyncobjDevice(t) | |
| 57 | + | dev.EXPECT().signalled(mock.Anything, mock.Anything).Return(true, nil) | |
| 58 | + | srv := &Server{fifoSurfaces: map[*surface]struct{}{}, frameReady: make(chan struct{}, 1)} | |
| 59 | + | sw, err := newSyncWaiter(func() {}) | |
| 60 | + | if err != nil { | |
| 61 | + | t.Fatal(err) | |
| 62 | + | } | |
| 63 | + | defer sw.pipeR.Close() | |
| 64 | + | defer sw.close() | |
| 65 | + | srv.syncWait = sw | |
| 66 | + | tl := &timeline{dev: dev, handle: 7, alive: true} | |
| 67 | + | surf := &surface{server: srv, sync: &syncState{}} | |
| 68 | + | take := func(point uint64) { | |
| 69 | + | surf.sync.acquire, surf.sync.release = syncPoint{tl: tl, point: point}, syncPoint{tl: tl, point: point + 1} | |
| 70 | + | surf.takeSyncPoints() | |
| 71 | + | surf.queueUpdate() | |
| 72 | + | } | |
| 73 | + | take(10) | |
| 74 | + | take(20) | |
| 75 | + | a, b := surf.queue[0], surf.queue[1] | |
| 76 | + | if a.sync == nil || b.sync == nil || a.sync == b.sync || a.sync.acquire.point != 10 || b.sync.acquire.point != 20 || surf.next.sync != nil { | |
| 77 | + | t.Fatalf("sync points mixed up: %+v %+v pending %+v", a.sync, b.sync, surf.next.sync) | |
| 78 | + | } | |
| 79 | + | // The commit's points live in the surface until queueUpdate: no heap | |
| 80 | + | // commitSync per commit (the mocked device's own allocations would drown | |
| 81 | + | // an AllocsPerRun count here). | |
| 82 | + | surf.sync.acquire, surf.sync.release = syncPoint{tl: tl, point: 30}, syncPoint{tl: tl, point: 31} | |
| 83 | + | surf.takeSyncPoints() | |
| 84 | + | if surf.next.sync != &surf.syncScratch { | |
| 85 | + | t.Fatal("commit points not held in the surface scratch") | |
| 86 | + | } | |
| 87 | + | } | |
| 88 | + | ||
| 89 | + | func TestEmitContentAllocations(t *testing.T) { | |
| 90 | + | s := &Server{ | |
| 91 | + | channels: Channels{Contents: make(chan ports.SurfaceContent)}, | |
| 92 | + | contents: map[ports.WindowID]ports.SurfaceContent{}, | |
| 93 | + | contentSeq: map[ports.WindowID]uint64{}, | |
| 94 | + | damage: map[ports.WindowID][]ports.SeqDamage{}, | |
| 95 | + | contentReady: make(chan struct{}, 1), | |
| 96 | + | } | |
| 97 | + | c := ports.SurfaceContent{ID: 1, Solid: &ports.SolidColor{}} | |
| 98 | + | var held []ports.SurfaceContent // readers retaining published histories | |
| 99 | + | var snapshots [][]ports.SeqDamage | |
| 100 | + | for range 3 * damageHistoryCap { | |
| 101 | + | s.emitContent(c, damage{full: true}) | |
| 102 | + | got := s.contents[1] | |
| 103 | + | held = append(held, got) | |
| 104 | + | snapshots = append(snapshots, append([]ports.SeqDamage(nil), got.DamageHistory...)) | |
| 105 | + | } | |
| 106 | + | for i, h := range held { | |
| 107 | + | // A published history never changes, nor can its owner append to it. | |
| 108 | + | if len(h.DamageHistory) != len(snapshots[i]) || cap(h.DamageHistory) != len(h.DamageHistory) { | |
| 109 | + | t.Fatalf("history %d: len %d cap %d", i, len(h.DamageHistory), cap(h.DamageHistory)) | |
| 110 | + | } | |
| 111 | + | for j, d := range h.DamageHistory { | |
| 112 | + | if d.Seq != snapshots[i][j].Seq || d.Full != snapshots[i][j].Full { | |
| 113 | + | t.Fatalf("history %d changed at %d: %+v want %+v", i, j, d, snapshots[i][j]) | |
| 114 | + | } | |
| 115 | + | } | |
| 116 | + | if n := len(h.DamageHistory); h.DamageHistory[n-1].Seq != h.Seq || n > damageHistory { | |
| 117 | + | t.Fatalf("history %d: %+v", i, h.DamageHistory) | |
| 118 | + | } | |
| 119 | + | } | |
| 120 | + | allocs := testing.AllocsPerRun(100, func() { s.emitContent(c, damage{full: true}) }) | |
| 121 | + | if allocs != 0 { | |
| 122 | + | t.Errorf("emitContent: %.2f allocs, want 0 (amortized)", allocs) | |
| 123 | + | } | |
| 124 | + | t.Logf("emitContent: %.2f allocs", allocs) | |
| 125 | + | } | |
| 126 | + | ||
| 127 | + | // A forwarder blocked on a stale frame is woken by the next publication | |
| 128 | + | // and sends the newer frame instead. | |
| 129 | + | func TestForwardContentsSendsNewerFrame(t *testing.T) { | |
| 130 | + | contents := make(chan ports.SurfaceContent) | |
| 131 | + | s := &Server{ | |
| 132 | + | channels: Channels{Contents: contents}, | |
| 133 | + | contents: map[ports.WindowID]ports.SurfaceContent{}, | |
| 134 | + | contentSeq: map[ports.WindowID]uint64{}, | |
| 135 | + | damage: map[ports.WindowID][]ports.SeqDamage{}, | |
| 136 | + | contentReady: make(chan struct{}, 1), | |
| 137 | + | } | |
| 138 | + | ctx, cancel := context.WithCancel(context.Background()) | |
| 139 | + | done := make(chan struct{}) | |
| 140 | + | go func() { defer close(done); s.forwardContents(ctx) }() | |
| 141 | + | defer func() { cancel(); <-done }() | |
| 142 | + | s.emitContent(ports.SurfaceContent{ID: 1, Seq: 1, Solid: &ports.SolidColor{}}, damage{full: true}) | |
| 143 | + | time.Sleep(10 * time.Millisecond) // let the forwarder block on seq 1 | |
| 144 | + | s.emitContent(ports.SurfaceContent{ID: 1, Seq: 2, Solid: &ports.SolidColor{}}, damage{full: true}) | |
| 145 | + | select { | |
| 146 | + | case c := <-contents: | |
| 147 | + | if c.Seq != 2 { | |
| 148 | + | t.Fatalf("stale frame %d forwarded, want 2", c.Seq) | |
| 149 | + | } | |
| 150 | + | case <-time.After(2 * time.Second): | |
| 151 | + | t.Fatal("no frame forwarded") | |
| 152 | + | } | |
| 153 | + | } | |
| @@ -0,0 +1,153 @@ | |||||
| 1 | + | package wayland | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "context" | |||
| 5 | + | "testing" | |||
| 6 | + | "time" | |||
| 7 | + | ||||
| 8 | + | "github.com/bnema/neferwl/internal/ports" | |||
| 9 | + | "github.com/stretchr/testify/mock" | |||
| 10 | + | ) | |||
| 11 | + | ||||
| 12 | + | // The steady-state hot paths that run for every frame or commit allocate | |||
| 13 | + | // nothing (or one pooled object per damage-history generation). | |||
| 14 | + | ||||
| 15 | + | func TestReleaseHeldAllocations(t *testing.T) { | |||
| 16 | + | out := &output{place: ports.OutputPlacement{Info: ports.OutputInfo{Name: "DP-2", RefreshMilli: 60000}}} | |||
| 17 | + | s := &Server{outputs: []*output{out}, reports: map[string]ports.OutputPresented{}} | |||
| 18 | + | reports := []ports.OutputPresented{{Output: "DP-2", Seen: map[ports.WindowID]uint64{1: 1}}} | |||
| 19 | + | now := time.Unix(100, 0) | |||
| 20 | + | s.releaseHeld(now, reports) | |||
| 21 | + | if allocs := testing.AllocsPerRun(100, func() { s.releaseHeld(now, reports) }); allocs != 0 { | |||
| 22 | + | t.Errorf("releaseHeld: %.1f allocs, want 0", allocs) | |||
| 23 | + | } | |||
| 24 | + | } | |||
| 25 | + | ||||
| 26 | + | func TestCommitDamageAllocations(t *testing.T) { | |||
| 27 | + | srv := &Server{fifoSurfaces: map[*surface]struct{}{}, frameReady: make(chan struct{}, 1)} | |||
| 28 | + | surf := &surface{server: srv} | |||
| 29 | + | commit := func() { | |||
| 30 | + | surf.Damage(nil, 0, 0, 4, 4) | |||
| 31 | + | surf.DamageBuffer(nil, 1, 1, 2, 2) | |||
| 32 | + | surf.queueUpdate() | |||
| 33 | + | surf.queue[0].applyGraph() | |||
| 34 | + | } | |||
| 35 | + | commit() | |||
| 36 | + | if allocs := testing.AllocsPerRun(100, commit); allocs != 0 { | |||
| 37 | + | t.Errorf("damage requests + queueUpdate + apply: %.1f allocs, want 0", allocs) | |||
| 38 | + | } | |||
| 39 | + | // The queued update keeps its rects while the next commit collects its own. | |||
| 40 | + | surf.Damage(nil, 0, 0, 1, 1) | |||
| 41 | + | surf.queueUpdate() | |||
| 42 | + | first := surf.queue[0] | |||
| 43 | + | surf.Damage(nil, 5, 5, 2, 2) | |||
| 44 | + | if len(first.damage) != 1 || first.damage[0].W != 1 || len(surf.next.damage) != 1 || surf.next.damage[0].W != 2 { | |||
| 45 | + | t.Fatalf("damage shared between commits: queued %v pending %v", first.damage, surf.next.damage) | |||
| 46 | + | } | |||
| 47 | + | surf.queueUpdate() | |||
| 48 | + | if second := surf.queue[1]; len(second.damage) != 1 || second.damage[0].W != 2 || first.damage[0].W != 1 { | |||
| 49 | + | t.Fatalf("damage mixed up: %v %v", first.damage, second.damage) | |||
| 50 | + | } | |||
| 51 | + | } | |||
| 52 | + | ||||
| 53 | + | // An explicit-sync commit moves its points into the update: the commit | |||
| 54 | + | // itself allocates no commitSync, and a pending one is not overwritten. | |||
| 55 | + | func TestCommitSyncStorageIsPerUpdate(t *testing.T) { | |||
| 56 | + | dev := newMocksyncobjDevice(t) | |||
| 57 | + | dev.EXPECT().signalled(mock.Anything, mock.Anything).Return(true, nil) | |||
| 58 | + | srv := &Server{fifoSurfaces: map[*surface]struct{}{}, frameReady: make(chan struct{}, 1)} | |||
| 59 | + | sw, err := newSyncWaiter(func() {}) | |||
| 60 | + | if err != nil { | |||
| 61 | + | t.Fatal(err) | |||
| 62 | + | } | |||
| 63 | + | defer sw.pipeR.Close() | |||
| 64 | + | defer sw.close() | |||
| 65 | + | srv.syncWait = sw | |||
| 66 | + | tl := &timeline{dev: dev, handle: 7, alive: true} | |||
| 67 | + | surf := &surface{server: srv, sync: &syncState{}} | |||
| 68 | + | take := func(point uint64) { | |||
| 69 | + | surf.sync.acquire, surf.sync.release = syncPoint{tl: tl, point: point}, syncPoint{tl: tl, point: point + 1} | |||
| 70 | + | surf.takeSyncPoints() | |||
| 71 | + | surf.queueUpdate() | |||
| 72 | + | } | |||
| 73 | + | take(10) | |||
| 74 | + | take(20) | |||
| 75 | + | a, b := surf.queue[0], surf.queue[1] | |||
| 76 | + | if a.sync == nil || b.sync == nil || a.sync == b.sync || a.sync.acquire.point != 10 || b.sync.acquire.point != 20 || surf.next.sync != nil { | |||
| 77 | + | t.Fatalf("sync points mixed up: %+v %+v pending %+v", a.sync, b.sync, surf.next.sync) | |||
| 78 | + | } | |||
| 79 | + | // The commit's points live in the surface until queueUpdate: no heap | |||
| 80 | + | // commitSync per commit (the mocked device's own allocations would drown | |||
| 81 | + | // an AllocsPerRun count here). | |||
| 82 | + | surf.sync.acquire, surf.sync.release = syncPoint{tl: tl, point: 30}, syncPoint{tl: tl, point: 31} | |||
| 83 | + | surf.takeSyncPoints() | |||
| 84 | + | if surf.next.sync != &surf.syncScratch { | |||
| 85 | + | t.Fatal("commit points not held in the surface scratch") | |||
| 86 | + | } | |||
| 87 | + | } | |||
| 88 | + | ||||
| 89 | + | func TestEmitContentAllocations(t *testing.T) { | |||
| 90 | + | s := &Server{ | |||
| 91 | + | channels: Channels{Contents: make(chan ports.SurfaceContent)}, | |||
| 92 | + | contents: map[ports.WindowID]ports.SurfaceContent{}, | |||
| 93 | + | contentSeq: map[ports.WindowID]uint64{}, | |||
| 94 | + | damage: map[ports.WindowID][]ports.SeqDamage{}, | |||
| 95 | + | contentReady: make(chan struct{}, 1), | |||
| 96 | + | } | |||
| 97 | + | c := ports.SurfaceContent{ID: 1, Solid: &ports.SolidColor{}} | |||
| 98 | + | var held []ports.SurfaceContent // readers retaining published histories | |||
| 99 | + | var snapshots [][]ports.SeqDamage | |||
| 100 | + | for range 3 * damageHistoryCap { | |||
| 101 | + | s.emitContent(c, damage{full: true}) | |||
| 102 | + | got := s.contents[1] | |||
| 103 | + | held = append(held, got) | |||
| 104 | + | snapshots = append(snapshots, append([]ports.SeqDamage(nil), got.DamageHistory...)) | |||
| 105 | + | } | |||
| 106 | + | for i, h := range held { | |||
| 107 | + | // A published history never changes, nor can its owner append to it. | |||
| 108 | + | if len(h.DamageHistory) != len(snapshots[i]) || cap(h.DamageHistory) != len(h.DamageHistory) { | |||
| 109 | + | t.Fatalf("history %d: len %d cap %d", i, len(h.DamageHistory), cap(h.DamageHistory)) | |||
| 110 | + | } | |||
| 111 | + | for j, d := range h.DamageHistory { | |||
| 112 | + | if d.Seq != snapshots[i][j].Seq || d.Full != snapshots[i][j].Full { | |||
| 113 | + | t.Fatalf("history %d changed at %d: %+v want %+v", i, j, d, snapshots[i][j]) | |||
| 114 | + | } | |||
| 115 | + | } | |||
| 116 | + | if n := len(h.DamageHistory); h.DamageHistory[n-1].Seq != h.Seq || n > damageHistory { | |||
| 117 | + | t.Fatalf("history %d: %+v", i, h.DamageHistory) | |||
| 118 | + | } | |||
| 119 | + | } | |||
| 120 | + | allocs := testing.AllocsPerRun(100, func() { s.emitContent(c, damage{full: true}) }) | |||
| 121 | + | if allocs != 0 { | |||
| 122 | + | t.Errorf("emitContent: %.2f allocs, want 0 (amortized)", allocs) | |||
| 123 | + | } | |||
| 124 | + | t.Logf("emitContent: %.2f allocs", allocs) | |||
| 125 | + | } | |||
| 126 | + | ||||
| 127 | + | // A forwarder blocked on a stale frame is woken by the next publication | |||
| 128 | + | // and sends the newer frame instead. | |||
| 129 | + | func TestForwardContentsSendsNewerFrame(t *testing.T) { | |||
| 130 | + | contents := make(chan ports.SurfaceContent) | |||
| 131 | + | s := &Server{ | |||
| 132 | + | channels: Channels{Contents: contents}, | |||
| 133 | + | contents: map[ports.WindowID]ports.SurfaceContent{}, | |||
| 134 | + | contentSeq: map[ports.WindowID]uint64{}, | |||
| 135 | + | damage: map[ports.WindowID][]ports.SeqDamage{}, | |||
| 136 | + | contentReady: make(chan struct{}, 1), | |||
| 137 | + | } | |||
| 138 | + | ctx, cancel := context.WithCancel(context.Background()) | |||
| 139 | + | done := make(chan struct{}) | |||
| 140 | + | go func() { defer close(done); s.forwardContents(ctx) }() | |||
| 141 | + | defer func() { cancel(); <-done }() | |||
| 142 | + | s.emitContent(ports.SurfaceContent{ID: 1, Seq: 1, Solid: &ports.SolidColor{}}, damage{full: true}) | |||
| 143 | + | time.Sleep(10 * time.Millisecond) // let the forwarder block on seq 1 | |||
| 144 | + | s.emitContent(ports.SurfaceContent{ID: 1, Seq: 2, Solid: &ports.SolidColor{}}, damage{full: true}) | |||
| 145 | + | select { | |||
| 146 | + | case c := <-contents: | |||
| 147 | + | if c.Seq != 2 { | |||
| 148 | + | t.Fatalf("stale frame %d forwarded, want 2", c.Seq) | |||
| 149 | + | } | |||
| 150 | + | case <-time.After(2 * time.Second): | |||
| 151 | + | t.Fatal("no frame forwarded") | |||
| 152 | + | } | |||
| 153 | + | } | |||
M internal/adapters/wayland/fifo.go +28 -6
| @@ -209,6 +209,7 @@ type update struct { | |||
| 209 | 209 | deps []*update | |
| 210 | 210 | owner *surface | |
| 211 | 211 | implicit [4]*syncWait | |
| 212 | + | syncStore commitSync // storage of sync when the commit had explicit-sync points | |
| 212 | 213 | prev *update | |
| 213 | 214 | synced, bound bool | |
| 214 | 215 | xdg *xdgSurface | |
| @@ -237,8 +238,8 @@ var updatePool sync.Pool | |||
| 237 | 238 | func (u *update) releaseRef() { | |
| 238 | 239 | u.refs-- | |
| 239 | 240 | if u.refs == 0 && u.retired { | |
| 240 | - | deps := u.deps[:0] | |
| 241 | - | *u = update{deps: deps} | |
| 241 | + | deps, dmg, bufDmg := u.deps[:0], u.damage[:0], u.bufDamage[:0] | |
| 242 | + | *u = update{deps: deps, damage: dmg, bufDamage: bufDmg} | |
| 242 | 243 | updatePool.Put(u) | |
| 243 | 244 | } | |
| 244 | 245 | } | |
| @@ -257,7 +258,7 @@ func (u *update) retireUpdate() { | |||
| 257 | 258 | dep.releaseRef() | |
| 258 | 259 | } | |
| 259 | 260 | if u.refs == 0 { | |
| 260 | - | *u = update{deps: u.deps} | |
| 261 | + | *u = update{deps: u.deps, damage: u.damage[:0], bufDamage: u.bufDamage[:0]} | |
| 261 | 262 | updatePool.Put(u) | |
| 262 | 263 | } | |
| 263 | 264 | } | |
| @@ -346,9 +347,19 @@ func (s *surface) queueUpdate() { | |||
| 346 | 347 | if u == nil { | |
| 347 | 348 | u = new(update) | |
| 348 | 349 | } | |
| 349 | - | deps := u.deps[:0] | |
| 350 | + | deps, dmg, bufDmg := u.deps[:0], u.damage[:0], u.bufDamage[:0] | |
| 350 | 351 | *u = s.takePending() | |
| 351 | 352 | u.deps = deps | |
| 353 | + | // The pooled update brings the capacity a retired commit's damage had; | |
| 354 | + | // the surface collects the next commit's rects in it. The update keeps | |
| 355 | + | // the rects of this commit until it retires. | |
| 356 | + | s.next.damage, s.next.bufDamage = dmg, bufDmg | |
| 357 | + | if u.sync != nil && u.sync == &s.syncScratch { | |
| 358 | + | // The update owns its points from here: the surface's scratch is | |
| 359 | + | // free for the next commit while this one waits in the queue. | |
| 360 | + | u.syncStore, s.syncScratch = s.syncScratch, commitSync{} | |
| 361 | + | u.sync = &u.syncStore | |
| 362 | + | } | |
| 352 | 363 | u.owner, u.synced = s, s.effectivelySynced() | |
| 353 | 364 | if s.server.syncWait != nil && u.attached && u.buffer != nil && u.sync == nil { | |
| 354 | 365 | if b, ok := s.server.buffers[u.buffer.Resource].(*dmabufBuffer); ok { | |
| @@ -377,7 +388,6 @@ func (s *surface) queueUpdate() { | |||
| 377 | 388 | } | |
| 378 | 389 | s.queue = append(s.queue, u) | |
| 379 | 390 | s.server.fifoSurfaces[s] = struct{}{} | |
| 380 | - | s.server.wakePacer() | |
| 381 | 391 | } | |
| 382 | 392 | ||
| 383 | 393 | // applyUpdate applies only the captured commit; later requests remain pending. | |
| @@ -745,8 +755,20 @@ func sameBuffer(a, b *wayland.Buffer) bool { | |||
| 745 | 755 | return a != nil && b != nil && a.Resource == b.Resource | |
| 746 | 756 | } | |
| 747 | 757 | ||
| 748 | - | // wakePacer makes the pacer look at its queues now. | |
| 758 | + | // wakePacer makes the pacer look at its queues. Display goroutine only. | |
| 759 | + | // While a commit or a tick runs (paceDepth) it only records the request: the | |
| 760 | + | // outermost caller then ticks inline (paceNow), saving the round trip of | |
| 761 | + | // waking the pacer goroutine just so that it calls Do back. | |
| 749 | 762 | func (s *Server) wakePacer() { | |
| 763 | + | if s.paceDepth > 0 { | |
| 764 | + | s.paceDirty = true | |
| 765 | + | return | |
| 766 | + | } | |
| 767 | + | s.signalPacer() | |
| 768 | + | } | |
| 769 | + | ||
| 770 | + | // signalPacer wakes the pacer goroutine; safe from any goroutine. | |
| 771 | + | func (s *Server) signalPacer() { | |
| 750 | 772 | select { | |
| 751 | 773 | case s.frameReady <- struct{}{}: | |
| 752 | 774 | default: | |
| @@ -209,6 +209,7 @@ type update struct { | |||||
| 209 | deps []*update | 209 | deps []*update | ||
| 210 | owner *surface | 210 | owner *surface | ||
| 211 | implicit [4]*syncWait | 211 | implicit [4]*syncWait | ||
| 212 | + | syncStore commitSync // storage of sync when the commit had explicit-sync points | |||
| 212 | prev *update | 213 | prev *update | ||
| 213 | synced, bound bool | 214 | synced, bound bool | ||
| 214 | xdg *xdgSurface | 215 | xdg *xdgSurface | ||
| @@ -237,8 +238,8 @@ var updatePool sync.Pool | |||||
| 237 | func (u *update) releaseRef() { | 238 | func (u *update) releaseRef() { | ||
| 238 | u.refs-- | 239 | u.refs-- | ||
| 239 | if u.refs == 0 && u.retired { | 240 | if u.refs == 0 && u.retired { | ||
| 240 | - | deps := u.deps[:0] | 241 | + | deps, dmg, bufDmg := u.deps[:0], u.damage[:0], u.bufDamage[:0] |
| 241 | - | *u = update{deps: deps} | 242 | + | *u = update{deps: deps, damage: dmg, bufDamage: bufDmg} |
| 242 | updatePool.Put(u) | 243 | updatePool.Put(u) | ||
| 243 | } | 244 | } | ||
| 244 | } | 245 | } | ||
| @@ -257,7 +258,7 @@ func (u *update) retireUpdate() { | |||||
| 257 | dep.releaseRef() | 258 | dep.releaseRef() | ||
| 258 | } | 259 | } | ||
| 259 | if u.refs == 0 { | 260 | if u.refs == 0 { | ||
| 260 | - | *u = update{deps: u.deps} | 261 | + | *u = update{deps: u.deps, damage: u.damage[:0], bufDamage: u.bufDamage[:0]} |
| 261 | updatePool.Put(u) | 262 | updatePool.Put(u) | ||
| 262 | } | 263 | } | ||
| 263 | } | 264 | } | ||
| @@ -346,9 +347,19 @@ func (s *surface) queueUpdate() { | |||||
| 346 | if u == nil { | 347 | if u == nil { | ||
| 347 | u = new(update) | 348 | u = new(update) | ||
| 348 | } | 349 | } | ||
| 349 | - | deps := u.deps[:0] | 350 | + | deps, dmg, bufDmg := u.deps[:0], u.damage[:0], u.bufDamage[:0] |
| 350 | *u = s.takePending() | 351 | *u = s.takePending() | ||
| 351 | u.deps = deps | 352 | u.deps = deps | ||
| 353 | + | // The pooled update brings the capacity a retired commit's damage had; | |||
| 354 | + | // the surface collects the next commit's rects in it. The update keeps | |||
| 355 | + | // the rects of this commit until it retires. | |||
| 356 | + | s.next.damage, s.next.bufDamage = dmg, bufDmg | |||
| 357 | + | if u.sync != nil && u.sync == &s.syncScratch { | |||
| 358 | + | // The update owns its points from here: the surface's scratch is | |||
| 359 | + | // free for the next commit while this one waits in the queue. | |||
| 360 | + | u.syncStore, s.syncScratch = s.syncScratch, commitSync{} | |||
| 361 | + | u.sync = &u.syncStore | |||
| 362 | + | } | |||
| 352 | u.owner, u.synced = s, s.effectivelySynced() | 363 | u.owner, u.synced = s, s.effectivelySynced() | ||
| 353 | if s.server.syncWait != nil && u.attached && u.buffer != nil && u.sync == nil { | 364 | if s.server.syncWait != nil && u.attached && u.buffer != nil && u.sync == nil { | ||
| 354 | if b, ok := s.server.buffers[u.buffer.Resource].(*dmabufBuffer); ok { | 365 | if b, ok := s.server.buffers[u.buffer.Resource].(*dmabufBuffer); ok { | ||
| @@ -377,7 +388,6 @@ func (s *surface) queueUpdate() { | |||||
| 377 | } | 388 | } | ||
| 378 | s.queue = append(s.queue, u) | 389 | s.queue = append(s.queue, u) | ||
| 379 | s.server.fifoSurfaces[s] = struct{}{} | 390 | s.server.fifoSurfaces[s] = struct{}{} | ||
| 380 | - | s.server.wakePacer() | |||
| 381 | } | 391 | } | ||
| 382 | 392 | ||||
| 383 | // applyUpdate applies only the captured commit; later requests remain pending. | 393 | // applyUpdate applies only the captured commit; later requests remain pending. | ||
| @@ -745,8 +755,20 @@ func sameBuffer(a, b *wayland.Buffer) bool { | |||||
| 745 | return a != nil && b != nil && a.Resource == b.Resource | 755 | return a != nil && b != nil && a.Resource == b.Resource | ||
| 746 | } | 756 | } | ||
| 747 | 757 | ||||
| 748 | - | // wakePacer makes the pacer look at its queues now. | 758 | + | // wakePacer makes the pacer look at its queues. Display goroutine only. |
| 759 | + | // While a commit or a tick runs (paceDepth) it only records the request: the | |||
| 760 | + | // outermost caller then ticks inline (paceNow), saving the round trip of | |||
| 761 | + | // waking the pacer goroutine just so that it calls Do back. | |||
| 749 | func (s *Server) wakePacer() { | 762 | func (s *Server) wakePacer() { | ||
| 763 | + | if s.paceDepth > 0 { | |||
| 764 | + | s.paceDirty = true | |||
| 765 | + | return | |||
| 766 | + | } | |||
| 767 | + | s.signalPacer() | |||
| 768 | + | } | |||
| 769 | + | ||||
| 770 | + | // signalPacer wakes the pacer goroutine; safe from any goroutine. | |||
| 771 | + | func (s *Server) signalPacer() { | |||
| 750 | select { | 772 | select { | ||
| 751 | case s.frameReady <- struct{}{}: | 773 | case s.frameReady <- struct{}{}: | ||
| 752 | default: | 774 | default: | ||
M internal/adapters/wayland/frames.go +96 -44
| @@ -24,14 +24,23 @@ const defaultFramePeriod = time.Second / 60 | |||
| 24 | 24 | const suspendedFramePeriod = time.Second | |
| 25 | 25 | const suspendedFrameQueue = "\x00suspended" // never a wl_output name | |
| 26 | 26 | ||
| 27 | - | // pace fires the due frame callbacks on page flips and deadlines. | |
| 27 | + | // maxPacePasses bounds the passes one tick repeats while a pass queues | |
| 28 | + | // more work; the rest goes back to the pacer goroutine. | |
| 29 | + | const maxPacePasses = 3 | |
| 30 | + | ||
| 31 | + | // pace sleeps until a flip, a wake or the deadline armed by the last tick, | |
| 32 | + | // then runs a tick on the display goroutine. The timer is only armed from | |
| 33 | + | // ticks, which all run there, so a commit that ticks inline (paceNow) never | |
| 34 | + | // races the pacer for it. | |
| 28 | 35 | func (s *Server) pace(ctx context.Context) { | |
| 29 | - | timer := time.NewTimer(defaultFramePeriod) | |
| 36 | + | timer := s.paceTimer // created by Run before the pacer starts | |
| 30 | 37 | defer timer.Stop() | |
| 31 | 38 | presented := s.channels.Presented | |
| 32 | 39 | if s.flipped == nil { | |
| 33 | 40 | s.flipped = make(map[string]bool) | |
| 34 | 41 | } | |
| 42 | + | // One method value for the whole loop: no closure per wake. | |
| 43 | + | tick := s.paceFromPacer | |
| 35 | 44 | for { | |
| 36 | 45 | clear(s.flipped) | |
| 37 | 46 | flipped := s.flipped | |
| @@ -61,52 +70,95 @@ func (s *Server) pace(ctx context.Context) { | |||
| 61 | 70 | } | |
| 62 | 71 | } | |
| 63 | 72 | s.frameReports = reports | |
| 64 | - | wait, idle := defaultFramePeriod, false | |
| 65 | - | if !s.display.Do(func() { | |
| 66 | - | if ctx.Err() == nil { | |
| 67 | - | // Each flip answers its own presentation feedbacks, in | |
| 68 | - | // order: flips are never merged here. | |
| 69 | - | for _, p := range reports { | |
| 70 | - | if p.Flip != nil { | |
| 71 | - | s.flips[p.Output] = *p.Flip | |
| 72 | - | s.presentFlip(p.Output, p.Flip) | |
| 73 | - | } | |
| 74 | - | } | |
| 75 | - | s.dropFeedbacks(time.Now()) | |
| 76 | - | if len(s.feedbacks) > 0 { | |
| 77 | - | wait = feedbackTimeout | |
| 78 | - | } | |
| 79 | - | var due []string | |
| 80 | - | var dueWait time.Duration | |
| 81 | - | due, dueWait, idle = s.dueFrames(time.Now(), flipped) | |
| 82 | - | if len(s.feedbacks) > 0 { | |
| 83 | - | // Unanswered feedbacks time out: keep ticking. | |
| 84 | - | dueWait, idle = min(dueWait, feedbackTimeout), false | |
| 85 | - | } | |
| 86 | - | wait = dueWait | |
| 87 | - | for _, name := range due { | |
| 88 | - | s.sendFrames(name, flipped[name]) | |
| 89 | - | } | |
| 90 | - | if s.releaseHeld(time.Now(), reports) && idle { | |
| 91 | - | // Held buffers wait for a flip or heldTimeout. | |
| 92 | - | wait, idle = heldTimeout, false | |
| 93 | - | } | |
| 94 | - | // Fifo barriers and queued commits wait for a refresh. | |
| 95 | - | if fw, waiting := s.tickFifo(time.Now(), flipped); waiting { | |
| 96 | - | wait, idle = min(wait, fw), false | |
| 97 | - | } | |
| 98 | - | } | |
| 99 | - | }) { | |
| 73 | + | if !s.display.Do(tick) { | |
| 100 | 74 | return | |
| 101 | 75 | } | |
| 102 | - | if idle { | |
| 103 | - | // Nothing waits: sleep until a commit queues a callback | |
| 104 | - | // (frameReady) or a flip. | |
| 105 | - | timer.Stop() | |
| 106 | - | continue | |
| 76 | + | } | |
| 77 | + | } | |
| 78 | + | ||
| 79 | + | // paceFromPacer runs the pacer's collected flips (flipped, frameReports) | |
| 80 | + | // on the display goroutine. | |
| 81 | + | func (s *Server) paceFromPacer() { s.paceTick(s.flipped, s.frameReports) } | |
| 82 | + | ||
| 83 | + | // paceNow runs a tick from code already on the display goroutine (a client | |
| 84 | + | // commit): the pacer goroutine would only call Do to get back here. Without | |
| 85 | + | // a running pacer (no timer) it falls back to waking it. | |
| 86 | + | func (s *Server) paceNow() { | |
| 87 | + | if s.paceTimer == nil { | |
| 88 | + | s.signalPacer() | |
| 89 | + | return | |
| 90 | + | } | |
| 91 | + | s.paceTick(nil, nil) | |
| 92 | + | } | |
| 93 | + | ||
| 94 | + | // paceTick answers the flips in reports, fires the due frame callbacks, | |
| 95 | + | // releases buffers and applies the ready FIFO commits, then arms the timer | |
| 96 | + | // for the next deadline (stopped when nothing waits). Display goroutine only. | |
| 97 | + | func (s *Server) paceTick(flipped map[string]bool, reports []ports.OutputPresented) { | |
| 98 | + | if s.ctx != nil && s.ctx.Err() != nil { | |
| 99 | + | return | |
| 100 | + | } | |
| 101 | + | wait, idle := defaultFramePeriod, false | |
| 102 | + | for pass := 0; ; pass++ { | |
| 103 | + | s.paceDirty = false | |
| 104 | + | s.paceDepth++ | |
| 105 | + | wait, idle = s.pacePass(flipped, reports) | |
| 106 | + | s.paceDepth-- | |
| 107 | + | if !s.paceDirty { | |
| 108 | + | break | |
| 107 | 109 | } | |
| 108 | - | timer.Reset(wait) | |
| 110 | + | // The pass queued work behind its own checks (applied commits | |
| 111 | + | // queue callbacks, released buffers): look again, as a flip-less | |
| 112 | + | // tick, instead of waking the pacer for it. | |
| 113 | + | flipped, reports = nil, nil | |
| 114 | + | if pass+1 == maxPacePasses { | |
| 115 | + | s.paceDirty = false | |
| 116 | + | s.signalPacer() | |
| 117 | + | break | |
| 118 | + | } | |
| 119 | + | } | |
| 120 | + | if s.paceTimer == nil { | |
| 121 | + | return | |
| 122 | + | } | |
| 123 | + | if idle { | |
| 124 | + | // Nothing waits: sleep until a commit queues a callback | |
| 125 | + | // (wakePacer) or a flip. | |
| 126 | + | s.paceTimer.Stop() | |
| 127 | + | return | |
| 128 | + | } | |
| 129 | + | s.paceTimer.Reset(wait) | |
| 130 | + | } | |
| 131 | + | ||
| 132 | + | // pacePass is one pass of paceTick; it returns the time to the next | |
| 133 | + | // deadline and whether nothing waits. | |
| 134 | + | func (s *Server) pacePass(flipped map[string]bool, reports []ports.OutputPresented) (wait time.Duration, idle bool) { | |
| 135 | + | // Each flip answers its own presentation feedbacks, in order: flips | |
| 136 | + | // are never merged here. | |
| 137 | + | for _, p := range reports { | |
| 138 | + | if p.Flip != nil { | |
| 139 | + | s.flips[p.Output] = *p.Flip | |
| 140 | + | s.presentFlip(p.Output, p.Flip) | |
| 141 | + | } | |
| 142 | + | } | |
| 143 | + | s.dropFeedbacks(time.Now()) | |
| 144 | + | var due []string | |
| 145 | + | due, wait, idle = s.dueFrames(time.Now(), flipped) | |
| 146 | + | if len(s.feedbacks) > 0 { | |
| 147 | + | // Unanswered feedbacks time out: keep ticking. | |
| 148 | + | wait, idle = min(wait, feedbackTimeout), false | |
| 149 | + | } | |
| 150 | + | for _, name := range due { | |
| 151 | + | s.sendFrames(name, flipped[name]) | |
| 152 | + | } | |
| 153 | + | if s.releaseHeld(time.Now(), reports) && idle { | |
| 154 | + | // Held buffers wait for a flip or heldTimeout. | |
| 155 | + | wait, idle = heldTimeout, false | |
| 156 | + | } | |
| 157 | + | // Fifo barriers and queued commits wait for a refresh. | |
| 158 | + | if fw, waiting := s.tickFifo(time.Now(), flipped); waiting { | |
| 159 | + | wait, idle = min(wait, fw), false | |
| 109 | 160 | } | |
| 161 | + | return wait, idle | |
| 110 | 162 | } | |
| 111 | 163 | ||
| 112 | 164 | // toplevelRoot resolves subsurfaces and popups to their parent toplevel. | |
| @@ -24,14 +24,23 @@ const defaultFramePeriod = time.Second / 60 | |||||
| 24 | const suspendedFramePeriod = time.Second | 24 | const suspendedFramePeriod = time.Second | ||
| 25 | const suspendedFrameQueue = "\x00suspended" // never a wl_output name | 25 | const suspendedFrameQueue = "\x00suspended" // never a wl_output name | ||
| 26 | 26 | ||||
| 27 | - | // pace fires the due frame callbacks on page flips and deadlines. | 27 | + | // maxPacePasses bounds the passes one tick repeats while a pass queues |
| 28 | + | // more work; the rest goes back to the pacer goroutine. | |||
| 29 | + | const maxPacePasses = 3 | |||
| 30 | + | ||||
| 31 | + | // pace sleeps until a flip, a wake or the deadline armed by the last tick, | |||
| 32 | + | // then runs a tick on the display goroutine. The timer is only armed from | |||
| 33 | + | // ticks, which all run there, so a commit that ticks inline (paceNow) never | |||
| 34 | + | // races the pacer for it. | |||
| 28 | func (s *Server) pace(ctx context.Context) { | 35 | func (s *Server) pace(ctx context.Context) { | ||
| 29 | - | timer := time.NewTimer(defaultFramePeriod) | 36 | + | timer := s.paceTimer // created by Run before the pacer starts |
| 30 | defer timer.Stop() | 37 | defer timer.Stop() | ||
| 31 | presented := s.channels.Presented | 38 | presented := s.channels.Presented | ||
| 32 | if s.flipped == nil { | 39 | if s.flipped == nil { | ||
| 33 | s.flipped = make(map[string]bool) | 40 | s.flipped = make(map[string]bool) | ||
| 34 | } | 41 | } | ||
| 42 | + | // One method value for the whole loop: no closure per wake. | |||
| 43 | + | tick := s.paceFromPacer | |||
| 35 | for { | 44 | for { | ||
| 36 | clear(s.flipped) | 45 | clear(s.flipped) | ||
| 37 | flipped := s.flipped | 46 | flipped := s.flipped | ||
| @@ -61,52 +70,95 @@ func (s *Server) pace(ctx context.Context) { | |||||
| 61 | } | 70 | } | ||
| 62 | } | 71 | } | ||
| 63 | s.frameReports = reports | 72 | s.frameReports = reports | ||
| 64 | - | wait, idle := defaultFramePeriod, false | 73 | + | if !s.display.Do(tick) { |
| 65 | - | if !s.display.Do(func() { | |||
| 66 | - | if ctx.Err() == nil { | |||
| 67 | - | // Each flip answers its own presentation feedbacks, in | |||
| 68 | - | // order: flips are never merged here. | |||
| 69 | - | for _, p := range reports { | |||
| 70 | - | if p.Flip != nil { | |||
| 71 | - | s.flips[p.Output] = *p.Flip | |||
| 72 | - | s.presentFlip(p.Output, p.Flip) | |||
| 73 | - | } | |||
| 74 | - | } | |||
| 75 | - | s.dropFeedbacks(time.Now()) | |||
| 76 | - | if len(s.feedbacks) > 0 { | |||
| 77 | - | wait = feedbackTimeout | |||
| 78 | - | } | |||
| 79 | - | var due []string | |||
| 80 | - | var dueWait time.Duration | |||
| 81 | - | due, dueWait, idle = s.dueFrames(time.Now(), flipped) | |||
| 82 | - | if len(s.feedbacks) > 0 { | |||
| 83 | - | // Unanswered feedbacks time out: keep ticking. | |||
| 84 | - | dueWait, idle = min(dueWait, feedbackTimeout), false | |||
| 85 | - | } | |||
| 86 | - | wait = dueWait | |||
| 87 | - | for _, name := range due { | |||
| 88 | - | s.sendFrames(name, flipped[name]) | |||
| 89 | - | } | |||
| 90 | - | if s.releaseHeld(time.Now(), reports) && idle { | |||
| 91 | - | // Held buffers wait for a flip or heldTimeout. | |||
| 92 | - | wait, idle = heldTimeout, false | |||
| 93 | - | } | |||
| 94 | - | // Fifo barriers and queued commits wait for a refresh. | |||
| 95 | - | if fw, waiting := s.tickFifo(time.Now(), flipped); waiting { | |||
| 96 | - | wait, idle = min(wait, fw), false | |||
| 97 | - | } | |||
| 98 | - | } | |||
| 99 | - | }) { | |||
| 100 | return | 74 | return | ||
| 101 | } | 75 | } | ||
| 102 | - | if idle { | 76 | + | } |
| 103 | - | // Nothing waits: sleep until a commit queues a callback | 77 | + | } |
| 104 | - | // (frameReady) or a flip. | 78 | + | |
| 105 | - | timer.Stop() | 79 | + | // paceFromPacer runs the pacer's collected flips (flipped, frameReports) |
| 106 | - | continue | 80 | + | // on the display goroutine. |
| 81 | + | func (s *Server) paceFromPacer() { s.paceTick(s.flipped, s.frameReports) } | |||
| 82 | + | ||||
| 83 | + | // paceNow runs a tick from code already on the display goroutine (a client | |||
| 84 | + | // commit): the pacer goroutine would only call Do to get back here. Without | |||
| 85 | + | // a running pacer (no timer) it falls back to waking it. | |||
| 86 | + | func (s *Server) paceNow() { | |||
| 87 | + | if s.paceTimer == nil { | |||
| 88 | + | s.signalPacer() | |||
| 89 | + | return | |||
| 90 | + | } | |||
| 91 | + | s.paceTick(nil, nil) | |||
| 92 | + | } | |||
| 93 | + | ||||
| 94 | + | // paceTick answers the flips in reports, fires the due frame callbacks, | |||
| 95 | + | // releases buffers and applies the ready FIFO commits, then arms the timer | |||
| 96 | + | // for the next deadline (stopped when nothing waits). Display goroutine only. | |||
| 97 | + | func (s *Server) paceTick(flipped map[string]bool, reports []ports.OutputPresented) { | |||
| 98 | + | if s.ctx != nil && s.ctx.Err() != nil { | |||
| 99 | + | return | |||
| 100 | + | } | |||
| 101 | + | wait, idle := defaultFramePeriod, false | |||
| 102 | + | for pass := 0; ; pass++ { | |||
| 103 | + | s.paceDirty = false | |||
| 104 | + | s.paceDepth++ | |||
| 105 | + | wait, idle = s.pacePass(flipped, reports) | |||
| 106 | + | s.paceDepth-- | |||
| 107 | + | if !s.paceDirty { | |||
| 108 | + | break | |||
| 107 | } | 109 | } | ||
| 108 | - | timer.Reset(wait) | 110 | + | // The pass queued work behind its own checks (applied commits |
| 111 | + | // queue callbacks, released buffers): look again, as a flip-less | |||
| 112 | + | // tick, instead of waking the pacer for it. | |||
| 113 | + | flipped, reports = nil, nil | |||
| 114 | + | if pass+1 == maxPacePasses { | |||
| 115 | + | s.paceDirty = false | |||
| 116 | + | s.signalPacer() | |||
| 117 | + | break | |||
| 118 | + | } | |||
| 119 | + | } | |||
| 120 | + | if s.paceTimer == nil { | |||
| 121 | + | return | |||
| 122 | + | } | |||
| 123 | + | if idle { | |||
| 124 | + | // Nothing waits: sleep until a commit queues a callback | |||
| 125 | + | // (wakePacer) or a flip. | |||
| 126 | + | s.paceTimer.Stop() | |||
| 127 | + | return | |||
| 128 | + | } | |||
| 129 | + | s.paceTimer.Reset(wait) | |||
| 130 | + | } | |||
| 131 | + | ||||
| 132 | + | // pacePass is one pass of paceTick; it returns the time to the next | |||
| 133 | + | // deadline and whether nothing waits. | |||
| 134 | + | func (s *Server) pacePass(flipped map[string]bool, reports []ports.OutputPresented) (wait time.Duration, idle bool) { | |||
| 135 | + | // Each flip answers its own presentation feedbacks, in order: flips | |||
| 136 | + | // are never merged here. | |||
| 137 | + | for _, p := range reports { | |||
| 138 | + | if p.Flip != nil { | |||
| 139 | + | s.flips[p.Output] = *p.Flip | |||
| 140 | + | s.presentFlip(p.Output, p.Flip) | |||
| 141 | + | } | |||
| 142 | + | } | |||
| 143 | + | s.dropFeedbacks(time.Now()) | |||
| 144 | + | var due []string | |||
| 145 | + | due, wait, idle = s.dueFrames(time.Now(), flipped) | |||
| 146 | + | if len(s.feedbacks) > 0 { | |||
| 147 | + | // Unanswered feedbacks time out: keep ticking. | |||
| 148 | + | wait, idle = min(wait, feedbackTimeout), false | |||
| 149 | + | } | |||
| 150 | + | for _, name := range due { | |||
| 151 | + | s.sendFrames(name, flipped[name]) | |||
| 152 | + | } | |||
| 153 | + | if s.releaseHeld(time.Now(), reports) && idle { | |||
| 154 | + | // Held buffers wait for a flip or heldTimeout. | |||
| 155 | + | wait, idle = heldTimeout, false | |||
| 156 | + | } | |||
| 157 | + | // Fifo barriers and queued commits wait for a refresh. | |||
| 158 | + | if fw, waiting := s.tickFifo(time.Now(), flipped); waiting { | |||
| 159 | + | wait, idle = min(wait, fw), false | |||
| 109 | } | 160 | } | ||
| 161 | + | return wait, idle | |||
| 110 | } | 162 | } | ||
| 111 | 163 | ||||
| 112 | // toplevelRoot resolves subsurfaces and popups to their parent toplevel. | 164 | // toplevelRoot resolves subsurfaces and popups to their parent toplevel. | ||
A internal/adapters/wayland/pace_inline_test.go +118 -0
| @@ -0,0 +1,118 @@ | |||
| 1 | + | package wayland | |
| 2 | + | ||
| 3 | + | import ( | |
| 4 | + | "testing" | |
| 5 | + | "time" | |
| 6 | + | ||
| 7 | + | "github.com/bnema/go-wayland-bindings/server/wayland" | |
| 8 | + | "github.com/bnema/neferwl/internal/ports" | |
| 9 | + | ) | |
| 10 | + | ||
| 11 | + | // paceFixture is a server whose surface waits on an output whose next | |
| 12 | + | // frame is an hour away: a commit queues its callback and nothing fires. | |
| 13 | + | func paceFixture(timer bool) (*Server, *surface) { | |
| 14 | + | out := &output{place: ports.OutputPlacement{Info: ports.OutputInfo{Name: "DP-2", RefreshMilli: 60000}}} | |
| 15 | + | s := &Server{ | |
| 16 | + | outputs: []*output{out}, | |
| 17 | + | awaiting: map[string][]*wayland.Callback{}, | |
| 18 | + | frameDue: map[string]time.Time{"DP-2": time.Now().Add(time.Hour)}, | |
| 19 | + | fifoSurfaces: map[*surface]struct{}{}, | |
| 20 | + | lastFlip: map[string]time.Time{}, | |
| 21 | + | flips: map[string]ports.FlipInfo{}, | |
| 22 | + | reports: map[string]ports.OutputPresented{}, | |
| 23 | + | frameReady: make(chan struct{}, 1), | |
| 24 | + | } | |
| 25 | + | if timer { | |
| 26 | + | s.paceTimer = time.NewTimer(time.Hour) | |
| 27 | + | s.paceTimer.Stop() | |
| 28 | + | } | |
| 29 | + | w := &window{hasLast: true, last: ports.ConfigureWindow{Output: "DP-2", Visible: true}} | |
| 30 | + | surf := &surface{server: s, xdg: &xdgSurface{window: w}} | |
| 31 | + | surf.next.callbacks = []*wayland.Callback{new(wayland.Callback)} | |
| 32 | + | return s, surf | |
| 33 | + | } | |
| 34 | + | ||
| 35 | + | // A commit on the display goroutine ticks the pacer inline: it arms the | |
| 36 | + | // pacer's timer itself and does not wake the pacer goroutine, which would | |
| 37 | + | // only call display.Do to get back to the display goroutine. | |
| 38 | + | func TestCommitTicksPacerInline(t *testing.T) { | |
| 39 | + | s, surf := paceFixture(true) | |
| 40 | + | surf.queueAndTick() | |
| 41 | + | if len(s.awaiting["DP-2"]) != 1 { | |
| 42 | + | t.Fatalf("callback not queued: %+v", s.awaiting) | |
| 43 | + | } | |
| 44 | + | if len(s.frameReady) != 0 { | |
| 45 | + | t.Fatal("commit woke the pacer goroutine") | |
| 46 | + | } | |
| 47 | + | waitArmed(t, s, "inline tick did not arm the pacer timer for the next deadline") | |
| 48 | + | if s.paceDepth != 0 || s.paceDirty { | |
| 49 | + | t.Fatalf("pace state leaked: depth %d dirty %v", s.paceDepth, s.paceDirty) | |
| 50 | + | } | |
| 51 | + | } | |
| 52 | + | ||
| 53 | + | // Without a running pacer (no timer) the wake falls back to the channel. | |
| 54 | + | func TestCommitWakesPacerWithoutTimer(t *testing.T) { | |
| 55 | + | s, surf := paceFixture(false) | |
| 56 | + | surf.queueAndTick() | |
| 57 | + | if len(s.frameReady) != 1 { | |
| 58 | + | t.Fatal("pacer not woken") | |
| 59 | + | } | |
| 60 | + | } | |
| 61 | + | ||
| 62 | + | // Wakes inside a tick coalesce into one more pass, not one channel wake each. | |
| 63 | + | func TestWakePacerDefersInsideTick(t *testing.T) { | |
| 64 | + | s, _ := paceFixture(true) | |
| 65 | + | s.paceDepth = 1 | |
| 66 | + | s.wakePacer() | |
| 67 | + | s.wakePacer() | |
| 68 | + | if len(s.frameReady) != 0 || !s.paceDirty { | |
| 69 | + | t.Fatalf("wake inside a tick: queued %d dirty %v", len(s.frameReady), s.paceDirty) | |
| 70 | + | } | |
| 71 | + | s.paceDepth = 0 | |
| 72 | + | s.wakePacer() | |
| 73 | + | if len(s.frameReady) != 1 { | |
| 74 | + | t.Fatal("wake outside a tick lost") | |
| 75 | + | } | |
| 76 | + | } | |
| 77 | + | ||
| 78 | + | // A commit that waits (a fifo barrier) is timed by the inline tick. | |
| 79 | + | func TestCommitWaitingOnBarrierArmsTimer(t *testing.T) { | |
| 80 | + | s, surf := paceFixture(true) | |
| 81 | + | surf.next.callbacks = nil | |
| 82 | + | surf.barrier, surf.barrierAt = true, time.Now() | |
| 83 | + | surf.next.wait = true | |
| 84 | + | surf.queueAndTick() | |
| 85 | + | if len(surf.queue) != 1 || len(s.frameReady) != 0 { | |
| 86 | + | t.Fatalf("queued %d, pacer wakes %d", len(surf.queue), len(s.frameReady)) | |
| 87 | + | } | |
| 88 | + | waitArmed(t, s, "timer not armed for the barrier deadline") | |
| 89 | + | } | |
| 90 | + | ||
| 91 | + | // waitArmed asserts the timer was armed: it is pending, or it already | |
| 92 | + | // fired and holds its value. | |
| 93 | + | func waitArmed(t *testing.T, s *Server, msg string) { | |
| 94 | + | t.Helper() | |
| 95 | + | if s.paceTimer.Stop() { | |
| 96 | + | return | |
| 97 | + | } | |
| 98 | + | select { | |
| 99 | + | case <-s.paceTimer.C: | |
| 100 | + | default: | |
| 101 | + | t.Fatal(msg) | |
| 102 | + | } | |
| 103 | + | } | |
| 104 | + | ||
| 105 | + | // A synchronized subsurface commit waits for its parent's commit: it does | |
| 106 | + | // not tick the pacer, so a burst of child commits costs no ticks. | |
| 107 | + | func TestSyncedCommitDoesNotTick(t *testing.T) { | |
| 108 | + | s, surf := paceFixture(true) | |
| 109 | + | surf.sub.parent = &surface{server: s} | |
| 110 | + | surf.sub.synced = true | |
| 111 | + | surf.queueAndTick() | |
| 112 | + | if len(surf.queue) != 1 || !surf.queue[0].synced { | |
| 113 | + | t.Fatalf("synced commit not queued: %d", len(surf.queue)) | |
| 114 | + | } | |
| 115 | + | if len(s.frameReady) != 0 || s.paceTimer.Stop() { | |
| 116 | + | t.Fatal("synced commit ticked the pacer") | |
| 117 | + | } | |
| 118 | + | } | |
| @@ -0,0 +1,118 @@ | |||||
| 1 | + | package wayland | |||
| 2 | + | ||||
| 3 | + | import ( | |||
| 4 | + | "testing" | |||
| 5 | + | "time" | |||
| 6 | + | ||||
| 7 | + | "github.com/bnema/go-wayland-bindings/server/wayland" | |||
| 8 | + | "github.com/bnema/neferwl/internal/ports" | |||
| 9 | + | ) | |||
| 10 | + | ||||
| 11 | + | // paceFixture is a server whose surface waits on an output whose next | |||
| 12 | + | // frame is an hour away: a commit queues its callback and nothing fires. | |||
| 13 | + | func paceFixture(timer bool) (*Server, *surface) { | |||
| 14 | + | out := &output{place: ports.OutputPlacement{Info: ports.OutputInfo{Name: "DP-2", RefreshMilli: 60000}}} | |||
| 15 | + | s := &Server{ | |||
| 16 | + | outputs: []*output{out}, | |||
| 17 | + | awaiting: map[string][]*wayland.Callback{}, | |||
| 18 | + | frameDue: map[string]time.Time{"DP-2": time.Now().Add(time.Hour)}, | |||
| 19 | + | fifoSurfaces: map[*surface]struct{}{}, | |||
| 20 | + | lastFlip: map[string]time.Time{}, | |||
| 21 | + | flips: map[string]ports.FlipInfo{}, | |||
| 22 | + | reports: map[string]ports.OutputPresented{}, | |||
| 23 | + | frameReady: make(chan struct{}, 1), | |||
| 24 | + | } | |||
| 25 | + | if timer { | |||
| 26 | + | s.paceTimer = time.NewTimer(time.Hour) | |||
| 27 | + | s.paceTimer.Stop() | |||
| 28 | + | } | |||
| 29 | + | w := &window{hasLast: true, last: ports.ConfigureWindow{Output: "DP-2", Visible: true}} | |||
| 30 | + | surf := &surface{server: s, xdg: &xdgSurface{window: w}} | |||
| 31 | + | surf.next.callbacks = []*wayland.Callback{new(wayland.Callback)} | |||
| 32 | + | return s, surf | |||
| 33 | + | } | |||
| 34 | + | ||||
| 35 | + | // A commit on the display goroutine ticks the pacer inline: it arms the | |||
| 36 | + | // pacer's timer itself and does not wake the pacer goroutine, which would | |||
| 37 | + | // only call display.Do to get back to the display goroutine. | |||
| 38 | + | func TestCommitTicksPacerInline(t *testing.T) { | |||
| 39 | + | s, surf := paceFixture(true) | |||
| 40 | + | surf.queueAndTick() | |||
| 41 | + | if len(s.awaiting["DP-2"]) != 1 { | |||
| 42 | + | t.Fatalf("callback not queued: %+v", s.awaiting) | |||
| 43 | + | } | |||
| 44 | + | if len(s.frameReady) != 0 { | |||
| 45 | + | t.Fatal("commit woke the pacer goroutine") | |||
| 46 | + | } | |||
| 47 | + | waitArmed(t, s, "inline tick did not arm the pacer timer for the next deadline") | |||
| 48 | + | if s.paceDepth != 0 || s.paceDirty { | |||
| 49 | + | t.Fatalf("pace state leaked: depth %d dirty %v", s.paceDepth, s.paceDirty) | |||
| 50 | + | } | |||
| 51 | + | } | |||
| 52 | + | ||||
| 53 | + | // Without a running pacer (no timer) the wake falls back to the channel. | |||
| 54 | + | func TestCommitWakesPacerWithoutTimer(t *testing.T) { | |||
| 55 | + | s, surf := paceFixture(false) | |||
| 56 | + | surf.queueAndTick() | |||
| 57 | + | if len(s.frameReady) != 1 { | |||
| 58 | + | t.Fatal("pacer not woken") | |||
| 59 | + | } | |||
| 60 | + | } | |||
| 61 | + | ||||
| 62 | + | // Wakes inside a tick coalesce into one more pass, not one channel wake each. | |||
| 63 | + | func TestWakePacerDefersInsideTick(t *testing.T) { | |||
| 64 | + | s, _ := paceFixture(true) | |||
| 65 | + | s.paceDepth = 1 | |||
| 66 | + | s.wakePacer() | |||
| 67 | + | s.wakePacer() | |||
| 68 | + | if len(s.frameReady) != 0 || !s.paceDirty { | |||
| 69 | + | t.Fatalf("wake inside a tick: queued %d dirty %v", len(s.frameReady), s.paceDirty) | |||
| 70 | + | } | |||
| 71 | + | s.paceDepth = 0 | |||
| 72 | + | s.wakePacer() | |||
| 73 | + | if len(s.frameReady) != 1 { | |||
| 74 | + | t.Fatal("wake outside a tick lost") | |||
| 75 | + | } | |||
| 76 | + | } | |||
| 77 | + | ||||
| 78 | + | // A commit that waits (a fifo barrier) is timed by the inline tick. | |||
| 79 | + | func TestCommitWaitingOnBarrierArmsTimer(t *testing.T) { | |||
| 80 | + | s, surf := paceFixture(true) | |||
| 81 | + | surf.next.callbacks = nil | |||
| 82 | + | surf.barrier, surf.barrierAt = true, time.Now() | |||
| 83 | + | surf.next.wait = true | |||
| 84 | + | surf.queueAndTick() | |||
| 85 | + | if len(surf.queue) != 1 || len(s.frameReady) != 0 { | |||
| 86 | + | t.Fatalf("queued %d, pacer wakes %d", len(surf.queue), len(s.frameReady)) | |||
| 87 | + | } | |||
| 88 | + | waitArmed(t, s, "timer not armed for the barrier deadline") | |||
| 89 | + | } | |||
| 90 | + | ||||
| 91 | + | // waitArmed asserts the timer was armed: it is pending, or it already | |||
| 92 | + | // fired and holds its value. | |||
| 93 | + | func waitArmed(t *testing.T, s *Server, msg string) { | |||
| 94 | + | t.Helper() | |||
| 95 | + | if s.paceTimer.Stop() { | |||
| 96 | + | return | |||
| 97 | + | } | |||
| 98 | + | select { | |||
| 99 | + | case <-s.paceTimer.C: | |||
| 100 | + | default: | |||
| 101 | + | t.Fatal(msg) | |||
| 102 | + | } | |||
| 103 | + | } | |||
| 104 | + | ||||
| 105 | + | // A synchronized subsurface commit waits for its parent's commit: it does | |||
| 106 | + | // not tick the pacer, so a burst of child commits costs no ticks. | |||
| 107 | + | func TestSyncedCommitDoesNotTick(t *testing.T) { | |||
| 108 | + | s, surf := paceFixture(true) | |||
| 109 | + | surf.sub.parent = &surface{server: s} | |||
| 110 | + | surf.sub.synced = true | |||
| 111 | + | surf.queueAndTick() | |||
| 112 | + | if len(surf.queue) != 1 || !surf.queue[0].synced { | |||
| 113 | + | t.Fatalf("synced commit not queued: %d", len(surf.queue)) | |||
| 114 | + | } | |||
| 115 | + | if len(s.frameReady) != 0 || s.paceTimer.Stop() { | |||
| 116 | + | t.Fatal("synced commit ticked the pacer") | |||
| 117 | + | } | |||
| 118 | + | } | |||
M internal/adapters/wayland/presentation.go +1 -0
| @@ -108,6 +108,7 @@ func (s *surface) commitFeedback(pending []*presentationtime.WpPresentationFeedb | |||
| 108 | 108 | for _, fb := range pending { | |
| 109 | 109 | srv.feedbacks = append(srv.feedbacks, feedbackWait{fb: fb, surf: s, win: win, seq: seq, at: time.Now()}) | |
| 110 | 110 | } | |
| 111 | + | srv.wakePacer() // an unanswered feedback times out: the pacer must keep ticking | |
| 111 | 112 | } | |
| 112 | 113 | ||
| 113 | 114 | func discard(fb *presentationtime.WpPresentationFeedback) { | |
| @@ -108,6 +108,7 @@ func (s *surface) commitFeedback(pending []*presentationtime.WpPresentationFeedb | |||||
| 108 | for _, fb := range pending { | 108 | for _, fb := range pending { | ||
| 109 | srv.feedbacks = append(srv.feedbacks, feedbackWait{fb: fb, surf: s, win: win, seq: seq, at: time.Now()}) | 109 | srv.feedbacks = append(srv.feedbacks, feedbackWait{fb: fb, surf: s, win: win, seq: seq, at: time.Now()}) | ||
| 110 | } | 110 | } | ||
| 111 | + | srv.wakePacer() // an unanswered feedback times out: the pacer must keep ticking | |||
| 111 | } | 112 | } | ||
| 112 | 113 | ||||
| 113 | func discard(fb *presentationtime.WpPresentationFeedback) { | 114 | func discard(fb *presentationtime.WpPresentationFeedback) { | ||
A internal/adapters/wayland/probe.go +15 -0
| @@ -0,0 +1,15 @@ | |||
| 1 | + | package wayland | |
| 2 | + | ||
| 3 | + | import "context" | |
| 4 | + | ||
| 5 | + | // Ping returns once the display loop ran an empty task, the display | |
| 6 | + | // stopped or ctx ended. The watchdog uses it to detect a stuck display | |
| 7 | + | // loop; a stuck loop leaves only the inner Do goroutine behind. | |
| 8 | + | func (s *Server) Ping(ctx context.Context) { | |
| 9 | + | done := make(chan struct{}) | |
| 10 | + | go func() { s.display.Do(func() {}); close(done) }() | |
| 11 | + | select { | |
| 12 | + | case <-done: | |
| 13 | + | case <-ctx.Done(): | |
| 14 | + | } | |
| 15 | + | } | |
| @@ -0,0 +1,15 @@ | |||||
| 1 | + | package wayland | |||
| 2 | + | ||||
| 3 | + | import "context" | |||
| 4 | + | ||||
| 5 | + | // Ping returns once the display loop ran an empty task, the display | |||
| 6 | + | // stopped or ctx ended. The watchdog uses it to detect a stuck display | |||
| 7 | + | // loop; a stuck loop leaves only the inner Do goroutine behind. | |||
| 8 | + | func (s *Server) Ping(ctx context.Context) { | |||
| 9 | + | done := make(chan struct{}) | |||
| 10 | + | go func() { s.display.Do(func() {}); close(done) }() | |||
| 11 | + | select { | |||
| 12 | + | case <-done: | |||
| 13 | + | case <-ctx.Done(): | |||
| 14 | + | } | |||
| 15 | + | } | |||
M internal/adapters/wayland/release.go +5 -5
| @@ -52,10 +52,7 @@ func (s *Server) releaseBuffer(surf *surface, b *wayland.Buffer, sync syncHold) | |||
| 52 | 52 | s.contentMu.Unlock() | |
| 53 | 53 | s.held = append(s.held, h) | |
| 54 | 54 | // Wake the pacer: it releases the buffer on the next output report. | |
| 55 | - | select { | |
| 56 | - | case s.frameReady <- struct{}{}: | |
| 57 | - | default: | |
| 58 | - | } | |
| 55 | + | s.wakePacer() | |
| 59 | 56 | } | |
| 60 | 57 | ||
| 61 | 58 | // release gives a buffer back: its release point is signalled when it | |
| @@ -98,7 +95,7 @@ func (s *Server) releaseHeld(now time.Time, reports []ports.OutputPresented) boo | |||
| 98 | 95 | for _, r := range reports { | |
| 99 | 96 | s.reports[r.Output] = r | |
| 100 | 97 | } | |
| 101 | - | live := make([]ports.OutputPresented, 0, len(s.outputs)) | |
| 98 | + | live := s.heldLive[:0] | |
| 102 | 99 | for name := range s.reports { | |
| 103 | 100 | if s.outputByNameExact(name) == nil { | |
| 104 | 101 | delete(s.reports, name) | |
| @@ -107,6 +104,8 @@ func (s *Server) releaseHeld(now time.Time, reports []ports.OutputPresented) boo | |||
| 107 | 104 | for _, r := range s.reports { | |
| 108 | 105 | live = append(live, r) | |
| 109 | 106 | } | |
| 107 | + | // keepHeld only reads live: the scratch holds nothing across calls. | |
| 108 | + | s.heldLive = live | |
| 110 | 109 | kept := s.held[:0] | |
| 111 | 110 | for _, h := range s.held { | |
| 112 | 111 | if s.bufferReferenced(h.res) || keepHeld(h, live, now) { | |
| @@ -117,6 +116,7 @@ func (s *Server) releaseHeld(now time.Time, reports []ports.OutputPresented) boo | |||
| 117 | 116 | } | |
| 118 | 117 | clear(s.held[len(kept):]) | |
| 119 | 118 | s.held = kept | |
| 119 | + | clear(live) // the reports carry maps: do not retain them | |
| 120 | 120 | return len(s.held) > 0 | |
| 121 | 121 | } | |
| 122 | 122 | ||
| @@ -52,10 +52,7 @@ func (s *Server) releaseBuffer(surf *surface, b *wayland.Buffer, sync syncHold) | |||||
| 52 | s.contentMu.Unlock() | 52 | s.contentMu.Unlock() | ||
| 53 | s.held = append(s.held, h) | 53 | s.held = append(s.held, h) | ||
| 54 | // Wake the pacer: it releases the buffer on the next output report. | 54 | // Wake the pacer: it releases the buffer on the next output report. | ||
| 55 | - | select { | 55 | + | s.wakePacer() |
| 56 | - | case s.frameReady <- struct{}{}: | |||
| 57 | - | default: | |||
| 58 | - | } | |||
| 59 | } | 56 | } | ||
| 60 | 57 | ||||
| 61 | // release gives a buffer back: its release point is signalled when it | 58 | // release gives a buffer back: its release point is signalled when it | ||
| @@ -98,7 +95,7 @@ func (s *Server) releaseHeld(now time.Time, reports []ports.OutputPresented) boo | |||||
| 98 | for _, r := range reports { | 95 | for _, r := range reports { | ||
| 99 | s.reports[r.Output] = r | 96 | s.reports[r.Output] = r | ||
| 100 | } | 97 | } | ||
| 101 | - | live := make([]ports.OutputPresented, 0, len(s.outputs)) | 98 | + | live := s.heldLive[:0] |
| 102 | for name := range s.reports { | 99 | for name := range s.reports { | ||
| 103 | if s.outputByNameExact(name) == nil { | 100 | if s.outputByNameExact(name) == nil { | ||
| 104 | delete(s.reports, name) | 101 | delete(s.reports, name) | ||
| @@ -107,6 +104,8 @@ func (s *Server) releaseHeld(now time.Time, reports []ports.OutputPresented) boo | |||||
| 107 | for _, r := range s.reports { | 104 | for _, r := range s.reports { | ||
| 108 | live = append(live, r) | 105 | live = append(live, r) | ||
| 109 | } | 106 | } | ||
| 107 | + | // keepHeld only reads live: the scratch holds nothing across calls. | |||
| 108 | + | s.heldLive = live | |||
| 110 | kept := s.held[:0] | 109 | kept := s.held[:0] | ||
| 111 | for _, h := range s.held { | 110 | for _, h := range s.held { | ||
| 112 | if s.bufferReferenced(h.res) || keepHeld(h, live, now) { | 111 | if s.bufferReferenced(h.res) || keepHeld(h, live, now) { | ||
| @@ -117,6 +116,7 @@ func (s *Server) releaseHeld(now time.Time, reports []ports.OutputPresented) boo | |||||
| 117 | } | 116 | } | ||
| 118 | clear(s.held[len(kept):]) | 117 | clear(s.held[len(kept):]) | ||
| 119 | s.held = kept | 118 | s.held = kept | ||
| 119 | + | clear(live) // the reports carry maps: do not retain them | |||
| 120 | return len(s.held) > 0 | 120 | return len(s.held) > 0 | ||
| 121 | } | 121 | } | ||
| 122 | 122 | ||||
M internal/adapters/wayland/server.go +36 -20
| @@ -151,6 +151,12 @@ type Server struct { | |||
| 151 | 151 | frameOwners map[*wayland.Callback]*surface | |
| 152 | 152 | frameDue map[string]time.Time | |
| 153 | 153 | frameReady chan struct{} | |
| 154 | + | // paceTimer is the pacer's deadline, armed by ticks on the display | |
| 155 | + | // goroutine; paceDepth/paceDirty defer wakePacer inside a commit or | |
| 156 | + | // tick (display goroutine only). | |
| 157 | + | paceTimer *time.Timer | |
| 158 | + | paceDepth int | |
| 159 | + | paceDirty bool | |
| 154 | 160 | // Pacer scratch: periods is used on the display goroutine, while | |
| 155 | 161 | // flipped and frameReports belong to pace and its synchronous Do call. | |
| 156 | 162 | framePeriods map[string]time.Duration | |
| @@ -158,10 +164,12 @@ type Server struct { | |||
| 158 | 164 | frameReports []ports.OutputPresented | |
| 159 | 165 | // held buffers wait until no output reads them (release.go); reports | |
| 160 | 166 | // are the outputs' latest ports.OutputPresented. | |
| 161 | - | held []heldBuffer | |
| 162 | - | reports map[string]ports.OutputPresented | |
| 163 | - | frames uint64 | |
| 164 | - | started time.Time | |
| 167 | + | held []heldBuffer | |
| 168 | + | // heldLive is releaseHeld's scratch (display goroutine only). | |
| 169 | + | heldLive []ports.OutputPresented | |
| 170 | + | reports map[string]ports.OutputPresented | |
| 171 | + | frames uint64 | |
| 172 | + | started time.Time | |
| 165 | 173 | // fifoSurfaces have a fifo barrier or queued commits (fifo.go); | |
| 166 | 174 | // lastFlip is each output's latest page flip. | |
| 167 | 175 | fifoSurfaces map[*surface]struct{} | |
| @@ -227,7 +235,6 @@ type Server struct { | |||
| 227 | 235 | clock ports.Clock | |
| 228 | 236 | powers []*outputPower | |
| 229 | 237 | outputsOff map[string]bool | |
| 230 | - | contentNotify chan struct{} | |
| 231 | 238 | contentReady chan struct{} | |
| 232 | 239 | outputs []*output | |
| 233 | 240 | outputManagers []*outputManager | |
| @@ -329,7 +336,6 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||
| 329 | 336 | dataSources: map[*server.Resource]*clipSource{}, | |
| 330 | 337 | primarySources: map[*server.Resource]*clipSource{}, | |
| 331 | 338 | controlSources: map[*server.Resource]*clipSource{}, | |
| 332 | - | contentNotify: make(chan struct{}), | |
| 333 | 339 | regions: map[*server.Resource]*region{}, | |
| 334 | 340 | relatives: map[server.Client][]*relativepointer.ZwpRelativePointerV1{}, | |
| 335 | 341 | gestures: map[server.Client][]*gestureObject{}, | |
| @@ -369,7 +375,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||
| 369 | 375 | var node *renderNode | |
| 370 | 376 | if opts.syncDev != nil { | |
| 371 | 377 | s.syncDev = opts.syncDev | |
| 372 | - | if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil { | |
| 378 | + | if s.syncWait, err = newSyncWaiter(s.signalPacer); err != nil { | |
| 373 | 379 | cleanup() | |
| 374 | 380 | d.Close() | |
| 375 | 381 | return nil, err | |
| @@ -378,7 +384,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||
| 378 | 384 | if node, err = openSyncobj(opts.SyncobjNode); err != nil { | |
| 379 | 385 | log.Info().Err(err).Msg("explicit sync off") | |
| 380 | 386 | node = nil | |
| 381 | - | } else if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil { | |
| 387 | + | } else if s.syncWait, err = newSyncWaiter(s.signalPacer); err != nil { | |
| 382 | 388 | node.close() | |
| 383 | 389 | node = nil | |
| 384 | 390 | } else { | |
| @@ -387,7 +393,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||
| 387 | 393 | } | |
| 388 | 394 | // Implicit dma-buf fences also need this waiter when explicit sync is off. | |
| 389 | 395 | if s.syncWait == nil { | |
| 390 | - | if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil { | |
| 396 | + | if s.syncWait, err = newSyncWaiter(s.signalPacer); err != nil { | |
| 391 | 397 | cleanup() | |
| 392 | 398 | d.Close() | |
| 393 | 399 | return nil, err | |
| @@ -453,6 +459,7 @@ func (s *Server) Run(ctx context.Context) error { | |||
| 453 | 459 | s.log.Info().Str("socket", s.name).Msg("starting wayland") | |
| 454 | 460 | s.started = time.Now() | |
| 455 | 461 | s.ctx = ctx | |
| 462 | + | s.paceTimer = time.NewTimer(defaultFramePeriod) | |
| 456 | 463 | var wg sync.WaitGroup | |
| 457 | 464 | wg.Add(15) | |
| 458 | 465 | go func() { defer wg.Done(); s.forwardBackendSecurity(ctx) }() | |
| @@ -563,6 +570,10 @@ func (s *Server) forwardOutputApplied(ctx context.Context) { | |||
| 563 | 570 | // enough for a renderer target a few frames old. | |
| 564 | 571 | const damageHistory = 4 | |
| 565 | 572 | ||
| 573 | + | // damageHistoryCap is the capacity of a history's backing array: one | |
| 574 | + | // allocation serves damageHistoryCap-damageHistory+1 publications. | |
| 575 | + | const damageHistoryCap = 8 * damageHistory | |
| 576 | + | ||
| 566 | 577 | // forwardOutputFormats applies the outputs' scanout formats on the | |
| 567 | 578 | // display goroutine. | |
| 568 | 579 | func (s *Server) forwardOutputFormats(ctx context.Context) { | |
| @@ -632,23 +643,28 @@ func (s *Server) emitContent(c ports.SurfaceContent, d damage) { | |||
| 632 | 643 | s.contentMu.Lock() | |
| 633 | 644 | s.contentSeq[c.ID]++ | |
| 634 | 645 | c.Seq = s.contentSeq[c.ID] | |
| 635 | - | // Copy-on-write: previous publications can still be in an output's hands. | |
| 646 | + | // Published histories are immutable: an output may hold one for as long | |
| 647 | + | // as it likes. The history grows inside one backing array, appended past | |
| 648 | + | // the end of every published slice (never over an element a reader can | |
| 649 | + | // see), and moves to a fresh array only when that one is full. Readers | |
| 650 | + | // get a capacity-clipped slice, so they cannot append into the spare. | |
| 636 | 651 | old := s.damage[c.ID] | |
| 637 | 652 | if len(old) >= damageHistory { | |
| 638 | 653 | old = old[len(old)-damageHistory+1:] | |
| 639 | 654 | } | |
| 640 | - | h := make([]ports.SeqDamage, len(old)+1) | |
| 641 | - | copy(h, old) | |
| 642 | - | h[len(old)] = ports.SeqDamage{Seq: c.Seq, Full: d.full, Rects: d.rects} | |
| 655 | + | if len(old) == cap(old) { | |
| 656 | + | grown := make([]ports.SeqDamage, len(old), damageHistoryCap) | |
| 657 | + | copy(grown, old) | |
| 658 | + | old = grown | |
| 659 | + | } | |
| 660 | + | h := append(old, ports.SeqDamage{Seq: c.Seq, Full: d.full, Rects: d.rects}) | |
| 643 | 661 | if c.Empty() { | |
| 644 | 662 | delete(s.damage, c.ID) | |
| 645 | 663 | } else { | |
| 646 | 664 | s.damage[c.ID] = h | |
| 647 | 665 | } | |
| 648 | - | c.DamageHistory = h | |
| 666 | + | c.DamageHistory = h[:len(h):len(h)] | |
| 649 | 667 | s.contents[c.ID] = c | |
| 650 | - | close(s.contentNotify) | |
| 651 | - | s.contentNotify = make(chan struct{}) | |
| 652 | 668 | s.contentMu.Unlock() | |
| 653 | 669 | select { | |
| 654 | 670 | case s.contentReady <- struct{}{}: | |
| @@ -663,13 +679,11 @@ func (s *Server) forwardContents(ctx context.Context) { | |||
| 663 | 679 | var c ports.SurfaceContent | |
| 664 | 680 | found := false | |
| 665 | 681 | var seq uint64 | |
| 666 | - | var notify <-chan struct{} | |
| 667 | 682 | for id, c = range s.contents { | |
| 668 | 683 | found = true | |
| 669 | 684 | seq = s.contentSeq[id] | |
| 670 | 685 | break | |
| 671 | 686 | } | |
| 672 | - | notify = s.contentNotify | |
| 673 | 687 | s.contentMu.Unlock() | |
| 674 | 688 | if !found { | |
| 675 | 689 | select { | |
| @@ -679,11 +693,13 @@ func (s *Server) forwardContents(ctx context.Context) { | |||
| 679 | 693 | continue | |
| 680 | 694 | } | |
| 681 | 695 | } | |
| 682 | - | // Do not hold a stale frame while the receiver is busy: wake on newer data. | |
| 696 | + | // Do not hold a stale frame while the receiver is busy: wake on newer | |
| 697 | + | // data. contentReady is signalled after every publication; a stale | |
| 698 | + | // signal only costs one more loop. | |
| 683 | 699 | select { | |
| 684 | 700 | case <-ctx.Done(): | |
| 685 | 701 | return | |
| 686 | - | case <-notify: | |
| 702 | + | case <-s.contentReady: | |
| 687 | 703 | continue | |
| 688 | 704 | case s.channels.Contents <- c: | |
| 689 | 705 | s.contentMu.Lock() | |
| @@ -151,6 +151,12 @@ type Server struct { | |||||
| 151 | frameOwners map[*wayland.Callback]*surface | 151 | frameOwners map[*wayland.Callback]*surface | ||
| 152 | frameDue map[string]time.Time | 152 | frameDue map[string]time.Time | ||
| 153 | frameReady chan struct{} | 153 | frameReady chan struct{} | ||
| 154 | + | // paceTimer is the pacer's deadline, armed by ticks on the display | |||
| 155 | + | // goroutine; paceDepth/paceDirty defer wakePacer inside a commit or | |||
| 156 | + | // tick (display goroutine only). | |||
| 157 | + | paceTimer *time.Timer | |||
| 158 | + | paceDepth int | |||
| 159 | + | paceDirty bool | |||
| 154 | // Pacer scratch: periods is used on the display goroutine, while | 160 | // Pacer scratch: periods is used on the display goroutine, while | ||
| 155 | // flipped and frameReports belong to pace and its synchronous Do call. | 161 | // flipped and frameReports belong to pace and its synchronous Do call. | ||
| 156 | framePeriods map[string]time.Duration | 162 | framePeriods map[string]time.Duration | ||
| @@ -158,10 +164,12 @@ type Server struct { | |||||
| 158 | frameReports []ports.OutputPresented | 164 | frameReports []ports.OutputPresented | ||
| 159 | // held buffers wait until no output reads them (release.go); reports | 165 | // held buffers wait until no output reads them (release.go); reports | ||
| 160 | // are the outputs' latest ports.OutputPresented. | 166 | // are the outputs' latest ports.OutputPresented. | ||
| 161 | - | held []heldBuffer | 167 | + | held []heldBuffer |
| 162 | - | reports map[string]ports.OutputPresented | 168 | + | // heldLive is releaseHeld's scratch (display goroutine only). |
| 163 | - | frames uint64 | 169 | + | heldLive []ports.OutputPresented |
| 164 | - | started time.Time | 170 | + | reports map[string]ports.OutputPresented |
| 171 | + | frames uint64 | |||
| 172 | + | started time.Time | |||
| 165 | // fifoSurfaces have a fifo barrier or queued commits (fifo.go); | 173 | // fifoSurfaces have a fifo barrier or queued commits (fifo.go); | ||
| 166 | // lastFlip is each output's latest page flip. | 174 | // lastFlip is each output's latest page flip. | ||
| 167 | fifoSurfaces map[*surface]struct{} | 175 | fifoSurfaces map[*surface]struct{} | ||
| @@ -227,7 +235,6 @@ type Server struct { | |||||
| 227 | clock ports.Clock | 235 | clock ports.Clock | ||
| 228 | powers []*outputPower | 236 | powers []*outputPower | ||
| 229 | outputsOff map[string]bool | 237 | outputsOff map[string]bool | ||
| 230 | - | contentNotify chan struct{} | |||
| 231 | contentReady chan struct{} | 238 | contentReady chan struct{} | ||
| 232 | outputs []*output | 239 | outputs []*output | ||
| 233 | outputManagers []*outputManager | 240 | outputManagers []*outputManager | ||
| @@ -329,7 +336,6 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||||
| 329 | dataSources: map[*server.Resource]*clipSource{}, | 336 | dataSources: map[*server.Resource]*clipSource{}, | ||
| 330 | primarySources: map[*server.Resource]*clipSource{}, | 337 | primarySources: map[*server.Resource]*clipSource{}, | ||
| 331 | controlSources: map[*server.Resource]*clipSource{}, | 338 | controlSources: map[*server.Resource]*clipSource{}, | ||
| 332 | - | contentNotify: make(chan struct{}), | |||
| 333 | regions: map[*server.Resource]*region{}, | 339 | regions: map[*server.Resource]*region{}, | ||
| 334 | relatives: map[server.Client][]*relativepointer.ZwpRelativePointerV1{}, | 340 | relatives: map[server.Client][]*relativepointer.ZwpRelativePointerV1{}, | ||
| 335 | gestures: map[server.Client][]*gestureObject{}, | 341 | gestures: map[server.Client][]*gestureObject{}, | ||
| @@ -369,7 +375,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||||
| 369 | var node *renderNode | 375 | var node *renderNode | ||
| 370 | if opts.syncDev != nil { | 376 | if opts.syncDev != nil { | ||
| 371 | s.syncDev = opts.syncDev | 377 | s.syncDev = opts.syncDev | ||
| 372 | - | if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil { | 378 | + | if s.syncWait, err = newSyncWaiter(s.signalPacer); err != nil { |
| 373 | cleanup() | 379 | cleanup() | ||
| 374 | d.Close() | 380 | d.Close() | ||
| 375 | return nil, err | 381 | return nil, err | ||
| @@ -378,7 +384,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||||
| 378 | if node, err = openSyncobj(opts.SyncobjNode); err != nil { | 384 | if node, err = openSyncobj(opts.SyncobjNode); err != nil { | ||
| 379 | log.Info().Err(err).Msg("explicit sync off") | 385 | log.Info().Err(err).Msg("explicit sync off") | ||
| 380 | node = nil | 386 | node = nil | ||
| 381 | - | } else if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil { | 387 | + | } else if s.syncWait, err = newSyncWaiter(s.signalPacer); err != nil { |
| 382 | node.close() | 388 | node.close() | ||
| 383 | node = nil | 389 | node = nil | ||
| 384 | } else { | 390 | } else { | ||
| @@ -387,7 +393,7 @@ func New(opts Options, ch Channels, log zerowrap.Logger) (*Server, error) { | |||||
| 387 | } | 393 | } | ||
| 388 | // Implicit dma-buf fences also need this waiter when explicit sync is off. | 394 | // Implicit dma-buf fences also need this waiter when explicit sync is off. | ||
| 389 | if s.syncWait == nil { | 395 | if s.syncWait == nil { | ||
| 390 | - | if s.syncWait, err = newSyncWaiter(s.wakePacer); err != nil { | 396 | + | if s.syncWait, err = newSyncWaiter(s.signalPacer); err != nil { |
| 391 | cleanup() | 397 | cleanup() | ||
| 392 | d.Close() | 398 | d.Close() | ||
| 393 | return nil, err | 399 | return nil, err | ||
| @@ -453,6 +459,7 @@ func (s *Server) Run(ctx context.Context) error { | |||||
| 453 | s.log.Info().Str("socket", s.name).Msg("starting wayland") | 459 | s.log.Info().Str("socket", s.name).Msg("starting wayland") | ||
| 454 | s.started = time.Now() | 460 | s.started = time.Now() | ||
| 455 | s.ctx = ctx | 461 | s.ctx = ctx | ||
| 462 | + | s.paceTimer = time.NewTimer(defaultFramePeriod) | |||
| 456 | var wg sync.WaitGroup | 463 | var wg sync.WaitGroup | ||
| 457 | wg.Add(15) | 464 | wg.Add(15) | ||
| 458 | go func() { defer wg.Done(); s.forwardBackendSecurity(ctx) }() | 465 | go func() { defer wg.Done(); s.forwardBackendSecurity(ctx) }() | ||
| @@ -563,6 +570,10 @@ func (s *Server) forwardOutputApplied(ctx context.Context) { | |||||
| 563 | // enough for a renderer target a few frames old. | 570 | // enough for a renderer target a few frames old. | ||
| 564 | const damageHistory = 4 | 571 | const damageHistory = 4 | ||
| 565 | 572 | ||||
| 573 | + | // damageHistoryCap is the capacity of a history's backing array: one | |||
| 574 | + | // allocation serves damageHistoryCap-damageHistory+1 publications. | |||
| 575 | + | const damageHistoryCap = 8 * damageHistory | |||
| 576 | + | ||||
| 566 | // forwardOutputFormats applies the outputs' scanout formats on the | 577 | // forwardOutputFormats applies the outputs' scanout formats on the | ||
| 567 | // display goroutine. | 578 | // display goroutine. | ||
| 568 | func (s *Server) forwardOutputFormats(ctx context.Context) { | 579 | func (s *Server) forwardOutputFormats(ctx context.Context) { | ||
| @@ -632,23 +643,28 @@ func (s *Server) emitContent(c ports.SurfaceContent, d damage) { | |||||
| 632 | s.contentMu.Lock() | 643 | s.contentMu.Lock() | ||
| 633 | s.contentSeq[c.ID]++ | 644 | s.contentSeq[c.ID]++ | ||
| 634 | c.Seq = s.contentSeq[c.ID] | 645 | c.Seq = s.contentSeq[c.ID] | ||
| 635 | - | // Copy-on-write: previous publications can still be in an output's hands. | 646 | + | // Published histories are immutable: an output may hold one for as long |
| 647 | + | // as it likes. The history grows inside one backing array, appended past | |||
| 648 | + | // the end of every published slice (never over an element a reader can | |||
| 649 | + | // see), and moves to a fresh array only when that one is full. Readers | |||
| 650 | + | // get a capacity-clipped slice, so they cannot append into the spare. | |||
| 636 | old := s.damage[c.ID] | 651 | old := s.damage[c.ID] | ||
| 637 | if len(old) >= damageHistory { | 652 | if len(old) >= damageHistory { | ||
| 638 | old = old[len(old)-damageHistory+1:] | 653 | old = old[len(old)-damageHistory+1:] | ||
| 639 | } | 654 | } | ||
| 640 | - | h := make([]ports.SeqDamage, len(old)+1) | 655 | + | if len(old) == cap(old) { |
| 641 | - | copy(h, old) | 656 | + | grown := make([]ports.SeqDamage, len(old), damageHistoryCap) |
| 642 | - | h[len(old)] = ports.SeqDamage{Seq: c.Seq, Full: d.full, Rects: d.rects} | 657 | + | copy(grown, old) |
| 658 | + | old = grown | |||
| 659 | + | } | |||
| 660 | + | h := append(old, ports.SeqDamage{Seq: c.Seq, Full: d.full, Rects: d.rects}) | |||
| 643 | if c.Empty() { | 661 | if c.Empty() { | ||
| 644 | delete(s.damage, c.ID) | 662 | delete(s.damage, c.ID) | ||
| 645 | } else { | 663 | } else { | ||
| 646 | s.damage[c.ID] = h | 664 | s.damage[c.ID] = h | ||
| 647 | } | 665 | } | ||
| 648 | - | c.DamageHistory = h | 666 | + | c.DamageHistory = h[:len(h):len(h)] |
| 649 | s.contents[c.ID] = c | 667 | s.contents[c.ID] = c | ||
| 650 | - | close(s.contentNotify) | |||
| 651 | - | s.contentNotify = make(chan struct{}) | |||
| 652 | s.contentMu.Unlock() | 668 | s.contentMu.Unlock() | ||
| 653 | select { | 669 | select { | ||
| 654 | case s.contentReady <- struct{}{}: | 670 | case s.contentReady <- struct{}{}: | ||
| @@ -663,13 +679,11 @@ func (s *Server) forwardContents(ctx context.Context) { | |||||
| 663 | var c ports.SurfaceContent | 679 | var c ports.SurfaceContent | ||
| 664 | found := false | 680 | found := false | ||
| 665 | var seq uint64 | 681 | var seq uint64 | ||
| 666 | - | var notify <-chan struct{} | |||
| 667 | for id, c = range s.contents { | 682 | for id, c = range s.contents { | ||
| 668 | found = true | 683 | found = true | ||
| 669 | seq = s.contentSeq[id] | 684 | seq = s.contentSeq[id] | ||
| 670 | break | 685 | break | ||
| 671 | } | 686 | } | ||
| 672 | - | notify = s.contentNotify | |||
| 673 | s.contentMu.Unlock() | 687 | s.contentMu.Unlock() | ||
| 674 | if !found { | 688 | if !found { | ||
| 675 | select { | 689 | select { | ||
| @@ -679,11 +693,13 @@ func (s *Server) forwardContents(ctx context.Context) { | |||||
| 679 | continue | 693 | continue | ||
| 680 | } | 694 | } | ||
| 681 | } | 695 | } | ||
| 682 | - | // Do not hold a stale frame while the receiver is busy: wake on newer data. | 696 | + | // Do not hold a stale frame while the receiver is busy: wake on newer |
| 697 | + | // data. contentReady is signalled after every publication; a stale | |||
| 698 | + | // signal only costs one more loop. | |||
| 683 | select { | 699 | select { | ||
| 684 | case <-ctx.Done(): | 700 | case <-ctx.Done(): | ||
| 685 | return | 701 | return | ||
| 686 | - | case <-notify: | 702 | + | case <-s.contentReady: |
| 687 | continue | 703 | continue | ||
| 688 | case s.channels.Contents <- c: | 704 | case s.channels.Contents <- c: | ||
| 689 | s.contentMu.Lock() | 705 | s.contentMu.Lock() | ||
M internal/adapters/wayland/surface.go +26 -1
| @@ -33,6 +33,9 @@ type surface struct { | |||
| 33 | 33 | committedViewport viewportState // value snapshot; no allocation on viewport commits | |
| 34 | 34 | // next is the state requested since the last commit (see pendingCommit). | |
| 35 | 35 | next pendingCommit | |
| 36 | + | // syncScratch holds next.sync between takeSyncPoints and queueUpdate, | |
| 37 | + | // which moves it into the update. | |
| 38 | + | syncScratch commitSync | |
| 36 | 39 | // bufferScale, transform and opaque are committed state. formatOpaque is | |
| 37 | 40 | // the current buffer's own opacity (x formats). | |
| 38 | 41 | bufferScale int | |
| @@ -371,8 +374,30 @@ func (s *surface) Commit(*wayland.Surface) { | |||
| 371 | 374 | s.takeSyncPoints() | |
| 372 | 375 | // Each request creates an ordered content update. A synchronized update | |
| 373 | 376 | // can only be reached through a parent's committed dependency graph. | |
| 377 | + | s.queueAndTick() | |
| 378 | + | } | |
| 379 | + | ||
| 380 | + | // queueAndTick queues the commit and applies what is ready. The pacer is | |
| 381 | + | // woken at most once, after the work, and by a tick on this goroutine | |
| 382 | + | // rather than by a wake that makes the pacer call Do back. | |
| 383 | + | func (s *surface) queueAndTick() { | |
| 384 | + | srv := s.server | |
| 385 | + | srv.paceDepth++ | |
| 374 | 386 | s.queueUpdate() | |
| 375 | - | s.server.tickFifo(time.Now(), nil) | |
| 387 | + | srv.tickFifo(time.Now(), nil) | |
| 388 | + | if n := len(s.queue); n > 0 && !s.queue[n-1].synced { | |
| 389 | + | // The commit waits for a barrier, a fence or a refresh: the pacer | |
| 390 | + | // must time it. A commit applied at once needs no tick of its own; | |
| 391 | + | // its callbacks, barrier and held buffers wake the pacer where | |
| 392 | + | // they are queued. A synchronized commit waits for its parent's | |
| 393 | + | // commit, which ticks for it. | |
| 394 | + | srv.wakePacer() | |
| 395 | + | } | |
| 396 | + | srv.paceDepth-- | |
| 397 | + | if srv.paceDepth == 0 && srv.paceDirty { | |
| 398 | + | srv.paceDirty = false | |
| 399 | + | srv.paceNow() | |
| 400 | + | } | |
| 376 | 401 | } | |
| 377 | 402 | ||
| 378 | 403 | // applyCommit makes only the captured update current. Live pending requests | |
| @@ -33,6 +33,9 @@ type surface struct { | |||||
| 33 | committedViewport viewportState // value snapshot; no allocation on viewport commits | 33 | committedViewport viewportState // value snapshot; no allocation on viewport commits | ||
| 34 | // next is the state requested since the last commit (see pendingCommit). | 34 | // next is the state requested since the last commit (see pendingCommit). | ||
| 35 | next pendingCommit | 35 | next pendingCommit | ||
| 36 | + | // syncScratch holds next.sync between takeSyncPoints and queueUpdate, | |||
| 37 | + | // which moves it into the update. | |||
| 38 | + | syncScratch commitSync | |||
| 36 | // bufferScale, transform and opaque are committed state. formatOpaque is | 39 | // bufferScale, transform and opaque are committed state. formatOpaque is | ||
| 37 | // the current buffer's own opacity (x formats). | 40 | // the current buffer's own opacity (x formats). | ||
| 38 | bufferScale int | 41 | bufferScale int | ||
| @@ -371,8 +374,30 @@ func (s *surface) Commit(*wayland.Surface) { | |||||
| 371 | s.takeSyncPoints() | 374 | s.takeSyncPoints() | ||
| 372 | // Each request creates an ordered content update. A synchronized update | 375 | // Each request creates an ordered content update. A synchronized update | ||
| 373 | // can only be reached through a parent's committed dependency graph. | 376 | // can only be reached through a parent's committed dependency graph. | ||
| 377 | + | s.queueAndTick() | |||
| 378 | + | } | |||
| 379 | + | ||||
| 380 | + | // queueAndTick queues the commit and applies what is ready. The pacer is | |||
| 381 | + | // woken at most once, after the work, and by a tick on this goroutine | |||
| 382 | + | // rather than by a wake that makes the pacer call Do back. | |||
| 383 | + | func (s *surface) queueAndTick() { | |||
| 384 | + | srv := s.server | |||
| 385 | + | srv.paceDepth++ | |||
| 374 | s.queueUpdate() | 386 | s.queueUpdate() | ||
| 375 | - | s.server.tickFifo(time.Now(), nil) | 387 | + | srv.tickFifo(time.Now(), nil) |
| 388 | + | if n := len(s.queue); n > 0 && !s.queue[n-1].synced { | |||
| 389 | + | // The commit waits for a barrier, a fence or a refresh: the pacer | |||
| 390 | + | // must time it. A commit applied at once needs no tick of its own; | |||
| 391 | + | // its callbacks, barrier and held buffers wake the pacer where | |||
| 392 | + | // they are queued. A synchronized commit waits for its parent's | |||
| 393 | + | // commit, which ticks for it. | |||
| 394 | + | srv.wakePacer() | |||
| 395 | + | } | |||
| 396 | + | srv.paceDepth-- | |||
| 397 | + | if srv.paceDepth == 0 && srv.paceDirty { | |||
| 398 | + | srv.paceDirty = false | |||
| 399 | + | srv.paceNow() | |||
| 400 | + | } | |||
| 376 | } | 401 | } | ||
| 377 | 402 | ||||
| 378 | // applyCommit makes only the captured update current. Live pending requests | 403 | // applyCommit makes only the captured update current. Live pending requests | ||
M internal/adapters/wayland/syncobj.go +4 -1
| @@ -487,7 +487,10 @@ func (s *surface) takeSyncPoints() { | |||
| 487 | 487 | if st == nil || !st.acquire.set() { | |
| 488 | 488 | return | |
| 489 | 489 | } | |
| 490 | - | cs := &commitSync{acquire: st.acquire, release: st.release} | |
| 490 | + | // The commit's points wait in the surface until queueUpdate moves them | |
| 491 | + | // into the update: no allocation per commit. | |
| 492 | + | cs := &s.syncScratch | |
| 493 | + | *cs = commitSync{acquire: st.acquire, release: st.release} | |
| 491 | 494 | st.acquire, st.release = syncPoint{}, syncPoint{} | |
| 492 | 495 | cs.acquire.tl.uses++ | |
| 493 | 496 | cs.release.tl.uses++ | |
| @@ -487,7 +487,10 @@ func (s *surface) takeSyncPoints() { | |||||
| 487 | if st == nil || !st.acquire.set() { | 487 | if st == nil || !st.acquire.set() { | ||
| 488 | return | 488 | return | ||
| 489 | } | 489 | } | ||
| 490 | - | cs := &commitSync{acquire: st.acquire, release: st.release} | 490 | + | // The commit's points wait in the surface until queueUpdate moves them |
| 491 | + | // into the update: no allocation per commit. | |||
| 492 | + | cs := &s.syncScratch | |||
| 493 | + | *cs = commitSync{acquire: st.acquire, release: st.release} | |||
| 491 | st.acquire, st.release = syncPoint{}, syncPoint{} | 494 | st.acquire, st.release = syncPoint{}, syncPoint{} | ||
| 492 | cs.acquire.tl.uses++ | 495 | cs.acquire.tl.uses++ | ||
| 493 | cs.release.tl.uses++ | 496 | cs.release.tl.uses++ | ||
M internal/app/drm.go +34 -0
| @@ -19,6 +19,7 @@ import ( | |||
| 19 | 19 | "github.com/bnema/neferwl/internal/adapters/logging" | |
| 20 | 20 | "github.com/bnema/neferwl/internal/adapters/sched" | |
| 21 | 21 | "github.com/bnema/neferwl/internal/adapters/seat" | |
| 22 | + | "github.com/bnema/neferwl/internal/adapters/watchdog" | |
| 22 | 23 | "github.com/bnema/neferwl/internal/ports" | |
| 23 | 24 | "github.com/bnema/zerowrap" | |
| 24 | 25 | ) | |
| @@ -119,6 +120,35 @@ type drmBackend struct { | |||
| 119 | 120 | // reads them while the output loop adds and removes them. | |
| 120 | 121 | mu sync.Mutex | |
| 121 | 122 | preparers map[seatDisablePreparer]struct{} | |
| 123 | + | // probes are the running output loops the watchdog pings, by | |
| 124 | + | // connector, guarded by mu. | |
| 125 | + | probes map[string]func() | |
| 126 | + | } | |
| 127 | + | ||
| 128 | + | func (b *drmBackend) addProbe(name string, ping func()) { | |
| 129 | + | b.mu.Lock() | |
| 130 | + | defer b.mu.Unlock() | |
| 131 | + | if b.probes == nil { | |
| 132 | + | b.probes = map[string]func(){} | |
| 133 | + | } | |
| 134 | + | b.probes[name] = ping | |
| 135 | + | } | |
| 136 | + | ||
| 137 | + | func (b *drmBackend) removeProbe(name string) { | |
| 138 | + | b.mu.Lock() | |
| 139 | + | defer b.mu.Unlock() | |
| 140 | + | delete(b.probes, name) | |
| 141 | + | } | |
| 142 | + | ||
| 143 | + | // watchdogProbes lists the running output loops for the watchdog. | |
| 144 | + | func (b *drmBackend) watchdogProbes() []watchdog.Probe { | |
| 145 | + | b.mu.Lock() | |
| 146 | + | defer b.mu.Unlock() | |
| 147 | + | out := make([]watchdog.Probe, 0, len(b.probes)) | |
| 148 | + | for name, ping := range b.probes { | |
| 149 | + | out = append(out, watchdog.Probe{Name: "output-" + name, Ping: ping}) | |
| 150 | + | } | |
| 151 | + | return out | |
| 122 | 152 | } | |
| 123 | 153 | ||
| 124 | 154 | // seatDisablePreparer is an output that can reset its planes before the | |
| @@ -490,6 +520,10 @@ func (b *drmBackend) runOutputs(ctx context.Context, want func(ports.Config) drm | |||
| 490 | 520 | defer o.Close() | |
| 491 | 521 | b.addPreparer(o) | |
| 492 | 522 | defer b.removePreparer(o) // before Close: it handles no request any more | |
| 523 | + | // octx derives from the session: the probe ends with this | |
| 524 | + | // output or the session. | |
| 525 | + | b.addProbe(name, func() { o.Ping(octx) }) | |
| 526 | + | defer b.removeProbe(name) | |
| 493 | 527 | if realtime { | |
| 494 | 528 | runtime.LockOSThread() | |
| 495 | 529 | // Keep the thread locked until this goroutine exits: an RT | |
| @@ -19,6 +19,7 @@ import ( | |||||
| 19 | "github.com/bnema/neferwl/internal/adapters/logging" | 19 | "github.com/bnema/neferwl/internal/adapters/logging" | ||
| 20 | "github.com/bnema/neferwl/internal/adapters/sched" | 20 | "github.com/bnema/neferwl/internal/adapters/sched" | ||
| 21 | "github.com/bnema/neferwl/internal/adapters/seat" | 21 | "github.com/bnema/neferwl/internal/adapters/seat" | ||
| 22 | + | "github.com/bnema/neferwl/internal/adapters/watchdog" | |||
| 22 | "github.com/bnema/neferwl/internal/ports" | 23 | "github.com/bnema/neferwl/internal/ports" | ||
| 23 | "github.com/bnema/zerowrap" | 24 | "github.com/bnema/zerowrap" | ||
| 24 | ) | 25 | ) | ||
| @@ -119,6 +120,35 @@ type drmBackend struct { | |||||
| 119 | // reads them while the output loop adds and removes them. | 120 | // reads them while the output loop adds and removes them. | ||
| 120 | mu sync.Mutex | 121 | mu sync.Mutex | ||
| 121 | preparers map[seatDisablePreparer]struct{} | 122 | preparers map[seatDisablePreparer]struct{} | ||
| 123 | + | // probes are the running output loops the watchdog pings, by | |||
| 124 | + | // connector, guarded by mu. | |||
| 125 | + | probes map[string]func() | |||
| 126 | + | } | |||
| 127 | + | ||||
| 128 | + | func (b *drmBackend) addProbe(name string, ping func()) { | |||
| 129 | + | b.mu.Lock() | |||
| 130 | + | defer b.mu.Unlock() | |||
| 131 | + | if b.probes == nil { | |||
| 132 | + | b.probes = map[string]func(){} | |||
| 133 | + | } | |||
| 134 | + | b.probes[name] = ping | |||
| 135 | + | } | |||
| 136 | + | ||||
| 137 | + | func (b *drmBackend) removeProbe(name string) { | |||
| 138 | + | b.mu.Lock() | |||
| 139 | + | defer b.mu.Unlock() | |||
| 140 | + | delete(b.probes, name) | |||
| 141 | + | } | |||
| 142 | + | ||||
| 143 | + | // watchdogProbes lists the running output loops for the watchdog. | |||
| 144 | + | func (b *drmBackend) watchdogProbes() []watchdog.Probe { | |||
| 145 | + | b.mu.Lock() | |||
| 146 | + | defer b.mu.Unlock() | |||
| 147 | + | out := make([]watchdog.Probe, 0, len(b.probes)) | |||
| 148 | + | for name, ping := range b.probes { | |||
| 149 | + | out = append(out, watchdog.Probe{Name: "output-" + name, Ping: ping}) | |||
| 150 | + | } | |||
| 151 | + | return out | |||
| 122 | } | 152 | } | ||
| 123 | 153 | ||||
| 124 | // seatDisablePreparer is an output that can reset its planes before the | 154 | // seatDisablePreparer is an output that can reset its planes before the | ||
| @@ -490,6 +520,10 @@ func (b *drmBackend) runOutputs(ctx context.Context, want func(ports.Config) drm | |||||
| 490 | defer o.Close() | 520 | defer o.Close() | ||
| 491 | b.addPreparer(o) | 521 | b.addPreparer(o) | ||
| 492 | defer b.removePreparer(o) // before Close: it handles no request any more | 522 | defer b.removePreparer(o) // before Close: it handles no request any more | ||
| 523 | + | // octx derives from the session: the probe ends with this | |||
| 524 | + | // output or the session. | |||
| 525 | + | b.addProbe(name, func() { o.Ping(octx) }) | |||
| 526 | + | defer b.removeProbe(name) | |||
| 493 | if realtime { | 527 | if realtime { | ||
| 494 | runtime.LockOSThread() | 528 | runtime.LockOSThread() | ||
| 495 | // Keep the thread locked until this goroutine exits: an RT | 529 | // Keep the thread locked until this goroutine exits: an RT | ||
M internal/app/session.go +17 -0
| @@ -23,6 +23,7 @@ import ( | |||
| 23 | 23 | "github.com/bnema/neferwl/internal/adapters/sessionsecurity" | |
| 24 | 24 | "github.com/bnema/neferwl/internal/adapters/statefile" | |
| 25 | 25 | "github.com/bnema/neferwl/internal/adapters/vulkan" | |
| 26 | + | "github.com/bnema/neferwl/internal/adapters/watchdog" | |
| 26 | 27 | "github.com/bnema/neferwl/internal/adapters/wayland" | |
| 27 | 28 | "github.com/bnema/neferwl/internal/adapters/workspaceid" | |
| 28 | 29 | "github.com/bnema/neferwl/internal/adapters/xkb" | |
| @@ -302,6 +303,22 @@ func (s *session) run(ctx context.Context, inject func(chan<- ports.InputEvent)) | |||
| 302 | 303 | close(script) | |
| 303 | 304 | } | |
| 304 | 305 | go func() { defer workers.Done(); done <- server.Run(ctx) }() | |
| 306 | + | if dir := logging.Dir(ctx); dir != "" { | |
| 307 | + | workers.Add(1) | |
| 308 | + | go func() { | |
| 309 | + | defer workers.Done() | |
| 310 | + | watchdog.Run(ctx, func() []watchdog.Probe { | |
| 311 | + | probes := []watchdog.Probe{ | |
| 312 | + | {Name: "wayland", Ping: func() { server.Ping(ctx) }}, | |
| 313 | + | {Name: "core", Ping: func() { c.Ping(ctx) }}, | |
| 314 | + | } | |
| 315 | + | if hw != nil { | |
| 316 | + | probes = append(probes, hw.watchdogProbes()...) | |
| 317 | + | } | |
| 318 | + | return probes | |
| 319 | + | }, watchdog.Options{Dir: dir, Every: time.Second, Timeout: 3 * time.Second, Log: logging.For(ctx, "app")}) | |
| 320 | + | }() | |
| 321 | + | } | |
| 305 | 322 | go func() { | |
| 306 | 323 | defer workers.Done() | |
| 307 | 324 | // Without a watch the allowlist stays as loaded: restart to apply. | |
| @@ -23,6 +23,7 @@ import ( | |||||
| 23 | "github.com/bnema/neferwl/internal/adapters/sessionsecurity" | 23 | "github.com/bnema/neferwl/internal/adapters/sessionsecurity" | ||
| 24 | "github.com/bnema/neferwl/internal/adapters/statefile" | 24 | "github.com/bnema/neferwl/internal/adapters/statefile" | ||
| 25 | "github.com/bnema/neferwl/internal/adapters/vulkan" | 25 | "github.com/bnema/neferwl/internal/adapters/vulkan" | ||
| 26 | + | "github.com/bnema/neferwl/internal/adapters/watchdog" | |||
| 26 | "github.com/bnema/neferwl/internal/adapters/wayland" | 27 | "github.com/bnema/neferwl/internal/adapters/wayland" | ||
| 27 | "github.com/bnema/neferwl/internal/adapters/workspaceid" | 28 | "github.com/bnema/neferwl/internal/adapters/workspaceid" | ||
| 28 | "github.com/bnema/neferwl/internal/adapters/xkb" | 29 | "github.com/bnema/neferwl/internal/adapters/xkb" | ||
| @@ -302,6 +303,22 @@ func (s *session) run(ctx context.Context, inject func(chan<- ports.InputEvent)) | |||||
| 302 | close(script) | 303 | close(script) | ||
| 303 | } | 304 | } | ||
| 304 | go func() { defer workers.Done(); done <- server.Run(ctx) }() | 305 | go func() { defer workers.Done(); done <- server.Run(ctx) }() | ||
| 306 | + | if dir := logging.Dir(ctx); dir != "" { | |||
| 307 | + | workers.Add(1) | |||
| 308 | + | go func() { | |||
| 309 | + | defer workers.Done() | |||
| 310 | + | watchdog.Run(ctx, func() []watchdog.Probe { | |||
| 311 | + | probes := []watchdog.Probe{ | |||
| 312 | + | {Name: "wayland", Ping: func() { server.Ping(ctx) }}, | |||
| 313 | + | {Name: "core", Ping: func() { c.Ping(ctx) }}, | |||
| 314 | + | } | |||
| 315 | + | if hw != nil { | |||
| 316 | + | probes = append(probes, hw.watchdogProbes()...) | |||
| 317 | + | } | |||
| 318 | + | return probes | |||
| 319 | + | }, watchdog.Options{Dir: dir, Every: time.Second, Timeout: 3 * time.Second, Log: logging.For(ctx, "app")}) | |||
| 320 | + | }() | |||
| 321 | + | } | |||
| 305 | go func() { | 322 | go func() { | ||
| 306 | defer workers.Done() | 323 | defer workers.Done() | ||
| 307 | // Without a watch the allowlist stays as loaded: restart to apply. | 324 | // Without a watch the allowlist stays as loaded: restart to apply. | ||
M internal/cli/run.go +2 -2
| @@ -123,12 +123,12 @@ func (f *runFlags) run(ctx context.Context, sizes [][2]int) error { | |||
| 123 | 123 | if err != nil { | |
| 124 | 124 | return err | |
| 125 | 125 | } | |
| 126 | - | defer closeLog() | |
| 126 | + | defer closeLog(false) // no-op after the panic path closed it | |
| 127 | 127 | log := logging.For(ctx, "app") | |
| 128 | 128 | defer func() { | |
| 129 | 129 | if p := recover(); p != nil { | |
| 130 | 130 | log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit") | |
| 131 | - | _ = closeLog() | |
| 131 | + | _ = closeLog(true) // keep the crash file for the re-panic | |
| 132 | 132 | panic(p) | |
| 133 | 133 | } | |
| 134 | 134 | }() | |
| @@ -123,12 +123,12 @@ func (f *runFlags) run(ctx context.Context, sizes [][2]int) error { | |||||
| 123 | if err != nil { | 123 | if err != nil { | ||
| 124 | return err | 124 | return err | ||
| 125 | } | 125 | } | ||
| 126 | - | defer closeLog() | 126 | + | defer closeLog(false) // no-op after the panic path closed it |
| 127 | log := logging.For(ctx, "app") | 127 | log := logging.For(ctx, "app") | ||
| 128 | defer func() { | 128 | defer func() { | ||
| 129 | if p := recover(); p != nil { | 129 | if p := recover(); p != nil { | ||
| 130 | log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit") | 130 | log.Error().Interface("panic", p).Str("stack", string(debug.Stack())).Msg("exit") | ||
| 131 | - | _ = closeLog() | 131 | + | _ = closeLog(true) // keep the crash file for the re-panic |
| 132 | panic(p) | 132 | panic(p) | ||
| 133 | } | 133 | } | ||
| 134 | }() | 134 | }() | ||
M internal/core/core.go +22 -2
| @@ -138,7 +138,9 @@ type Core struct { | |||
| 138 | 138 | swipe *swipeGesture | |
| 139 | 139 | // gesture is the touchpad gesture forwarded to a client | |
| 140 | 140 | // (clientgesture.go). | |
| 141 | - | gesture clientGesture | |
| 141 | + | gesture clientGesture | |
| 142 | + | // ping carries watchdog probes (Ping); Run answers each one. | |
| 143 | + | ping chan chan struct{} | |
| 142 | 144 | frameC <-chan time.Time | |
| 143 | 145 | frameTimer ports.Timer | |
| 144 | 146 | // shots is the snapshot of what the screens show before an action | |
| @@ -401,7 +403,7 @@ func New(cfg ports.Config, ch Channels, opts Options) (*Core, error) { | |||
| 401 | 403 | return nil, fmt.Errorf("scenes, layouts, constraints, state and workspaces must have capacity 1") | |
| 402 | 404 | } | |
| 403 | 405 | // A placeholder screen holds windows until the first output arrives. | |
| 404 | - | c := &Core{inputKeys: map[string]bool{}, slots: map[slotKey]*slotState{}, placement: newSpawnPlacement(), windows: newWindowRegistry(), popups: map[WindowID]*popupState{}, ch: ch, opts: opts, pressed: map[string]bool{}, buttons: map[uint32]bool{}, swallow: map[uint32]bool{}, configures: newConfigures()} | |
| 406 | + | c := &Core{inputKeys: map[string]bool{}, slots: map[slotKey]*slotState{}, placement: newSpawnPlacement(), windows: newWindowRegistry(), popups: map[WindowID]*popupState{}, ch: ch, opts: opts, pressed: map[string]bool{}, buttons: map[uint32]bool{}, swallow: map[uint32]bool{}, configures: newConfigures(), ping: make(chan chan struct{})} | |
| 405 | 407 | c.screens = []*screen{{mon: newMonitorWithIDs("", "", &c.nextWorkspaceID), scale: 1, cfgScale: 1}} | |
| 406 | 408 | if err := c.apply(cfg); err != nil { | |
| 407 | 409 | return nil, err | |
| @@ -1023,6 +1025,21 @@ func (c *Core) hit(x, y float64) (WindowID, float64, float64) { | |||
| 1023 | 1025 | return id, sx, sy | |
| 1024 | 1026 | } | |
| 1025 | 1027 | ||
| 1028 | + | // Ping returns once Run handled a probe, or once ctx ends: the watchdog | |
| 1029 | + | // uses it to detect a stuck owner loop. | |
| 1030 | + | func (c *Core) Ping(ctx context.Context) { | |
| 1031 | + | ack := make(chan struct{}) | |
| 1032 | + | select { | |
| 1033 | + | case c.ping <- ack: | |
| 1034 | + | case <-ctx.Done(): | |
| 1035 | + | return | |
| 1036 | + | } | |
| 1037 | + | select { | |
| 1038 | + | case <-ack: | |
| 1039 | + | case <-ctx.Done(): | |
| 1040 | + | } | |
| 1041 | + | } | |
| 1042 | + | ||
| 1026 | 1043 | func (c *Core) Run(ctx context.Context) error { | |
| 1027 | 1044 | c.syncSecurity() | |
| 1028 | 1045 | defer c.stopFrame() | |
| @@ -1084,6 +1101,9 @@ func (c *Core) Run(ctx context.Context) error { | |||
| 1084 | 1101 | return nil | |
| 1085 | 1102 | } | |
| 1086 | 1103 | continue | |
| 1104 | + | case ack := <-c.ping: | |
| 1105 | + | close(ack) | |
| 1106 | + | continue | |
| 1087 | 1107 | case <-c.frameC: | |
| 1088 | 1108 | if c.securityCheckpoint(ctx) != nil { | |
| 1089 | 1109 | return nil | |
| @@ -138,7 +138,9 @@ type Core struct { | |||||
| 138 | swipe *swipeGesture | 138 | swipe *swipeGesture | ||
| 139 | // gesture is the touchpad gesture forwarded to a client | 139 | // gesture is the touchpad gesture forwarded to a client | ||
| 140 | // (clientgesture.go). | 140 | // (clientgesture.go). | ||
| 141 | - | gesture clientGesture | 141 | + | gesture clientGesture |
| 142 | + | // ping carries watchdog probes (Ping); Run answers each one. | |||
| 143 | + | ping chan chan struct{} | |||
| 142 | frameC <-chan time.Time | 144 | frameC <-chan time.Time | ||
| 143 | frameTimer ports.Timer | 145 | frameTimer ports.Timer | ||
| 144 | // shots is the snapshot of what the screens show before an action | 146 | // shots is the snapshot of what the screens show before an action | ||
| @@ -401,7 +403,7 @@ func New(cfg ports.Config, ch Channels, opts Options) (*Core, error) { | |||||
| 401 | return nil, fmt.Errorf("scenes, layouts, constraints, state and workspaces must have capacity 1") | 403 | return nil, fmt.Errorf("scenes, layouts, constraints, state and workspaces must have capacity 1") | ||
| 402 | } | 404 | } | ||
| 403 | // A placeholder screen holds windows until the first output arrives. | 405 | // A placeholder screen holds windows until the first output arrives. | ||
| 404 | - | c := &Core{inputKeys: map[string]bool{}, slots: map[slotKey]*slotState{}, placement: newSpawnPlacement(), windows: newWindowRegistry(), popups: map[WindowID]*popupState{}, ch: ch, opts: opts, pressed: map[string]bool{}, buttons: map[uint32]bool{}, swallow: map[uint32]bool{}, configures: newConfigures()} | 406 | + | c := &Core{inputKeys: map[string]bool{}, slots: map[slotKey]*slotState{}, placement: newSpawnPlacement(), windows: newWindowRegistry(), popups: map[WindowID]*popupState{}, ch: ch, opts: opts, pressed: map[string]bool{}, buttons: map[uint32]bool{}, swallow: map[uint32]bool{}, configures: newConfigures(), ping: make(chan chan struct{})} |
| 405 | c.screens = []*screen{{mon: newMonitorWithIDs("", "", &c.nextWorkspaceID), scale: 1, cfgScale: 1}} | 407 | c.screens = []*screen{{mon: newMonitorWithIDs("", "", &c.nextWorkspaceID), scale: 1, cfgScale: 1}} | ||
| 406 | if err := c.apply(cfg); err != nil { | 408 | if err := c.apply(cfg); err != nil { | ||
| 407 | return nil, err | 409 | return nil, err | ||
| @@ -1023,6 +1025,21 @@ func (c *Core) hit(x, y float64) (WindowID, float64, float64) { | |||||
| 1023 | return id, sx, sy | 1025 | return id, sx, sy | ||
| 1024 | } | 1026 | } | ||
| 1025 | 1027 | ||||
| 1028 | + | // Ping returns once Run handled a probe, or once ctx ends: the watchdog | |||
| 1029 | + | // uses it to detect a stuck owner loop. | |||
| 1030 | + | func (c *Core) Ping(ctx context.Context) { | |||
| 1031 | + | ack := make(chan struct{}) | |||
| 1032 | + | select { | |||
| 1033 | + | case c.ping <- ack: | |||
| 1034 | + | case <-ctx.Done(): | |||
| 1035 | + | return | |||
| 1036 | + | } | |||
| 1037 | + | select { | |||
| 1038 | + | case <-ack: | |||
| 1039 | + | case <-ctx.Done(): | |||
| 1040 | + | } | |||
| 1041 | + | } | |||
| 1042 | + | ||||
| 1026 | func (c *Core) Run(ctx context.Context) error { | 1043 | func (c *Core) Run(ctx context.Context) error { | ||
| 1027 | c.syncSecurity() | 1044 | c.syncSecurity() | ||
| 1028 | defer c.stopFrame() | 1045 | defer c.stopFrame() | ||
| @@ -1084,6 +1101,9 @@ func (c *Core) Run(ctx context.Context) error { | |||||
| 1084 | return nil | 1101 | return nil | ||
| 1085 | } | 1102 | } | ||
| 1086 | continue | 1103 | continue | ||
| 1104 | + | case ack := <-c.ping: | |||
| 1105 | + | close(ack) | |||
| 1106 | + | continue | |||
| 1087 | case <-c.frameC: | 1107 | case <-c.frameC: | ||
| 1088 | if c.securityCheckpoint(ctx) != nil { | 1108 | if c.securityCheckpoint(ctx) != nil { | ||
| 1089 | return nil | 1109 | return nil | ||