feat(startup): trace first GTK presentation

commit: 3f7ece6df012c560265e1078dcfc4e3858e2c149
author: brice · 3mo ago · 2026-07-14 07:33 UTC
committer: brice · 3mo ago · 2026-07-14 09:35 UTC
parent: 49ad311
signature: GPG VerifiedCD88F9E564E0102646FB6077A1A07C7C7C3E349D · arch-gpg Verified for the committer email

14 files · +541 -166

M cmd/dumber/main.go +6 -1


@@ -141,6 +141,11 @@ func configureBrowserLaunchRelay(cfg *config.Config) {
141	141		}
142	142
143	143		func main() {
	144	+	// This is intentionally before subprocess detection: each process records
	145	+	// its own first observable main event before CEF can take over execution.
	146	+	logging.InitStartupTrace("")
	147	+	logging.Trace().Mark("process_entry")
	148	+
144	149		// CEF subprocess handling: when CEF re-launches this binary with
145	150		// --type=renderer/gpu/etc, we must call ExecuteProcess before anything
146	151		// else (Cobra, config, arg stripping). We only treat a leading Chromium

@@ -218,6 +223,7 @@ func runGUI(cfg *config.Config) int {
218	223		cfg = initConfig()
219	224		configureBrowserLaunchRelay(cfg)
220	225		}
	226	+	logging.Trace().Mark("config_complete")
221	227		timer.Mark("config")
222	228
223	229		ctx := initStartupContextWithTrace(cfg)

@@ -414,7 +420,6 @@ func resolveCurrentExecutable(executable func() (string, error)) (string, error)
414	420
415	421		func initStartupContextWithTrace(cfg *config.Config) context.Context {
416	422		logging.InitStartupTrace(cfg.Logging.Level)
417		-	logging.Trace().Mark("config_loaded")
418	423
419	424		ctx := initStartupContext(cfg)
420	425		bootstrapLog := logging.FromContext(ctx)

 }
 func main() {
+	// This is intentionally before subprocess detection: each process records
+	// its own first observable main event before CEF can take over execution.
+	logging.InitStartupTrace("")
+	logging.Trace().Mark("process_entry")
 	// CEF subprocess handling: when CEF re-launches this binary with
 	// --type=renderer/gpu/etc, we must call ExecuteProcess before anything
 	// else (Cobra, config, arg stripping). We only treat a leading Chromium
 		cfg = initConfig()
 		configureBrowserLaunchRelay(cfg)
 	}
+	logging.Trace().Mark("config_complete")
 	timer.Mark("config")
 	ctx := initStartupContextWithTrace(cfg)
 func initStartupContextWithTrace(cfg *config.Config) context.Context {
 	logging.InitStartupTrace(cfg.Logging.Level)
-	logging.Trace().Mark("config_loaded")
 	ctx := initStartupContext(cfg)
 	bootstrapLog := logging.FromContext(ctx)

A docs/first-presentation.md +36 -0

@@ -0,0 +1,36 @@
	1	+	# First presentation startup trace
	2	+
	3	+	Dumber records one cold-start timeline for each GUI process. The trace begins
	4	+	at `process_entry`, before CEF subprocess handling, and accepts these one-shot
	5	+	milestones only in order:
	6	+
	7	+	1. `process_entry`
	8	+	2. `config_complete`
	9	+	3. `cef_library_load_begin` (immediately before `InitWithApp`)
	10	+	4. `cef_initialized`
	11	+	5. `browser_create_requested`
	12	+	6. `first_accelerated_paint_received`
	13	+	7. `first_dmabuf_texture_swap` (after `GtkPicture.SetPaintable` succeeds)
	14	+	8. `first_gtk_presentation` (the subsequent GTK frame-clock after-paint)
	15	+
	16	+	CEF library-load completion is intentionally not recorded: `InitWithApp` is an
	17	+	opaque operation. Duplicate, unknown, and out-of-order transitions are
	18	+	rejected. At the last milestone Dumber emits exactly one normal-level JSON
	19	+	summary (`startup_trace: first presentation`) with the selected `backend`, an
	20	+	`incomplete_reason`, total milliseconds, and monotonic milestones.
	21	+
	22	+	## Reproducible collection
	23	+
	24	+	Build the candidate, then run:
	25	+
	26	+	```bash
	27	+	DUMBER_FIRST_PRESENTATION_BIN="$PWD/dist/dumber" \
	28	+	scripts/collect_first_presentation.sh
	29	+	```
	30	+
	31	+	The script requires the current display and the CEF 147 runtime at
	32	+	`~/.local/share/cef-147-runtime` (override with `DUMBER_CEF_DIR`). It performs
	33	+	exactly five bounded launches with fresh XDG homes and CEF root cache, fixes the
	34	+	DMABUF/Vulkan environment, and writes `metadata.json`, `run-01.json` through
	35	+	`run-05.json`, and `baseline.json` below `phase1/first-presentation`. A missing
	36	+	or incomplete timeline, non-DMABUF backend, or invalid run fails collection.

@@ -0,0 +1,36 @@
	1	+	# First presentation startup trace
	2	+
	3	+	Dumber records one cold-start timeline for each GUI process. The trace begins
	4	+	at `process_entry`, before CEF subprocess handling, and accepts these one-shot
	5	+	milestones only in order:
	6	+
	7	+	1. `process_entry`
	8	+	2. `config_complete`
	9	+	3. `cef_library_load_begin` (immediately before `InitWithApp`)
	10	+	4. `cef_initialized`
	11	+	5. `browser_create_requested`
	12	+	6. `first_accelerated_paint_received`
	13	+	7. `first_dmabuf_texture_swap` (after `GtkPicture.SetPaintable` succeeds)
	14	+	8. `first_gtk_presentation` (the subsequent GTK frame-clock after-paint)
	15	+
	16	+	CEF library-load completion is intentionally not recorded: `InitWithApp` is an
	17	+	opaque operation. Duplicate, unknown, and out-of-order transitions are
	18	+	rejected. At the last milestone Dumber emits exactly one normal-level JSON
	19	+	summary (`startup_trace: first presentation`) with the selected `backend`, an
	20	+	`incomplete_reason`, total milliseconds, and monotonic milestones.
	21	+
	22	+	## Reproducible collection
	23	+
	24	+	Build the candidate, then run:
	25	+
	26	+	```bash
	27	+	DUMBER_FIRST_PRESENTATION_BIN="$PWD/dist/dumber" \
	28	+	scripts/collect_first_presentation.sh
	29	+	```
	30	+
	31	+	The script requires the current display and the CEF 147 runtime at
	32	+	`~/.local/share/cef-147-runtime` (override with `DUMBER_CEF_DIR`). It performs
	33	+	exactly five bounded launches with fresh XDG homes and CEF root cache, fixes the
	34	+	DMABUF/Vulkan environment, and writes `metadata.json`, `run-01.json` through
	35	+	`run-05.json`, and `baseline.json` below `phase1/first-presentation`. A missing
	36	+	or incomplete timeline, non-DMABUF backend, or invalid run fails collection.

M go.mod +1 -1


@@ -7,7 +7,7 @@ require (
7	7		github.com/andybalholm/brotli v1.2.2
8	8		github.com/bnema/purego v0.11.0-bnema.4
9	9		github.com/bnema/purego-cef v0.13.3
10		-	github.com/bnema/purego-cef2gtk v0.8.2
	10	+	github.com/bnema/purego-cef2gtk v0.8.3-0.20260714065021-7e2055015742
11	11		github.com/bnema/purego-pipewire v0.1.4
12	12		github.com/bnema/purego-sqlite v0.1.3
13	13		github.com/bnema/puregotk v0.7.0


@@ -7,7 +7,7 @@ require (
7		github.com/andybalholm/brotli v1.2.2	7		github.com/andybalholm/brotli v1.2.2
8		github.com/bnema/purego v0.11.0-bnema.4	8		github.com/bnema/purego v0.11.0-bnema.4
9		github.com/bnema/purego-cef v0.13.3	9		github.com/bnema/purego-cef v0.13.3
10	-	github.com/bnema/purego-cef2gtk v0.8.2	10	+	github.com/bnema/purego-cef2gtk v0.8.3-0.20260714065021-7e2055015742
11		github.com/bnema/purego-pipewire v0.1.4	11		github.com/bnema/purego-pipewire v0.1.4
12		github.com/bnema/purego-sqlite v0.1.3	12		github.com/bnema/purego-sqlite v0.1.3
13		github.com/bnema/puregotk v0.7.0	13		github.com/bnema/puregotk v0.7.0

M go.sum +2 -0 generated file: collapsed

load diff

M internal/infrastructure/cef/engine_init.go +5 -0


@@ -56,6 +56,7 @@ func NewEngine(
56	56		return nil, err
57	57		}
58	58		cef2gtk.ConfigureRenderStackEnvironment(renderStackPlan)
	59	+	logging.Trace().SetBackend(renderStackPlan.Backend.String())
59	60
60	61		settings, err := prepareCEFSettings(opts, paths, cfg, logger)
61	62		if err != nil {

@@ -199,9 +200,13 @@ func initializeCEF(eng Engine, settings purecef.Settings, logger zerolog.Logge
199	200		Str("env_cef_dir", os.Getenv("CEF_DIR")).
200	201		Msg("cef: runtime selection")
201	202		logger.Debug().Msg("cef: calling InitWithApp")
	203	+	// InitWithApp encapsulates loading libcef, so only the begin boundary is
	204	+	// observable here; do not invent a separate library-load completion event.
	205	+	logging.Trace().Mark("cef_library_load_begin")
202	206		if err := purecef.InitWithApp(settings, app); err != nil {
203	207		return fmt.Errorf("cef.InitWithApp: %w", err)
204	208		}
	209	+	logging.Trace().Mark("cef_initialized")
205	210		if libcefPath := loadedLibCEFPath(); libcefPath != "" {
206	211		logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded")
207	212		} else {


@@ -56,6 +56,7 @@ func NewEngine(
56	return nil, err	56		return nil, err
57	}	57		}
58	cef2gtk.ConfigureRenderStackEnvironment(renderStackPlan)	58		cef2gtk.ConfigureRenderStackEnvironment(renderStackPlan)
		59	+	logging.Trace().SetBackend(renderStackPlan.Backend.String())
59		60
60	settings, err := prepareCEFSettings(opts, paths, cfg, logger)	61		settings, err := prepareCEFSettings(opts, paths, cfg, logger)
61	if err != nil {	62		if err != nil {

@@ -199,9 +200,13 @@ func initializeCEF(eng Engine, settings purecef.Settings, logger zerolog.Logge
199	Str("env_cef_dir", os.Getenv("CEF_DIR")).	200		Str("env_cef_dir", os.Getenv("CEF_DIR")).
200	Msg("cef: runtime selection")	201		Msg("cef: runtime selection")
201	logger.Debug().Msg("cef: calling InitWithApp")	202		logger.Debug().Msg("cef: calling InitWithApp")
		203	+	// InitWithApp encapsulates loading libcef, so only the begin boundary is
		204	+	// observable here; do not invent a separate library-load completion event.
		205	+	logging.Trace().Mark("cef_library_load_begin")
202	if err := purecef.InitWithApp(settings, app); err != nil {	206		if err := purecef.InitWithApp(settings, app); err != nil {
203	return fmt.Errorf("cef.InitWithApp: %w", err)	207		return fmt.Errorf("cef.InitWithApp: %w", err)
204	}	208		}
		209	+	logging.Trace().Mark("cef_initialized")
205	if libcefPath := loadedLibCEFPath(); libcefPath != "" {	210		if libcefPath := loadedLibCEFPath(); libcefPath != "" {
206	logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded")	211		logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded")
207	} else {	212		} else {

M internal/infrastructure/cef/factory.go +2 -0


@@ -278,6 +278,8 @@ func (f WebViewFactory) postPendingBrowserCreate(ctx context.Context, wv WebVi
278	278		// renderer without an initial paint. We replay pending navigation from
279	279		// OnAfterCreated once the host is fully wired.
280	280		initialURL := "about:blank"
	281	+	// This is the request boundary, not the later OnAfterCreated callback.
	282	+	logging.Trace().Mark("browser_create_requested")
281	283		result := cefBrowserHostCreateBrowser(
282	284		pc.windowInfo,
283	285		pc.client,


@@ -278,6 +278,8 @@ func (f WebViewFactory) postPendingBrowserCreate(ctx context.Context, wv WebVi
278	// renderer without an initial paint. We replay pending navigation from	278		// renderer without an initial paint. We replay pending navigation from
279	// OnAfterCreated once the host is fully wired.	279		// OnAfterCreated once the host is fully wired.
280	initialURL := "about:blank"	280		initialURL := "about:blank"
		281	+	// This is the request boundary, not the later OnAfterCreated callback.
		282	+	logging.Trace().Mark("browser_create_requested")
281	result := cefBrowserHostCreateBrowser(	283		result := cefBrowserHostCreateBrowser(
282	pc.windowInfo,	284		pc.windowInfo,
283	pc.client,	285		pc.client,

M internal/infrastructure/cef/render_handler_adapter.go +35 -15


@@ -23,6 +23,26 @@ type dumberRenderHandler struct {
23	23
24	24		var _ purecef.RenderHandler = (*dumberRenderHandler)(nil)
25	25
	26	+	// startupPresentationHooks consumes the one-shot facts emitted by
	27	+	// purego-cef2gtk. The bridge owns the native DMABUF and frame-clock boundaries;
	28	+	// Dumber only records their ordered application-level timeline.
	29	+	func startupPresentationHooks() cef2gtk.Hooks {
	30	+	return cef2gtk.Hooks{
	31	+	OnFirstAcceleratedPaint: func() {
	32	+	logging.Trace().Mark("first_accelerated_paint_received")
	33	+	},
	34	+	OnFirstDMABUFTextureSwap: func() {
	35	+	logging.Trace().Mark("first_dmabuf_texture_swap")
	36	+	},
	37	+	OnFirstPresentation: func() {
	38	+	logging.Trace().Mark("first_gtk_presentation")
	39	+	},
	40	+	OnDMABUFUnsupported: func() {
	41	+	logging.Trace().SetIncompleteReason("dmabuf_texture_swap_unavailable")
	42	+	},
	43	+	}
	44	+	}
	45	+
26	46		func newDumberRenderHandler(wv *WebView) purecef.RenderHandler {
27	47		if wv == nil \|\| wv.viewBridge == nil {
28	48		return nil

@@ -30,23 +50,23 @@ func newDumberRenderHandler(wv *WebView) purecef.RenderHandler {
30	50		h := &dumberRenderHandler{wv: wv}
31	51
32	52		var unsupportedPaintOnce sync.Once
33		-	h.main = wv.viewBridge.RenderHandler(cef2gtk.Hooks{
34		-	OnUnsupportedPaint: func() {
35		-	unsupportedPaintOnce.Do(func() {
36		-	if wv.ctx != nil {
37		-	logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge")
38		-	}
39		-	})
40		-	},
41		-	OnError: func(err error) {
	53	+	hooks := startupPresentationHooks()
	54	+	hooks.OnUnsupportedPaint = func() {
	55	+	unsupportedPaintOnce.Do(func() {
42	56		if wv.ctx != nil {
43		-	logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error")
	57	+	logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge")
44	58		}
45		-	},
46		-	OnTextSelectionChanged: func(selectedText string, _ *purecef.Range) {
47		-	handleRenderTextSelectionChanged(wv, selectedText)
48		-	},
49		-	})
	59	+	})
	60	+	}
	61	+	hooks.OnError = func(err error) {
	62	+	if wv.ctx != nil {
	63	+	logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error")
	64	+	}
	65	+	}
	66	+	hooks.OnTextSelectionChanged = func(selectedText string, _ *purecef.Range) {
	67	+	handleRenderTextSelectionChanged(wv, selectedText)
	68	+	}
	69	+	h.main = wv.viewBridge.RenderHandler(hooks)
50	70
51	71		if wv.popupSurface != nil {
52	72		var popupUnsupportedPaintOnce sync.Once

 var _ purecef.RenderHandler = (*dumberRenderHandler)(nil)
+// startupPresentationHooks consumes the one-shot facts emitted by
+// purego-cef2gtk. The bridge owns the native DMABUF and frame-clock boundaries;
+// Dumber only records their ordered application-level timeline.
+func startupPresentationHooks() cef2gtk.Hooks {
+	return cef2gtk.Hooks{
+		OnFirstAcceleratedPaint: func() {
+			logging.Trace().Mark("first_accelerated_paint_received")
+		},
+		OnFirstDMABUFTextureSwap: func() {
+			logging.Trace().Mark("first_dmabuf_texture_swap")
+		},
+		OnFirstPresentation: func() {
+			logging.Trace().Mark("first_gtk_presentation")
+		},
+		OnDMABUFUnsupported: func() {
+			logging.Trace().SetIncompleteReason("dmabuf_texture_swap_unavailable")
+		},
+	}
+}
 func newDumberRenderHandler(wv *WebView) purecef.RenderHandler {
 	if wv == nil || wv.viewBridge == nil {
 		return nil
 	h := &dumberRenderHandler{wv: wv}
 	var unsupportedPaintOnce sync.Once
-	h.main = wv.viewBridge.RenderHandler(cef2gtk.Hooks{
+	hooks := startupPresentationHooks()
-		OnUnsupportedPaint: func() {
+	hooks.OnUnsupportedPaint = func() {
-			unsupportedPaintOnce.Do(func() {
+		unsupportedPaintOnce.Do(func() {
-				if wv.ctx != nil {
-					logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge")
-				}
-			})
-		},
-		OnError: func(err error) {
 			if wv.ctx != nil {
-				logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error")
+				logging.FromContext(wv.ctx).Warn().Msg("cef: unsupported CPU paint from accelerated bridge")
 			}
-		},
+		})
-		OnTextSelectionChanged: func(selectedText string, _ *purecef.Range) {
+	}
-			handleRenderTextSelectionChanged(wv, selectedText)
+	hooks.OnError = func(err error) {
-		},
+		if wv.ctx != nil {
-	})
+			logging.FromContext(wv.ctx).Warn().Err(err).Msg("cef: accelerated render bridge error")
+		}
+	}
+	hooks.OnTextSelectionChanged = func(selectedText string, _ *purecef.Range) {
+		handleRenderTextSelectionChanged(wv, selectedText)
+	}
+	h.main = wv.viewBridge.RenderHandler(hooks)
 	if wv.popupSurface != nil {
 		var popupUnsupportedPaintOnce sync.Once

M internal/logging/startup_trace.go +104 -136

@@ -1,32 +1,44 @@
1	1		package logging
2	2
3	3		import (
4		-	"fmt"
5		-	"strings"
6	4		"sync"
7	5		"time"
8	6
9	7		"github.com/rs/zerolog"
10	8		)
11	9
12		-	// StartupTrace tracks cold start milestones from process launch to first paint.
13		-	// Thread-safe for use across goroutines.
14		-	// Enabled only when log level is debug or trace.
	10	+	// StartupTrace records the single truthful path from process entry to the first
	11	+	// GTK presentation. It deliberately rejects unknown, duplicate, and out of
	12	+	// order milestones: accepting a convenient timestamp would make the result
	13	+	// unsuitable for cold-start measurement.
15	14		type StartupTrace struct {
16		-	mu sync.Mutex
17		-	t0 time.Time
18		-	milestones []Milestone
19		-	enabled bool
20		-	logger *zerolog.Logger
21		-	buffered []Milestone // milestones recorded before logger is set
22		-	finished bool
	15	+	mu sync.Mutex
	16	+	now func() time.Time
	17	+	t0 time.Time
	18	+	milestones []Milestone
	19	+	logger *zerolog.Logger
	20	+	buffered []Milestone
	21	+	backend string
	22	+	incompleteReason string
	23	+	summaryEmitted bool
23	24		}
24	25
25		-	// Milestone represents a timing checkpoint during startup.
	26	+	// Milestone represents a timing checkpoint measured from process entry.
26	27		type Milestone struct {
27	28		Name string
28		-	Elapsed time.Duration // time since t0
29		-	Delta time.Duration // time since previous milestone
	29	+	Elapsed time.Duration
	30	+	Delta time.Duration
	31	+	}
	32	+
	33	+	var startupMilestoneOrder = []string{
	34	+	"process_entry",
	35	+	"config_complete",
	36	+	"cef_library_load_begin",
	37	+	"cef_initialized",
	38	+	"browser_create_requested",
	39	+	"first_accelerated_paint_received",
	40	+	"first_dmabuf_texture_swap",
	41	+	"first_gtk_presentation",
30	42		}
31	43
32	44		var (

@@ -35,186 +47,142 @@ var (
35	47		globalTraceOnce sync.Once
36	48		)
37	49
38		-	// InitStartupTrace initializes the global startup trace.
39		-	// Call this as early as possible in main() to capture T0.
40		-	// The trace is enabled only if the given log level is debug or trace.
41		-	func InitStartupTrace(logLevel string) {
	50	+	func newStartupTrace(now func() time.Time) *StartupTrace {
	51	+	start := now()
	52	+	return &StartupTrace{
	53	+	now: now,
	54	+	t0: start,
	55	+	milestones: make([]Milestone, 0, len(startupMilestoneOrder)),
	56	+	buffered: make([]Milestone, 0, len(startupMilestoneOrder)),
	57	+	}
	58	+	}
	59	+
	60	+	// InitStartupTrace must be called at the first instruction in main. logLevel is
	61	+	// retained for source compatibility; this measurement is always collected so
	62	+	// its final structured summary is available at normal log level.
	63	+	func InitStartupTrace(_ string) {
42	64		globalTraceOnce.Do(func() {
43		-	enabled := logLevel == "debug" \|\| logLevel == "trace"
	65	+	trace := newStartupTrace(time.Now)
44	66		globalTraceMu.Lock()
45		-	globalTrace = &StartupTrace{
46		-	t0: time.Now(),
47		-	milestones: make([]Milestone, 0, 32),
48		-	enabled: enabled,
49		-	buffered: make([]Milestone, 0, 8),
50		-	}
	67	+	globalTrace = trace
51	68		globalTraceMu.Unlock()
52		-
53		-	if enabled {
54		-	// Record process_start as first milestone
55		-	globalTrace.Mark("process_start")
56		-	}
57	69		})
58	70		}
59	71
60		-	// Trace returns the global startup trace instance.
61		-	// Returns a no-op trace if not initialized or disabled.
	72	+	// Trace returns the process startup trace. Callers before initialization get a
	73	+	// harmless trace which rejects all transitions.
62	74		func Trace() *StartupTrace {
63	75		globalTraceMu.Lock()
64	76		defer globalTraceMu.Unlock()
65	77		if globalTrace == nil {
66		-	// Return a disabled no-op trace
67		-	return &StartupTrace{enabled: false}
	78	+	return &StartupTrace{}
68	79		}
69	80		return globalTrace
70	81		}
71	82
72		-	// SetLogger sets the logger for emitting milestone logs.
73		-	// Flushes any buffered milestones that were recorded before the logger was set.
	83	+	// SetLogger makes buffered milestones available to the process logger.
74	84		func (st StartupTrace) SetLogger(logger zerolog.Logger) {
75		-	if st == nil \|\| !st.enabled {
	85	+	if st == nil \|\| logger == nil {
76	86		return
77	87		}
78		-
79	88		st.mu.Lock()
80	89		defer st.mu.Unlock()
81		-
82	90		st.logger = logger
83		-
84		-	// Flush buffered milestones
85		-	for _, m := range st.buffered {
86		-	st.emitMilestone(m)
	91	+	for _, milestone := range st.buffered {
	92	+	st.emitMilestone(milestone)
87	93		}
88	94		st.buffered = nil
	95	+	st.emitSummaryLocked()
89	96		}
90	97
91		-	// UpdateLogger updates the logger and re-emits all milestones to the new logger.
92		-	// Call this after the session file logger is available to capture milestones in the log file.
93		-	func (st StartupTrace) UpdateLogger(logger zerolog.Logger) {
94		-	if st == nil \|\| !st.enabled {
	98	+	// UpdateLogger switches the destination without replaying events. Replaying
	99	+	// would violate the one-shot property in session logs.
	100	+	func (st StartupTrace) UpdateLogger(logger zerolog.Logger) { st.SetLogger(logger) }
	101	+
	102	+	// SetBackend records the selected presentation backend for the final summary.
	103	+	func (st *StartupTrace) SetBackend(backend string) {
	104	+	if st == nil {
95	105		return
96	106		}
97		-
98	107		st.mu.Lock()
99	108		defer st.mu.Unlock()
100		-
101		-	st.logger = logger
102		-
103		-	// Re-emit all milestones to the new logger
104		-	for _, m := range st.milestones {
105		-	st.emitMilestone(m)
106		-	}
	109	+	st.backend = backend
107	110		}
108	111
109		-	// Mark records a milestone with the given name.
110		-	// Emits a debug log line showing elapsed time and delta from previous milestone.
111		-	func (st *StartupTrace) Mark(name string) {
112		-	if st == nil \|\| !st.enabled {
	112	+	// SetIncompleteReason records why a trace cannot reach a valid DMABUF result.
	113	+	func (st *StartupTrace) SetIncompleteReason(reason string) {
	114	+	if st == nil {
113	115		return
114	116		}
115		-
116	117		st.mu.Lock()
117	118		defer st.mu.Unlock()
118		-
119		-	if st.finished {
120		-	return
	119	+	if st.incompleteReason == "" {
	120	+	st.incompleteReason = reason
121	121		}
	122	+	}
122	123
123		-	now := time.Now()
124		-	elapsed := now.Sub(st.t0)
125		-
126		-	var delta time.Duration
127		-	if len(st.milestones) > 0 {
128		-	delta = elapsed - st.milestones[len(st.milestones)-1].Elapsed
	124	+	// Mark accepts exactly the next startup milestone and returns whether it was
	125	+	// recorded. It is safe for callbacks from CEF and GTK threads.
	126	+	func (st *StartupTrace) Mark(name string) bool {
	127	+	if st == nil \|\| st.now == nil {
	128	+	return false
129	129		}
130		-
131		-	m := Milestone{
132		-	Name: name,
133		-	Elapsed: elapsed,
134		-	Delta: delta,
	130	+	st.mu.Lock()
	131	+	defer st.mu.Unlock()
	132	+	if len(st.milestones) >= len(startupMilestoneOrder) \|\| name != startupMilestoneOrder[len(st.milestones)] {
	133	+	return false
135	134		}
136		-	st.milestones = append(st.milestones, m)
137	135
138		-	if st.logger != nil {
139		-	st.emitMilestone(m)
	136	+	now := st.now()
	137	+	milestone := Milestone{Name: name, Elapsed: now.Sub(st.t0)}
	138	+	if len(st.milestones) > 0 {
	139	+	milestone.Delta = milestone.Elapsed - st.milestones[len(st.milestones)-1].Elapsed
	140	+	}
	141	+	st.milestones = append(st.milestones, milestone)
	142	+	if st.logger == nil {
	143	+	st.buffered = append(st.buffered, milestone)
140	144		} else {
141		-	// Buffer until logger is set
142		-	st.buffered = append(st.buffered, m)
	145	+	st.emitMilestone(milestone)
143	146		}
	147	+	st.emitSummaryLocked()
	148	+	return true
144	149		}
145	150
146		-	// emitMilestone logs a single milestone. Caller must hold mutex.
147	151		func (st *StartupTrace) emitMilestone(m Milestone) {
148	152		if st.logger == nil {
149	153		return
150	154		}
151		-
152		-	elapsedMs := m.Elapsed.Milliseconds()
153		-
154		-	event := st.logger.Debug().
	155	+	st.logger.Debug().
155	156		Str("milestone", m.Name).
156		-	Int64("t_ms", elapsedMs)
157		-
158		-	if m.Delta > 0 {
159		-	event = event.Int64("delta_ms", m.Delta.Milliseconds())
160		-	}
161		-
162		-	// Format: startup_trace: milestone_name (T+123ms, +45ms)
163		-	if m.Delta > 0 {
164		-	event.Msgf("startup_trace: %s (T+%dms, +%dms)", m.Name, elapsedMs, m.Delta.Milliseconds())
165		-	} else {
166		-	event.Msgf("startup_trace: %s (T+%dms)", m.Name, elapsedMs)
167		-	}
	157	+	Int64("t_ms", m.Elapsed.Milliseconds()).
	158	+	Int64("delta_ms", m.Delta.Milliseconds()).
	159	+	Msg("startup_trace: milestone")
168	160		}
169	161
170		-	// Finish marks the startup trace as complete and emits a summary.
171		-	// Called on first_paint milestone.
172		-	func (st *StartupTrace) Finish() {
173		-	if st == nil \|\| !st.enabled {
174		-	return
175		-	}
176		-
177		-	st.mu.Lock()
178		-	defer st.mu.Unlock()
179		-
180		-	if st.finished {
	162	+	func (st *StartupTrace) emitSummaryLocked() {
	163	+	if st.summaryEmitted \|\| st.logger == nil \|\| len(st.milestones) != len(startupMilestoneOrder) {
181	164		return
182	165		}
183		-	st.finished = true
184		-
185		-	if st.logger == nil {
186		-	return
187		-	}
188		-
189		-	// Build summary string
190		-	total := time.Since(st.t0)
191		-	var parts []string
192		-	for _, m := range st.milestones {
193		-	parts = append(parts, fmt.Sprintf("%s:%d", m.Name, m.Elapsed.Milliseconds()))
194		-	}
195		-	summary := strings.Join(parts, ",")
196		-
	166	+	st.summaryEmitted = true
197	167		st.logger.Info().
198		-	Int64("total_ms", total.Milliseconds()).
199		-	Str("milestones", summary).
200		-	Msg("startup_trace: cold start complete")
	168	+	Str("backend", st.backend).
	169	+	Str("incomplete_reason", st.incompleteReason).
	170	+	Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()).
	171	+	Interface("milestones", st.milestones).
	172	+	Msg("startup_trace: first presentation")
201	173		}
202	174
203		-	// Enabled returns whether the trace is active.
204		-	func (st *StartupTrace) Enabled() bool {
205		-	if st == nil {
206		-	return false
207		-	}
208		-	return st.enabled
209		-	}
	175	+	// Finish is retained for old callers. A startup trace only finishes at the
	176	+	// actual first GTK presentation milestone.
	177	+	func (st *StartupTrace) Finish() { _ = st.Mark("first_gtk_presentation") }
	178	+
	179	+	func (st *StartupTrace) Enabled() bool { return st != nil && st.now != nil }
210	180
211		-	// TotalElapsed returns the total time since T0.
212	181		func (st *StartupTrace) TotalElapsed() time.Duration {
213		-	if st == nil \|\| !st.enabled {
	182	+	if st == nil \|\| st.now == nil {
214	183		return 0
215	184		}
216		-
217	185		st.mu.Lock()
218	186		defer st.mu.Unlock()
219		-	return time.Since(st.t0)
	187	+	return st.now().Sub(st.t0)
220	188		}

@@ -1,32 +1,44 @@
1		package logging	1		package logging
2			2
3		import (	3		import (
4	-	"fmt"
5	-	"strings"
6		"sync"	4		"sync"
7		"time"	5		"time"
8			6
9		"github.com/rs/zerolog"	7		"github.com/rs/zerolog"
10		)	8		)
11			9
12	-	// StartupTrace tracks cold start milestones from process launch to first paint.	10	+	// StartupTrace records the single truthful path from process entry to the first
13	-	// Thread-safe for use across goroutines.	11	+	// GTK presentation. It deliberately rejects unknown, duplicate, and out of
14	-	// Enabled only when log level is debug or trace.	12	+	// order milestones: accepting a convenient timestamp would make the result
			13	+	// unsuitable for cold-start measurement.
15		type StartupTrace struct {	14		type StartupTrace struct {
16	-	mu sync.Mutex	15	+	mu sync.Mutex
17	-	t0 time.Time	16	+	now func() time.Time
18	-	milestones []Milestone	17	+	t0 time.Time
19	-	enabled bool	18	+	milestones []Milestone
20	-	logger *zerolog.Logger	19	+	logger *zerolog.Logger
21	-	buffered []Milestone // milestones recorded before logger is set	20	+	buffered []Milestone
22	-	finished bool	21	+	backend string
			22	+	incompleteReason string
			23	+	summaryEmitted bool
23		}	24		}
24			25
25	-	// Milestone represents a timing checkpoint during startup.	26	+	// Milestone represents a timing checkpoint measured from process entry.
26		type Milestone struct {	27		type Milestone struct {
27		Name string	28		Name string
28	-	Elapsed time.Duration // time since t0	29	+	Elapsed time.Duration
29	-	Delta time.Duration // time since previous milestone	30	+	Delta time.Duration
			31	+	}
			32	+
			33	+	var startupMilestoneOrder = []string{
			34	+	"process_entry",
			35	+	"config_complete",
			36	+	"cef_library_load_begin",
			37	+	"cef_initialized",
			38	+	"browser_create_requested",
			39	+	"first_accelerated_paint_received",
			40	+	"first_dmabuf_texture_swap",
			41	+	"first_gtk_presentation",
30		}	42		}
31			43
32		var (	44		var (

@@ -35,186 +47,142 @@ var (
35		globalTraceOnce sync.Once	47		globalTraceOnce sync.Once
36		)	48		)
37			49
38	-	// InitStartupTrace initializes the global startup trace.	50	+	func newStartupTrace(now func() time.Time) *StartupTrace {
39	-	// Call this as early as possible in main() to capture T0.	51	+	start := now()
40	-	// The trace is enabled only if the given log level is debug or trace.	52	+	return &StartupTrace{
41	-	func InitStartupTrace(logLevel string) {	53	+	now: now,
			54	+	t0: start,
			55	+	milestones: make([]Milestone, 0, len(startupMilestoneOrder)),
			56	+	buffered: make([]Milestone, 0, len(startupMilestoneOrder)),
			57	+	}
			58	+	}
			59	+
			60	+	// InitStartupTrace must be called at the first instruction in main. logLevel is
			61	+	// retained for source compatibility; this measurement is always collected so
			62	+	// its final structured summary is available at normal log level.
			63	+	func InitStartupTrace(_ string) {
42		globalTraceOnce.Do(func() {	64		globalTraceOnce.Do(func() {
43	-	enabled := logLevel == "debug" \|\| logLevel == "trace"	65	+	trace := newStartupTrace(time.Now)
44		globalTraceMu.Lock()	66		globalTraceMu.Lock()
45	-	globalTrace = &StartupTrace{	67	+	globalTrace = trace
46	-	t0: time.Now(),
47	-	milestones: make([]Milestone, 0, 32),
48	-	enabled: enabled,
49	-	buffered: make([]Milestone, 0, 8),
50	-	}
51		globalTraceMu.Unlock()	68		globalTraceMu.Unlock()
52	-
53	-	if enabled {
54	-	// Record process_start as first milestone
55	-	globalTrace.Mark("process_start")
56	-	}
57		})	69		})
58		}	70		}
59			71
60	-	// Trace returns the global startup trace instance.	72	+	// Trace returns the process startup trace. Callers before initialization get a
61	-	// Returns a no-op trace if not initialized or disabled.	73	+	// harmless trace which rejects all transitions.
62		func Trace() *StartupTrace {	74		func Trace() *StartupTrace {
63		globalTraceMu.Lock()	75		globalTraceMu.Lock()
64		defer globalTraceMu.Unlock()	76		defer globalTraceMu.Unlock()
65		if globalTrace == nil {	77		if globalTrace == nil {
66	-	// Return a disabled no-op trace	78	+	return &StartupTrace{}
67	-	return &StartupTrace{enabled: false}
68		}	79		}
69		return globalTrace	80		return globalTrace
70		}	81		}
71			82
72	-	// SetLogger sets the logger for emitting milestone logs.	83	+	// SetLogger makes buffered milestones available to the process logger.
73	-	// Flushes any buffered milestones that were recorded before the logger was set.
74		func (st StartupTrace) SetLogger(logger zerolog.Logger) {	84		func (st StartupTrace) SetLogger(logger zerolog.Logger) {
75	-	if st == nil \|\| !st.enabled {	85	+	if st == nil \|\| logger == nil {
76		return	86		return
77		}	87		}
78	-
79		st.mu.Lock()	88		st.mu.Lock()
80		defer st.mu.Unlock()	89		defer st.mu.Unlock()
81	-
82		st.logger = logger	90		st.logger = logger
83	-		91	+	for _, milestone := range st.buffered {
84	-	// Flush buffered milestones	92	+	st.emitMilestone(milestone)
85	-	for _, m := range st.buffered {
86	-	st.emitMilestone(m)
87		}	93		}
88		st.buffered = nil	94		st.buffered = nil
			95	+	st.emitSummaryLocked()
89		}	96		}
90			97
91	-	// UpdateLogger updates the logger and re-emits all milestones to the new logger.	98	+	// UpdateLogger switches the destination without replaying events. Replaying
92	-	// Call this after the session file logger is available to capture milestones in the log file.	99	+	// would violate the one-shot property in session logs.
93	-	func (st StartupTrace) UpdateLogger(logger zerolog.Logger) {	100	+	func (st StartupTrace) UpdateLogger(logger zerolog.Logger) { st.SetLogger(logger) }
94	-	if st == nil \|\| !st.enabled {	101	+
			102	+	// SetBackend records the selected presentation backend for the final summary.
			103	+	func (st *StartupTrace) SetBackend(backend string) {
			104	+	if st == nil {
95		return	105		return
96		}	106		}
97	-
98		st.mu.Lock()	107		st.mu.Lock()
99		defer st.mu.Unlock()	108		defer st.mu.Unlock()
100	-		109	+	st.backend = backend
101	-	st.logger = logger
102	-
103	-	// Re-emit all milestones to the new logger
104	-	for _, m := range st.milestones {
105	-	st.emitMilestone(m)
106	-	}
107		}	110		}
108			111
109	-	// Mark records a milestone with the given name.	112	+	// SetIncompleteReason records why a trace cannot reach a valid DMABUF result.
110	-	// Emits a debug log line showing elapsed time and delta from previous milestone.	113	+	func (st *StartupTrace) SetIncompleteReason(reason string) {
111	-	func (st *StartupTrace) Mark(name string) {	114	+	if st == nil {
112	-	if st == nil \|\| !st.enabled {
113		return	115		return
114		}	116		}
115	-
116		st.mu.Lock()	117		st.mu.Lock()
117		defer st.mu.Unlock()	118		defer st.mu.Unlock()
118	-		119	+	if st.incompleteReason == "" {
119	-	if st.finished {	120	+	st.incompleteReason = reason
120	-	return
121		}	121		}
			122	+	}
122			123
123	-	now := time.Now()	124	+	// Mark accepts exactly the next startup milestone and returns whether it was
124	-	elapsed := now.Sub(st.t0)	125	+	// recorded. It is safe for callbacks from CEF and GTK threads.
125	-		126	+	func (st *StartupTrace) Mark(name string) bool {
126	-	var delta time.Duration	127	+	if st == nil \|\| st.now == nil {
127	-	if len(st.milestones) > 0 {	128	+	return false
128	-	delta = elapsed - st.milestones[len(st.milestones)-1].Elapsed
129		}	129		}
130	-		130	+	st.mu.Lock()
131	-	m := Milestone{	131	+	defer st.mu.Unlock()
132	-	Name: name,	132	+	if len(st.milestones) >= len(startupMilestoneOrder) \|\| name != startupMilestoneOrder[len(st.milestones)] {
133	-	Elapsed: elapsed,	133	+	return false
134	-	Delta: delta,
135		}	134		}
136	-	st.milestones = append(st.milestones, m)
137			135
138	-	if st.logger != nil {	136	+	now := st.now()
139	-	st.emitMilestone(m)	137	+	milestone := Milestone{Name: name, Elapsed: now.Sub(st.t0)}
			138	+	if len(st.milestones) > 0 {
			139	+	milestone.Delta = milestone.Elapsed - st.milestones[len(st.milestones)-1].Elapsed
			140	+	}
			141	+	st.milestones = append(st.milestones, milestone)
			142	+	if st.logger == nil {
			143	+	st.buffered = append(st.buffered, milestone)
140		} else {	144		} else {
141	-	// Buffer until logger is set	145	+	st.emitMilestone(milestone)
142	-	st.buffered = append(st.buffered, m)
143		}	146		}
			147	+	st.emitSummaryLocked()
			148	+	return true
144		}	149		}
145			150
146	-	// emitMilestone logs a single milestone. Caller must hold mutex.
147		func (st *StartupTrace) emitMilestone(m Milestone) {	151		func (st *StartupTrace) emitMilestone(m Milestone) {
148		if st.logger == nil {	152		if st.logger == nil {
149		return	153		return
150		}	154		}
151	-		155	+	st.logger.Debug().
152	-	elapsedMs := m.Elapsed.Milliseconds()
153	-
154	-	event := st.logger.Debug().
155		Str("milestone", m.Name).	156		Str("milestone", m.Name).
156	-	Int64("t_ms", elapsedMs)	157	+	Int64("t_ms", m.Elapsed.Milliseconds()).
157	-		158	+	Int64("delta_ms", m.Delta.Milliseconds()).
158	-	if m.Delta > 0 {	159	+	Msg("startup_trace: milestone")
159	-	event = event.Int64("delta_ms", m.Delta.Milliseconds())
160	-	}
161	-
162	-	// Format: startup_trace: milestone_name (T+123ms, +45ms)
163	-	if m.Delta > 0 {
164	-	event.Msgf("startup_trace: %s (T+%dms, +%dms)", m.Name, elapsedMs, m.Delta.Milliseconds())
165	-	} else {
166	-	event.Msgf("startup_trace: %s (T+%dms)", m.Name, elapsedMs)
167	-	}
168		}	160		}
169			161
170	-	// Finish marks the startup trace as complete and emits a summary.	162	+	func (st *StartupTrace) emitSummaryLocked() {
171	-	// Called on first_paint milestone.	163	+	if st.summaryEmitted \|\| st.logger == nil \|\| len(st.milestones) != len(startupMilestoneOrder) {
172	-	func (st *StartupTrace) Finish() {
173	-	if st == nil \|\| !st.enabled {
174	-	return
175	-	}
176	-
177	-	st.mu.Lock()
178	-	defer st.mu.Unlock()
179	-
180	-	if st.finished {
181		return	164		return
182		}	165		}
183	-	st.finished = true	166	+	st.summaryEmitted = true
184	-
185	-	if st.logger == nil {
186	-	return
187	-	}
188	-
189	-	// Build summary string
190	-	total := time.Since(st.t0)
191	-	var parts []string
192	-	for _, m := range st.milestones {
193	-	parts = append(parts, fmt.Sprintf("%s:%d", m.Name, m.Elapsed.Milliseconds()))
194	-	}
195	-	summary := strings.Join(parts, ",")
196	-
197		st.logger.Info().	167		st.logger.Info().
198	-	Int64("total_ms", total.Milliseconds()).	168	+	Str("backend", st.backend).
199	-	Str("milestones", summary).	169	+	Str("incomplete_reason", st.incompleteReason).
200	-	Msg("startup_trace: cold start complete")	170	+	Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()).
			171	+	Interface("milestones", st.milestones).
			172	+	Msg("startup_trace: first presentation")
201		}	173		}
202			174
203	-	// Enabled returns whether the trace is active.	175	+	// Finish is retained for old callers. A startup trace only finishes at the
204	-	func (st *StartupTrace) Enabled() bool {	176	+	// actual first GTK presentation milestone.
205	-	if st == nil {	177	+	func (st *StartupTrace) Finish() { _ = st.Mark("first_gtk_presentation") }
206	-	return false	178	+
207	-	}	179	+	func (st *StartupTrace) Enabled() bool { return st != nil && st.now != nil }
208	-	return st.enabled
209	-	}
210			180
211	-	// TotalElapsed returns the total time since T0.
212		func (st *StartupTrace) TotalElapsed() time.Duration {	181		func (st *StartupTrace) TotalElapsed() time.Duration {
213	-	if st == nil \|\| !st.enabled {	182	+	if st == nil \|\| st.now == nil {
214		return 0	183		return 0
215		}	184		}
216	-
217		st.mu.Lock()	185		st.mu.Lock()
218		defer st.mu.Unlock()	186		defer st.mu.Unlock()
219	-	return time.Since(st.t0)	187	+	return st.now().Sub(st.t0)
220		}	188		}

A scripts/collect_first_presentation.sh +95 -0

@@ -0,0 +1,95 @@
	1	+	#!/usr/bin/env bash
	2	+	# Collect exactly five isolated CEF/DMABUF cold starts. The application is
	3	+	# deliberately terminated after the bounded observation window; a completed
	4	+	# first-presentation summary, rather than process exit, is the success signal.
	5	+	set -euo pipefail
	6	+
	7	+	readonly runs=5
	8	+	readonly timeout_seconds="${DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS:-45}"
	9	+	readonly runtime="${DUMBER_CEF_DIR:-$HOME/.local/share/cef-147-runtime}"
	10	+	readonly binary="${DUMBER_FIRST_PRESENTATION_BIN:-$PWD/dist/dumber}"
	11	+	readonly output="${DUMBER_FIRST_PRESENTATION_OUTPUT:-$PWD/phase1/first-presentation}"
	12	+
	13	+	[[ -x "$binary" ]] \|\| { echo "first-presentation: executable not found: $binary" >&2; exit 2; }
	14	+	[[ -d "$runtime" ]] \|\| { echo "first-presentation: CEF runtime not found: $runtime" >&2; exit 2; }
	15	+	[[ -n "${WAYLAND_DISPLAY:-}${DISPLAY:-}" ]] \|\| { echo "first-presentation: a current Wayland/X11 display is required" >&2; exit 2; }
	16	+
	17	+	rm -rf "$output"
	18	+	mkdir -p "$output"
	19	+	python3 - "$output/metadata.json" "$runtime" "$binary" "$timeout_seconds" <<'PY'
	20	+	import json, os, subprocess, sys
	21	+	path, runtime, binary, timeout = sys.argv[1:]
	22	+	json.dump({
	23	+	"runs": 5,
	24	+	"runtime": runtime,
	25	+	"binary": binary,
	26	+	"timeout_seconds": int(timeout),
	27	+	"git_revision": subprocess.check_output(["git", "rev-parse", "HEAD"], text=True).strip(),
	28	+	"environment": {key: os.environ.get(key, "") for key in ("WAYLAND_DISPLAY", "DISPLAY", "XDG_CURRENT_DESKTOP")},
	29	+	"fixed_environment": {"DUMBER_RENDER_STACK": "vulkan-dmabuf", "PUREGO_CEF2GTK_BACKEND": "gdk-dmabuf", "GSK_RENDERER": "vulkan"}
	30	+	}, open(path, "w"), indent=2, sort_keys=True)
	31	+	PY
	32	+
	33	+	for number in $(seq 1 "$runs"); do
	34	+	run="$(printf 'run-%02d' "$number")"
	35	+	root="$output/$run"
	36	+	mkdir -p "$root"/{config,data,state,cache}
	37	+	mkdir -p "$root/config/dumber"
	38	+	cat >"$root/config/dumber/config.toml" <<EOF
	39	+	[logging]
	40	+	level = "debug"
	41	+	format = "json"
	42	+	enable_file_log = false
	43	+
	44	+	[engine.cef]
	45	+	cef_dir = "$runtime"
	46	+	EOF
	47	+	# Every directory below is newly created for this one launch. Do not inherit
	48	+	# a profile, shader cache, CEF root cache, or mutable app configuration.
	49	+	set +e
	50	+	env -i \
	51	+	HOME="$HOME" PATH="$PATH" LANG="${LANG:-C.UTF-8}" \
	52	+	WAYLAND_DISPLAY="${WAYLAND_DISPLAY:-}" DISPLAY="${DISPLAY:-}" XDG_RUNTIME_DIR="${XDG_RUNTIME_DIR:-}" \
	53	+	XDG_CONFIG_HOME="$root/config" XDG_DATA_HOME="$root/data" XDG_STATE_HOME="$root/state" XDG_CACHE_HOME="$root/cache" \
	54	+	DUMBER_CEF_ROOT_CACHE_PATH="$root/cef-root-cache" DUMBER_RENDER_STACK="vulkan-dmabuf" \
	55	+	PUREGO_CEF2GTK_BACKEND="gdk-dmabuf" PUREGO_CEF2GTK_ANGLE_BACKEND="vulkan" GSK_RENDERER="vulkan" \
	56	+	timeout --signal=TERM --kill-after=5s "${timeout_seconds}s" "$binary" browse about:blank >"$root/process.log" 2>&1
	57	+	exit_code=$?
	58	+	set -e
	59	+	# timeout is expected for a GUI kept alive after the first presentation.
	60	+	if [[ "$exit_code" != 0 && "$exit_code" != 124 ]]; then
	61	+	echo "$run: launch exited unexpectedly ($exit_code); see $root/process.log" >&2
	62	+	exit 1
	63	+	fi
	64	+	python3 - "$root/process.log" "$output/$run.json" "$run" <<'PY'
	65	+	import json, sys
	66	+	log, destination, run = sys.argv[1:]
	67	+	order = ["process_entry", "config_complete", "cef_library_load_begin", "cef_initialized", "browser_create_requested", "first_accelerated_paint_received", "first_dmabuf_texture_swap", "first_gtk_presentation"]
	68	+	records, summary = [], None
	69	+	for line in open(log, errors="replace"):
	70	+	try: event = json.loads(line)
	71	+	except json.JSONDecodeError: continue
	72	+	if event.get("message") == "startup_trace: milestone": records.append(event)
	73	+	if event.get("message") == "startup_trace: first presentation": summary = event
	74	+	names = [event.get("milestone") for event in records]
	75	+	times = [event.get("t_ms") for event in records]
	76	+	valid = names == order and all(isinstance(t, int) for t in times) and times == sorted(times)
	77	+	valid = valid and summary is not None and summary.get("backend") == "gdk-dmabuf" and not summary.get("incomplete_reason")
	78	+	result = {"run": run, "valid": valid, "milestones": records, "summary": summary}
	79	+	json.dump(result, open(destination, "w"), indent=2)
	80	+	if not valid:
	81	+	raise SystemExit(f"{run}: invalid or incomplete non-DMABUF timeline")
	82	+	PY
	83	+	done
	84	+
	85	+	python3 - "$output" <<'PY'
	86	+	import json, math, statistics, sys
	87	+	root = sys.argv[1]
	88	+	runs = [json.load(open(f"{root}/run-{n:02d}.json")) for n in range(1, 6)]
	89	+	if len(runs) != 5 or not all(run["valid"] for run in runs): raise SystemExit("expected exactly five valid runs")
	90	+	totals = sorted(run["summary"]["total_ms"] for run in runs)
	91	+	p95 = totals[max(0, math.ceil(.95 * len(totals)) - 1)]
	92	+	json.dump({"runs": 5, "total_ms": {"min": totals[0], "median": statistics.median(totals), "max": totals[-1], "p95": p95}}, open(f"{root}/baseline.json", "w"), indent=2)
	93	+	PY
	94	+
	95	+	echo "first-presentation artifacts: $output"

@@ -0,0 +1,95 @@
	1	+	#!/usr/bin/env bash
	2	+	# Collect exactly five isolated CEF/DMABUF cold starts. The application is
	3	+	# deliberately terminated after the bounded observation window; a completed
	4	+	# first-presentation summary, rather than process exit, is the success signal.
	5	+	set -euo pipefail
	6	+
	7	+	readonly runs=5
	8	+	readonly timeout_seconds="${DUMBER_FIRST_PRESENTATION_TIMEOUT_SECONDS:-45}"
	9	+	readonly runtime="${DUMBER_CEF_DIR:-$HOME/.local/share/cef-147-runtime}"
	10	+	readonly binary="${DUMBER_FIRST_PRESENTATION_BIN:-$PWD/dist/dumber}"
	11	+	readonly output="${DUMBER_FIRST_PRESENTATION_OUTPUT:-$PWD/phase1/first-presentation}"
	12	+
	13	+	[[ -x "$binary" ]] \|\| { echo "first-presentation: executable not found: $binary" >&2; exit 2; }
	14	+	[[ -d "$runtime" ]] \|\| { echo "first-presentation: CEF runtime not found: $runtime" >&2; exit 2; }
	15	+	[[ -n "${WAYLAND_DISPLAY:-}${DISPLAY:-}" ]] \|\| { echo "first-presentation: a current Wayland/X11 display is required" >&2; exit 2; }
	16	+
	17	+	rm -rf "$output"
	18	+	mkdir -p "$output"
	19	+	python3 - "$output/metadata.json" "$runtime" "$binary" "$timeout_seconds" <<'PY'
	20	+	import json, os, subprocess, sys
	21	+	path, runtime, binary, timeout = sys.argv[1:]
	22	+	json.dump({
	23	+	"runs": 5,
	24	+	"runtime": runtime,
	25	+	"binary": binary,
	26	+	"timeout_seconds": int(timeout),
	27	+	"git_revision": subprocess.check_output(["git", "rev-parse", "HEAD"], text=True).strip(),
	28	+	"environment": {key: os.environ.get(key, "") for key in ("WAYLAND_DISPLAY", "DISPLAY", "XDG_CURRENT_DESKTOP")},
	29	+	"fixed_environment": {"DUMBER_RENDER_STACK": "vulkan-dmabuf", "PUREGO_CEF2GTK_BACKEND": "gdk-dmabuf", "GSK_RENDERER": "vulkan"}
	30	+	}, open(path, "w"), indent=2, sort_keys=True)
	31	+	PY
	32	+
	33	+	for number in $(seq 1 "$runs"); do
	34	+	run="$(printf 'run-%02d' "$number")"
	35	+	root="$output/$run"
	36	+	mkdir -p "$root"/{config,data,state,cache}
	37	+	mkdir -p "$root/config/dumber"
	38	+	cat >"$root/config/dumber/config.toml" <<EOF
	39	+	[logging]
	40	+	level = "debug"
	41	+	format = "json"
	42	+	enable_file_log = false
	43	+
	44	+	[engine.cef]
	45	+	cef_dir = "$runtime"
	46	+	EOF
	47	+	# Every directory below is newly created for this one launch. Do not inherit
	48	+	# a profile, shader cache, CEF root cache, or mutable app configuration.
	49	+	set +e
	50	+	env -i \
	51	+	HOME="$HOME" PATH="$PATH" LANG="${LANG:-C.UTF-8}" \
	52	+	WAYLAND_DISPLAY="${WAYLAND_DISPLAY:-}" DISPLAY="${DISPLAY:-}" XDG_RUNTIME_DIR="${XDG_RUNTIME_DIR:-}" \
	53	+	XDG_CONFIG_HOME="$root/config" XDG_DATA_HOME="$root/data" XDG_STATE_HOME="$root/state" XDG_CACHE_HOME="$root/cache" \
	54	+	DUMBER_CEF_ROOT_CACHE_PATH="$root/cef-root-cache" DUMBER_RENDER_STACK="vulkan-dmabuf" \
	55	+	PUREGO_CEF2GTK_BACKEND="gdk-dmabuf" PUREGO_CEF2GTK_ANGLE_BACKEND="vulkan" GSK_RENDERER="vulkan" \
	56	+	timeout --signal=TERM --kill-after=5s "${timeout_seconds}s" "$binary" browse about:blank >"$root/process.log" 2>&1
	57	+	exit_code=$?
	58	+	set -e
	59	+	# timeout is expected for a GUI kept alive after the first presentation.
	60	+	if [[ "$exit_code" != 0 && "$exit_code" != 124 ]]; then
	61	+	echo "$run: launch exited unexpectedly ($exit_code); see $root/process.log" >&2
	62	+	exit 1
	63	+	fi
	64	+	python3 - "$root/process.log" "$output/$run.json" "$run" <<'PY'
	65	+	import json, sys
	66	+	log, destination, run = sys.argv[1:]
	67	+	order = ["process_entry", "config_complete", "cef_library_load_begin", "cef_initialized", "browser_create_requested", "first_accelerated_paint_received", "first_dmabuf_texture_swap", "first_gtk_presentation"]
	68	+	records, summary = [], None
	69	+	for line in open(log, errors="replace"):
	70	+	try: event = json.loads(line)
	71	+	except json.JSONDecodeError: continue
	72	+	if event.get("message") == "startup_trace: milestone": records.append(event)
	73	+	if event.get("message") == "startup_trace: first presentation": summary = event
	74	+	names = [event.get("milestone") for event in records]
	75	+	times = [event.get("t_ms") for event in records]
	76	+	valid = names == order and all(isinstance(t, int) for t in times) and times == sorted(times)
	77	+	valid = valid and summary is not None and summary.get("backend") == "gdk-dmabuf" and not summary.get("incomplete_reason")
	78	+	result = {"run": run, "valid": valid, "milestones": records, "summary": summary}
	79	+	json.dump(result, open(destination, "w"), indent=2)
	80	+	if not valid:
	81	+	raise SystemExit(f"{run}: invalid or incomplete non-DMABUF timeline")
	82	+	PY
	83	+	done
	84	+
	85	+	python3 - "$output" <<'PY'
	86	+	import json, math, statistics, sys
	87	+	root = sys.argv[1]
	88	+	runs = [json.load(open(f"{root}/run-{n:02d}.json")) for n in range(1, 6)]
	89	+	if len(runs) != 5 or not all(run["valid"] for run in runs): raise SystemExit("expected exactly five valid runs")
	90	+	totals = sorted(run["summary"]["total_ms"] for run in runs)
	91	+	p95 = totals[max(0, math.ceil(.95 * len(totals)) - 1)]
	92	+	json.dump({"runs": 5, "total_ms": {"min": totals[0], "median": statistics.median(totals), "max": totals[-1], "p95": p95}}, open(f"{root}/baseline.json", "w"), indent=2)
	93	+	PY
	94	+
	95	+	echo "first-presentation artifacts: $output"

M vendor/github.com/bnema/purego-cef2gtk/handlers.go +22 -6 generated file: collapsed

load diff

M vendor/github.com/bnema/purego-cef2gtk/internal/gtkgdk/renderer.go +44 -6


@@ -128,11 +128,15 @@ type Renderer struct {
128	128		picture *gtk.Picture
129	129		offload *gtk.GraphicsOffload
130	130
131		-	display *gdk.Display
132		-	formats dmabufFormatSet
133		-	builder dmabufTextureBuilder
134		-	current *ownedTexture
135		-	retired []*ownedTexture
	131	+	display *gdk.Display
	132	+	formats dmabufFormatSet
	133	+	builder dmabufTextureBuilder
	134	+	current *ownedTexture
	135	+	retired []*ownedTexture
	136	+	pictureSetPaintable func(*gdk.Texture)
	137	+	firstTextureSwapMu sync.Mutex
	138	+	firstTextureSwap func()
	139	+	firstTextureSwapped bool
136	140
137	141		pendingMu sync.Mutex
138	142		pendingFrame *ownedFrame

@@ -285,6 +289,35 @@ func (r Renderer) Widget() gtk.Widget {
285	289		return r.widget
286	290		}
287	291
	292	+	// SetFirstDMABUFTextureSwapHook registers the one-shot callback invoked after
	293	+	// GtkPicture.SetPaintable succeeds for the first imported DMABUF texture.
	294	+	func (r *Renderer) SetFirstDMABUFTextureSwapHook(fn func()) bool {
	295	+	if r == nil {
	296	+	return false
	297	+	}
	298	+	r.firstTextureSwapMu.Lock()
	299	+	r.firstTextureSwap = fn
	300	+	r.firstTextureSwapMu.Unlock()
	301	+	return true
	302	+	}
	303	+
	304	+	func (r *Renderer) recordFirstDMABUFTextureSwap() {
	305	+	if r == nil {
	306	+	return
	307	+	}
	308	+	r.firstTextureSwapMu.Lock()
	309	+	if r.firstTextureSwapped {
	310	+	r.firstTextureSwapMu.Unlock()
	311	+	return
	312	+	}
	313	+	r.firstTextureSwapped = true
	314	+	fn := r.firstTextureSwap
	315	+	r.firstTextureSwapMu.Unlock()
	316	+	if fn != nil {
	317	+	fn()
	318	+	}
	319	+	}
	320	+
288	321		// Picture returns the GtkPicture used as the paintable presenter.
289	322		func (r Renderer) Picture() gtk.Picture {
290	323		if r == nil {

@@ -490,9 +523,14 @@ func (r Renderer) importAndSwapOwnedFrame(frame ownedFrame) error {
490	523		return ErrMissingPicture
491	524		}
492	525		old := r.current
493		-	r.picture.SetPaintable(built.texture)
	526	+	if r.pictureSetPaintable != nil {
	527	+	r.pictureSetPaintable(built.texture)
	528	+	} else {
	529	+	r.picture.SetPaintable(built.texture)
	530	+	}
494	531		r.current = built
495	532		r.recordPaintableSwap()
	533	+	r.recordFirstDMABUFTextureSwap()
496	534		r.retireOwnedTexture(old)
497	535		return nil
498	536		}


@@ -128,11 +128,15 @@ type Renderer struct {
128		picture *gtk.Picture	128		picture *gtk.Picture
129		offload *gtk.GraphicsOffload	129		offload *gtk.GraphicsOffload
130			130
131	-	display *gdk.Display	131	+	display *gdk.Display
132	-	formats dmabufFormatSet	132	+	formats dmabufFormatSet
133	-	builder dmabufTextureBuilder	133	+	builder dmabufTextureBuilder
134	-	current *ownedTexture	134	+	current *ownedTexture
135	-	retired []*ownedTexture	135	+	retired []*ownedTexture
			136	+	pictureSetPaintable func(*gdk.Texture)
			137	+	firstTextureSwapMu sync.Mutex
			138	+	firstTextureSwap func()
			139	+	firstTextureSwapped bool
136			140
137		pendingMu sync.Mutex	141		pendingMu sync.Mutex
138		pendingFrame *ownedFrame	142		pendingFrame *ownedFrame

@@ -285,6 +289,35 @@ func (r Renderer) Widget() gtk.Widget {
285		return r.widget	289		return r.widget
286		}	290		}
287			291
			292	+	// SetFirstDMABUFTextureSwapHook registers the one-shot callback invoked after
			293	+	// GtkPicture.SetPaintable succeeds for the first imported DMABUF texture.
			294	+	func (r *Renderer) SetFirstDMABUFTextureSwapHook(fn func()) bool {
			295	+	if r == nil {
			296	+	return false
			297	+	}
			298	+	r.firstTextureSwapMu.Lock()
			299	+	r.firstTextureSwap = fn
			300	+	r.firstTextureSwapMu.Unlock()
			301	+	return true
			302	+	}
			303	+
			304	+	func (r *Renderer) recordFirstDMABUFTextureSwap() {
			305	+	if r == nil {
			306	+	return
			307	+	}
			308	+	r.firstTextureSwapMu.Lock()
			309	+	if r.firstTextureSwapped {
			310	+	r.firstTextureSwapMu.Unlock()
			311	+	return
			312	+	}
			313	+	r.firstTextureSwapped = true
			314	+	fn := r.firstTextureSwap
			315	+	r.firstTextureSwapMu.Unlock()
			316	+	if fn != nil {
			317	+	fn()
			318	+	}
			319	+	}
			320	+
288		// Picture returns the GtkPicture used as the paintable presenter.	321		// Picture returns the GtkPicture used as the paintable presenter.
289		func (r Renderer) Picture() gtk.Picture {	322		func (r Renderer) Picture() gtk.Picture {
290		if r == nil {	323		if r == nil {

@@ -490,9 +523,14 @@ func (r Renderer) importAndSwapOwnedFrame(frame ownedFrame) error {
490		return ErrMissingPicture	523		return ErrMissingPicture
491		}	524		}
492		old := r.current	525		old := r.current
493	-	r.picture.SetPaintable(built.texture)	526	+	if r.pictureSetPaintable != nil {
			527	+	r.pictureSetPaintable(built.texture)
			528	+	} else {
			529	+	r.picture.SetPaintable(built.texture)
			530	+	}
494		r.current = built	531		r.current = built
495		r.recordPaintableSwap()	532		r.recordPaintableSwap()
			533	+	r.recordFirstDMABUFTextureSwap()
496		r.retireOwnedTexture(old)	534		r.retireOwnedTexture(old)
497		return nil	535		return nil
498		}	536		}

M vendor/github.com/bnema/purego-cef2gtk/internal/gtkgl/accelerated_renderer.go +6 -0 generated file: collapsed

load diff

M vendor/github.com/bnema/purego-cef2gtk/view.go +182 -0 generated file: collapsed

load diff

M vendor/modules.txt +1 -1 generated file: collapsed

load diff