1package cef
2
3import (
4 "time"
5
6 purecef "github.com/bnema/purego-cef/cef"
7 cef2gtk "github.com/bnema/purego-cef2gtk"
8
9 "github.com/bnema/dumber/internal/logging"
10)
11
12const (
13 renderStallWatchdogInterval = 1 * time.Second
14 renderStallWarnAfter = 3 * time.Second
15 renderStallWarnRepeat = 10 * time.Second
16 renderStallCEFUIBlockedAfter = 3 * time.Second
17)
18
19type renderStallClassification struct {
20 Category string
21 CEFUIBlocked bool
22 CEFIOAlive bool
23}
24
25type renderStallDiagnostics struct {
26 browser purecef.Browser
27 uri string
28 title string
29 isLoading bool
30 pendingURI string
31 audioPlaying bool
32 diag cef2gtk.Diagnostics
33 lastPaintAge time.Duration
34 latestEvent cef2gtk.DiagnosticEvent
35}
36
37func classifyRenderStall(uiHeartbeat, ioHeartbeat cefHeartbeatSnapshot) renderStallClassification {
38 uiBlocked := uiHeartbeat.PostResult == 1 && uiHeartbeat.InFlight && uiHeartbeat.LastAckAge >= renderStallCEFUIBlockedAfter
39 ioAlive := ioHeartbeat.PostResult == 1 &&
40 !ioHeartbeat.InFlight &&
41 ioHeartbeat.LastAckAge > 0 &&
42 ioHeartbeat.LastAckAge < renderStallCEFUIBlockedAfter
43 category := "osr-paint-stalled"
44 if uiBlocked {
45 category = "cef-ui-task-runner-blocked"
46 if ioAlive {
47 category = "cef-ui-task-runner-blocked-io-alive"
48 }
49 }
50 return renderStallClassification{Category: category, CEFUIBlocked: uiBlocked, CEFIOAlive: ioAlive}
51}
52
53func (wv *WebView) startRenderStallWatchdog() {
54 if wv == nil || wv.ctx == nil || wv.viewBridge == nil {
55 return
56 }
57
58 wv.renderStallMu.Lock()
59 defer wv.renderStallMu.Unlock()
60 if wv.renderStallStop != nil {
61 return
62 }
63
64 stop := make(chan struct{})
65 done := make(chan struct{})
66 bridge := wv.viewBridge
67 wv.renderStallStop = stop
68 wv.renderStallDone = done
69
70 go wv.renderStallWatchdogLoop(bridge, stop, done)
71}
72
73func (wv *WebView) stopRenderStallWatchdog() {
74 if wv == nil {
75 return
76 }
77 wv.renderStallMu.Lock()
78 stop := wv.renderStallStop
79 done := wv.renderStallDone
80 wv.renderStallStop = nil
81 wv.renderStallDone = nil
82 wv.renderStallMu.Unlock()
83
84 if stop == nil || done == nil {
85 return
86 }
87 close(stop)
88 select {
89 case <-done:
90 case <-time.After(cefHeartbeatStopTimeout):
91 if wv.ctx != nil {
92 logging.FromContext(wv.ctx).Warn().Msg("cef: render stall watchdog stop timed out")
93 }
94 }
95}
96
97func (wv *WebView) renderStallWatchdogLoop(bridge *Cef2gtkAdapter, stop <-chan struct{}, done chan<- struct{}) {
98 defer close(done)
99 ticker := time.NewTicker(renderStallWatchdogInterval)
100 defer ticker.Stop()
101
102 var lastWarn time.Time
103 for {
104 select {
105 case <-stop:
106 return
107 case now := <-ticker.C:
108 if wv.maybeLogRenderStall(bridge, now, lastWarn) {
109 lastWarn = now
110 }
111 }
112 }
113}
114
115func (wv *WebView) maybeLogRenderStall(bridge *Cef2gtkAdapter, now, lastWarn time.Time) bool {
116 diag, ok := wv.shouldLogRenderStall(bridge, now, lastWarn)
117 if !ok {
118 return false
119 }
120 wv.logRenderStall(bridge, now, diag)
121 return true
122}
123
124func (wv *WebView) shouldLogRenderStall(bridge *Cef2gtkAdapter, now, lastWarn time.Time) (renderStallDiagnostics, bool) {
125 if wv == nil || bridge == nil || wv.destroyed.Load() || wv.ctx == nil {
126 return renderStallDiagnostics{}, false
127 }
128 diag, ok := wv.collectStallDiagnostics(bridge, now)
129 if !ok {
130 return renderStallDiagnostics{}, false
131 }
132 if diag.lastPaintAge < renderStallWarnAfter {
133 return renderStallDiagnostics{}, false
134 }
135 if !lastWarn.IsZero() && now.Sub(lastWarn) < renderStallWarnRepeat {
136 return renderStallDiagnostics{}, false
137 }
138 return diag, true
139}
140
141func (wv *WebView) collectStallDiagnostics(bridge *Cef2gtkAdapter, now time.Time) (renderStallDiagnostics, bool) {
142 wv.mu.RLock()
143 browser := wv.browser
144 uri := wv.uri
145 title := wv.title
146 isLoading := wv.isLoading
147 pendingURI := wv.pendingURI
148 wv.mu.RUnlock()
149 if browser == nil {
150 return renderStallDiagnostics{}, false
151 }
152
153 audioPlaying := wv.audioPlaying.Load()
154 if !audioPlaying && !isLoading && pendingURI == "" {
155 return renderStallDiagnostics{}, false
156 }
157
158 diag := bridge.Diagnostics()
159 lastPaint := latestDiagnosticEventTime(diag, "accelerated-paint")
160 if lastPaint.IsZero() {
161 return renderStallDiagnostics{}, false
162 }
163 return renderStallDiagnostics{
164 browser: browser,
165 uri: uri,
166 title: title,
167 isLoading: isLoading,
168 pendingURI: pendingURI,
169 audioPlaying: audioPlaying,
170 diag: diag,
171 lastPaintAge: now.Sub(lastPaint),
172 latestEvent: latestDiagnosticEvent(diag),
173 }, true
174}
175
176func (wv *WebView) logRenderStall(bridge *Cef2gtkAdapter, now time.Time, diag renderStallDiagnostics) {
177 uiHeartbeat, ioHeartbeat := wv.cefHeartbeatSnapshots(now)
178 classification := classifyRenderStall(uiHeartbeat, ioHeartbeat)
179 wv.logRenderDiagnosticSnapshot(
180 now, "stall", classification, bridge, diag.diag, diag.lastPaintAge,
181 diag.browser, diag.uri, diag.title, diag.isLoading, diag.pendingURI, diag.audioPlaying,
182 )
183 wv.logCEFProcessDiagnostics("stall", classification)
184 if wv.engine != nil {
185 wv.engine.logAllWebViewRenderSnapshots(now, wv.id, "stall-global", classification)
186 }
187 wv.maybeRunRenderStallRecovery(now, bridge, diag.diag.AcceleratedPaints)
188 profile, profileAge, hasProfile := wv.latestCEF2GTKProfileSnapshot(now)
189 logging.FromContext(wv.ctx).Warn().
190 Str("classification", classification.Category).
191 Bool("cef_ui_blocked", classification.CEFUIBlocked).
192 Bool("cef_io_alive", classification.CEFIOAlive).
193 Uint64("webview_id", uint64(wv.id)).
194 Int32("browser_id", diag.browser.GetIdentifier()).
195 Bool("has_uri", diag.uri != "").
196 Bool("has_title", diag.title != "").
197 Bool("is_loading", diag.isLoading).
198 Bool("has_pending_uri", diag.pendingURI != "").
199 Bool("audio_playing", diag.audioPlaying).
200 Int64("cef_ui_heartbeat_ack_age_ms", durationMillis(uiHeartbeat.LastAckAge)).
201 Int64("cef_ui_heartbeat_latency_ms", durationMillis(uiHeartbeat.Latency)).
202 Int32("cef_ui_heartbeat_post_result", uiHeartbeat.PostResult).
203 Bool("cef_ui_heartbeat_in_flight", uiHeartbeat.InFlight).
204 Int64("cef_io_heartbeat_ack_age_ms", durationMillis(ioHeartbeat.LastAckAge)).
205 Int64("cef_io_heartbeat_latency_ms", durationMillis(ioHeartbeat.Latency)).
206 Int32("cef_io_heartbeat_post_result", ioHeartbeat.PostResult).
207 Bool("cef_io_heartbeat_in_flight", ioHeartbeat.InFlight).
208 Uint64("audio_packets", wv.audioPacketCount.Load()).
209 Uint64("audio_writes", wv.audioWriteCount.Load()).
210 Int64("last_accelerated_paint_age_ms", diag.lastPaintAge.Milliseconds()).
211 Bool("profile_snapshot_available", hasProfile).
212 Int64("profile_snapshot_age_ms", durationMillis(profileAge)).
213 Uint64("profile_frames_received", profile.FramesReceived).
214 Uint64("profile_frames_queued", profile.FramesQueued).
215 Uint64("profile_frames_rendered", profile.FramesRendered).
216 Uint32("profile_gc_delta", profile.GC.NumGCDelta).
217 Str("render_backend", diag.diag.Backend).
218 Int("accelerated_paints", diag.diag.AcceleratedPaints).
219 Int("unsupported_paints", diag.diag.UnsupportedPaints).
220 Int("accelerated_paint_errors", diag.diag.AcceleratedPaintErrors).
221 Int("import_failures", diag.diag.ImportFailures).
222 Int("render_failures", diag.diag.RenderFailures).
223 Int("textures_built", diag.diag.TexturesBuilt).
224 Int("texture_build_failures", diag.diag.TextureBuildFailures).
225 Int("fd_dup_failures", diag.diag.FDDupFailures).
226 Int("unsupported_formats", diag.diag.UnsupportedFormats).
227 Int("paintable_swaps", diag.diag.PaintableSwaps).
228 Bool("pending_frame", diag.diag.PendingFrame).
229 Bool("pending_scheduled", diag.diag.PendingScheduled).
230 Int64("pending_age_ms", durationMillis(diag.diag.PendingAge)).
231 Uint("pending_source_id", diag.diag.PendingSourceID).
232 Int("pending_reschedules", diag.diag.PendingReschedules).
233 Int("pending_schedule_failures", diag.diag.PendingScheduleFailures).
234 Int("pending_idle_callbacks", diag.diag.PendingIdleCallbacks).
235 Str("latest_render_event_kind", diag.latestEvent.Kind).
236 Bool("latest_render_event_has_message", diag.latestEvent.Message != "").
237 Msg("cef: accelerated rendering appears stalled")
238}
239
240func latestDiagnosticEventTime(diag cef2gtk.Diagnostics, kind string) time.Time {
241 return latestDiagnosticEventOfKind(diag, kind).Time
242}
243
244func latestDiagnosticEventOfKind(diag cef2gtk.Diagnostics, kind string) cef2gtk.DiagnosticEvent {
245 var latest cef2gtk.DiagnosticEvent
246 for _, event := range diag.Events {
247 if event.Kind != kind {
248 continue
249 }
250 if latest.Time.IsZero() || event.Time.After(latest.Time) {
251 latest = event
252 }
253 }
254 return latest
255}
256
257func latestDiagnosticEvent(diag cef2gtk.Diagnostics) cef2gtk.DiagnosticEvent {
258 var latest cef2gtk.DiagnosticEvent
259 for _, event := range diag.Events {
260 if latest.Time.IsZero() || event.Time.After(latest.Time) {
261 latest = event
262 }
263 }
264 return latest
265}