add cef pump and render diagnostics

commit: 93202e9a9588d6cb487095cd3283662cd4671b0a
author: brice · 7mo ago · 2026-03-20 12:23 UTC
committer: brice · 6mo ago · 2026-03-28 04:36 UTC
parent: 0569599
signature: GPG VerifiedCD88F9E564E0102646FB6077A1A07C7C7C3E349D · arch-gpg Verified for the committer email

4 files · +250 -8

M internal/infrastructure/cef/engine.go +74 -3


@@ -53,9 +53,12 @@ type Engine struct {
53	53		pumpReentry bool
54	54
55	55		// Diagnostic counters (temporary).
56		-	pumpWakeCount uint64
57		-	pumpWorkCount uint64
58		-	scheduleCount atomic.Uint64 // incremented from any thread — read from main thread only
	56	+	pumpWakeCount uint64
	57	+	pumpWorkCount uint64
	58	+	pumpWorkTotalNs uint64
	59	+	pumpWorkMaxNs int64
	60	+	pumpSlowCount uint64
	61	+	scheduleCount atomic.Uint64 // incremented from any thread — read from main thread only
59	62
60	63		scheduleImmediateCount atomic.Uint64
61	64		scheduleDelayedCount atomic.Uint64

@@ -74,6 +77,13 @@ type Engine struct {
74	77		browserCreateLastWidth atomic.Int32
75	78		browserCreateLastHeight atomic.Int32
76	79		lastStallLoggedCreateSeq uint64
	80	+
	81	+	pumpDiagLastLogAt time.Time
	82	+	pumpDiagLastWakeCount uint64
	83	+	pumpDiagLastWorkCount uint64
	84	+	pumpDiagLastSchedule uint64
	85	+	pumpDiagLastWorkTotalNs uint64
	86	+	pumpDiagLastSlowCount uint64
77	87		}
78	88
79	89		// Factory returns the WebViewFactory for creating new WebView instances.

@@ -500,7 +510,16 @@ func (e *Engine) onPumpWake() {
500	510		Int64("now_ms", nowMs).
501	511		Msg("cef: pump doing work")
502	512		}
	513	+	workStartedAt := time.Now()
503	514		wasReentrant := e.performMessageLoopWork()
	515	+	workDuration := time.Since(workStartedAt)
	516	+	e.pumpWorkTotalNs += uint64(workDuration)
	517	+	if workDuration.Nanoseconds() > e.pumpWorkMaxNs {
	518	+	e.pumpWorkMaxNs = workDuration.Nanoseconds()
	519	+	}
	520	+	if workDuration >= 2*time.Millisecond {
	521	+	e.pumpSlowCount++
	522	+	}
504	523
505	524		// Match the upstream external-pump reference behavior: if CEF did not
506	525		// request another deadline, keep a placeholder wakeup so async work such as

@@ -518,9 +537,11 @@ func (e *Engine) onPumpWake() {
518	537		}
519	538		if nextDueAtMs <= nowMs {
520	539		e.signalPump()
	540	+	e.maybeLogPumpDiagnostics()
521	541		return
522	542		}
523	543		e.armPumpTimer(nextDueAtMs, nowMs)
	544	+	e.maybeLogPumpDiagnostics()
524	545		}
525	546
526	547		// performMessageLoopWork calls DoMessageLoopWork with reentrancy protection.

@@ -538,3 +559,53 @@ func (e *Engine) performMessageLoopWork() bool {
538	559
539	560		return e.pumpReentry
540	561		}
	562	+
	563	+	func (e *Engine) maybeLogPumpDiagnostics() {
	564	+	now := time.Now()
	565	+	if !e.pumpDiagLastLogAt.IsZero() && now.Sub(e.pumpDiagLastLogAt) < 3*time.Second {
	566	+	return
	567	+	}
	568	+
	569	+	wakeDelta := e.pumpWakeCount - e.pumpDiagLastWakeCount
	570	+	workDelta := e.pumpWorkCount - e.pumpDiagLastWorkCount
	571	+	scheduleTotal := e.scheduleCount.Load()
	572	+	scheduleDelta := scheduleTotal - e.pumpDiagLastSchedule
	573	+	workTotalNsDelta := e.pumpWorkTotalNs - e.pumpDiagLastWorkTotalNs
	574	+	slowDelta := e.pumpSlowCount - e.pumpDiagLastSlowCount
	575	+	if wakeDelta == 0 && workDelta == 0 && scheduleDelta == 0 {
	576	+	return
	577	+	}
	578	+
	579	+	elapsed := now.Sub(e.pumpDiagLastLogAt)
	580	+	if e.pumpDiagLastLogAt.IsZero() \|\| elapsed <= 0 {
	581	+	elapsed = time.Second
	582	+	}
	583	+	elapsedSec := elapsed.Seconds()
	584	+
	585	+	avgWorkUs := float64(0)
	586	+	if workDelta > 0 {
	587	+	avgWorkUs = float64(workTotalNsDelta) / float64(workDelta) / 1_000
	588	+	}
	589	+
	590	+	logging.FromContext(e.ctx).Debug().
	591	+	Float64("wake_hz", float64(wakeDelta)/elapsedSec).
	592	+	Float64("work_hz", float64(workDelta)/elapsedSec).
	593	+	Float64("schedule_hz", float64(scheduleDelta)/elapsedSec).
	594	+	Uint64("wake_delta", wakeDelta).
	595	+	Uint64("work_delta", workDelta).
	596	+	Uint64("schedule_delta", scheduleDelta).
	597	+	Float64("avg_do_work_us", avgWorkUs).
	598	+	Float64("max_do_work_us", float64(e.pumpWorkMaxNs)/1_000).
	599	+	Uint64("slow_do_work_delta", slowDelta).
	600	+	Uint64("wake_total", e.pumpWakeCount).
	601	+	Uint64("work_total", e.pumpWorkCount).
	602	+	Uint64("schedule_total", scheduleTotal).
	603	+	Msg("cef: pump activity")
	604	+
	605	+	e.pumpDiagLastLogAt = now
	606	+	e.pumpDiagLastWakeCount = e.pumpWakeCount
	607	+	e.pumpDiagLastWorkCount = e.pumpWorkCount
	608	+	e.pumpDiagLastSchedule = scheduleTotal
	609	+	e.pumpDiagLastWorkTotalNs = e.pumpWorkTotalNs
	610	+	e.pumpDiagLastSlowCount = e.pumpSlowCount
	611	+	}


