add deeper cef browser creation diagnostics
- commit
- 4fd44b9c3bba87e5ec045fb60431cee81729286a
- author
- brice · · 2026-03-20 09:46 UTC
- committer
- brice · · 2026-03-28 04:36 UTC
- parent
- d42aca3
- signature
- GPG Verified
CD88F9E564E0102646FB6077A1A07C7C7C3E349D· arch-gpg Verified for the committer email
6 files · +288 -94
M internal/infrastructure/cef/app.go +33 -7
| @@ -2,6 +2,8 @@ package cef | |||
| 2 | 2 | ||
| 3 | 3 | import ( | |
| 4 | 4 | purecef "github.com/bnema/purego-cef/cef" | |
| 5 | + | ||
| 6 | + | "github.com/bnema/dumber/internal/logging" | |
| 5 | 7 | ) | |
| 6 | 8 | ||
| 7 | 9 | // dumberApp implements purecef.App to provide a BrowserProcessHandler with | |
| @@ -21,11 +23,21 @@ func newDumberApp(engine *Engine) purecef.App { | |||
| 21 | 23 | return purecef.NewApp(app) | |
| 22 | 24 | } | |
| 23 | 25 | ||
| 24 | - | func (a *dumberApp) OnBeforeCommandLineProcessing(_ string, _ purecef.CommandLine) {} | |
| 25 | - | func (a *dumberApp) OnRegisterCustomSchemes(_ purecef.SchemeRegistrar) {} | |
| 26 | - | func (a *dumberApp) GetResourceBundleHandler() purecef.ResourceBundleHandler { return nil } | |
| 27 | - | func (a *dumberApp) GetBrowserProcessHandler() purecef.BrowserProcessHandler { return a.bph } | |
| 28 | - | func (a *dumberApp) GetRenderProcessHandler() purecef.RenderProcessHandler { return nil } | |
| 26 | + | func (a *dumberApp) OnBeforeCommandLineProcessing(processType string, commandLine purecef.CommandLine) { | |
| 27 | + | log := logging.FromContext(a.engine.ctx) | |
| 28 | + | cmdline := "" | |
| 29 | + | if commandLine != nil { | |
| 30 | + | cmdline = commandLine.GetCommandLineString() | |
| 31 | + | } | |
| 32 | + | log.Debug(). | |
| 33 | + | Str("process_type", processType). | |
| 34 | + | Str("command_line", cmdline). | |
| 35 | + | Msg("cef: OnBeforeCommandLineProcessing") | |
| 36 | + | } | |
| 37 | + | func (a *dumberApp) OnRegisterCustomSchemes(_ purecef.SchemeRegistrar) {} | |
| 38 | + | func (a *dumberApp) GetResourceBundleHandler() purecef.ResourceBundleHandler { return nil } | |
| 39 | + | func (a *dumberApp) GetBrowserProcessHandler() purecef.BrowserProcessHandler { return a.bph } | |
| 40 | + | func (a *dumberApp) GetRenderProcessHandler() purecef.RenderProcessHandler { return nil } | |
| 29 | 41 | ||
| 30 | 42 | // dumberBPH implements purecef.BrowserProcessHandler. Only | |
| 31 | 43 | // OnScheduleMessagePumpWork carries real logic; the rest are no-ops. | |
| @@ -35,8 +47,22 @@ type dumberBPH struct { | |||
| 35 | 47 | ||
| 36 | 48 | func (h *dumberBPH) OnRegisterCustomPreferences(_ purecef.PreferencesType, _ purecef.PreferenceRegistrar) { | |
| 37 | 49 | } | |
| 38 | - | func (h *dumberBPH) OnContextInitialized() {} | |
| 39 | - | func (h *dumberBPH) OnBeforeChildProcessLaunch(_ purecef.CommandLine) {} | |
| 50 | + | func (h *dumberBPH) OnContextInitialized() { | |
| 51 | + | h.engine.recordContextInitialized() | |
| 52 | + | } | |
| 53 | + | func (h *dumberBPH) OnBeforeChildProcessLaunch(commandLine purecef.CommandLine) { | |
| 54 | + | processType := "" | |
| 55 | + | commandLineString := "" | |
| 56 | + | useAngle := "" | |
| 57 | + | ozonePlatform := "" | |
| 58 | + | if commandLine != nil { | |
| 59 | + | processType = commandLine.GetSwitchValue("type") | |
| 60 | + | commandLineString = commandLine.GetCommandLineString() | |
| 61 | + | useAngle = commandLine.GetSwitchValue("use-angle") | |
| 62 | + | ozonePlatform = commandLine.GetSwitchValue("ozone-platform") | |
| 63 | + | } | |
| 64 | + | h.engine.recordChildProcessLaunch(processType, useAngle, ozonePlatform, commandLineString) | |
| 65 | + | } | |
| 40 | 66 | func (h *dumberBPH) OnAlreadyRunningAppRelaunch(_ purecef.CommandLine, _ string) int32 { return 0 } | |
| 41 | 67 | func (h *dumberBPH) GetDefaultClient() purecef.Client { return nil } | |
| 42 | 68 | func (h *dumberBPH) GetDefaultRequestContextHandler() purecef.RequestContextHandler { return nil } | |
| @@ -2,6 +2,8 @@ package cef | |||||
| 2 | 2 | ||||
| 3 | import ( | 3 | import ( | ||
| 4 | purecef "github.com/bnema/purego-cef/cef" | 4 | purecef "github.com/bnema/purego-cef/cef" | ||
| 5 | + | ||||
| 6 | + | "github.com/bnema/dumber/internal/logging" | |||
| 5 | ) | 7 | ) | ||
| 6 | 8 | ||||
| 7 | // dumberApp implements purecef.App to provide a BrowserProcessHandler with | 9 | // dumberApp implements purecef.App to provide a BrowserProcessHandler with | ||
| @@ -21,11 +23,21 @@ func newDumberApp(engine *Engine) purecef.App { | |||||
| 21 | return purecef.NewApp(app) | 23 | return purecef.NewApp(app) | ||
| 22 | } | 24 | } | ||
| 23 | 25 | ||||
| 24 | - | func (a *dumberApp) OnBeforeCommandLineProcessing(_ string, _ purecef.CommandLine) {} | 26 | + | func (a *dumberApp) OnBeforeCommandLineProcessing(processType string, commandLine purecef.CommandLine) { |
| 25 | - | func (a *dumberApp) OnRegisterCustomSchemes(_ purecef.SchemeRegistrar) {} | 27 | + | log := logging.FromContext(a.engine.ctx) |
| 26 | - | func (a *dumberApp) GetResourceBundleHandler() purecef.ResourceBundleHandler { return nil } | 28 | + | cmdline := "" |
| 27 | - | func (a *dumberApp) GetBrowserProcessHandler() purecef.BrowserProcessHandler { return a.bph } | 29 | + | if commandLine != nil { |
| 28 | - | func (a *dumberApp) GetRenderProcessHandler() purecef.RenderProcessHandler { return nil } | 30 | + | cmdline = commandLine.GetCommandLineString() |
| 31 | + | } | |||
| 32 | + | log.Debug(). | |||
| 33 | + | Str("process_type", processType). | |||
| 34 | + | Str("command_line", cmdline). | |||
| 35 | + | Msg("cef: OnBeforeCommandLineProcessing") | |||
| 36 | + | } | |||
| 37 | + | func (a *dumberApp) OnRegisterCustomSchemes(_ purecef.SchemeRegistrar) {} | |||
| 38 | + | func (a *dumberApp) GetResourceBundleHandler() purecef.ResourceBundleHandler { return nil } | |||
| 39 | + | func (a *dumberApp) GetBrowserProcessHandler() purecef.BrowserProcessHandler { return a.bph } | |||
| 40 | + | func (a *dumberApp) GetRenderProcessHandler() purecef.RenderProcessHandler { return nil } | |||
| 29 | 41 | ||||
| 30 | // dumberBPH implements purecef.BrowserProcessHandler. Only | 42 | // dumberBPH implements purecef.BrowserProcessHandler. Only | ||
| 31 | // OnScheduleMessagePumpWork carries real logic; the rest are no-ops. | 43 | // OnScheduleMessagePumpWork carries real logic; the rest are no-ops. | ||
| @@ -35,8 +47,22 @@ type dumberBPH struct { | |||||
| 35 | 47 | ||||
| 36 | func (h *dumberBPH) OnRegisterCustomPreferences(_ purecef.PreferencesType, _ purecef.PreferenceRegistrar) { | 48 | func (h *dumberBPH) OnRegisterCustomPreferences(_ purecef.PreferencesType, _ purecef.PreferenceRegistrar) { | ||
| 37 | } | 49 | } | ||
| 38 | - | func (h *dumberBPH) OnContextInitialized() {} | 50 | + | func (h *dumberBPH) OnContextInitialized() { |
| 39 | - | func (h *dumberBPH) OnBeforeChildProcessLaunch(_ purecef.CommandLine) {} | 51 | + | h.engine.recordContextInitialized() |
| 52 | + | } | |||
| 53 | + | func (h *dumberBPH) OnBeforeChildProcessLaunch(commandLine purecef.CommandLine) { | |||
| 54 | + | processType := "" | |||
| 55 | + | commandLineString := "" | |||
| 56 | + | useAngle := "" | |||
| 57 | + | ozonePlatform := "" | |||
| 58 | + | if commandLine != nil { | |||
| 59 | + | processType = commandLine.GetSwitchValue("type") | |||
| 60 | + | commandLineString = commandLine.GetCommandLineString() | |||
| 61 | + | useAngle = commandLine.GetSwitchValue("use-angle") | |||
| 62 | + | ozonePlatform = commandLine.GetSwitchValue("ozone-platform") | |||
| 63 | + | } | |||
| 64 | + | h.engine.recordChildProcessLaunch(processType, useAngle, ozonePlatform, commandLineString) | |||
| 65 | + | } | |||
| 40 | func (h *dumberBPH) OnAlreadyRunningAppRelaunch(_ purecef.CommandLine, _ string) int32 { return 0 } | 66 | func (h *dumberBPH) OnAlreadyRunningAppRelaunch(_ purecef.CommandLine, _ string) int32 { return 0 } | ||
| 41 | func (h *dumberBPH) GetDefaultClient() purecef.Client { return nil } | 67 | func (h *dumberBPH) GetDefaultClient() purecef.Client { return nil } | ||
| 42 | func (h *dumberBPH) GetDefaultRequestContextHandler() purecef.RequestContextHandler { return nil } | 68 | func (h *dumberBPH) GetDefaultRequestContextHandler() purecef.RequestContextHandler { return nil } | ||
M internal/infrastructure/cef/engine.go +224 -81
| @@ -2,7 +2,8 @@ package cef | |||
| 2 | 2 | ||
| 3 | 3 | import ( | |
| 4 | 4 | "context" | |
| 5 | - | "sync" | |
| 5 | + | "sync/atomic" | |
| 6 | + | "time" | |
| 6 | 7 | ||
| 7 | 8 | purecef "github.com/bnema/purego-cef/cef" | |
| 8 | 9 | "github.com/jwijenbergh/puregotk/v4/glib" | |
| @@ -14,11 +15,11 @@ import ( | |||
| 14 | 15 | // Compile-time interface check. | |
| 15 | 16 | var _ port.Engine = (*Engine)(nil) | |
| 16 | 17 | ||
| 17 | - | // cefMaxTimerDelayMS is the maximum delay between pump ticks. | |
| 18 | - | // Set to 33ms (30fps) as a balance between responsiveness and CPU cost. | |
| 19 | - | // With --disable-gpu-compositing, Chromium rasterizes in software so | |
| 20 | - | // every pump tick has significant CPU cost. | |
| 21 | - | const cefMaxTimerDelayMS int64 = 33 | |
| 18 | + | // pumpTickMS is the interval of the persistent glib timer that checks | |
| 19 | + | // for pending CEF work. This is a polling interval, NOT the frame rate — | |
| 20 | + | // when there's no pending work, the tick is a single atomic load (near-zero | |
| 21 | + | // CPU). When work is pending, it calls DoMessageLoopWork immediately. | |
| 22 | + | const pumpTickMS uint = 4 | |
| 22 | 23 | ||
| 23 | 24 | // Engine implements port.Engine for the CEF browser backend. | |
| 24 | 25 | // It manages the CEF lifecycle and provides access to all engine subsystems. | |
| @@ -28,22 +29,44 @@ type Engine struct { | |||
| 28 | 29 | factory *WebViewFactory | |
| 29 | 30 | pool *WebViewPool | |
| 30 | 31 | ||
| 31 | - | // Adaptive message pump state. OnScheduleMessagePumpWork schedules | |
| 32 | - | // one-shot glib sources; pumpSourceID tracks the pending source so it | |
| 33 | - | // can be cancelled when CEF requests a different delay. | |
| 34 | - | pumpMu sync.Mutex | |
| 35 | - | pumpCB glib.SourceFunc // kept alive for GC | |
| 36 | - | pumpSourceID uint | |
| 37 | - | pumpReady bool // set true once GTK main loop is running | |
| 38 | - | pumpClosing bool | |
| 39 | - | pumpHasPending bool // an OnScheduleMessagePumpWork arrived before pumpReady | |
| 40 | - | pumpPendingMs int64 // delay from the last pre-ready request | |
| 41 | - | ||
| 42 | - | // Reentrancy guard: DoMessageLoopWork can trigger callbacks that | |
| 43 | - | // re-enter the pump. The reference implementation detects this and | |
| 44 | - | // schedules an immediate follow-up instead of recursing. | |
| 32 | + | // pumpRequested is set atomically by OnScheduleMessagePumpWork (which | |
| 33 | + | // can be called from ANY thread — GPU, IO, renderer, etc.). The | |
| 34 | + | // persistent glib timer on the main thread reads and clears this flag. | |
| 35 | + | // Value: 0 = no work, 1 = work requested. | |
| 36 | + | pumpRequested atomic.Int32 | |
| 37 | + | ||
| 38 | + | // Pump lifecycle managed only from the main GTK thread. | |
| 39 | + | pumpCB glib.SourceFunc | |
| 40 | + | pumpSourceID uint | |
| 41 | + | pumpStarted bool | |
| 42 | + | pumpClosing bool | |
| 43 | + | ||
| 44 | + | // Reentrancy guard for DoMessageLoopWork. | |
| 45 | 45 | pumpActive bool | |
| 46 | 46 | pumpReentry bool | |
| 47 | + | ||
| 48 | + | // Diagnostic counters (temporary). | |
| 49 | + | pumpTickCount uint64 | |
| 50 | + | pumpWorkCount uint64 | |
| 51 | + | scheduleCount atomic.Uint64 // incremented from any thread — read from main thread only | |
| 52 | + | ||
| 53 | + | scheduleImmediateCount atomic.Uint64 | |
| 54 | + | scheduleDelayedCount atomic.Uint64 | |
| 55 | + | scheduleLastDelayMs atomic.Int64 | |
| 56 | + | scheduleMaxDelayMs atomic.Int64 | |
| 57 | + | ||
| 58 | + | contextInitializedCount atomic.Uint64 | |
| 59 | + | childLaunchRenderer atomic.Uint64 | |
| 60 | + | childLaunchGPU atomic.Uint64 | |
| 61 | + | childLaunchOther atomic.Uint64 | |
| 62 | + | ||
| 63 | + | browserCreateRequests atomic.Uint64 | |
| 64 | + | browserAfterCreated atomic.Uint64 | |
| 65 | + | browserCreateLastAtMs atomic.Int64 | |
| 66 | + | browserCreateLastResult atomic.Int32 | |
| 67 | + | browserCreateLastWidth atomic.Int32 | |
| 68 | + | browserCreateLastHeight atomic.Int32 | |
| 69 | + | lastStallLoggedCreateSeq uint64 | |
| 47 | 70 | } | |
| 48 | 71 | ||
| 49 | 72 | // Factory returns the WebViewFactory for creating new WebView instances. | |
| @@ -105,26 +128,11 @@ func (e *Engine) ConfigureDownloads(_ context.Context, _ string, _ port.Download | |||
| 105 | 128 | } | |
| 106 | 129 | ||
| 107 | 130 | // OnToolkitReady is called after the UI toolkit has initialized. | |
| 108 | - | // Marks the pump as ready so that OnScheduleMessagePumpWork callbacks | |
| 109 | - | // (which may have arrived during cef_initialize) start scheduling work. | |
| 131 | + | // Starts the persistent pump timer on the GTK main thread. | |
| 110 | 132 | func (e *Engine) OnToolkitReady(_ context.Context) error { | |
| 111 | 133 | log := logging.FromContext(e.ctx) | |
| 112 | - | log.Debug().Msg("cef: OnToolkitReady called, pump is now ready") | |
| 113 | - | ||
| 114 | - | e.pumpMu.Lock() | |
| 115 | - | e.pumpReady = true | |
| 116 | - | hasPending := e.pumpHasPending | |
| 117 | - | pendingMs := e.pumpPendingMs | |
| 118 | - | e.pumpHasPending = false | |
| 119 | - | e.pumpMu.Unlock() | |
| 120 | - | ||
| 121 | - | // Replay any buffered OnScheduleMessagePumpWork that arrived before GTK | |
| 122 | - | // was ready, or kick an immediate pump if none was buffered. | |
| 123 | - | if hasPending { | |
| 124 | - | e.scheduleMessagePumpWork(pendingMs) | |
| 125 | - | } else { | |
| 126 | - | e.scheduleMessagePumpWork(0) | |
| 127 | - | } | |
| 134 | + | log.Debug().Msg("cef: OnToolkitReady called, starting message pump") | |
| 135 | + | e.startMessagePump() | |
| 128 | 136 | return nil | |
| 129 | 137 | } | |
| 130 | 138 | ||
| @@ -143,61 +151,174 @@ func (e *Engine) SetHandlerContext(ctx context.Context) { | |||
| 143 | 151 | e.ctx = ctx | |
| 144 | 152 | } | |
| 145 | 153 | ||
| 146 | - | // --------------------------------------------------------------------------- | |
| 147 | - | // Adaptive CEF message pump (demand-driven via OnScheduleMessagePumpWork) | |
| 148 | - | // --------------------------------------------------------------------------- | |
| 154 | + | const browserCreateStallWarnMS int64 = 1500 | |
| 149 | 155 | ||
| 150 | - | // scheduleMessagePumpWork is called by the BrowserProcessHandler when CEF | |
| 151 | - | // has work to process, and by performMessageLoopWork to re-schedule after | |
| 152 | - | // each pump tick. It replaces any pending one-shot timer with a new one | |
| 153 | - | // matching the requested delay. | |
| 154 | - | func (e *Engine) scheduleMessagePumpWork(delayMs int64) { | |
| 155 | - | e.pumpMu.Lock() | |
| 156 | - | defer e.pumpMu.Unlock() | |
| 156 | + | func (e *Engine) recordContextInitialized() { | |
| 157 | + | count := e.contextInitializedCount.Add(1) | |
| 158 | + | logging.FromContext(e.ctx).Debug(). | |
| 159 | + | Uint64("count", count). | |
| 160 | + | Msg("cef: OnContextInitialized") | |
| 161 | + | } | |
| 162 | + | ||
| 163 | + | func (e *Engine) recordChildProcessLaunch(processType, useAngle, ozonePlatform, commandLine string) { | |
| 164 | + | switch processType { | |
| 165 | + | case "renderer": | |
| 166 | + | e.childLaunchRenderer.Add(1) | |
| 167 | + | case "gpu-process": | |
| 168 | + | e.childLaunchGPU.Add(1) | |
| 169 | + | default: | |
| 170 | + | e.childLaunchOther.Add(1) | |
| 171 | + | } | |
| 157 | 172 | ||
| 158 | - | if e.pumpClosing { | |
| 173 | + | logging.FromContext(e.ctx).Debug(). | |
| 174 | + | Str("process_type", processType). | |
| 175 | + | Str("use_angle", useAngle). | |
| 176 | + | Str("ozone_platform", ozonePlatform). | |
| 177 | + | Str("command_line", commandLine). | |
| 178 | + | Uint64("renderer_launches", e.childLaunchRenderer.Load()). | |
| 179 | + | Uint64("gpu_launches", e.childLaunchGPU.Load()). | |
| 180 | + | Uint64("other_launches", e.childLaunchOther.Load()). | |
| 181 | + | Msg("cef: OnBeforeChildProcessLaunch") | |
| 182 | + | } | |
| 183 | + | ||
| 184 | + | func (e *Engine) recordBrowserCreateRequest(width, height, result int32) { | |
| 185 | + | count := e.browserCreateRequests.Add(1) | |
| 186 | + | e.browserCreateLastAtMs.Store(time.Now().UnixMilli()) | |
| 187 | + | e.browserCreateLastResult.Store(result) | |
| 188 | + | e.browserCreateLastWidth.Store(width) | |
| 189 | + | e.browserCreateLastHeight.Store(height) | |
| 190 | + | ||
| 191 | + | log := logging.FromContext(e.ctx).Debug(). | |
| 192 | + | Uint64("request_count", count). | |
| 193 | + | Int32("width", width). | |
| 194 | + | Int32("height", height). | |
| 195 | + | Int32("result", result). | |
| 196 | + | Msg | |
| 197 | + | if result != 1 { | |
| 198 | + | logging.FromContext(e.ctx).Warn(). | |
| 199 | + | Uint64("request_count", count). | |
| 200 | + | Int32("width", width). | |
| 201 | + | Int32("height", height). | |
| 202 | + | Int32("result", result). | |
| 203 | + | Msg("cef: BrowserHostCreateBrowser returned non-success") | |
| 159 | 204 | return | |
| 160 | 205 | } | |
| 206 | + | log("cef: BrowserHostCreateBrowser returned") | |
| 207 | + | } | |
| 161 | 208 | ||
| 162 | - | // Buffer requests that arrive before the GTK main loop is running. | |
| 163 | - | if !e.pumpReady { | |
| 164 | - | e.pumpHasPending = true | |
| 165 | - | e.pumpPendingMs = delayMs | |
| 209 | + | func (e *Engine) recordBrowserAfterCreated(browser purecef.Browser) { | |
| 210 | + | count := e.browserAfterCreated.Add(1) | |
| 211 | + | browserID := int32(0) | |
| 212 | + | if browser != nil { | |
| 213 | + | browserID = browser.GetIdentifier() | |
| 214 | + | } | |
| 215 | + | logging.FromContext(e.ctx).Debug(). | |
| 216 | + | Uint64("after_created_count", count). | |
| 217 | + | Uint64("create_requests", e.browserCreateRequests.Load()). | |
| 218 | + | Int32("browser_id", browserID). | |
| 219 | + | Msg("cef: browser created") | |
| 220 | + | } | |
| 221 | + | ||
| 222 | + | func (e *Engine) maybeLogBrowserCreateStall() { | |
| 223 | + | if e.pumpTickCount%250 != 0 { | |
| 166 | 224 | return | |
| 167 | 225 | } | |
| 168 | 226 | ||
| 169 | - | // Cancel any pending scheduled work. | |
| 170 | - | if e.pumpSourceID != 0 { | |
| 171 | - | glib.SourceRemove(e.pumpSourceID) | |
| 172 | - | e.pumpSourceID = 0 | |
| 227 | + | createCount := e.browserCreateRequests.Load() | |
| 228 | + | if createCount == 0 || createCount == e.browserAfterCreated.Load() || createCount == e.lastStallLoggedCreateSeq { | |
| 229 | + | return | |
| 173 | 230 | } | |
| 174 | 231 | ||
| 175 | - | // Cap the delay at the maximum tick interval. | |
| 176 | - | if delayMs > cefMaxTimerDelayMS { | |
| 177 | - | delayMs = cefMaxTimerDelayMS | |
| 232 | + | createdAt := e.browserCreateLastAtMs.Load() | |
| 233 | + | if createdAt == 0 { | |
| 234 | + | return | |
| 178 | 235 | } | |
| 179 | 236 | ||
| 180 | - | // The callback is one-shot (returns false). | |
| 181 | - | e.pumpCB = glib.SourceFunc(func(_ uintptr) bool { | |
| 182 | - | e.pumpMu.Lock() | |
| 183 | - | e.pumpSourceID = 0 | |
| 184 | - | e.pumpMu.Unlock() | |
| 237 | + | ageMs := time.Now().UnixMilli() - createdAt | |
| 238 | + | if ageMs < browserCreateStallWarnMS { | |
| 239 | + | return | |
| 240 | + | } | |
| 185 | 241 | ||
| 186 | - | e.performMessageLoopWork() | |
| 187 | - | return false | |
| 188 | - | }) | |
| 242 | + | e.lastStallLoggedCreateSeq = createCount | |
| 243 | + | logging.FromContext(e.ctx).Warn(). | |
| 244 | + | Uint64("create_requests", createCount). | |
| 245 | + | Uint64("after_created", e.browserAfterCreated.Load()). | |
| 246 | + | Int64("create_age_ms", ageMs). | |
| 247 | + | Int32("last_create_result", e.browserCreateLastResult.Load()). | |
| 248 | + | Int32("last_create_width", e.browserCreateLastWidth.Load()). | |
| 249 | + | Int32("last_create_height", e.browserCreateLastHeight.Load()). | |
| 250 | + | Uint64("pump_ticks", e.pumpTickCount). | |
| 251 | + | Uint64("pump_work", e.pumpWorkCount). | |
| 252 | + | Uint64("schedule_calls", e.scheduleCount.Load()). | |
| 253 | + | Uint64("schedule_immediate", e.scheduleImmediateCount.Load()). | |
| 254 | + | Uint64("schedule_delayed", e.scheduleDelayedCount.Load()). | |
| 255 | + | Int64("last_schedule_delay_ms", e.scheduleLastDelayMs.Load()). | |
| 256 | + | Int64("max_schedule_delay_ms", e.scheduleMaxDelayMs.Load()). | |
| 257 | + | Uint64("context_initialized", e.contextInitializedCount.Load()). | |
| 258 | + | Uint64("renderer_launches", e.childLaunchRenderer.Load()). | |
| 259 | + | Uint64("gpu_launches", e.childLaunchGPU.Load()). | |
| 260 | + | Uint64("other_launches", e.childLaunchOther.Load()). | |
| 261 | + | Msg("cef: browser creation appears stalled") | |
| 262 | + | } | |
| 263 | + | ||
| 264 | + | // --------------------------------------------------------------------------- | |
| 265 | + | // CEF message pump — thread-safe via atomic signaling | |
| 266 | + | // | |
| 267 | + | // OnScheduleMessagePumpWork can be called from ANY Chromium thread (UI, IO, | |
| 268 | + | // GPU compositor, etc.). It MUST NOT call any glib/GTK functions. Instead it | |
| 269 | + | // sets an atomic flag. A persistent glib timer on the main GTK thread polls | |
| 270 | + | // this flag and calls DoMessageLoopWork when work is pending. | |
| 271 | + | // | |
| 272 | + | // CPU cost when idle: one atomic load per tick (4ms) = negligible. | |
| 273 | + | // Latency: max 4ms before CEF work is processed. | |
| 274 | + | // --------------------------------------------------------------------------- | |
| 189 | 275 | ||
| 276 | + | // scheduleMessagePumpWork is called by OnScheduleMessagePumpWork from any | |
| 277 | + | // thread. It only sets an atomic flag — no glib calls, no allocations. | |
| 278 | + | // IMPORTANT: No logging, no context access, no allocations here — this can | |
| 279 | + | // be called from native CEF threads (GPU, IO, renderer). | |
| 280 | + | func (e *Engine) scheduleMessagePumpWork(delayMs int64) { | |
| 281 | + | e.pumpRequested.Store(1) | |
| 282 | + | e.scheduleCount.Add(1) | |
| 283 | + | e.scheduleLastDelayMs.Store(delayMs) | |
| 190 | 284 | if delayMs <= 0 { | |
| 191 | - | e.pumpSourceID = glib.IdleAdd(&e.pumpCB, 0) | |
| 192 | - | } else { | |
| 193 | - | e.pumpSourceID = glib.TimeoutAdd(uint(delayMs), &e.pumpCB, 0) | |
| 285 | + | e.scheduleImmediateCount.Add(1) | |
| 286 | + | return | |
| 287 | + | } | |
| 288 | + | ||
| 289 | + | e.scheduleDelayedCount.Add(1) | |
| 290 | + | for { | |
| 291 | + | current := e.scheduleMaxDelayMs.Load() | |
| 292 | + | if delayMs <= current { | |
| 293 | + | return | |
| 294 | + | } | |
| 295 | + | if e.scheduleMaxDelayMs.CompareAndSwap(current, delayMs) { | |
| 296 | + | return | |
| 297 | + | } | |
| 194 | 298 | } | |
| 195 | 299 | } | |
| 196 | 300 | ||
| 197 | - | func (e *Engine) stopMessagePump() { | |
| 198 | - | e.pumpMu.Lock() | |
| 199 | - | defer e.pumpMu.Unlock() | |
| 301 | + | func (e *Engine) startMessagePump() { | |
| 302 | + | if e.pumpStarted || e.pumpClosing { | |
| 303 | + | return | |
| 304 | + | } | |
| 200 | 305 | ||
| 306 | + | // Ensure there's a pending request so the first tick does work. | |
| 307 | + | e.pumpRequested.Store(1) | |
| 308 | + | ||
| 309 | + | e.pumpCB = glib.SourceFunc(func(_ uintptr) bool { | |
| 310 | + | if e.pumpClosing { | |
| 311 | + | return false | |
| 312 | + | } | |
| 313 | + | e.pumpTick() | |
| 314 | + | return true // keep the timer running | |
| 315 | + | }) | |
| 316 | + | ||
| 317 | + | e.pumpSourceID = glib.TimeoutAdd(pumpTickMS, &e.pumpCB, 0) | |
| 318 | + | e.pumpStarted = true | |
| 319 | + | } | |
| 320 | + | ||
| 321 | + | func (e *Engine) stopMessagePump() { | |
| 201 | 322 | e.pumpClosing = true | |
| 202 | 323 | if e.pumpSourceID != 0 { | |
| 203 | 324 | glib.SourceRemove(e.pumpSourceID) | |
| @@ -205,10 +326,28 @@ func (e *Engine) stopMessagePump() { | |||
| 205 | 326 | } | |
| 206 | 327 | } | |
| 207 | 328 | ||
| 329 | + | // pumpTick is called on the GTK main thread by the persistent timer. | |
| 330 | + | // It checks if CEF requested work and processes it. | |
| 331 | + | func (e *Engine) pumpTick() { | |
| 332 | + | e.pumpTickCount++ | |
| 333 | + | e.maybeLogBrowserCreateStall() | |
| 334 | + | // Check if work was requested (from any thread). | |
| 335 | + | if e.pumpRequested.Swap(0) == 0 { | |
| 336 | + | return // nothing to do | |
| 337 | + | } | |
| 338 | + | ||
| 339 | + | e.pumpWorkCount++ | |
| 340 | + | if e.pumpWorkCount <= 20 || e.pumpWorkCount%100 == 0 { | |
| 341 | + | logging.FromContext(e.ctx).Debug(). | |
| 342 | + | Uint64("tick", e.pumpTickCount). | |
| 343 | + | Uint64("work", e.pumpWorkCount). | |
| 344 | + | Uint64("schedule_calls", e.scheduleCount.Load()). | |
| 345 | + | Msg("cef: pump doing work") | |
| 346 | + | } | |
| 347 | + | e.performMessageLoopWork() | |
| 348 | + | } | |
| 349 | + | ||
| 208 | 350 | // performMessageLoopWork calls DoMessageLoopWork with reentrancy protection. | |
| 209 | - | // If CEF called OnScheduleMessagePumpWork re-entrantly during DoMessageLoopWork, | |
| 210 | - | // we re-schedule immediately. Otherwise the pump goes idle — CEF will call | |
| 211 | - | // OnScheduleMessagePumpWork when it has new work, which restarts the pump. | |
| 212 | 351 | func (e *Engine) performMessageLoopWork() { | |
| 213 | 352 | if e.pumpActive { | |
| 214 | 353 | e.pumpReentry = true | |
| @@ -220,10 +359,14 @@ func (e *Engine) performMessageLoopWork() { | |||
| 220 | 359 | purecef.DoMessageLoopWork() | |
| 221 | 360 | e.pumpActive = false | |
| 222 | 361 | ||
| 362 | + | // If CEF re-entered during the call (called OnScheduleMessagePumpWork | |
| 363 | + | // from within DoMessageLoopWork), the atomic flag is already set. | |
| 364 | + | // The next timer tick (within 4ms) will pick it up. | |
| 365 | + | // For immediate re-entrant work, do one more pass now. | |
| 223 | 366 | if e.pumpReentry { | |
| 224 | - | // CEF requested work re-entrantly — schedule immediate follow-up. | |
| 225 | - | e.scheduleMessagePumpWork(0) | |
| 367 | + | e.pumpActive = true | |
| 368 | + | e.pumpReentry = false | |
| 369 | + | purecef.DoMessageLoopWork() | |
| 370 | + | e.pumpActive = false | |
| 226 | 371 | } | |
| 227 | - | // Otherwise: pump goes idle. CEF will call OnScheduleMessagePumpWork | |
| 228 | - | // when new work arrives (timer, IPC, input response, etc.). | |
| 229 | 372 | } | |
| @@ -2,7 +2,8 @@ package cef | |||||
| 2 | 2 | ||||
| 3 | import ( | 3 | import ( | ||
| 4 | "context" | 4 | "context" | ||
| 5 | - | "sync" | 5 | + | "sync/atomic" |
| 6 | + | "time" | |||
| 6 | 7 | ||||
| 7 | purecef "github.com/bnema/purego-cef/cef" | 8 | purecef "github.com/bnema/purego-cef/cef" | ||
| 8 | "github.com/jwijenbergh/puregotk/v4/glib" | 9 | "github.com/jwijenbergh/puregotk/v4/glib" | ||
| @@ -14,11 +15,11 @@ import ( | |||||
| 14 | // Compile-time interface check. | 15 | // Compile-time interface check. | ||
| 15 | var _ port.Engine = (*Engine)(nil) | 16 | var _ port.Engine = (*Engine)(nil) | ||
| 16 | 17 | ||||
| 17 | - | // cefMaxTimerDelayMS is the maximum delay between pump ticks. | 18 | + | // pumpTickMS is the interval of the persistent glib timer that checks |
| 18 | - | // Set to 33ms (30fps) as a balance between responsiveness and CPU cost. | 19 | + | // for pending CEF work. This is a polling interval, NOT the frame rate — |
| 19 | - | // With --disable-gpu-compositing, Chromium rasterizes in software so | 20 | + | // when there's no pending work, the tick is a single atomic load (near-zero |
| 20 | - | // every pump tick has significant CPU cost. | 21 | + | // CPU). When work is pending, it calls DoMessageLoopWork immediately. |
| 21 | - | const cefMaxTimerDelayMS int64 = 33 | 22 | + | const pumpTickMS uint = 4 |
| 22 | 23 | ||||
| 23 | // Engine implements port.Engine for the CEF browser backend. | 24 | // Engine implements port.Engine for the CEF browser backend. | ||
| 24 | // It manages the CEF lifecycle and provides access to all engine subsystems. | 25 | // It manages the CEF lifecycle and provides access to all engine subsystems. | ||
| @@ -28,22 +29,44 @@ type Engine struct { | |||||
| 28 | factory *WebViewFactory | 29 | factory *WebViewFactory | ||
| 29 | pool *WebViewPool | 30 | pool *WebViewPool | ||
| 30 | 31 | ||||
| 31 | - | // Adaptive message pump state. OnScheduleMessagePumpWork schedules | 32 | + | // pumpRequested is set atomically by OnScheduleMessagePumpWork (which |
| 32 | - | // one-shot glib sources; pumpSourceID tracks the pending source so it | 33 | + | // can be called from ANY thread — GPU, IO, renderer, etc.). The |
| 33 | - | // can be cancelled when CEF requests a different delay. | 34 | + | // persistent glib timer on the main thread reads and clears this flag. |
| 34 | - | pumpMu sync.Mutex | 35 | + | // Value: 0 = no work, 1 = work requested. |
| 35 | - | pumpCB glib.SourceFunc // kept alive for GC | 36 | + | pumpRequested atomic.Int32 |
| 36 | - | pumpSourceID uint | 37 | + | |
| 37 | - | pumpReady bool // set true once GTK main loop is running | 38 | + | // Pump lifecycle managed only from the main GTK thread. |
| 38 | - | pumpClosing bool | 39 | + | pumpCB glib.SourceFunc |
| 39 | - | pumpHasPending bool // an OnScheduleMessagePumpWork arrived before pumpReady | 40 | + | pumpSourceID uint |
| 40 | - | pumpPendingMs int64 // delay from the last pre-ready request | 41 | + | pumpStarted bool |
| 41 | - | 42 | + | pumpClosing bool | |
| 42 | - | // Reentrancy guard: DoMessageLoopWork can trigger callbacks that | 43 | + | |
| 43 | - | // re-enter the pump. The reference implementation detects this and | 44 | + | // Reentrancy guard for DoMessageLoopWork. |
| 44 | - | // schedules an immediate follow-up instead of recursing. | |||
| 45 | pumpActive bool | 45 | pumpActive bool | ||
| 46 | pumpReentry bool | 46 | pumpReentry bool | ||
| 47 | + | ||||
| 48 | + | // Diagnostic counters (temporary). | |||
| 49 | + | pumpTickCount uint64 | |||
| 50 | + | pumpWorkCount uint64 | |||
| 51 | + | scheduleCount atomic.Uint64 // incremented from any thread — read from main thread only | |||
| 52 | + | ||||
| 53 | + | scheduleImmediateCount atomic.Uint64 | |||
| 54 | + | scheduleDelayedCount atomic.Uint64 | |||
| 55 | + | scheduleLastDelayMs atomic.Int64 | |||
| 56 | + | scheduleMaxDelayMs atomic.Int64 | |||
| 57 | + | ||||
| 58 | + | contextInitializedCount atomic.Uint64 | |||
| 59 | + | childLaunchRenderer atomic.Uint64 | |||
| 60 | + | childLaunchGPU atomic.Uint64 | |||
| 61 | + | childLaunchOther atomic.Uint64 | |||
| 62 | + | ||||
| 63 | + | browserCreateRequests atomic.Uint64 | |||
| 64 | + | browserAfterCreated atomic.Uint64 | |||
| 65 | + | browserCreateLastAtMs atomic.Int64 | |||
| 66 | + | browserCreateLastResult atomic.Int32 | |||
| 67 | + | browserCreateLastWidth atomic.Int32 | |||
| 68 | + | browserCreateLastHeight atomic.Int32 | |||
| 69 | + | lastStallLoggedCreateSeq uint64 | |||
| 47 | } | 70 | } | ||
| 48 | 71 | ||||
| 49 | // Factory returns the WebViewFactory for creating new WebView instances. | 72 | // Factory returns the WebViewFactory for creating new WebView instances. | ||
| @@ -105,26 +128,11 @@ func (e *Engine) ConfigureDownloads(_ context.Context, _ string, _ port.Download | |||||
| 105 | } | 128 | } | ||
| 106 | 129 | ||||
| 107 | // OnToolkitReady is called after the UI toolkit has initialized. | 130 | // OnToolkitReady is called after the UI toolkit has initialized. | ||
| 108 | - | // Marks the pump as ready so that OnScheduleMessagePumpWork callbacks | 131 | + | // Starts the persistent pump timer on the GTK main thread. |
| 109 | - | // (which may have arrived during cef_initialize) start scheduling work. | |||
| 110 | func (e *Engine) OnToolkitReady(_ context.Context) error { | 132 | func (e *Engine) OnToolkitReady(_ context.Context) error { | ||
| 111 | log := logging.FromContext(e.ctx) | 133 | log := logging.FromContext(e.ctx) | ||
| 112 | - | log.Debug().Msg("cef: OnToolkitReady called, pump is now ready") | 134 | + | log.Debug().Msg("cef: OnToolkitReady called, starting message pump") |
| 113 | - | 135 | + | e.startMessagePump() | |
| 114 | - | e.pumpMu.Lock() | |||
| 115 | - | e.pumpReady = true | |||
| 116 | - | hasPending := e.pumpHasPending | |||
| 117 | - | pendingMs := e.pumpPendingMs | |||
| 118 | - | e.pumpHasPending = false | |||
| 119 | - | e.pumpMu.Unlock() | |||
| 120 | - | ||||
| 121 | - | // Replay any buffered OnScheduleMessagePumpWork that arrived before GTK | |||
| 122 | - | // was ready, or kick an immediate pump if none was buffered. | |||
| 123 | - | if hasPending { | |||
| 124 | - | e.scheduleMessagePumpWork(pendingMs) | |||
| 125 | - | } else { | |||
| 126 | - | e.scheduleMessagePumpWork(0) | |||
| 127 | - | } | |||
| 128 | return nil | 136 | return nil | ||
| 129 | } | 137 | } | ||
| 130 | 138 | ||||
| @@ -143,61 +151,174 @@ func (e *Engine) SetHandlerContext(ctx context.Context) { | |||||
| 143 | e.ctx = ctx | 151 | e.ctx = ctx | ||
| 144 | } | 152 | } | ||
| 145 | 153 | ||||
| 146 | - | // --------------------------------------------------------------------------- | 154 | + | const browserCreateStallWarnMS int64 = 1500 |
| 147 | - | // Adaptive CEF message pump (demand-driven via OnScheduleMessagePumpWork) | |||
| 148 | - | // --------------------------------------------------------------------------- | |||
| 149 | 155 | ||||
| 150 | - | // scheduleMessagePumpWork is called by the BrowserProcessHandler when CEF | 156 | + | func (e *Engine) recordContextInitialized() { |
| 151 | - | // has work to process, and by performMessageLoopWork to re-schedule after | 157 | + | count := e.contextInitializedCount.Add(1) |
| 152 | - | // each pump tick. It replaces any pending one-shot timer with a new one | 158 | + | logging.FromContext(e.ctx).Debug(). |
| 153 | - | // matching the requested delay. | 159 | + | Uint64("count", count). |
| 154 | - | func (e *Engine) scheduleMessagePumpWork(delayMs int64) { | 160 | + | Msg("cef: OnContextInitialized") |
| 155 | - | e.pumpMu.Lock() | 161 | + | } |
| 156 | - | defer e.pumpMu.Unlock() | 162 | + | |
| 163 | + | func (e *Engine) recordChildProcessLaunch(processType, useAngle, ozonePlatform, commandLine string) { | |||
| 164 | + | switch processType { | |||
| 165 | + | case "renderer": | |||
| 166 | + | e.childLaunchRenderer.Add(1) | |||
| 167 | + | case "gpu-process": | |||
| 168 | + | e.childLaunchGPU.Add(1) | |||
| 169 | + | default: | |||
| 170 | + | e.childLaunchOther.Add(1) | |||
| 171 | + | } | |||
| 157 | 172 | ||||
| 158 | - | if e.pumpClosing { | 173 | + | logging.FromContext(e.ctx).Debug(). |
| 174 | + | Str("process_type", processType). | |||
| 175 | + | Str("use_angle", useAngle). | |||
| 176 | + | Str("ozone_platform", ozonePlatform). | |||
| 177 | + | Str("command_line", commandLine). | |||
| 178 | + | Uint64("renderer_launches", e.childLaunchRenderer.Load()). | |||
| 179 | + | Uint64("gpu_launches", e.childLaunchGPU.Load()). | |||
| 180 | + | Uint64("other_launches", e.childLaunchOther.Load()). | |||
| 181 | + | Msg("cef: OnBeforeChildProcessLaunch") | |||
| 182 | + | } | |||
| 183 | + | ||||
| 184 | + | func (e *Engine) recordBrowserCreateRequest(width, height, result int32) { | |||
| 185 | + | count := e.browserCreateRequests.Add(1) | |||
| 186 | + | e.browserCreateLastAtMs.Store(time.Now().UnixMilli()) | |||
| 187 | + | e.browserCreateLastResult.Store(result) | |||
| 188 | + | e.browserCreateLastWidth.Store(width) | |||
| 189 | + | e.browserCreateLastHeight.Store(height) | |||
| 190 | + | ||||
| 191 | + | log := logging.FromContext(e.ctx).Debug(). | |||
| 192 | + | Uint64("request_count", count). | |||
| 193 | + | Int32("width", width). | |||
| 194 | + | Int32("height", height). | |||
| 195 | + | Int32("result", result). | |||
| 196 | + | Msg | |||
| 197 | + | if result != 1 { | |||
| 198 | + | logging.FromContext(e.ctx).Warn(). | |||
| 199 | + | Uint64("request_count", count). | |||
| 200 | + | Int32("width", width). | |||
| 201 | + | Int32("height", height). | |||
| 202 | + | Int32("result", result). | |||
| 203 | + | Msg("cef: BrowserHostCreateBrowser returned non-success") | |||
| 159 | return | 204 | return | ||
| 160 | } | 205 | } | ||
| 206 | + | log("cef: BrowserHostCreateBrowser returned") | |||
| 207 | + | } | |||
| 161 | 208 | ||||
| 162 | - | // Buffer requests that arrive before the GTK main loop is running. | 209 | + | func (e *Engine) recordBrowserAfterCreated(browser purecef.Browser) { |
| 163 | - | if !e.pumpReady { | 210 | + | count := e.browserAfterCreated.Add(1) |
| 164 | - | e.pumpHasPending = true | 211 | + | browserID := int32(0) |
| 165 | - | e.pumpPendingMs = delayMs | 212 | + | if browser != nil { |
| 213 | + | browserID = browser.GetIdentifier() | |||
| 214 | + | } | |||
| 215 | + | logging.FromContext(e.ctx).Debug(). | |||
| 216 | + | Uint64("after_created_count", count). | |||
| 217 | + | Uint64("create_requests", e.browserCreateRequests.Load()). | |||
| 218 | + | Int32("browser_id", browserID). | |||
| 219 | + | Msg("cef: browser created") | |||
| 220 | + | } | |||
| 221 | + | ||||
| 222 | + | func (e *Engine) maybeLogBrowserCreateStall() { | |||
| 223 | + | if e.pumpTickCount%250 != 0 { | |||
| 166 | return | 224 | return | ||
| 167 | } | 225 | } | ||
| 168 | 226 | ||||
| 169 | - | // Cancel any pending scheduled work. | 227 | + | createCount := e.browserCreateRequests.Load() |
| 170 | - | if e.pumpSourceID != 0 { | 228 | + | if createCount == 0 || createCount == e.browserAfterCreated.Load() || createCount == e.lastStallLoggedCreateSeq { |
| 171 | - | glib.SourceRemove(e.pumpSourceID) | 229 | + | return |
| 172 | - | e.pumpSourceID = 0 | |||
| 173 | } | 230 | } | ||
| 174 | 231 | ||||
| 175 | - | // Cap the delay at the maximum tick interval. | 232 | + | createdAt := e.browserCreateLastAtMs.Load() |
| 176 | - | if delayMs > cefMaxTimerDelayMS { | 233 | + | if createdAt == 0 { |
| 177 | - | delayMs = cefMaxTimerDelayMS | 234 | + | return |
| 178 | } | 235 | } | ||
| 179 | 236 | ||||
| 180 | - | // The callback is one-shot (returns false). | 237 | + | ageMs := time.Now().UnixMilli() - createdAt |
| 181 | - | e.pumpCB = glib.SourceFunc(func(_ uintptr) bool { | 238 | + | if ageMs < browserCreateStallWarnMS { |
| 182 | - | e.pumpMu.Lock() | 239 | + | return |
| 183 | - | e.pumpSourceID = 0 | 240 | + | } |
| 184 | - | e.pumpMu.Unlock() | |||
| 185 | 241 | ||||
| 186 | - | e.performMessageLoopWork() | 242 | + | e.lastStallLoggedCreateSeq = createCount |
| 187 | - | return false | 243 | + | logging.FromContext(e.ctx).Warn(). |
| 188 | - | }) | 244 | + | Uint64("create_requests", createCount). |
| 245 | + | Uint64("after_created", e.browserAfterCreated.Load()). | |||
| 246 | + | Int64("create_age_ms", ageMs). | |||
| 247 | + | Int32("last_create_result", e.browserCreateLastResult.Load()). | |||
| 248 | + | Int32("last_create_width", e.browserCreateLastWidth.Load()). | |||
| 249 | + | Int32("last_create_height", e.browserCreateLastHeight.Load()). | |||
| 250 | + | Uint64("pump_ticks", e.pumpTickCount). | |||
| 251 | + | Uint64("pump_work", e.pumpWorkCount). | |||
| 252 | + | Uint64("schedule_calls", e.scheduleCount.Load()). | |||
| 253 | + | Uint64("schedule_immediate", e.scheduleImmediateCount.Load()). | |||
| 254 | + | Uint64("schedule_delayed", e.scheduleDelayedCount.Load()). | |||
| 255 | + | Int64("last_schedule_delay_ms", e.scheduleLastDelayMs.Load()). | |||
| 256 | + | Int64("max_schedule_delay_ms", e.scheduleMaxDelayMs.Load()). | |||
| 257 | + | Uint64("context_initialized", e.contextInitializedCount.Load()). | |||
| 258 | + | Uint64("renderer_launches", e.childLaunchRenderer.Load()). | |||
| 259 | + | Uint64("gpu_launches", e.childLaunchGPU.Load()). | |||
| 260 | + | Uint64("other_launches", e.childLaunchOther.Load()). | |||
| 261 | + | Msg("cef: browser creation appears stalled") | |||
| 262 | + | } | |||
| 263 | + | ||||
| 264 | + | // --------------------------------------------------------------------------- | |||
| 265 | + | // CEF message pump — thread-safe via atomic signaling | |||
| 266 | + | // | |||
| 267 | + | // OnScheduleMessagePumpWork can be called from ANY Chromium thread (UI, IO, | |||
| 268 | + | // GPU compositor, etc.). It MUST NOT call any glib/GTK functions. Instead it | |||
| 269 | + | // sets an atomic flag. A persistent glib timer on the main GTK thread polls | |||
| 270 | + | // this flag and calls DoMessageLoopWork when work is pending. | |||
| 271 | + | // | |||
| 272 | + | // CPU cost when idle: one atomic load per tick (4ms) = negligible. | |||
| 273 | + | // Latency: max 4ms before CEF work is processed. | |||
| 274 | + | // --------------------------------------------------------------------------- | |||
| 189 | 275 | ||||
| 276 | + | // scheduleMessagePumpWork is called by OnScheduleMessagePumpWork from any | |||
| 277 | + | // thread. It only sets an atomic flag — no glib calls, no allocations. | |||
| 278 | + | // IMPORTANT: No logging, no context access, no allocations here — this can | |||
| 279 | + | // be called from native CEF threads (GPU, IO, renderer). | |||
| 280 | + | func (e *Engine) scheduleMessagePumpWork(delayMs int64) { | |||
| 281 | + | e.pumpRequested.Store(1) | |||
| 282 | + | e.scheduleCount.Add(1) | |||
| 283 | + | e.scheduleLastDelayMs.Store(delayMs) | |||
| 190 | if delayMs <= 0 { | 284 | if delayMs <= 0 { | ||
| 191 | - | e.pumpSourceID = glib.IdleAdd(&e.pumpCB, 0) | 285 | + | e.scheduleImmediateCount.Add(1) |
| 192 | - | } else { | 286 | + | return |
| 193 | - | e.pumpSourceID = glib.TimeoutAdd(uint(delayMs), &e.pumpCB, 0) | 287 | + | } |
| 288 | + | ||||
| 289 | + | e.scheduleDelayedCount.Add(1) | |||
| 290 | + | for { | |||
| 291 | + | current := e.scheduleMaxDelayMs.Load() | |||
| 292 | + | if delayMs <= current { | |||
| 293 | + | return | |||
| 294 | + | } | |||
| 295 | + | if e.scheduleMaxDelayMs.CompareAndSwap(current, delayMs) { | |||
| 296 | + | return | |||
| 297 | + | } | |||
| 194 | } | 298 | } | ||
| 195 | } | 299 | } | ||
| 196 | 300 | ||||
| 197 | - | func (e *Engine) stopMessagePump() { | 301 | + | func (e *Engine) startMessagePump() { |
| 198 | - | e.pumpMu.Lock() | 302 | + | if e.pumpStarted || e.pumpClosing { |
| 199 | - | defer e.pumpMu.Unlock() | 303 | + | return |
| 304 | + | } | |||
| 200 | 305 | ||||
| 306 | + | // Ensure there's a pending request so the first tick does work. | |||
| 307 | + | e.pumpRequested.Store(1) | |||
| 308 | + | ||||
| 309 | + | e.pumpCB = glib.SourceFunc(func(_ uintptr) bool { | |||
| 310 | + | if e.pumpClosing { | |||
| 311 | + | return false | |||
| 312 | + | } | |||
| 313 | + | e.pumpTick() | |||
| 314 | + | return true // keep the timer running | |||
| 315 | + | }) | |||
| 316 | + | ||||
| 317 | + | e.pumpSourceID = glib.TimeoutAdd(pumpTickMS, &e.pumpCB, 0) | |||
| 318 | + | e.pumpStarted = true | |||
| 319 | + | } | |||
| 320 | + | ||||
| 321 | + | func (e *Engine) stopMessagePump() { | |||
| 201 | e.pumpClosing = true | 322 | e.pumpClosing = true | ||
| 202 | if e.pumpSourceID != 0 { | 323 | if e.pumpSourceID != 0 { | ||
| 203 | glib.SourceRemove(e.pumpSourceID) | 324 | glib.SourceRemove(e.pumpSourceID) | ||
| @@ -205,10 +326,28 @@ func (e *Engine) stopMessagePump() { | |||||
| 205 | } | 326 | } | ||
| 206 | } | 327 | } | ||
| 207 | 328 | ||||
| 329 | + | // pumpTick is called on the GTK main thread by the persistent timer. | |||
| 330 | + | // It checks if CEF requested work and processes it. | |||
| 331 | + | func (e *Engine) pumpTick() { | |||
| 332 | + | e.pumpTickCount++ | |||
| 333 | + | e.maybeLogBrowserCreateStall() | |||
| 334 | + | // Check if work was requested (from any thread). | |||
| 335 | + | if e.pumpRequested.Swap(0) == 0 { | |||
| 336 | + | return // nothing to do | |||
| 337 | + | } | |||
| 338 | + | ||||
| 339 | + | e.pumpWorkCount++ | |||
| 340 | + | if e.pumpWorkCount <= 20 || e.pumpWorkCount%100 == 0 { | |||
| 341 | + | logging.FromContext(e.ctx).Debug(). | |||
| 342 | + | Uint64("tick", e.pumpTickCount). | |||
| 343 | + | Uint64("work", e.pumpWorkCount). | |||
| 344 | + | Uint64("schedule_calls", e.scheduleCount.Load()). | |||
| 345 | + | Msg("cef: pump doing work") | |||
| 346 | + | } | |||
| 347 | + | e.performMessageLoopWork() | |||
| 348 | + | } | |||
| 349 | + | ||||
| 208 | // performMessageLoopWork calls DoMessageLoopWork with reentrancy protection. | 350 | // performMessageLoopWork calls DoMessageLoopWork with reentrancy protection. | ||
| 209 | - | // If CEF called OnScheduleMessagePumpWork re-entrantly during DoMessageLoopWork, | |||
| 210 | - | // we re-schedule immediately. Otherwise the pump goes idle — CEF will call | |||
| 211 | - | // OnScheduleMessagePumpWork when it has new work, which restarts the pump. | |||
| 212 | func (e *Engine) performMessageLoopWork() { | 351 | func (e *Engine) performMessageLoopWork() { | ||
| 213 | if e.pumpActive { | 352 | if e.pumpActive { | ||
| 214 | e.pumpReentry = true | 353 | e.pumpReentry = true | ||
| @@ -220,10 +359,14 @@ func (e *Engine) performMessageLoopWork() { | |||||
| 220 | purecef.DoMessageLoopWork() | 359 | purecef.DoMessageLoopWork() | ||
| 221 | e.pumpActive = false | 360 | e.pumpActive = false | ||
| 222 | 361 | ||||
| 362 | + | // If CEF re-entered during the call (called OnScheduleMessagePumpWork | |||
| 363 | + | // from within DoMessageLoopWork), the atomic flag is already set. | |||
| 364 | + | // The next timer tick (within 4ms) will pick it up. | |||
| 365 | + | // For immediate re-entrant work, do one more pass now. | |||
| 223 | if e.pumpReentry { | 366 | if e.pumpReentry { | ||
| 224 | - | // CEF requested work re-entrantly — schedule immediate follow-up. | 367 | + | e.pumpActive = true |
| 225 | - | e.scheduleMessagePumpWork(0) | 368 | + | e.pumpReentry = false |
| 369 | + | purecef.DoMessageLoopWork() | |||
| 370 | + | e.pumpActive = false | |||
| 226 | } | 371 | } | ||
| 227 | - | // Otherwise: pump goes idle. CEF will call OnScheduleMessagePumpWork | |||
| 228 | - | // when new work arrives (timer, IPC, input response, etc.). | |||
| 229 | } | 372 | } | ||
M internal/infrastructure/cef/engine_init.go +1 -1
| @@ -74,7 +74,7 @@ func NewEngine(ctx context.Context, cfg config.CEFEngineConfig) (*Engine, error) | |||
| 74 | 74 | ||
| 75 | 75 | // 4. Create factory + pool and wire them into the engine. | |
| 76 | 76 | scale := int32(1) // TODO: detect from GDK | |
| 77 | - | factory := newWebViewFactory(gl, scale) | |
| 77 | + | factory := newWebViewFactory(eng, gl, scale) | |
| 78 | 78 | pool := newWebViewPool(factory) | |
| 79 | 79 | ||
| 80 | 80 | eng.gl = gl | |
| @@ -74,7 +74,7 @@ func NewEngine(ctx context.Context, cfg config.CEFEngineConfig) (*Engine, error) | |||||
| 74 | 74 | ||||
| 75 | // 4. Create factory + pool and wire them into the engine. | 75 | // 4. Create factory + pool and wire them into the engine. | ||
| 76 | scale := int32(1) // TODO: detect from GDK | 76 | scale := int32(1) // TODO: detect from GDK | ||
| 77 | - | factory := newWebViewFactory(gl, scale) | 77 | + | factory := newWebViewFactory(eng, gl, scale) |
| 78 | pool := newWebViewPool(factory) | 78 | pool := newWebViewPool(factory) | ||
| 79 | 79 | ||||
| 80 | eng.gl = gl | 80 | eng.gl = gl | ||
M internal/infrastructure/cef/factory.go +21 -5
| @@ -7,6 +7,7 @@ import ( | |||
| 7 | 7 | purecef "github.com/bnema/purego-cef/cef" | |
| 8 | 8 | ||
| 9 | 9 | "github.com/bnema/dumber/internal/application/port" | |
| 10 | + | "github.com/bnema/dumber/internal/logging" | |
| 10 | 11 | ) | |
| 11 | 12 | ||
| 12 | 13 | // Compile-time interface check. | |
| @@ -16,6 +17,7 @@ var _ port.WebViewFactory = (*WebViewFactory)(nil) | |||
| 16 | 17 | // gets a unique ID, its own renderPipeline and inputBridge, and an | |
| 17 | 18 | // asynchronously-created CEF browser (via BrowserHostCreateBrowser). | |
| 18 | 19 | type WebViewFactory struct { | |
| 20 | + | engine *Engine | |
| 19 | 21 | gl *glLoader | |
| 20 | 22 | nextID atomic.Uint64 | |
| 21 | 23 | scale int32 | |
| @@ -23,13 +25,14 @@ type WebViewFactory struct { | |||
| 23 | 25 | ||
| 24 | 26 | // newWebViewFactory returns a factory that will create WebViews using the | |
| 25 | 27 | // given GL loader and HiDPI scale factor. | |
| 26 | - | func newWebViewFactory(gl *glLoader, scale int32) *WebViewFactory { | |
| 28 | + | func newWebViewFactory(engine *Engine, gl *glLoader, scale int32) *WebViewFactory { | |
| 27 | 29 | if scale < 1 { | |
| 28 | 30 | scale = 1 | |
| 29 | 31 | } | |
| 30 | 32 | return &WebViewFactory{ | |
| 31 | - | gl: gl, | |
| 32 | - | scale: scale, | |
| 33 | + | engine: engine, | |
| 34 | + | gl: gl, | |
| 35 | + | scale: scale, | |
| 33 | 36 | } | |
| 34 | 37 | } | |
| 35 | 38 | ||
| @@ -44,6 +47,7 @@ func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) { | |||
| 44 | 47 | wv := &WebView{ | |
| 45 | 48 | id: id, | |
| 46 | 49 | ctx: ctx, | |
| 50 | + | engine: f.engine, | |
| 47 | 51 | pipeline: pipeline, | |
| 48 | 52 | } | |
| 49 | 53 | ||
| @@ -77,10 +81,12 @@ func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) { | |||
| 77 | 81 | } | |
| 78 | 82 | ||
| 79 | 83 | // When the GL area gets its first non-zero size, create the browser. | |
| 80 | - | pipeline.onFirstResize = func(_, _ int32) { | |
| 84 | + | pipeline.onFirstResize = func(w, h int32) { | |
| 85 | + | log := logging.FromContext(ctx) | |
| 86 | + | log.Debug().Int32("w", w).Int32("h", h).Msg("cef: onFirstResize fired, creating browser") | |
| 81 | 87 | if pc := wv.pendingCreate; pc != nil { | |
| 82 | 88 | wv.pendingCreate = nil | |
| 83 | - | purecef.BrowserHostCreateBrowser( | |
| 89 | + | result := purecef.BrowserHostCreateBrowser( | |
| 84 | 90 | pc.windowInfo, | |
| 85 | 91 | pc.client, | |
| 86 | 92 | "about:blank", | |
| @@ -88,6 +94,16 @@ func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) { | |||
| 88 | 94 | nil, // extraInfo | |
| 89 | 95 | nil, // requestContext | |
| 90 | 96 | ) | |
| 97 | + | if f.engine != nil { | |
| 98 | + | f.engine.recordBrowserCreateRequest(w, h, result) | |
| 99 | + | } | |
| 100 | + | log.Debug(). | |
| 101 | + | Int32("result", result). | |
| 102 | + | Int32("windowless", pc.windowInfo.WindowlessRenderingEnabled). | |
| 103 | + | Int32("shared_texture", pc.windowInfo.SharedTextureEnabled). | |
| 104 | + | Int32("external_begin_frame", pc.windowInfo.ExternalBeginFrameEnabled). | |
| 105 | + | Bool("client_nil", pc.client == nil). | |
| 106 | + | Msg("cef: BrowserHostCreateBrowser call completed") | |
| 91 | 107 | } | |
| 92 | 108 | } | |
| 93 | 109 | ||
| @@ -7,6 +7,7 @@ import ( | |||||
| 7 | purecef "github.com/bnema/purego-cef/cef" | 7 | purecef "github.com/bnema/purego-cef/cef" | ||
| 8 | 8 | ||||
| 9 | "github.com/bnema/dumber/internal/application/port" | 9 | "github.com/bnema/dumber/internal/application/port" | ||
| 10 | + | "github.com/bnema/dumber/internal/logging" | |||
| 10 | ) | 11 | ) | ||
| 11 | 12 | ||||
| 12 | // Compile-time interface check. | 13 | // Compile-time interface check. | ||
| @@ -16,6 +17,7 @@ var _ port.WebViewFactory = (*WebViewFactory)(nil) | |||||
| 16 | // gets a unique ID, its own renderPipeline and inputBridge, and an | 17 | // gets a unique ID, its own renderPipeline and inputBridge, and an | ||
| 17 | // asynchronously-created CEF browser (via BrowserHostCreateBrowser). | 18 | // asynchronously-created CEF browser (via BrowserHostCreateBrowser). | ||
| 18 | type WebViewFactory struct { | 19 | type WebViewFactory struct { | ||
| 20 | + | engine *Engine | |||
| 19 | gl *glLoader | 21 | gl *glLoader | ||
| 20 | nextID atomic.Uint64 | 22 | nextID atomic.Uint64 | ||
| 21 | scale int32 | 23 | scale int32 | ||
| @@ -23,13 +25,14 @@ type WebViewFactory struct { | |||||
| 23 | 25 | ||||
| 24 | // newWebViewFactory returns a factory that will create WebViews using the | 26 | // newWebViewFactory returns a factory that will create WebViews using the | ||
| 25 | // given GL loader and HiDPI scale factor. | 27 | // given GL loader and HiDPI scale factor. | ||
| 26 | - | func newWebViewFactory(gl *glLoader, scale int32) *WebViewFactory { | 28 | + | func newWebViewFactory(engine *Engine, gl *glLoader, scale int32) *WebViewFactory { |
| 27 | if scale < 1 { | 29 | if scale < 1 { | ||
| 28 | scale = 1 | 30 | scale = 1 | ||
| 29 | } | 31 | } | ||
| 30 | return &WebViewFactory{ | 32 | return &WebViewFactory{ | ||
| 31 | - | gl: gl, | 33 | + | engine: engine, |
| 32 | - | scale: scale, | 34 | + | gl: gl, |
| 35 | + | scale: scale, | |||
| 33 | } | 36 | } | ||
| 34 | } | 37 | } | ||
| 35 | 38 | ||||
| @@ -44,6 +47,7 @@ func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) { | |||||
| 44 | wv := &WebView{ | 47 | wv := &WebView{ | ||
| 45 | id: id, | 48 | id: id, | ||
| 46 | ctx: ctx, | 49 | ctx: ctx, | ||
| 50 | + | engine: f.engine, | |||
| 47 | pipeline: pipeline, | 51 | pipeline: pipeline, | ||
| 48 | } | 52 | } | ||
| 49 | 53 | ||||
| @@ -77,10 +81,12 @@ func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) { | |||||
| 77 | } | 81 | } | ||
| 78 | 82 | ||||
| 79 | // When the GL area gets its first non-zero size, create the browser. | 83 | // When the GL area gets its first non-zero size, create the browser. | ||
| 80 | - | pipeline.onFirstResize = func(_, _ int32) { | 84 | + | pipeline.onFirstResize = func(w, h int32) { |
| 85 | + | log := logging.FromContext(ctx) | |||
| 86 | + | log.Debug().Int32("w", w).Int32("h", h).Msg("cef: onFirstResize fired, creating browser") | |||
| 81 | if pc := wv.pendingCreate; pc != nil { | 87 | if pc := wv.pendingCreate; pc != nil { | ||
| 82 | wv.pendingCreate = nil | 88 | wv.pendingCreate = nil | ||
| 83 | - | purecef.BrowserHostCreateBrowser( | 89 | + | result := purecef.BrowserHostCreateBrowser( |
| 84 | pc.windowInfo, | 90 | pc.windowInfo, | ||
| 85 | pc.client, | 91 | pc.client, | ||
| 86 | "about:blank", | 92 | "about:blank", | ||
| @@ -88,6 +94,16 @@ func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) { | |||||
| 88 | nil, // extraInfo | 94 | nil, // extraInfo | ||
| 89 | nil, // requestContext | 95 | nil, // requestContext | ||
| 90 | ) | 96 | ) | ||
| 97 | + | if f.engine != nil { | |||
| 98 | + | f.engine.recordBrowserCreateRequest(w, h, result) | |||
| 99 | + | } | |||
| 100 | + | log.Debug(). | |||
| 101 | + | Int32("result", result). | |||
| 102 | + | Int32("windowless", pc.windowInfo.WindowlessRenderingEnabled). | |||
| 103 | + | Int32("shared_texture", pc.windowInfo.SharedTextureEnabled). | |||
| 104 | + | Int32("external_begin_frame", pc.windowInfo.ExternalBeginFrameEnabled). | |||
| 105 | + | Bool("client_nil", pc.client == nil). | |||
| 106 | + | Msg("cef: BrowserHostCreateBrowser call completed") | |||
| 91 | } | 107 | } | ||
| 92 | } | 108 | } | ||
| 93 | 109 | ||||
M internal/infrastructure/cef/webview.go +1 -0
| @@ -30,6 +30,7 @@ var errNoBrowser = errors.New("cef: browser not yet created") | |||
| 30 | 30 | type WebView struct { | |
| 31 | 31 | id port.WebViewID | |
| 32 | 32 | ctx context.Context | |
| 33 | + | engine *Engine | |
| 33 | 34 | browser purecef.Browser | |
| 34 | 35 | host purecef.BrowserHost | |
| 35 | 36 | client purecef.Client // prevent GC from collecting the client before CEF AddRef's it | |
| @@ -30,6 +30,7 @@ var errNoBrowser = errors.New("cef: browser not yet created") | |||||
| 30 | type WebView struct { | 30 | type WebView struct { | ||
| 31 | id port.WebViewID | 31 | id port.WebViewID | ||
| 32 | ctx context.Context | 32 | ctx context.Context | ||
| 33 | + | engine *Engine | |||
| 33 | browser purecef.Browser | 34 | browser purecef.Browser | ||
| 34 | host purecef.BrowserHost | 35 | host purecef.BrowserHost | ||
| 35 | client purecef.Client // prevent GC from collecting the client before CEF AddRef's it | 36 | client purecef.Client // prevent GC from collecting the client before CEF AddRef's it | ||
M internal/infrastructure/cef/webview_handlers.go +8 -0
| @@ -299,9 +299,17 @@ func (h *handlerSet) OnBeforeDevToolsPopup( | |||
| 299 | 299 | // OnAfterCreated stores the browser and host references and enables input. | |
| 300 | 300 | func (h *handlerSet) OnAfterCreated(browser purecef.Browser) { | |
| 301 | 301 | log := logging.FromContext(h.wv.ctx) | |
| 302 | + | browserID := int32(0) | |
| 303 | + | if browser != nil { | |
| 304 | + | browserID = browser.GetIdentifier() | |
| 305 | + | } | |
| 302 | 306 | log.Debug(). | |
| 303 | 307 | Bool("browser_nil", browser == nil). | |
| 308 | + | Int32("browser_id", browserID). | |
| 304 | 309 | Msg("cef: OnAfterCreated") | |
| 310 | + | if h.wv.engine != nil { | |
| 311 | + | h.wv.engine.recordBrowserAfterCreated(browser) | |
| 312 | + | } | |
| 305 | 313 | h.wv.browser = browser | |
| 306 | 314 | h.wv.host = browser.GetHost() | |
| 307 | 315 | h.wv.input.setHost(h.wv.host) | |
| @@ -299,9 +299,17 @@ func (h *handlerSet) OnBeforeDevToolsPopup( | |||||
| 299 | // OnAfterCreated stores the browser and host references and enables input. | 299 | // OnAfterCreated stores the browser and host references and enables input. | ||
| 300 | func (h *handlerSet) OnAfterCreated(browser purecef.Browser) { | 300 | func (h *handlerSet) OnAfterCreated(browser purecef.Browser) { | ||
| 301 | log := logging.FromContext(h.wv.ctx) | 301 | log := logging.FromContext(h.wv.ctx) | ||
| 302 | + | browserID := int32(0) | |||
| 303 | + | if browser != nil { | |||
| 304 | + | browserID = browser.GetIdentifier() | |||
| 305 | + | } | |||
| 302 | log.Debug(). | 306 | log.Debug(). | ||
| 303 | Bool("browser_nil", browser == nil). | 307 | Bool("browser_nil", browser == nil). | ||
| 308 | + | Int32("browser_id", browserID). | |||
| 304 | Msg("cef: OnAfterCreated") | 309 | Msg("cef: OnAfterCreated") | ||
| 310 | + | if h.wv.engine != nil { | |||
| 311 | + | h.wv.engine.recordBrowserAfterCreated(browser) | |||
| 312 | + | } | |||
| 305 | h.wv.browser = browser | 313 | h.wv.browser = browser | ||
| 306 | h.wv.host = browser.GetHost() | 314 | h.wv.host = browser.GetHost() | ||
| 307 | h.wv.input.setHost(h.wv.host) | 315 | h.wv.input.setHost(h.wv.host) | ||