@@ -53,9 +53,12 @@ type Engine struct {
53		pumpReentry bool	53		pumpReentry bool
54			54
55		// Diagnostic counters (temporary).	55		// Diagnostic counters (temporary).
56	-	pumpWakeCount uint64	56	+	pumpWakeCount uint64
57	-	pumpWorkCount uint64	57	+	pumpWorkCount uint64
58	-	scheduleCount atomic.Uint64 // incremented from any thread — read from main thread only	58	+	pumpWorkTotalNs uint64
			59	+	pumpWorkMaxNs int64
			60	+	pumpSlowCount uint64
			61	+	scheduleCount atomic.Uint64 // incremented from any thread — read from main thread only
59			62
60		scheduleImmediateCount atomic.Uint64	63		scheduleImmediateCount atomic.Uint64
61		scheduleDelayedCount atomic.Uint64	64		scheduleDelayedCount atomic.Uint64

@@ -74,6 +77,13 @@ type Engine struct {
74		browserCreateLastWidth atomic.Int32	77		browserCreateLastWidth atomic.Int32
75		browserCreateLastHeight atomic.Int32	78		browserCreateLastHeight atomic.Int32
76		lastStallLoggedCreateSeq uint64	79		lastStallLoggedCreateSeq uint64
			80	+
			81	+	pumpDiagLastLogAt time.Time
			82	+	pumpDiagLastWakeCount uint64
			83	+	pumpDiagLastWorkCount uint64
			84	+	pumpDiagLastSchedule uint64
			85	+	pumpDiagLastWorkTotalNs uint64
			86	+	pumpDiagLastSlowCount uint64
77		}	87		}
78			88
79		// Factory returns the WebViewFactory for creating new WebView instances.	89		// Factory returns the WebViewFactory for creating new WebView instances.

@@ -500,7 +510,16 @@ func (e *Engine) onPumpWake() {
500		Int64("now_ms", nowMs).	510		Int64("now_ms", nowMs).
501		Msg("cef: pump doing work")	511		Msg("cef: pump doing work")
502		}	512		}
			513	+	workStartedAt := time.Now()
503		wasReentrant := e.performMessageLoopWork()	514		wasReentrant := e.performMessageLoopWork()
			515	+	workDuration := time.Since(workStartedAt)
			516	+	e.pumpWorkTotalNs += uint64(workDuration)
			517	+	if workDuration.Nanoseconds() > e.pumpWorkMaxNs {
			518	+	e.pumpWorkMaxNs = workDuration.Nanoseconds()
			519	+	}
			520	+	if workDuration >= 2*time.Millisecond {
			521	+	e.pumpSlowCount++
			522	+	}
504			523
505		// Match the upstream external-pump reference behavior: if CEF did not	524		// Match the upstream external-pump reference behavior: if CEF did not
506		// request another deadline, keep a placeholder wakeup so async work such as	525		// request another deadline, keep a placeholder wakeup so async work such as

@@ -518,9 +537,11 @@ func (e *Engine) onPumpWake() {
518		}	537		}
519		if nextDueAtMs <= nowMs {	538		if nextDueAtMs <= nowMs {
520		e.signalPump()	539		e.signalPump()
			540	+	e.maybeLogPumpDiagnostics()
521		return	541		return
522		}	542		}
523		e.armPumpTimer(nextDueAtMs, nowMs)	543		e.armPumpTimer(nextDueAtMs, nowMs)
			544	+	e.maybeLogPumpDiagnostics()
524		}	545		}
525			546
526		// performMessageLoopWork calls DoMessageLoopWork with reentrancy protection.	547		// performMessageLoopWork calls DoMessageLoopWork with reentrancy protection.

@@ -538,3 +559,53 @@ func (e *Engine) performMessageLoopWork() bool {
538			559
539		return e.pumpReentry	560		return e.pumpReentry
540		}	561		}
			562	+
			563	+	func (e *Engine) maybeLogPumpDiagnostics() {
			564	+	now := time.Now()
			565	+	if !e.pumpDiagLastLogAt.IsZero() && now.Sub(e.pumpDiagLastLogAt) < 3*time.Second {
			566	+	return
			567	+	}
			568	+
			569	+	wakeDelta := e.pumpWakeCount - e.pumpDiagLastWakeCount
			570	+	workDelta := e.pumpWorkCount - e.pumpDiagLastWorkCount
			571	+	scheduleTotal := e.scheduleCount.Load()
			572	+	scheduleDelta := scheduleTotal - e.pumpDiagLastSchedule
			573	+	workTotalNsDelta := e.pumpWorkTotalNs - e.pumpDiagLastWorkTotalNs
			574	+	slowDelta := e.pumpSlowCount - e.pumpDiagLastSlowCount
			575	+	if wakeDelta == 0 && workDelta == 0 && scheduleDelta == 0 {
			576	+	return
			577	+	}
			578	+
			579	+	elapsed := now.Sub(e.pumpDiagLastLogAt)
			580	+	if e.pumpDiagLastLogAt.IsZero() \|\| elapsed <= 0 {
			581	+	elapsed = time.Second
			582	+	}
			583	+	elapsedSec := elapsed.Seconds()
			584	+
			585	+	avgWorkUs := float64(0)
			586	+	if workDelta > 0 {
			587	+	avgWorkUs = float64(workTotalNsDelta) / float64(workDelta) / 1_000
			588	+	}
			589	+
			590	+	logging.FromContext(e.ctx).Debug().
			591	+	Float64("wake_hz", float64(wakeDelta)/elapsedSec).
			592	+	Float64("work_hz", float64(workDelta)/elapsedSec).
			593	+	Float64("schedule_hz", float64(scheduleDelta)/elapsedSec).
			594	+	Uint64("wake_delta", wakeDelta).
			595	+	Uint64("work_delta", workDelta).
			596	+	Uint64("schedule_delta", scheduleDelta).
			597	+	Float64("avg_do_work_us", avgWorkUs).
			598	+	Float64("max_do_work_us", float64(e.pumpWorkMaxNs)/1_000).
			599	+	Uint64("slow_do_work_delta", slowDelta).
			600	+	Uint64("wake_total", e.pumpWakeCount).
			601	+	Uint64("work_total", e.pumpWorkCount).
			602	+	Uint64("schedule_total", scheduleTotal).
			603	+	Msg("cef: pump activity")
			604	+
			605	+	e.pumpDiagLastLogAt = now
			606	+	e.pumpDiagLastWakeCount = e.pumpWakeCount
			607	+	e.pumpDiagLastWorkCount = e.pumpWorkCount
			608	+	e.pumpDiagLastSchedule = scheduleTotal
			609	+	e.pumpDiagLastWorkTotalNs = e.pumpWorkTotalNs
			610	+	e.pumpDiagLastSlowCount = e.pumpSlowCount
			611	+	}

M internal/infrastructure/cef/factory.go +1 -1


@@ -42,7 +42,7 @@ func newWebViewFactory(engine Engine, gl glLoader, scale int32) *WebViewFactor
42	42		func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) {
43	43		id := port.WebViewID(f.nextID.Add(1))
44	44
45		-	pipeline := newRenderPipeline(f.gl, f.scale)
	45	+	pipeline := newRenderPipeline(ctx, f.gl, f.scale)
46	46
47	47		wv := &WebView{
48	48		id: id,


@@ -42,7 +42,7 @@ func newWebViewFactory(engine Engine, gl glLoader, scale int32) *WebViewFactor
42		func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) {	42		func (f *WebViewFactory) Create(ctx context.Context) (port.WebView, error) {
43		id := port.WebViewID(f.nextID.Add(1))	43		id := port.WebViewID(f.nextID.Add(1))
44			44
45	-	pipeline := newRenderPipeline(f.gl, f.scale)	45	+	pipeline := newRenderPipeline(ctx, f.gl, f.scale)
46			46
47		wv := &WebView{	47		wv := &WebView{
48		id: id,	48		id: id,

M internal/infrastructure/cef/render_pipeline.go +169 -4

@@ -1,9 +1,12 @@
1	1		package cef
2	2
3	3		import (
	4	+	"context"
4	5		"sync"
	6	+	"time"
5	7		"unsafe"
6	8
	9	+	"github.com/bnema/dumber/internal/logging"
7	10		"github.com/jwijenbergh/puregotk/v4/gtk"
8	11		)
9	12

@@ -20,6 +23,7 @@ type rect struct {
20	23		// The GL render signal uploads from staging → PBO → texture, then draws a
21	24		// fullscreen quad. Two PBOs alternate so GPU DMA and CPU writes overlap.
22	25		type renderPipeline struct {
	26	+	ctx context.Context
23	27		gl *glLoader
24	28		glArea *gtk.GLArea
25	29

@@ -46,6 +50,35 @@ type renderPipeline struct {
46	50		// GL initialized flag.
47	51		glReady bool
48	52
	53	+	// Diagnostics (main thread only).
	54	+	paintCount uint64
	55	+	acceleratedPaintCount uint64
	56	+	queueRenderCount uint64
	57	+	glRenderCount uint64
	58	+	uploadCount uint64
	59	+	fullUploadCount uint64
	60	+	paintBytes uint64
	61	+	uploadBytes uint64
	62	+	dirtyRectCount uint64
	63	+	paintCopyTotalNs uint64
	64	+	uploadTotalNs uint64
	65	+	renderTotalNs uint64
	66	+	maxPaintCopyNs int64
	67	+	maxUploadNs int64
	68	+	maxRenderNs int64
	69	+	diagLastLogAt time.Time
	70	+	diagLastPaintCount uint64
	71	+	diagLastAccelCount uint64
	72	+	diagLastQueueCount uint64
	73	+	diagLastRenderCount uint64
	74	+	diagLastUploadCount uint64
	75	+	diagLastFullUploads uint64
	76	+	diagLastPaintBytes uint64
	77	+	diagLastUploadBytes uint64
	78	+	diagLastPaintCopyNs uint64
	79	+	diagLastUploadNs uint64
	80	+	diagLastRenderNs uint64
	81	+
49	82		// onFirstResize is called once when the first non-zero resize occurs.
50	83		onFirstResize func(width, height int32)
51	84

@@ -84,12 +117,13 @@ var quadVertices = [16]float32{
84	117
85	118		// newRenderPipeline creates a GtkGLArea and wires up the render and resize
86	119		// signals. The returned pipeline is ready to receive handlePaint calls.
87		-	func newRenderPipeline(gl glLoader, scale int32) renderPipeline {
	120	+	func newRenderPipeline(ctx context.Context, gl glLoader, scale int32) renderPipeline {
88	121		if scale < 1 {
89	122		scale = 1
90	123		}
91	124
92	125		rp := &renderPipeline{
	126	+	ctx: ctx,
93	127		gl: gl,
94	128		scale: scale,
95	129		}

@@ -122,10 +156,12 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
122	156		return
123	157		}
124	158
	159	+	startedAt := time.Now()
125	160		rp.mu.Lock()
126	161
127	162		bufSize := int(width) * int(height) * 4
128	163		srcSlice := unsafe.Slice((*byte)(buffer), bufSize)
	164	+	copiedBytes := uint64(0)
129	165
130	166		// Detect size change, or first paint (staging not yet allocated).
131	167		if width != rp.width \|\| height != rp.height \|\| rp.staging == nil {

@@ -135,6 +171,7 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
135	171		rp.sizeChanged = true
136	172		// On size change, copy the entire buffer.
137	173		copy(rp.staging, srcSlice)
	174	+	copiedBytes = uint64(bufSize)
138	175		} else {
139	176		// Copy only dirty rect rows.
140	177		stride := int(width) * 4

@@ -144,6 +181,7 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
144	181		dstOff := srcOff
145	182		rowBytes := int(r.Width) * 4
146	183		copy(rp.staging[dstOff:dstOff+rowBytes], srcSlice[srcOff:srcOff+rowBytes])
	184	+	copiedBytes += uint64(rowBytes)
147	185		}
148	186		}
149	187		}

@@ -157,11 +195,23 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
157	195
158	196		rp.mu.Unlock()
159	197
	198	+	copyDuration := time.Since(startedAt)
	199	+	rp.paintCount++
	200	+	rp.queueRenderCount++
	201	+	rp.paintBytes += copiedBytes
	202	+	rp.dirtyRectCount += uint64(len(rects))
	203	+	rp.paintCopyTotalNs += uint64(copyDuration)
	204	+	if copyDuration.Nanoseconds() > rp.maxPaintCopyNs {
	205	+	rp.maxPaintCopyNs = copyDuration.Nanoseconds()
	206	+	}
	207	+
160	208		rp.glArea.QueueRender()
	209	+	rp.maybeLogDiagnostics()
161	210		}
162	211
163	212		// onGLRender is the GTK "render" signal handler. GL context is current.
164	213		func (rp *renderPipeline) onGLRender() bool {
	214	+	renderStartedAt := time.Now()
165	215		rp.mu.Lock()
166	216
167	217		needsUpload := rp.needsUpload

@@ -185,11 +235,29 @@ func (rp *renderPipeline) onGLRender() bool {
185	235		}
186	236
187	237		if !rp.glReady {
	238	+	rp.glRenderCount++
	239	+	renderDuration := time.Since(renderStartedAt)
	240	+	rp.renderTotalNs += uint64(renderDuration)
	241	+	if renderDuration.Nanoseconds() > rp.maxRenderNs {
	242	+	rp.maxRenderNs = renderDuration.Nanoseconds()
	243	+	}
	244	+	rp.maybeLogDiagnostics()
188	245		return true
189	246		}
190	247
191	248		if needsUpload {
192		-	rp.uploadToPBO(dirtyRects, sizeChanged)
	249	+	uploadStartedAt := time.Now()
	250	+	uploadedBytes := rp.uploadToPBO(dirtyRects, sizeChanged)
	251	+	uploadDuration := time.Since(uploadStartedAt)
	252	+	rp.uploadCount++
	253	+	if sizeChanged {
	254	+	rp.fullUploadCount++
	255	+	}
	256	+	rp.uploadBytes += uploadedBytes
	257	+	rp.uploadTotalNs += uint64(uploadDuration)
	258	+	if uploadDuration.Nanoseconds() > rp.maxUploadNs {
	259	+	rp.maxUploadNs = uploadDuration.Nanoseconds()
	260	+	}
193	261		}
194	262
195	263		// Draw fullscreen quad.

@@ -203,12 +271,20 @@ func (rp *renderPipeline) onGLRender() bool {
203	271		gl.bindTexture(glTexture2D, 0)
204	272		gl.useProgram(0)
205	273
	274	+	rp.glRenderCount++
	275	+	renderDuration := time.Since(renderStartedAt)
	276	+	rp.renderTotalNs += uint64(renderDuration)
	277	+	if renderDuration.Nanoseconds() > rp.maxRenderNs {
	278	+	rp.maxRenderNs = renderDuration.Nanoseconds()
	279	+	}
	280	+	rp.maybeLogDiagnostics()
	281	+
206	282		return true
207	283		}
208	284
209	285		// uploadToPBO uploads dirty regions from the staging buffer into a PBO, then
210	286		// transfers to the GL texture via async DMA.
211		-	func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) {
	287	+	func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) uint64 {
212	288		gl := rp.gl
213	289
214	290		rp.mu.Lock()

@@ -227,20 +303,23 @@ func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) {
227	303		mapped := gl.mapBuffer(glPixelUnpackBuffer, glWriteOnly)
228	304		if mapped == nil {
229	305		gl.bindBuffer(glPixelUnpackBuffer, 0)
230		-	return
	306	+	return 0
231	307		}
232	308
233	309		mappedSlice := unsafe.Slice((*byte)(mapped), int(bufSize))
	310	+	uploadedBytes := uint64(0)
234	311
235	312		rp.mu.Lock()
236	313		if fullUpload {
237	314		copy(mappedSlice, rp.staging)
	315	+	uploadedBytes = uint64(bufSize)
238	316		} else {
239	317		for _, r := range dirtyRects {
240	318		for row := r.Y; row < r.Y+r.Height; row++ {
241	319		off := int(row)stride + int(r.X)4
242	320		rowBytes := int(r.Width) * 4
243	321		copy(mappedSlice[off:off+rowBytes], rp.staging[off:off+rowBytes])
	322	+	uploadedBytes += uint64(rowBytes)
244	323		}
245	324		}
246	325		}

@@ -270,6 +349,7 @@ func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) {
270	349		rp.pboIndex = 1 - rp.pboIndex
271	350
272	351		gl.bindBuffer(glPixelUnpackBuffer, 0)
	352	+	return uploadedBytes
273	353		}
274	354
275	355		// initGL creates or recreates all GL resources for the current surface size.

@@ -344,6 +424,91 @@ func (rp *renderPipeline) initGL() {
344	424		rp.glReady = true
345	425		}
346	426
	427	+	func (rp *renderPipeline) recordAcceleratedPaint() uint64 {
	428	+	rp.acceleratedPaintCount++
	429	+	rp.maybeLogDiagnostics()
	430	+	return rp.acceleratedPaintCount
	431	+	}
	432	+
	433	+	func (rp *renderPipeline) maybeLogDiagnostics() {
	434	+	now := time.Now()
	435	+	if !rp.diagLastLogAt.IsZero() && now.Sub(rp.diagLastLogAt) < 2*time.Second {
	436	+	return
	437	+	}
	438	+
	439	+	paintDelta := rp.paintCount - rp.diagLastPaintCount
	440	+	accelDelta := rp.acceleratedPaintCount - rp.diagLastAccelCount
	441	+	queueDelta := rp.queueRenderCount - rp.diagLastQueueCount
	442	+	renderDelta := rp.glRenderCount - rp.diagLastRenderCount
	443	+	uploadDelta := rp.uploadCount - rp.diagLastUploadCount
	444	+	fullUploadDelta := rp.fullUploadCount - rp.diagLastFullUploads
	445	+	paintBytesDelta := rp.paintBytes - rp.diagLastPaintBytes
	446	+	uploadBytesDelta := rp.uploadBytes - rp.diagLastUploadBytes
	447	+	paintCopyNsDelta := rp.paintCopyTotalNs - rp.diagLastPaintCopyNs
	448	+	uploadNsDelta := rp.uploadTotalNs - rp.diagLastUploadNs
	449	+	renderNsDelta := rp.renderTotalNs - rp.diagLastRenderNs
	450	+	if paintDelta == 0 && accelDelta == 0 && queueDelta == 0 && renderDelta == 0 && uploadDelta == 0 {
	451	+	return
	452	+	}
	453	+
	454	+	elapsed := now.Sub(rp.diagLastLogAt)
	455	+	if rp.diagLastLogAt.IsZero() \|\| elapsed <= 0 {
	456	+	elapsed = time.Second
	457	+	}
	458	+	elapsedSec := elapsed.Seconds()
	459	+
	460	+	paintAvgUs := float64(0)
	461	+	if paintDelta > 0 {
	462	+	paintAvgUs = float64(paintCopyNsDelta) / float64(paintDelta) / 1_000
	463	+	}
	464	+	uploadAvgUs := float64(0)
	465	+	if uploadDelta > 0 {
	466	+	uploadAvgUs = float64(uploadNsDelta) / float64(uploadDelta) / 1_000
	467	+	}
	468	+	renderAvgUs := float64(0)
	469	+	if renderDelta > 0 {
	470	+	renderAvgUs = float64(renderNsDelta) / float64(renderDelta) / 1_000
	471	+	}
	472	+
	473	+	logging.FromContext(rp.ctx).Debug().
	474	+	Float64("paint_hz", float64(paintDelta)/elapsedSec).
	475	+	Float64("queue_hz", float64(queueDelta)/elapsedSec).
	476	+	Float64("render_hz", float64(renderDelta)/elapsedSec).
	477	+	Float64("upload_hz", float64(uploadDelta)/elapsedSec).
	478	+	Uint64("paint_delta", paintDelta).
	479	+	Uint64("accelerated_paint_delta", accelDelta).
	480	+	Uint64("queue_delta", queueDelta).
	481	+	Uint64("render_delta", renderDelta).
	482	+	Uint64("upload_delta", uploadDelta).
	483	+	Uint64("full_upload_delta", fullUploadDelta).
	484	+	Float64("paint_mb", float64(paintBytesDelta)/(1024*1024)).
	485	+	Float64("upload_mb", float64(uploadBytesDelta)/(1024*1024)).
	486	+	Float64("avg_paint_copy_us", paintAvgUs).
	487	+	Float64("avg_upload_us", uploadAvgUs).
	488	+	Float64("avg_render_us", renderAvgUs).
	489	+	Float64("max_paint_copy_us", float64(rp.maxPaintCopyNs)/1_000).
	490	+	Float64("max_upload_us", float64(rp.maxUploadNs)/1_000).
	491	+	Float64("max_render_us", float64(rp.maxRenderNs)/1_000).
	492	+	Uint64("paint_total", rp.paintCount).
	493	+	Uint64("accelerated_paint_total", rp.acceleratedPaintCount).
	494	+	Uint64("render_total", rp.glRenderCount).
	495	+	Uint64("upload_total", rp.uploadCount).
	496	+	Msg("cef: render pipeline activity")
	497	+
	498	+	rp.diagLastLogAt = now
	499	+	rp.diagLastPaintCount = rp.paintCount
	500	+	rp.diagLastAccelCount = rp.acceleratedPaintCount
	501	+	rp.diagLastQueueCount = rp.queueRenderCount
	502	+	rp.diagLastRenderCount = rp.glRenderCount
	503	+	rp.diagLastUploadCount = rp.uploadCount
	504	+	rp.diagLastFullUploads = rp.fullUploadCount
	505	+	rp.diagLastPaintBytes = rp.paintBytes
	506	+	rp.diagLastUploadBytes = rp.uploadBytes
	507	+	rp.diagLastPaintCopyNs = rp.paintCopyTotalNs
	508	+	rp.diagLastUploadNs = rp.uploadTotalNs
	509	+	rp.diagLastRenderNs = rp.renderTotalNs
	510	+	}
	511	+
347	512		// buildShaderProgram compiles and links the vertex+fragment shaders.
348	513		func (rp *renderPipeline) buildShaderProgram() uint32 {
349	514		gl := rp.gl

@@ -1,9 +1,12 @@
1		package cef	1		package cef
2			2
3		import (	3		import (
			4	+	"context"
4		"sync"	5		"sync"
			6	+	"time"
5		"unsafe"	7		"unsafe"
6			8
			9	+	"github.com/bnema/dumber/internal/logging"
7		"github.com/jwijenbergh/puregotk/v4/gtk"	10		"github.com/jwijenbergh/puregotk/v4/gtk"
8		)	11		)
9			12

@@ -20,6 +23,7 @@ type rect struct {
20		// The GL render signal uploads from staging → PBO → texture, then draws a	23		// The GL render signal uploads from staging → PBO → texture, then draws a
21		// fullscreen quad. Two PBOs alternate so GPU DMA and CPU writes overlap.	24		// fullscreen quad. Two PBOs alternate so GPU DMA and CPU writes overlap.
22		type renderPipeline struct {	25		type renderPipeline struct {
			26	+	ctx context.Context
23		gl *glLoader	27		gl *glLoader
24		glArea *gtk.GLArea	28		glArea *gtk.GLArea
25			29

@@ -46,6 +50,35 @@ type renderPipeline struct {
46		// GL initialized flag.	50		// GL initialized flag.
47		glReady bool	51		glReady bool
48			52
			53	+	// Diagnostics (main thread only).
			54	+	paintCount uint64
			55	+	acceleratedPaintCount uint64
			56	+	queueRenderCount uint64
			57	+	glRenderCount uint64
			58	+	uploadCount uint64
			59	+	fullUploadCount uint64
			60	+	paintBytes uint64
			61	+	uploadBytes uint64
			62	+	dirtyRectCount uint64
			63	+	paintCopyTotalNs uint64
			64	+	uploadTotalNs uint64
			65	+	renderTotalNs uint64
			66	+	maxPaintCopyNs int64
			67	+	maxUploadNs int64
			68	+	maxRenderNs int64
			69	+	diagLastLogAt time.Time
			70	+	diagLastPaintCount uint64
			71	+	diagLastAccelCount uint64
			72	+	diagLastQueueCount uint64
			73	+	diagLastRenderCount uint64
			74	+	diagLastUploadCount uint64
			75	+	diagLastFullUploads uint64
			76	+	diagLastPaintBytes uint64
			77	+	diagLastUploadBytes uint64
			78	+	diagLastPaintCopyNs uint64
			79	+	diagLastUploadNs uint64
			80	+	diagLastRenderNs uint64
			81	+
49		// onFirstResize is called once when the first non-zero resize occurs.	82		// onFirstResize is called once when the first non-zero resize occurs.
50		onFirstResize func(width, height int32)	83		onFirstResize func(width, height int32)
51			84

@@ -84,12 +117,13 @@ var quadVertices = [16]float32{
84			117
85		// newRenderPipeline creates a GtkGLArea and wires up the render and resize	118		// newRenderPipeline creates a GtkGLArea and wires up the render and resize
86		// signals. The returned pipeline is ready to receive handlePaint calls.	119		// signals. The returned pipeline is ready to receive handlePaint calls.
87	-	func newRenderPipeline(gl glLoader, scale int32) renderPipeline {	120	+	func newRenderPipeline(ctx context.Context, gl glLoader, scale int32) renderPipeline {
88		if scale < 1 {	121		if scale < 1 {
89		scale = 1	122		scale = 1
90		}	123		}
91			124
92		rp := &renderPipeline{	125		rp := &renderPipeline{
			126	+	ctx: ctx,
93		gl: gl,	127		gl: gl,
94		scale: scale,	128		scale: scale,
95		}	129		}

@@ -122,10 +156,12 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
122		return	156		return
123		}	157		}
124			158
			159	+	startedAt := time.Now()
125		rp.mu.Lock()	160		rp.mu.Lock()
126			161
127		bufSize := int(width) * int(height) * 4	162		bufSize := int(width) * int(height) * 4
128		srcSlice := unsafe.Slice((*byte)(buffer), bufSize)	163		srcSlice := unsafe.Slice((*byte)(buffer), bufSize)
			164	+	copiedBytes := uint64(0)
129			165
130		// Detect size change, or first paint (staging not yet allocated).	166		// Detect size change, or first paint (staging not yet allocated).
131		if width != rp.width \|\| height != rp.height \|\| rp.staging == nil {	167		if width != rp.width \|\| height != rp.height \|\| rp.staging == nil {

@@ -135,6 +171,7 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
135		rp.sizeChanged = true	171		rp.sizeChanged = true
136		// On size change, copy the entire buffer.	172		// On size change, copy the entire buffer.
137		copy(rp.staging, srcSlice)	173		copy(rp.staging, srcSlice)
			174	+	copiedBytes = uint64(bufSize)
138		} else {	175		} else {
139		// Copy only dirty rect rows.	176		// Copy only dirty rect rows.
140		stride := int(width) * 4	177		stride := int(width) * 4

@@ -144,6 +181,7 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
144		dstOff := srcOff	181		dstOff := srcOff
145		rowBytes := int(r.Width) * 4	182		rowBytes := int(r.Width) * 4
146		copy(rp.staging[dstOff:dstOff+rowBytes], srcSlice[srcOff:srcOff+rowBytes])	183		copy(rp.staging[dstOff:dstOff+rowBytes], srcSlice[srcOff:srcOff+rowBytes])
			184	+	copiedBytes += uint64(rowBytes)
147		}	185		}
148		}	186		}
149		}	187		}

@@ -157,11 +195,23 @@ func (rp *renderPipeline) handlePaint(buffer unsafe.Pointer, width, height int32
157			195
158		rp.mu.Unlock()	196		rp.mu.Unlock()
159			197
			198	+	copyDuration := time.Since(startedAt)
			199	+	rp.paintCount++
			200	+	rp.queueRenderCount++
			201	+	rp.paintBytes += copiedBytes
			202	+	rp.dirtyRectCount += uint64(len(rects))
			203	+	rp.paintCopyTotalNs += uint64(copyDuration)
			204	+	if copyDuration.Nanoseconds() > rp.maxPaintCopyNs {
			205	+	rp.maxPaintCopyNs = copyDuration.Nanoseconds()
			206	+	}
			207	+
160		rp.glArea.QueueRender()	208		rp.glArea.QueueRender()
			209	+	rp.maybeLogDiagnostics()
161		}	210		}
162			211
163		// onGLRender is the GTK "render" signal handler. GL context is current.	212		// onGLRender is the GTK "render" signal handler. GL context is current.
164		func (rp *renderPipeline) onGLRender() bool {	213		func (rp *renderPipeline) onGLRender() bool {
			214	+	renderStartedAt := time.Now()
165		rp.mu.Lock()	215		rp.mu.Lock()
166			216
167		needsUpload := rp.needsUpload	217		needsUpload := rp.needsUpload

@@ -185,11 +235,29 @@ func (rp *renderPipeline) onGLRender() bool {
185		}	235		}
186			236
187		if !rp.glReady {	237		if !rp.glReady {
			238	+	rp.glRenderCount++
			239	+	renderDuration := time.Since(renderStartedAt)
			240	+	rp.renderTotalNs += uint64(renderDuration)
			241	+	if renderDuration.Nanoseconds() > rp.maxRenderNs {
			242	+	rp.maxRenderNs = renderDuration.Nanoseconds()
			243	+	}
			244	+	rp.maybeLogDiagnostics()
188		return true	245		return true
189		}	246		}
190			247
191		if needsUpload {	248		if needsUpload {
192	-	rp.uploadToPBO(dirtyRects, sizeChanged)	249	+	uploadStartedAt := time.Now()
			250	+	uploadedBytes := rp.uploadToPBO(dirtyRects, sizeChanged)
			251	+	uploadDuration := time.Since(uploadStartedAt)
			252	+	rp.uploadCount++
			253	+	if sizeChanged {
			254	+	rp.fullUploadCount++
			255	+	}
			256	+	rp.uploadBytes += uploadedBytes
			257	+	rp.uploadTotalNs += uint64(uploadDuration)
			258	+	if uploadDuration.Nanoseconds() > rp.maxUploadNs {
			259	+	rp.maxUploadNs = uploadDuration.Nanoseconds()
			260	+	}
193		}	261		}
194			262
195		// Draw fullscreen quad.	263		// Draw fullscreen quad.

@@ -203,12 +271,20 @@ func (rp *renderPipeline) onGLRender() bool {
203		gl.bindTexture(glTexture2D, 0)	271		gl.bindTexture(glTexture2D, 0)
204		gl.useProgram(0)	272		gl.useProgram(0)
205			273
			274	+	rp.glRenderCount++
			275	+	renderDuration := time.Since(renderStartedAt)
			276	+	rp.renderTotalNs += uint64(renderDuration)
			277	+	if renderDuration.Nanoseconds() > rp.maxRenderNs {
			278	+	rp.maxRenderNs = renderDuration.Nanoseconds()
			279	+	}
			280	+	rp.maybeLogDiagnostics()
			281	+
206		return true	282		return true
207		}	283		}
208			284
209		// uploadToPBO uploads dirty regions from the staging buffer into a PBO, then	285		// uploadToPBO uploads dirty regions from the staging buffer into a PBO, then
210		// transfers to the GL texture via async DMA.	286		// transfers to the GL texture via async DMA.
211	-	func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) {	287	+	func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) uint64 {
212		gl := rp.gl	288		gl := rp.gl
213			289
214		rp.mu.Lock()	290		rp.mu.Lock()

@@ -227,20 +303,23 @@ func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) {
227		mapped := gl.mapBuffer(glPixelUnpackBuffer, glWriteOnly)	303		mapped := gl.mapBuffer(glPixelUnpackBuffer, glWriteOnly)
228		if mapped == nil {	304		if mapped == nil {
229		gl.bindBuffer(glPixelUnpackBuffer, 0)	305		gl.bindBuffer(glPixelUnpackBuffer, 0)
230	-	return	306	+	return 0
231		}	307		}
232			308
233		mappedSlice := unsafe.Slice((*byte)(mapped), int(bufSize))	309		mappedSlice := unsafe.Slice((*byte)(mapped), int(bufSize))
			310	+	uploadedBytes := uint64(0)
234			311
235		rp.mu.Lock()	312		rp.mu.Lock()
236		if fullUpload {	313		if fullUpload {
237		copy(mappedSlice, rp.staging)	314		copy(mappedSlice, rp.staging)
			315	+	uploadedBytes = uint64(bufSize)
238		} else {	316		} else {
239		for _, r := range dirtyRects {	317		for _, r := range dirtyRects {
240		for row := r.Y; row < r.Y+r.Height; row++ {	318		for row := r.Y; row < r.Y+r.Height; row++ {
241		off := int(row)stride + int(r.X)4	319		off := int(row)stride + int(r.X)4
242		rowBytes := int(r.Width) * 4	320		rowBytes := int(r.Width) * 4
243		copy(mappedSlice[off:off+rowBytes], rp.staging[off:off+rowBytes])	321		copy(mappedSlice[off:off+rowBytes], rp.staging[off:off+rowBytes])
			322	+	uploadedBytes += uint64(rowBytes)
244		}	323		}
245		}	324		}
246		}	325		}

@@ -270,6 +349,7 @@ func (rp *renderPipeline) uploadToPBO(dirtyRects []rect, fullUpload bool) {
270		rp.pboIndex = 1 - rp.pboIndex	349		rp.pboIndex = 1 - rp.pboIndex
271			350
272		gl.bindBuffer(glPixelUnpackBuffer, 0)	351		gl.bindBuffer(glPixelUnpackBuffer, 0)
			352	+	return uploadedBytes
273		}	353		}
274			354
275		// initGL creates or recreates all GL resources for the current surface size.	355		// initGL creates or recreates all GL resources for the current surface size.

@@ -344,6 +424,91 @@ func (rp *renderPipeline) initGL() {
344		rp.glReady = true	424		rp.glReady = true
345		}	425		}
346			426
			427	+	func (rp *renderPipeline) recordAcceleratedPaint() uint64 {
			428	+	rp.acceleratedPaintCount++
			429	+	rp.maybeLogDiagnostics()
			430	+	return rp.acceleratedPaintCount
			431	+	}
			432	+
			433	+	func (rp *renderPipeline) maybeLogDiagnostics() {
			434	+	now := time.Now()
			435	+	if !rp.diagLastLogAt.IsZero() && now.Sub(rp.diagLastLogAt) < 2*time.Second {
			436	+	return
			437	+	}
			438	+
			439	+	paintDelta := rp.paintCount - rp.diagLastPaintCount
			440	+	accelDelta := rp.acceleratedPaintCount - rp.diagLastAccelCount
			441	+	queueDelta := rp.queueRenderCount - rp.diagLastQueueCount
			442	+	renderDelta := rp.glRenderCount - rp.diagLastRenderCount
			443	+	uploadDelta := rp.uploadCount - rp.diagLastUploadCount
			444	+	fullUploadDelta := rp.fullUploadCount - rp.diagLastFullUploads
			445	+	paintBytesDelta := rp.paintBytes - rp.diagLastPaintBytes
			446	+	uploadBytesDelta := rp.uploadBytes - rp.diagLastUploadBytes
			447	+	paintCopyNsDelta := rp.paintCopyTotalNs - rp.diagLastPaintCopyNs
			448	+	uploadNsDelta := rp.uploadTotalNs - rp.diagLastUploadNs
			449	+	renderNsDelta := rp.renderTotalNs - rp.diagLastRenderNs
			450	+	if paintDelta == 0 && accelDelta == 0 && queueDelta == 0 && renderDelta == 0 && uploadDelta == 0 {
			451	+	return
			452	+	}
			453	+
			454	+	elapsed := now.Sub(rp.diagLastLogAt)
			455	+	if rp.diagLastLogAt.IsZero() \|\| elapsed <= 0 {
			456	+	elapsed = time.Second
			457	+	}
			458	+	elapsedSec := elapsed.Seconds()
			459	+
			460	+	paintAvgUs := float64(0)
			461	+	if paintDelta > 0 {
			462	+	paintAvgUs = float64(paintCopyNsDelta) / float64(paintDelta) / 1_000
			463	+	}
			464	+	uploadAvgUs := float64(0)
			465	+	if uploadDelta > 0 {
			466	+	uploadAvgUs = float64(uploadNsDelta) / float64(uploadDelta) / 1_000
			467	+	}
			468	+	renderAvgUs := float64(0)
			469	+	if renderDelta > 0 {
			470	+	renderAvgUs = float64(renderNsDelta) / float64(renderDelta) / 1_000
			471	+	}
			472	+
			473	+	logging.FromContext(rp.ctx).Debug().
			474	+	Float64("paint_hz", float64(paintDelta)/elapsedSec).
			475	+	Float64("queue_hz", float64(queueDelta)/elapsedSec).
			476	+	Float64("render_hz", float64(renderDelta)/elapsedSec).
			477	+	Float64("upload_hz", float64(uploadDelta)/elapsedSec).
			478	+	Uint64("paint_delta", paintDelta).
			479	+	Uint64("accelerated_paint_delta", accelDelta).
			480	+	Uint64("queue_delta", queueDelta).
			481	+	Uint64("render_delta", renderDelta).
			482	+	Uint64("upload_delta", uploadDelta).
			483	+	Uint64("full_upload_delta", fullUploadDelta).
			484	+	Float64("paint_mb", float64(paintBytesDelta)/(1024*1024)).
			485	+	Float64("upload_mb", float64(uploadBytesDelta)/(1024*1024)).
			486	+	Float64("avg_paint_copy_us", paintAvgUs).
			487	+	Float64("avg_upload_us", uploadAvgUs).
			488	+	Float64("avg_render_us", renderAvgUs).
			489	+	Float64("max_paint_copy_us", float64(rp.maxPaintCopyNs)/1_000).
			490	+	Float64("max_upload_us", float64(rp.maxUploadNs)/1_000).
			491	+	Float64("max_render_us", float64(rp.maxRenderNs)/1_000).
			492	+	Uint64("paint_total", rp.paintCount).
			493	+	Uint64("accelerated_paint_total", rp.acceleratedPaintCount).
			494	+	Uint64("render_total", rp.glRenderCount).
			495	+	Uint64("upload_total", rp.uploadCount).
			496	+	Msg("cef: render pipeline activity")
			497	+
			498	+	rp.diagLastLogAt = now
			499	+	rp.diagLastPaintCount = rp.paintCount
			500	+	rp.diagLastAccelCount = rp.acceleratedPaintCount
			501	+	rp.diagLastQueueCount = rp.queueRenderCount
			502	+	rp.diagLastRenderCount = rp.glRenderCount
			503	+	rp.diagLastUploadCount = rp.uploadCount
			504	+	rp.diagLastFullUploads = rp.fullUploadCount
			505	+	rp.diagLastPaintBytes = rp.paintBytes
			506	+	rp.diagLastUploadBytes = rp.uploadBytes
			507	+	rp.diagLastPaintCopyNs = rp.paintCopyTotalNs
			508	+	rp.diagLastUploadNs = rp.uploadTotalNs
			509	+	rp.diagLastRenderNs = rp.renderTotalNs
			510	+	}
			511	+
347		// buildShaderProgram compiles and links the vertex+fragment shaders.	512		// buildShaderProgram compiles and links the vertex+fragment shaders.
348		func (rp *renderPipeline) buildShaderProgram() uint32 {	513		func (rp *renderPipeline) buildShaderProgram() uint32 {
349		gl := rp.gl	514		gl := rp.gl

M internal/infrastructure/cef/webview_handlers.go +6 -0


@@ -112,6 +112,12 @@ func (h *handlerSet) OnPaint(
112	112		}
113	113
114	114		func (h handlerSet) OnAcceleratedPaint(_ purecef.Browser, _ purecef.PaintElementType, _ []purecef.Rect, _ purecef.AcceleratedPaintInfo) {
	115	+	count := h.wv.pipeline.recordAcceleratedPaint()
	116	+	if count <= 5 \|\| count%100 == 0 {
	117	+	logging.FromContext(h.wv.ctx).Info().
	118	+	Uint64("count", count).
	119	+	Msg("cef: OnAcceleratedPaint")
	120	+	}
115	121		}
116	122
117	123		func (h handlerSet) GetTouchHandleSize(_ purecef.Browser, _ purecef.HorizontalAlignment, _ purecef.Size) {


@@ -112,6 +112,12 @@ func (h *handlerSet) OnPaint(
112	}	112		}
113		113
114	func (h handlerSet) OnAcceleratedPaint(_ purecef.Browser, _ purecef.PaintElementType, _ []purecef.Rect, _ purecef.AcceleratedPaintInfo) {	114		func (h handlerSet) OnAcceleratedPaint(_ purecef.Browser, _ purecef.PaintElementType, _ []purecef.Rect, _ purecef.AcceleratedPaintInfo) {
		115	+	count := h.wv.pipeline.recordAcceleratedPaint()
		116	+	if count <= 5 \|\| count%100 == 0 {
		117	+	logging.FromContext(h.wv.ctx).Info().
		118	+	Uint64("count", count).
		119	+	Msg("cef: OnAcceleratedPaint")
		120	+	}
115	}	121		}
116		122
117	func (h handlerSet) GetTouchHandleSize(_ purecef.Browser, _ purecef.HorizontalAlignment, _ purecef.Size) {	123		func (h handlerSet) GetTouchHandleSize(_ purecef.Browser, _ purecef.HorizontalAlignment, _ purecef.Size) {