fix(startup): own CEF trace lifecycle

commit: 6949e93681b096d8373eda4300b7512130baa09b
author: brice · 3mo ago · 2026-07-15 08:54 UTC
parent: ce24e6e
signature: GPG VerifiedCD88F9E564E0102646FB6077A1A07C7C7C3E349D · arch-gpg Verified for the committer email

12 files · +381 -329

M cmd/dumber/main.go +27 -19


@@ -10,6 +10,7 @@ import (
10	10		"runtime"
11	11		"strings"
12	12		"syscall"
	13	+	"time"
13	14
14	15		"github.com/bnema/dumber/internal/application/port"
15	16		"github.com/bnema/dumber/internal/application/usecase"

@@ -140,11 +141,16 @@ func configureBrowserLaunchRelay(cfg *config.Config) {
140	141		browserLaunchRelay = relay
141	142		}
142	143
	144	+	type startupTiming struct {
	145	+	processEntry time.Time
	146	+	configComplete time.Time
	147	+	}
	148	+
143	149		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.InitCEFStartupTrace()
147		-	logging.CEFTrace().Mark("process_entry")
	150	+	// CEF is not known until configuration is complete. Keep these neutral
	151	+	// timestamps so a CEF GUI trace can be seeded truthfully without creating
	152	+	// one for WebKit, the standalone omnibox, CLI, or CEF helper processes.
	153	+	timing := startupTiming{processEntry: time.Now()}
148	154
149	155		// CEF subprocess handling: when CEF re-launches this binary with
150	156		// --type=renderer/gpu/etc, we must call ExecuteProcess before anything

@@ -175,6 +181,7 @@ func main() {
175	181		// Run GUI mode for browse command
176	182		if mode == launchModeBrowse {
177	183		cfg := initConfig()
	184	+	timing.configComplete = time.Now()
178	185		configureBrowserLaunchRelay(cfg)
179	186		startupURL := domainurl.ResolveBrowserStartupURL(browseURL)
180	187		if forwarded, err := tryForwardBrowseURLToRunningInstance(context.Background(), browserLaunchRelay, startupURL); err != nil {

@@ -191,7 +198,7 @@ func main() {
191	198		initialURL = startupURL
192	199		restoreSessionID = os.Getenv("DUMBER_RESTORE_SESSION")
193	200		os.Args = os.Args[:1]
194		-	os.Exit(runGUI(cfg))
	201	+	os.Exit(runGUI(cfg, timing))
195	202		return
196	203		}
197	204

@@ -212,7 +219,7 @@ func main() {
212	219		cmd.Execute()
213	220		}
214	221
215		-	func runGUI(cfg *config.Config) int {
	222	+	func runGUI(cfg *config.Config, timing startupTiming) int {
216	223		bootstrap.ApplyGTKIMModuleFallbackDefault(os.Stderr)
217	224
218	225		runtime.LockOSThread()

@@ -221,12 +228,13 @@ func runGUI(cfg *config.Config) int {
221	228
222	229		if cfg == nil {
223	230		cfg = initConfig()
	231	+	timing.configComplete = time.Now()
224	232		configureBrowserLaunchRelay(cfg)
225	233		}
226		-	logging.CEFTrace().Mark("config_complete")
227	234		timer.Mark("config")
228	235
229		-	ctx := initStartupContextWithTrace(cfg)
	236	+	ctx := initStartupContext(cfg)
	237	+	activateCEFStartupTraceForGUI(cfg, timing, logging.FromContext(ctx), infracef.ActivateStartupTrace)
230	238		applyCEFRenderStackDefault(ctx, cfg)
231	239		timer.Mark("logger")
232	240		bootstrapLog := logging.FromContext(ctx)

@@ -259,7 +267,6 @@ func runGUI(cfg *config.Config) int {
259	267		timer.Mark("session")
260	268
261	269		log := logging.FromContext(ctx)
262		-	logging.CEFTrace().SetLogger(log)
263	270		logCoreDumpLimits(ctx)
264	271
265	272		engine.SetHandlerContext(ctx)

@@ -303,7 +310,7 @@ func runStandaloneOmnibox() int {
303	310
304	311		cfg := initConfig()
305	312		configureBrowserLaunchRelay(cfg)
306		-	ctx := initStartupContextWithTrace(cfg)
	313	+	ctx := initStartupContext(cfg)
307	314		applyCEFRenderStackDefault(ctx, cfg)
308	315
309	316		initResult, err := runParallelInitPhase(ctx, cfg)

@@ -418,15 +425,16 @@ func resolveCurrentExecutable(executable func() (string, error)) (string, error)
418	425		return executable()
419	426		}
420	427
421		-	func initStartupContextWithTrace(cfg *config.Config) context.Context {
422		-	logging.InitCEFStartupTrace()
423		-
424		-	ctx := initStartupContext(cfg)
425		-	bootstrapLog := logging.FromContext(ctx)
426		-
427		-	logging.CEFTrace().SetLogger(bootstrapLog)
428		-
429		-	return ctx
	428	+	func activateCEFStartupTraceForGUI(
	429	+	cfg *config.Config,
	430	+	timing startupTiming,
	431	+	logger *zerolog.Logger,
	432	+	activate func(time.Time, time.Time, *zerolog.Logger),
	433	+	) {
	434	+	if cfg == nil \|\| cfg.Engine.ResolveEngineType() != config.EngineTypeCEF {
	435	+	return
	436	+	}
	437	+	activate(timing.processEntry, timing.configComplete, logger)
430	438		}
431	439
432	440		func runParallelInitPhase(ctx context.Context, cfg config.Config) (bootstrap.ParallelInitResult, error) {


@@ -10,6 +10,7 @@ import (
10		"runtime"	10		"runtime"
11		"strings"	11		"strings"
12		"syscall"	12		"syscall"
			13	+	"time"
13			14
14		"github.com/bnema/dumber/internal/application/port"	15		"github.com/bnema/dumber/internal/application/port"
15		"github.com/bnema/dumber/internal/application/usecase"	16		"github.com/bnema/dumber/internal/application/usecase"

@@ -140,11 +141,16 @@ func configureBrowserLaunchRelay(cfg *config.Config) {
140		browserLaunchRelay = relay	141		browserLaunchRelay = relay
141		}	142		}
142			143
			144	+	type startupTiming struct {
			145	+	processEntry time.Time
			146	+	configComplete time.Time
			147	+	}
			148	+
143		func main() {	149		func main() {
144	-	// This is intentionally before subprocess detection: each process records	150	+	// CEF is not known until configuration is complete. Keep these neutral
145	-	// its own first observable main event before CEF can take over execution.	151	+	// timestamps so a CEF GUI trace can be seeded truthfully without creating
146	-	logging.InitCEFStartupTrace()	152	+	// one for WebKit, the standalone omnibox, CLI, or CEF helper processes.
147	-	logging.CEFTrace().Mark("process_entry")	153	+	timing := startupTiming{processEntry: time.Now()}
148			154
149		// CEF subprocess handling: when CEF re-launches this binary with	155		// CEF subprocess handling: when CEF re-launches this binary with
150		// --type=renderer/gpu/etc, we must call ExecuteProcess before anything	156		// --type=renderer/gpu/etc, we must call ExecuteProcess before anything

@@ -175,6 +181,7 @@ func main() {
175		// Run GUI mode for browse command	181		// Run GUI mode for browse command
176		if mode == launchModeBrowse {	182		if mode == launchModeBrowse {
177		cfg := initConfig()	183		cfg := initConfig()
			184	+	timing.configComplete = time.Now()
178		configureBrowserLaunchRelay(cfg)	185		configureBrowserLaunchRelay(cfg)
179		startupURL := domainurl.ResolveBrowserStartupURL(browseURL)	186		startupURL := domainurl.ResolveBrowserStartupURL(browseURL)
180		if forwarded, err := tryForwardBrowseURLToRunningInstance(context.Background(), browserLaunchRelay, startupURL); err != nil {	187		if forwarded, err := tryForwardBrowseURLToRunningInstance(context.Background(), browserLaunchRelay, startupURL); err != nil {

@@ -191,7 +198,7 @@ func main() {
191		initialURL = startupURL	198		initialURL = startupURL
192		restoreSessionID = os.Getenv("DUMBER_RESTORE_SESSION")	199		restoreSessionID = os.Getenv("DUMBER_RESTORE_SESSION")
193		os.Args = os.Args[:1]	200		os.Args = os.Args[:1]
194	-	os.Exit(runGUI(cfg))	201	+	os.Exit(runGUI(cfg, timing))
195		return	202		return
196		}	203		}
197			204

@@ -212,7 +219,7 @@ func main() {
212		cmd.Execute()	219		cmd.Execute()
213		}	220		}
214			221
215	-	func runGUI(cfg *config.Config) int {	222	+	func runGUI(cfg *config.Config, timing startupTiming) int {
216		bootstrap.ApplyGTKIMModuleFallbackDefault(os.Stderr)	223		bootstrap.ApplyGTKIMModuleFallbackDefault(os.Stderr)
217			224
218		runtime.LockOSThread()	225		runtime.LockOSThread()

@@ -221,12 +228,13 @@ func runGUI(cfg *config.Config) int {
221			228
222		if cfg == nil {	229		if cfg == nil {
223		cfg = initConfig()	230		cfg = initConfig()
			231	+	timing.configComplete = time.Now()
224		configureBrowserLaunchRelay(cfg)	232		configureBrowserLaunchRelay(cfg)
225		}	233		}
226	-	logging.CEFTrace().Mark("config_complete")
227		timer.Mark("config")	234		timer.Mark("config")
228			235
229	-	ctx := initStartupContextWithTrace(cfg)	236	+	ctx := initStartupContext(cfg)
			237	+	activateCEFStartupTraceForGUI(cfg, timing, logging.FromContext(ctx), infracef.ActivateStartupTrace)
230		applyCEFRenderStackDefault(ctx, cfg)	238		applyCEFRenderStackDefault(ctx, cfg)
231		timer.Mark("logger")	239		timer.Mark("logger")
232		bootstrapLog := logging.FromContext(ctx)	240		bootstrapLog := logging.FromContext(ctx)

@@ -259,7 +267,6 @@ func runGUI(cfg *config.Config) int {
259		timer.Mark("session")	267		timer.Mark("session")
260			268
261		log := logging.FromContext(ctx)	269		log := logging.FromContext(ctx)
262	-	logging.CEFTrace().SetLogger(log)
263		logCoreDumpLimits(ctx)	270		logCoreDumpLimits(ctx)
264			271
265		engine.SetHandlerContext(ctx)	272		engine.SetHandlerContext(ctx)

@@ -303,7 +310,7 @@ func runStandaloneOmnibox() int {
303			310
304		cfg := initConfig()	311		cfg := initConfig()
305		configureBrowserLaunchRelay(cfg)	312		configureBrowserLaunchRelay(cfg)
306	-	ctx := initStartupContextWithTrace(cfg)	313	+	ctx := initStartupContext(cfg)
307		applyCEFRenderStackDefault(ctx, cfg)	314		applyCEFRenderStackDefault(ctx, cfg)
308			315
309		initResult, err := runParallelInitPhase(ctx, cfg)	316		initResult, err := runParallelInitPhase(ctx, cfg)

@@ -418,15 +425,16 @@ func resolveCurrentExecutable(executable func() (string, error)) (string, error)
418		return executable()	425		return executable()
419		}	426		}
420			427
421	-	func initStartupContextWithTrace(cfg *config.Config) context.Context {	428	+	func activateCEFStartupTraceForGUI(
422	-	logging.InitCEFStartupTrace()	429	+	cfg *config.Config,
423	-		430	+	timing startupTiming,
424	-	ctx := initStartupContext(cfg)	431	+	logger *zerolog.Logger,
425	-	bootstrapLog := logging.FromContext(ctx)	432	+	activate func(time.Time, time.Time, *zerolog.Logger),
426	-		433	+	) {
427	-	logging.CEFTrace().SetLogger(bootstrapLog)	434	+	if cfg == nil \|\| cfg.Engine.ResolveEngineType() != config.EngineTypeCEF {
428	-		435	+	return
429	-	return ctx	436	+	}
			437	+	activate(timing.processEntry, timing.configComplete, logger)
430		}	438		}
431			439
432		func runParallelInitPhase(ctx context.Context, cfg config.Config) (bootstrap.ParallelInitResult, error) {	440		func runParallelInitPhase(ctx context.Context, cfg config.Config) (bootstrap.ParallelInitResult, error) {

M cmd/dumber/main_test.go +16 -0


@@ -4,12 +4,14 @@ import (
4	4		"context"
5	5		"errors"
6	6		"testing"
	7	+	"time"
7	8
8	9		"github.com/bnema/dumber/internal/application/port/mocks"
9	10		"github.com/bnema/dumber/internal/bootstrap"
10	11		"github.com/bnema/dumber/internal/infrastructure/colorscheme"
11	12		"github.com/bnema/dumber/internal/infrastructure/config"
12	13		"github.com/bnema/dumber/internal/infrastructure/desktop"
	14	+	"github.com/rs/zerolog"
13	15		)
14	16
15	17		func TestLaunchModeFromArgs_DetectsStandaloneOmnibox(t *testing.T) {

@@ -172,6 +174,20 @@ func TestResolveCurrentExecutable_PropagatesError(t *testing.T) {
172	174		}
173	175		}
174	176
	177	+	func TestWebKitGUIStartupDoesNotActivateCEFTrace(t *testing.T) {
	178	+	cfg := &config.Config{}
	179	+	cfg.Engine.Type = config.EngineTypeWebKit
	180	+	activationCalls := 0
	181	+
	182	+	activateCEFStartupTraceForGUI(cfg, startupTiming{}, nil, func(time.Time, time.Time, *zerolog.Logger) {
	183	+	activationCalls++
	184	+	})
	185	+
	186	+	if activationCalls != 0 {
	187	+	t.Fatal("WebKit GUI startup must not initialize, record, or summarize the CEF first-presentation trace")
	188	+	}
	189	+	}
	190	+
175	191		func TestPreInitializeAdwaitaForCEF_InitializesAndMarksDetector(t *testing.T) {
176	192		initResult := &bootstrap.ParallelInitResult{
177	193		AdwaitaDetector: colorscheme.NewAdwaitaDetector(),


@@ -4,12 +4,14 @@ import (
4	"context"	4		"context"
5	"errors"	5		"errors"
6	"testing"	6		"testing"
		7	+	"time"
7		8
8	"github.com/bnema/dumber/internal/application/port/mocks"	9		"github.com/bnema/dumber/internal/application/port/mocks"
9	"github.com/bnema/dumber/internal/bootstrap"	10		"github.com/bnema/dumber/internal/bootstrap"
10	"github.com/bnema/dumber/internal/infrastructure/colorscheme"	11		"github.com/bnema/dumber/internal/infrastructure/colorscheme"
11	"github.com/bnema/dumber/internal/infrastructure/config"	12		"github.com/bnema/dumber/internal/infrastructure/config"
12	"github.com/bnema/dumber/internal/infrastructure/desktop"	13		"github.com/bnema/dumber/internal/infrastructure/desktop"
		14	+	"github.com/rs/zerolog"
13	)	15		)
14		16
15	func TestLaunchModeFromArgs_DetectsStandaloneOmnibox(t *testing.T) {	17		func TestLaunchModeFromArgs_DetectsStandaloneOmnibox(t *testing.T) {

@@ -172,6 +174,20 @@ func TestResolveCurrentExecutable_PropagatesError(t *testing.T) {
172	}	174		}
173	}	175		}
174		176
		177	+	func TestWebKitGUIStartupDoesNotActivateCEFTrace(t *testing.T) {
		178	+	cfg := &config.Config{}
		179	+	cfg.Engine.Type = config.EngineTypeWebKit
		180	+	activationCalls := 0
		181	+
		182	+	activateCEFStartupTraceForGUI(cfg, startupTiming{}, nil, func(time.Time, time.Time, *zerolog.Logger) {
		183	+	activationCalls++
		184	+	})
		185	+
		186	+	if activationCalls != 0 {
		187	+	t.Fatal("WebKit GUI startup must not initialize, record, or summarize the CEF first-presentation trace")
		188	+	}
		189	+	}
		190	+
175	func TestPreInitializeAdwaitaForCEF_InitializesAndMarksDetector(t *testing.T) {	191		func TestPreInitializeAdwaitaForCEF_InitializesAndMarksDetector(t *testing.T) {
176	initResult := &bootstrap.ParallelInitResult{	192		initResult := &bootstrap.ParallelInitResult{
177	AdwaitaDetector: colorscheme.NewAdwaitaDetector(),	193		AdwaitaDetector: colorscheme.NewAdwaitaDetector(),

M docs/first-presentation.md +6 -2


@@ -4,8 +4,12 @@ Dumber records this cold-start timeline **only for the accelerated CEF → DMABU
4	4		→ GTK path**. It is not a backend-neutral startup metric: the WebKit backend
5	5		does not add milestones to this trace and never emits this CEF summary.
6	6
7		-	For a CEF GUI process, the trace begins at `process_entry`, before CEF
8		-	subprocess handling, and accepts these one-shot milestones only in order:
	7	+	For a selected CEF GUI process, Dumber captures neutral `process_entry` and
	8	+	`config_complete` timestamps, then activates and seeds this CEF-owned trace only
	9	+	after configuration selects CEF. CEF helper processes, WebKit GUI startup, the
	10	+	standalone omnibox, and CLI commands never initialize this trace, record its
	11	+	milestones, or emit its summary. A selected CEF GUI trace accepts these one-shot
	12	+	milestones only in order:
9	13
10	14		1. `process_entry`
11	15		2. `config_complete`

 → GTK path**. It is not a backend-neutral startup metric: the WebKit backend
 does not add milestones to this trace and never emits this CEF summary.
-For a CEF GUI process, the trace begins at `process_entry`, before CEF
+For a selected CEF GUI process, Dumber captures neutral `process_entry` and
-subprocess handling, and accepts these one-shot milestones only in order:
+`config_complete` timestamps, then activates and seeds this CEF-owned trace only
+after configuration selects CEF. CEF helper processes, WebKit GUI startup, the
+standalone omnibox, and CLI commands never initialize this trace, record its
+milestones, or emit its summary. A selected CEF GUI trace accepts these one-shot
+milestones only in order:
 1. `process_entry`
 2. `config_complete`

M internal/infrastructure/cef/engine_init.go +3 -3


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

@@ -218,11 +218,11 @@ func initializeCEF(eng Engine, settings purecef.Settings, logger zerolog.Logge
218	218		logger.Debug().Msg("cef: calling InitWithApp")
219	219		// InitWithApp encapsulates loading libcef, so only the begin boundary is
220	220		// observable here; do not invent a separate library-load completion event.
221		-	logging.CEFTrace().Mark("cef_library_load_begin")
	221	+	activeStartupTrace().Mark("cef_library_load_begin")
222	222		if err := purecef.InitWithApp(settings, app); err != nil {
223	223		return fmt.Errorf("cef.InitWithApp: %w", err)
224	224		}
225		-	logging.CEFTrace().Mark("cef_initialized")
	225	+	activeStartupTrace().Mark("cef_initialized")
226	226		if libcefPath := loadedLibCEFPath(); libcefPath != "" {
227	227		logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded")
228	228		} else {


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

@@ -218,11 +218,11 @@ func initializeCEF(eng Engine, settings purecef.Settings, logger zerolog.Logge
218		logger.Debug().Msg("cef: calling InitWithApp")	218		logger.Debug().Msg("cef: calling InitWithApp")
219		// InitWithApp encapsulates loading libcef, so only the begin boundary is	219		// InitWithApp encapsulates loading libcef, so only the begin boundary is
220		// observable here; do not invent a separate library-load completion event.	220		// observable here; do not invent a separate library-load completion event.
221	-	logging.CEFTrace().Mark("cef_library_load_begin")	221	+	activeStartupTrace().Mark("cef_library_load_begin")
222		if err := purecef.InitWithApp(settings, app); err != nil {	222		if err := purecef.InitWithApp(settings, app); err != nil {
223		return fmt.Errorf("cef.InitWithApp: %w", err)	223		return fmt.Errorf("cef.InitWithApp: %w", err)
224		}	224		}
225	-	logging.CEFTrace().Mark("cef_initialized")	225	+	activeStartupTrace().Mark("cef_initialized")
226		if libcefPath := loadedLibCEFPath(); libcefPath != "" {	226		if libcefPath := loadedLibCEFPath(); libcefPath != "" {
227		logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded")	227		logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded")
228		} else {	228		} else {

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


@@ -279,7 +279,7 @@ func (f WebViewFactory) postPendingBrowserCreate(ctx context.Context, wv WebVi
279	279		// OnAfterCreated once the host is fully wired.
280	280		initialURL := "about:blank"
281	281		// This is the request boundary, not the later OnAfterCreated callback.
282		-	logging.CEFTrace().Mark("browser_create_requested")
	282	+	activeStartupTrace().Mark("browser_create_requested")
283	283		result := cefBrowserHostCreateBrowser(
284	284		pc.windowInfo,
285	285		pc.client,


@@ -279,7 +279,7 @@ func (f WebViewFactory) postPendingBrowserCreate(ctx context.Context, wv WebVi
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.	281		// This is the request boundary, not the later OnAfterCreated callback.
282	-	logging.CEFTrace().Mark("browser_create_requested")	282	+	activeStartupTrace().Mark("browser_create_requested")
283		result := cefBrowserHostCreateBrowser(	283		result := cefBrowserHostCreateBrowser(
284		pc.windowInfo,	284		pc.windowInfo,
285		pc.client,	285		pc.client,

R internal/logging/first_presentation_collector_test.go → internal/infrastructure/cef/first_presentation_collector_test.go +9 -9 renamed, 96% similar

@@ -1,4 +1,4 @@
1		-	package logging
	1	+	package cef
2	2
3	3		import (
4	4		"encoding/json"

@@ -23,7 +23,7 @@ const validFirstPresentationLog = `{"message":"startup_trace: milestone","milest
23	23		{"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}`
24	24
25	25		func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testing.T) {
26		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	26	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
27	27		require.NoError(t, err)
28	28		script, err := os.ReadFile(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))
29	29		require.NoError(t, err)

@@ -32,7 +32,7 @@ func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testin
32	32		}
33	33
34	34		func TestFirstPresentationCollectorRejectsUnsafeOutputPaths(t *testing.T) {
35		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	35	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
36	36		require.NoError(t, err)
37	37		temp := t.TempDir()
38	38		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -109,7 +109,7 @@ func requireFileContents(t *testing.T, path, want string) {
109	109		}
110	110
111	111		func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
112		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	112	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
113	113		require.NoError(t, err)
114	114		temp := t.TempDir()
115	115		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -169,7 +169,7 @@ func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
169	169		}
170	170
171	171		func TestFirstPresentationCollectorDerivesSelectedImmutableModuleProvenance(t *testing.T) {
172		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	172	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
173	173		require.NoError(t, err)
174	174		temp := t.TempDir()
175	175		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -218,7 +218,7 @@ func TestFirstPresentationCollectorDerivesSelectedImmutableModuleProvenance(t *t
218	218		}
219	219
220	220		func TestFirstPresentationCollectorRejectsNonImmutableModuleProvenanceWithoutLeaks(t *testing.T) {
221		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	221	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
222	222		require.NoError(t, err)
223	223
224	224		for _, test := range []struct {

@@ -298,7 +298,7 @@ exit 1
298	298		}
299	299
300	300		func TestFirstPresentationCollectorDefaultsToXDGStateEvidenceDirectory(t *testing.T) {
301		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	301	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
302	302		require.NoError(t, err)
303	303		temp := t.TempDir()
304	304		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -342,7 +342,7 @@ func envWithout(name string) []string {
342	342		}
343	343
344	344		func TestFirstPresentationCollectorReadsProvenanceWithScopedGitSafeDirectory(t *testing.T) {
345		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	345	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
346	346		require.NoError(t, err)
347	347		temp := t.TempDir()
348	348		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -386,7 +386,7 @@ exit 128
386	386		}
387	387
388	388		func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) {
389		-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))
	389	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
390	390		require.NoError(t, err)
391	391
392	392		for _, test := range []struct {

@@ -1,4 +1,4 @@
1	-	package logging	1	+	package cef
2			2
3		import (	3		import (
4		"encoding/json"	4		"encoding/json"

@@ -23,7 +23,7 @@ const validFirstPresentationLog = `{"message":"startup_trace: milestone","milest
23		{"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}`	23		{"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}`
24			24
25		func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testing.T) {	25		func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testing.T) {
26	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	26	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
27		require.NoError(t, err)	27		require.NoError(t, err)
28		script, err := os.ReadFile(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))	28		script, err := os.ReadFile(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh"))
29		require.NoError(t, err)	29		require.NoError(t, err)

@@ -32,7 +32,7 @@ func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testin
32		}	32		}
33			33
34		func TestFirstPresentationCollectorRejectsUnsafeOutputPaths(t *testing.T) {	34		func TestFirstPresentationCollectorRejectsUnsafeOutputPaths(t *testing.T) {
35	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	35	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
36		require.NoError(t, err)	36		require.NoError(t, err)
37		temp := t.TempDir()	37		temp := t.TempDir()
38		runtime := filepath.Join(temp, "cef-147-runtime")	38		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -109,7 +109,7 @@ func requireFileContents(t *testing.T, path, want string) {
109		}	109		}
110			110
111		func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {	111		func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
112	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	112	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
113		require.NoError(t, err)	113		require.NoError(t, err)
114		temp := t.TempDir()	114		temp := t.TempDir()
115		runtime := filepath.Join(temp, "cef-147-runtime")	115		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -169,7 +169,7 @@ func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) {
169		}	169		}
170			170
171		func TestFirstPresentationCollectorDerivesSelectedImmutableModuleProvenance(t *testing.T) {	171		func TestFirstPresentationCollectorDerivesSelectedImmutableModuleProvenance(t *testing.T) {
172	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	172	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
173		require.NoError(t, err)	173		require.NoError(t, err)
174		temp := t.TempDir()	174		temp := t.TempDir()
175		runtime := filepath.Join(temp, "cef-147-runtime")	175		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -218,7 +218,7 @@ func TestFirstPresentationCollectorDerivesSelectedImmutableModuleProvenance(t *t
218		}	218		}
219			219
220		func TestFirstPresentationCollectorRejectsNonImmutableModuleProvenanceWithoutLeaks(t *testing.T) {	220		func TestFirstPresentationCollectorRejectsNonImmutableModuleProvenanceWithoutLeaks(t *testing.T) {
221	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	221	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
222		require.NoError(t, err)	222		require.NoError(t, err)
223			223
224		for _, test := range []struct {	224		for _, test := range []struct {

@@ -298,7 +298,7 @@ exit 1
298		}	298		}
299			299
300		func TestFirstPresentationCollectorDefaultsToXDGStateEvidenceDirectory(t *testing.T) {	300		func TestFirstPresentationCollectorDefaultsToXDGStateEvidenceDirectory(t *testing.T) {
301	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	301	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
302		require.NoError(t, err)	302		require.NoError(t, err)
303		temp := t.TempDir()	303		temp := t.TempDir()
304		runtime := filepath.Join(temp, "cef-147-runtime")	304		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -342,7 +342,7 @@ func envWithout(name string) []string {
342		}	342		}
343			343
344		func TestFirstPresentationCollectorReadsProvenanceWithScopedGitSafeDirectory(t *testing.T) {	344		func TestFirstPresentationCollectorReadsProvenanceWithScopedGitSafeDirectory(t *testing.T) {
345	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	345	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
346		require.NoError(t, err)	346		require.NoError(t, err)
347		temp := t.TempDir()	347		temp := t.TempDir()
348		runtime := filepath.Join(temp, "cef-147-runtime")	348		runtime := filepath.Join(temp, "cef-147-runtime")

@@ -386,7 +386,7 @@ exit 128
386		}	386		}
387			387
388		func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) {	388		func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) {
389	-	repoRoot, err := filepath.Abs(filepath.Join("..", ".."))	389	+	repoRoot, err := filepath.Abs(filepath.Join("..", "..", ".."))
390		require.NoError(t, err)	390		require.NoError(t, err)
391			391
392		for _, test := range []struct {	392		for _, test := range []struct {

M internal/infrastructure/cef/render_handler_adapter.go +2 -2


@@ -26,7 +26,7 @@ var _ purecef.RenderHandler = (*dumberRenderHandler)(nil)
26	26		// startupPresentationHooks consumes the one-shot facts emitted by
27	27		// purego-cef2gtk. The bridge owns the native DMABUF and frame-clock boundaries;
28	28		// Dumber only records their ordered application-level timeline.
29		-	func startupPresentationHooks(trace *logging.CEFStartupTrace) cef2gtk.Hooks {
	29	+	func startupPresentationHooks(trace *startupTrace) cef2gtk.Hooks {
30	30		return cef2gtk.Hooks{
31	31		OnFirstAcceleratedPaint: func() {
32	32		trace.Mark("first_accelerated_paint_received")

@@ -50,7 +50,7 @@ func newDumberRenderHandler(wv *WebView) purecef.RenderHandler {
50	50		h := &dumberRenderHandler{wv: wv}
51	51
52	52		var unsupportedPaintOnce sync.Once
53		-	hooks := startupPresentationHooks(logging.CEFTrace())
	53	+	hooks := startupPresentationHooks(activeStartupTrace())
54	54		hooks.OnUnsupportedPaint = func() {
55	55		unsupportedPaintOnce.Do(func() {
56	56		if wv.ctx != nil {


@@ -26,7 +26,7 @@ var _ purecef.RenderHandler = (*dumberRenderHandler)(nil)
26		// startupPresentationHooks consumes the one-shot facts emitted by	26		// startupPresentationHooks consumes the one-shot facts emitted by
27		// purego-cef2gtk. The bridge owns the native DMABUF and frame-clock boundaries;	27		// purego-cef2gtk. The bridge owns the native DMABUF and frame-clock boundaries;
28		// Dumber only records their ordered application-level timeline.	28		// Dumber only records their ordered application-level timeline.
29	-	func startupPresentationHooks(trace *logging.CEFStartupTrace) cef2gtk.Hooks {	29	+	func startupPresentationHooks(trace *startupTrace) cef2gtk.Hooks {
30		return cef2gtk.Hooks{	30		return cef2gtk.Hooks{
31		OnFirstAcceleratedPaint: func() {	31		OnFirstAcceleratedPaint: func() {
32		trace.Mark("first_accelerated_paint_received")	32		trace.Mark("first_accelerated_paint_received")

@@ -50,7 +50,7 @@ func newDumberRenderHandler(wv *WebView) purecef.RenderHandler {
50		h := &dumberRenderHandler{wv: wv}	50		h := &dumberRenderHandler{wv: wv}
51			51
52		var unsupportedPaintOnce sync.Once	52		var unsupportedPaintOnce sync.Once
53	-	hooks := startupPresentationHooks(logging.CEFTrace())	53	+	hooks := startupPresentationHooks(activeStartupTrace())
54		hooks.OnUnsupportedPaint = func() {	54		hooks.OnUnsupportedPaint = func() {
55		unsupportedPaintOnce.Do(func() {	55		unsupportedPaintOnce.Do(func() {
56		if wv.ctx != nil {	56		if wv.ctx != nil {

M internal/infrastructure/cef/startup_presentation_hooks_test.go +2 -2


@@ -5,15 +5,15 @@ import (
5	5		"encoding/json"
6	6		"strings"
7	7		"testing"
	8	+	"time"
8	9
9		-	"github.com/bnema/dumber/internal/logging"
10	10		"github.com/rs/zerolog"
11	11		"github.com/stretchr/testify/require"
12	12		)
13	13
14	14		func TestStartupPresentationHooksWireEveryUpstreamFirstPresentationCallback(t *testing.T) {
15	15		var output bytes.Buffer
16		-	trace := logging.NewCEFStartupTrace()
	16	+	trace := newStartupTrace(time.Now, time.Now())
17	17		trace.SetBackend("gdk-dmabuf")
18	18		logger := zerolog.New(&output)
19	19		trace.SetLogger(&logger)

 	"encoding/json"
 	"strings"
 	"testing"
+	"time"
-	"github.com/bnema/dumber/internal/logging"
 	"github.com/rs/zerolog"
 	"github.com/stretchr/testify/require"
 )
 func TestStartupPresentationHooksWireEveryUpstreamFirstPresentationCallback(t *testing.T) {
 	var output bytes.Buffer
-	trace := logging.NewCEFStartupTrace()
+	trace := newStartupTrace(time.Now, time.Now())
 	trace.SetBackend("gdk-dmabuf")
 	logger := zerolog.New(&output)
 	trace.SetLogger(&logger)

A internal/infrastructure/cef/startup_trace.go +199 -0

@@ -0,0 +1,199 @@
	1	+	package cef
	2	+
	3	+	import (
	4	+	"sync"
	5	+	"time"
	6	+
	7	+	"github.com/rs/zerolog"
	8	+	)
	9	+
	10	+	// startupTrace records the accelerated CEF/DMABUF/GTK path from process entry
	11	+	// to the first GTK presentation. It deliberately rejects unknown, duplicate,
	12	+	// and out-of-order milestones so collected cold-start measurements remain
	13	+	// truthful.
	14	+	type startupTrace struct {
	15	+	mu sync.Mutex
	16	+	now func() time.Time
	17	+	t0 time.Time
	18	+	milestones []startupMilestone
	19	+	logger *zerolog.Logger
	20	+	buffered []startupMilestone
	21	+	backend string
	22	+	incompleteReason string
	23	+	summaryEmitted bool
	24	+	}
	25	+
	26	+	type startupMilestone struct {
	27	+	Name string
	28	+	Elapsed time.Duration
	29	+	Delta time.Duration
	30	+	}
	31	+
	32	+	var startupMilestoneOrder = []string{
	33	+	"process_entry",
	34	+	"config_complete",
	35	+	"cef_library_load_begin",
	36	+	"cef_initialized",
	37	+	"browser_create_requested",
	38	+	"first_accelerated_paint_received",
	39	+	"first_dmabuf_texture_swap",
	40	+	"first_gtk_presentation",
	41	+	}
	42	+
	43	+	var processStartupTrace struct {
	44	+	sync.Mutex
	45	+	trace *startupTrace
	46	+	}
	47	+
	48	+	func newStartupTrace(now func() time.Time, processEntry time.Time) *startupTrace {
	49	+	return &startupTrace{
	50	+	now: now,
	51	+	t0: processEntry,
	52	+	milestones: make([]startupMilestone, 0, len(startupMilestoneOrder)),
	53	+	buffered: make([]startupMilestone, 0, len(startupMilestoneOrder)),
	54	+	}
	55	+	}
	56	+
	57	+	// ActivateStartupTrace starts the CEF-only first-presentation trace after GUI
	58	+	// engine selection. The supplied timestamps are captured by the application at
	59	+	// process entry and configuration completion, before CEF initialization.
	60	+	func ActivateStartupTrace(processEntry, configComplete time.Time, logger *zerolog.Logger) {
	61	+	if processEntry.IsZero() \|\| configComplete.IsZero() {
	62	+	return
	63	+	}
	64	+
	65	+	processStartupTrace.Lock()
	66	+	defer processStartupTrace.Unlock()
	67	+	if processStartupTrace.trace != nil {
	68	+	return
	69	+	}
	70	+
	71	+	trace := newStartupTrace(time.Now, processEntry)
	72	+	if !trace.markAt("process_entry", processEntry) \|\| !trace.markAt("config_complete", configComplete) {
	73	+	return
	74	+	}
	75	+	trace.SetLogger(logger)
	76	+	processStartupTrace.trace = trace
	77	+	}
	78	+
	79	+	func activeStartupTrace() *startupTrace {
	80	+	processStartupTrace.Lock()
	81	+	defer processStartupTrace.Unlock()
	82	+	return processStartupTrace.trace
	83	+	}
	84	+
	85	+	func (st startupTrace) SetLogger(logger zerolog.Logger) {
	86	+	if st == nil \|\| logger == nil {
	87	+	return
	88	+	}
	89	+	st.mu.Lock()
	90	+	defer st.mu.Unlock()
	91	+	st.logger = logger
	92	+	for _, milestone := range st.buffered {
	93	+	st.emitMilestone(milestone)
	94	+	}
	95	+	st.buffered = nil
	96	+	st.emitSummaryLocked()
	97	+	}
	98	+
	99	+	func (st *startupTrace) SetBackend(backend string) {
	100	+	if st == nil {
	101	+	return
	102	+	}
	103	+	st.mu.Lock()
	104	+	defer st.mu.Unlock()
	105	+	st.backend = backend
	106	+	}
	107	+
	108	+	func (st *startupTrace) SetIncompleteReason(reason string) {
	109	+	if st == nil {
	110	+	return
	111	+	}
	112	+	st.mu.Lock()
	113	+	defer st.mu.Unlock()
	114	+	if st.incompleteReason == "" {
	115	+	st.incompleteReason = reason
	116	+	}
	117	+	}
	118	+
	119	+	// Mark accepts exactly the next non-presentation startup milestone.
	120	+	func (st *startupTrace) Mark(name string) bool {
	121	+	if name == "first_gtk_presentation" {
	122	+	return false
	123	+	}
	124	+	return st.markAt(name, st.currentTime())
	125	+	}
	126	+
	127	+	// MarkGTKAfterPaint records the final milestone from the CEF-to-GTK bridge's
	128	+	// first frame-clock after-paint callback.
	129	+	func (st *startupTrace) MarkGTKAfterPaint() bool {
	130	+	return st.markAt("first_gtk_presentation", st.currentTime())
	131	+	}
	132	+
	133	+	func (st *startupTrace) currentTime() time.Time {
	134	+	if st == nil \|\| st.now == nil {
	135	+	return time.Time{}
	136	+	}
	137	+	return st.now()
	138	+	}
	139	+
	140	+	func (st *startupTrace) markAt(name string, at time.Time) bool {
	141	+	if st == nil \|\| st.now == nil \|\| at.IsZero() {
	142	+	return false
	143	+	}
	144	+	st.mu.Lock()
	145	+	defer st.mu.Unlock()
	146	+	if at.Before(st.t0) \|\| len(st.milestones) >= len(startupMilestoneOrder) \|\| name != startupMilestoneOrder[len(st.milestones)] {
	147	+	return false
	148	+	}
	149	+
	150	+	milestone := startupMilestone{Name: name, Elapsed: at.Sub(st.t0)}
	151	+	previousMilliseconds := int64(0)
	152	+	if len(st.milestones) > 0 {
	153	+	previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()
	154	+	}
	155	+	milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond
	156	+	st.milestones = append(st.milestones, milestone)
	157	+	if st.logger == nil {
	158	+	st.buffered = append(st.buffered, milestone)
	159	+	} else {
	160	+	st.emitMilestone(milestone)
	161	+	}
	162	+	st.emitSummaryLocked()
	163	+	return true
	164	+	}
	165	+
	166	+	func (st *startupTrace) emitMilestone(m startupMilestone) {
	167	+	if st.logger == nil {
	168	+	return
	169	+	}
	170	+	st.logger.Debug().
	171	+	Str("milestone", m.Name).
	172	+	Int64("t_ms", m.Elapsed.Milliseconds()).
	173	+	Int64("delta_ms", m.Delta.Milliseconds()).
	174	+	Msg("startup_trace: milestone")
	175	+	}
	176	+
	177	+	func (st *startupTrace) emitSummaryLocked() {
	178	+	if st.summaryEmitted \|\| st.logger == nil \|\| len(st.milestones) != len(startupMilestoneOrder) {
	179	+	return
	180	+	}
	181	+	st.summaryEmitted = true
	182	+	st.logger.Info().
	183	+	Str("backend", st.backend).
	184	+	Str("incomplete_reason", st.incompleteReason).
	185	+	Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()).
	186	+	Interface("milestones", st.milestones).
	187	+	Msg("startup_trace: first presentation")
	188	+	}
	189	+
	190	+	func (st *startupTrace) Enabled() bool { return st != nil && st.now != nil }
	191	+
	192	+	func (st *startupTrace) TotalElapsed() time.Duration {
	193	+	if st == nil \|\| st.now == nil {
	194	+	return 0
	195	+	}
	196	+	st.mu.Lock()
	197	+	defer st.mu.Unlock()
	198	+	return st.now().Sub(st.t0)
	199	+	}

@@ -0,0 +1,199 @@
	1	+	package cef
	2	+
	3	+	import (
	4	+	"sync"
	5	+	"time"
	6	+
	7	+	"github.com/rs/zerolog"
	8	+	)
	9	+
	10	+	// startupTrace records the accelerated CEF/DMABUF/GTK path from process entry
	11	+	// to the first GTK presentation. It deliberately rejects unknown, duplicate,
	12	+	// and out-of-order milestones so collected cold-start measurements remain
	13	+	// truthful.
	14	+	type startupTrace struct {
	15	+	mu sync.Mutex
	16	+	now func() time.Time
	17	+	t0 time.Time
	18	+	milestones []startupMilestone
	19	+	logger *zerolog.Logger
	20	+	buffered []startupMilestone
	21	+	backend string
	22	+	incompleteReason string
	23	+	summaryEmitted bool
	24	+	}
	25	+
	26	+	type startupMilestone struct {
	27	+	Name string
	28	+	Elapsed time.Duration
	29	+	Delta time.Duration
	30	+	}
	31	+
	32	+	var startupMilestoneOrder = []string{
	33	+	"process_entry",
	34	+	"config_complete",
	35	+	"cef_library_load_begin",
	36	+	"cef_initialized",
	37	+	"browser_create_requested",
	38	+	"first_accelerated_paint_received",
	39	+	"first_dmabuf_texture_swap",
	40	+	"first_gtk_presentation",
	41	+	}
	42	+
	43	+	var processStartupTrace struct {
	44	+	sync.Mutex
	45	+	trace *startupTrace
	46	+	}
	47	+
	48	+	func newStartupTrace(now func() time.Time, processEntry time.Time) *startupTrace {
	49	+	return &startupTrace{
	50	+	now: now,
	51	+	t0: processEntry,
	52	+	milestones: make([]startupMilestone, 0, len(startupMilestoneOrder)),
	53	+	buffered: make([]startupMilestone, 0, len(startupMilestoneOrder)),
	54	+	}
	55	+	}
	56	+
	57	+	// ActivateStartupTrace starts the CEF-only first-presentation trace after GUI
	58	+	// engine selection. The supplied timestamps are captured by the application at
	59	+	// process entry and configuration completion, before CEF initialization.
	60	+	func ActivateStartupTrace(processEntry, configComplete time.Time, logger *zerolog.Logger) {
	61	+	if processEntry.IsZero() \|\| configComplete.IsZero() {
	62	+	return
	63	+	}
	64	+
	65	+	processStartupTrace.Lock()
	66	+	defer processStartupTrace.Unlock()
	67	+	if processStartupTrace.trace != nil {
	68	+	return
	69	+	}
	70	+
	71	+	trace := newStartupTrace(time.Now, processEntry)
	72	+	if !trace.markAt("process_entry", processEntry) \|\| !trace.markAt("config_complete", configComplete) {
	73	+	return
	74	+	}
	75	+	trace.SetLogger(logger)
	76	+	processStartupTrace.trace = trace
	77	+	}
	78	+
	79	+	func activeStartupTrace() *startupTrace {
	80	+	processStartupTrace.Lock()
	81	+	defer processStartupTrace.Unlock()
	82	+	return processStartupTrace.trace
	83	+	}
	84	+
	85	+	func (st startupTrace) SetLogger(logger zerolog.Logger) {
	86	+	if st == nil \|\| logger == nil {
	87	+	return
	88	+	}
	89	+	st.mu.Lock()
	90	+	defer st.mu.Unlock()
	91	+	st.logger = logger
	92	+	for _, milestone := range st.buffered {
	93	+	st.emitMilestone(milestone)
	94	+	}
	95	+	st.buffered = nil
	96	+	st.emitSummaryLocked()
	97	+	}
	98	+
	99	+	func (st *startupTrace) SetBackend(backend string) {
	100	+	if st == nil {
	101	+	return
	102	+	}
	103	+	st.mu.Lock()
	104	+	defer st.mu.Unlock()
	105	+	st.backend = backend
	106	+	}
	107	+
	108	+	func (st *startupTrace) SetIncompleteReason(reason string) {
	109	+	if st == nil {
	110	+	return
	111	+	}
	112	+	st.mu.Lock()
	113	+	defer st.mu.Unlock()
	114	+	if st.incompleteReason == "" {
	115	+	st.incompleteReason = reason
	116	+	}
	117	+	}
	118	+
	119	+	// Mark accepts exactly the next non-presentation startup milestone.
	120	+	func (st *startupTrace) Mark(name string) bool {
	121	+	if name == "first_gtk_presentation" {
	122	+	return false
	123	+	}
	124	+	return st.markAt(name, st.currentTime())
	125	+	}
	126	+
	127	+	// MarkGTKAfterPaint records the final milestone from the CEF-to-GTK bridge's
	128	+	// first frame-clock after-paint callback.
	129	+	func (st *startupTrace) MarkGTKAfterPaint() bool {
	130	+	return st.markAt("first_gtk_presentation", st.currentTime())
	131	+	}
	132	+
	133	+	func (st *startupTrace) currentTime() time.Time {
	134	+	if st == nil \|\| st.now == nil {
	135	+	return time.Time{}
	136	+	}
	137	+	return st.now()
	138	+	}
	139	+
	140	+	func (st *startupTrace) markAt(name string, at time.Time) bool {
	141	+	if st == nil \|\| st.now == nil \|\| at.IsZero() {
	142	+	return false
	143	+	}
	144	+	st.mu.Lock()
	145	+	defer st.mu.Unlock()
	146	+	if at.Before(st.t0) \|\| len(st.milestones) >= len(startupMilestoneOrder) \|\| name != startupMilestoneOrder[len(st.milestones)] {
	147	+	return false
	148	+	}
	149	+
	150	+	milestone := startupMilestone{Name: name, Elapsed: at.Sub(st.t0)}
	151	+	previousMilliseconds := int64(0)
	152	+	if len(st.milestones) > 0 {
	153	+	previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()
	154	+	}
	155	+	milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond
	156	+	st.milestones = append(st.milestones, milestone)
	157	+	if st.logger == nil {
	158	+	st.buffered = append(st.buffered, milestone)
	159	+	} else {
	160	+	st.emitMilestone(milestone)
	161	+	}
	162	+	st.emitSummaryLocked()
	163	+	return true
	164	+	}
	165	+
	166	+	func (st *startupTrace) emitMilestone(m startupMilestone) {
	167	+	if st.logger == nil {
	168	+	return
	169	+	}
	170	+	st.logger.Debug().
	171	+	Str("milestone", m.Name).
	172	+	Int64("t_ms", m.Elapsed.Milliseconds()).
	173	+	Int64("delta_ms", m.Delta.Milliseconds()).
	174	+	Msg("startup_trace: milestone")
	175	+	}
	176	+
	177	+	func (st *startupTrace) emitSummaryLocked() {
	178	+	if st.summaryEmitted \|\| st.logger == nil \|\| len(st.milestones) != len(startupMilestoneOrder) {
	179	+	return
	180	+	}
	181	+	st.summaryEmitted = true
	182	+	st.logger.Info().
	183	+	Str("backend", st.backend).
	184	+	Str("incomplete_reason", st.incompleteReason).
	185	+	Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()).
	186	+	Interface("milestones", st.milestones).
	187	+	Msg("startup_trace: first presentation")
	188	+	}
	189	+
	190	+	func (st *startupTrace) Enabled() bool { return st != nil && st.now != nil }
	191	+
	192	+	func (st *startupTrace) TotalElapsed() time.Duration {
	193	+	if st == nil \|\| st.now == nil {
	194	+	return 0
	195	+	}
	196	+	st.mu.Lock()
	197	+	defer st.mu.Unlock()
	198	+	return st.now().Sub(st.t0)
	199	+	}

A internal/infrastructure/cef/startup_trace_test.go +116 -0

@@ -0,0 +1,116 @@
	1	+	package cef
	2	+
	3	+	import (
	4	+	"bytes"
	5	+	"testing"
	6	+	"time"
	7	+
	8	+	"github.com/rs/zerolog"
	9	+	"github.com/stretchr/testify/require"
	10	+	)
	11	+
	12	+	func TestActivateStartupTraceSeedsNeutralProcessAndConfigTiming(t *testing.T) {
	13	+	processStartupTrace.Lock()
	14	+	previous := processStartupTrace.trace
	15	+	processStartupTrace.trace = nil
	16	+	processStartupTrace.Unlock()
	17	+	t.Cleanup(func() {
	18	+	processStartupTrace.Lock()
	19	+	processStartupTrace.trace = previous
	20	+	processStartupTrace.Unlock()
	21	+	})
	22	+
	23	+	processEntry := time.Unix(100, 0)
	24	+	configComplete := processEntry.Add(15 * time.Millisecond)
	25	+	var output bytes.Buffer
	26	+	logger := zerolog.New(&output).Level(zerolog.DebugLevel)
	27	+
	28	+	ActivateStartupTrace(processEntry, configComplete, &logger)
	29	+	trace := activeStartupTrace()
	30	+
	31	+	require.NotNil(t, trace)
	32	+	require.Equal(t, []string{"process_entry", "config_complete"}, []string{trace.milestones[0].Name, trace.milestones[1].Name})
	33	+	require.Equal(t, int64(0), trace.milestones[0].Elapsed.Milliseconds())
	34	+	require.Equal(t, int64(15), trace.milestones[1].Elapsed.Milliseconds())
	35	+	require.Contains(t, output.String(), `"milestone":"process_entry"`)
	36	+	require.Contains(t, output.String(), `"milestone":"config_complete"`)
	37	+	require.NotContains(t, output.String(), `"message":"startup_trace: first presentation"`)
	38	+	}
	39	+
	40	+	func TestStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) {
	41	+	now := time.Unix(100, 0)
	42	+	trace := newStartupTrace(func() time.Time { return now }, now)
	43	+
	44	+	require.True(t, trace.Mark("process_entry"))
	45	+	require.False(t, trace.Mark("cef_initialized"), "out-of-order transition must be rejected")
	46	+	require.False(t, trace.Mark("process_entry"), "duplicate transition must be rejected")
	47	+
	48	+	for _, name := range []string{
	49	+	"config_complete",
	50	+	"cef_library_load_begin",
	51	+	"cef_initialized",
	52	+	"browser_create_requested",
	53	+	"first_accelerated_paint_received",
	54	+	"first_dmabuf_texture_swap",
	55	+	"first_gtk_presentation",
	56	+	} {
	57	+	now = now.Add(time.Millisecond)
	58	+	if name == "first_gtk_presentation" {
	59	+	require.Truef(t, trace.MarkGTKAfterPaint(), "milestone %s should be accepted", name)
	60	+	} else {
	61	+	require.Truef(t, trace.Mark(name), "milestone %s should be accepted", name)
	62	+	}
	63	+	}
	64	+	require.False(t, trace.Mark("first_gtk_presentation"))
	65	+	}
	66	+
	67	+	func TestStartupTracePreservesProcessAndConfigTimestamps(t *testing.T) {
	68	+	processEntry := time.Unix(100, 0)
	69	+	configComplete := processEntry.Add(1500 * time.Microsecond)
	70	+	now := configComplete.Add(900 * time.Microsecond)
	71	+	trace := newStartupTrace(func() time.Time { return now }, processEntry)
	72	+
	73	+	require.True(t, trace.markAt("process_entry", processEntry))
	74	+	require.True(t, trace.markAt("config_complete", configComplete))
	75	+
	76	+	require.Equal(t, int64(0), trace.milestones[0].Elapsed.Milliseconds())
	77	+	require.Equal(t, int64(0), trace.milestones[0].Delta.Milliseconds())
	78	+	require.Equal(t, int64(1), trace.milestones[1].Elapsed.Milliseconds())
	79	+	require.Equal(t, int64(1), trace.milestones[1].Delta.Milliseconds())
	80	+	}
	81	+
	82	+	func TestStartupTraceReservesFirstGTKPresentationForAfterPaint(t *testing.T) {
	83	+	now := time.Unix(100, 0)
	84	+	trace := newStartupTrace(func() time.Time { return now }, now)
	85	+
	86	+	for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] {
	87	+	now = now.Add(time.Millisecond)
	88	+	require.True(t, trace.Mark(name))
	89	+	}
	90	+
	91	+	require.Len(t, trace.milestones, len(startupMilestoneOrder)-1)
	92	+	require.False(t, trace.Mark("first_gtk_presentation"), "only the CEF-to-GTK after-paint hook can record the reserved milestone")
	93	+	require.False(t, trace.summaryEmitted)
	94	+	require.True(t, trace.MarkGTKAfterPaint(), "only the after-paint hook may record this milestone")
	95	+	}
	96	+
	97	+	func TestStartupTraceEmitsOneNormalSummaryAtFirstPresentation(t *testing.T) {
	98	+	var output bytes.Buffer
	99	+	logger := zerolog.New(&output)
	100	+	now := time.Unix(100, 0)
	101	+	trace := newStartupTrace(func() time.Time { return now }, now)
	102	+	trace.SetBackend("gdk-dmabuf")
	103	+	trace.SetLogger(&logger)
	104	+
	105	+	for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] {
	106	+	now = now.Add(time.Millisecond)
	107	+	require.True(t, trace.Mark(name))
	108	+	}
	109	+	now = now.Add(time.Millisecond)
	110	+	require.True(t, trace.MarkGTKAfterPaint())
	111	+	trace.MarkGTKAfterPaint()
	112	+
	113	+	require.Contains(t, output.String(), `"message":"startup_trace: first presentation"`)
	114	+	require.Contains(t, output.String(), `"backend":"gdk-dmabuf"`)
	115	+	require.Equal(t, 1, bytes.Count(output.Bytes(), []byte(`"message":"startup_trace: first presentation"`)))
	116	+	}

@@ -0,0 +1,116 @@
	1	+	package cef
	2	+
	3	+	import (
	4	+	"bytes"
	5	+	"testing"
	6	+	"time"
	7	+
	8	+	"github.com/rs/zerolog"
	9	+	"github.com/stretchr/testify/require"
	10	+	)
	11	+
	12	+	func TestActivateStartupTraceSeedsNeutralProcessAndConfigTiming(t *testing.T) {
	13	+	processStartupTrace.Lock()
	14	+	previous := processStartupTrace.trace
	15	+	processStartupTrace.trace = nil
	16	+	processStartupTrace.Unlock()
	17	+	t.Cleanup(func() {
	18	+	processStartupTrace.Lock()
	19	+	processStartupTrace.trace = previous
	20	+	processStartupTrace.Unlock()
	21	+	})
	22	+
	23	+	processEntry := time.Unix(100, 0)
	24	+	configComplete := processEntry.Add(15 * time.Millisecond)
	25	+	var output bytes.Buffer
	26	+	logger := zerolog.New(&output).Level(zerolog.DebugLevel)
	27	+
	28	+	ActivateStartupTrace(processEntry, configComplete, &logger)
	29	+	trace := activeStartupTrace()
	30	+
	31	+	require.NotNil(t, trace)
	32	+	require.Equal(t, []string{"process_entry", "config_complete"}, []string{trace.milestones[0].Name, trace.milestones[1].Name})
	33	+	require.Equal(t, int64(0), trace.milestones[0].Elapsed.Milliseconds())
	34	+	require.Equal(t, int64(15), trace.milestones[1].Elapsed.Milliseconds())
	35	+	require.Contains(t, output.String(), `"milestone":"process_entry"`)
	36	+	require.Contains(t, output.String(), `"milestone":"config_complete"`)
	37	+	require.NotContains(t, output.String(), `"message":"startup_trace: first presentation"`)
	38	+	}
	39	+
	40	+	func TestStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) {
	41	+	now := time.Unix(100, 0)
	42	+	trace := newStartupTrace(func() time.Time { return now }, now)
	43	+
	44	+	require.True(t, trace.Mark("process_entry"))
	45	+	require.False(t, trace.Mark("cef_initialized"), "out-of-order transition must be rejected")
	46	+	require.False(t, trace.Mark("process_entry"), "duplicate transition must be rejected")
	47	+
	48	+	for _, name := range []string{
	49	+	"config_complete",
	50	+	"cef_library_load_begin",
	51	+	"cef_initialized",
	52	+	"browser_create_requested",
	53	+	"first_accelerated_paint_received",
	54	+	"first_dmabuf_texture_swap",
	55	+	"first_gtk_presentation",
	56	+	} {
	57	+	now = now.Add(time.Millisecond)
	58	+	if name == "first_gtk_presentation" {
	59	+	require.Truef(t, trace.MarkGTKAfterPaint(), "milestone %s should be accepted", name)
	60	+	} else {
	61	+	require.Truef(t, trace.Mark(name), "milestone %s should be accepted", name)
	62	+	}
	63	+	}
	64	+	require.False(t, trace.Mark("first_gtk_presentation"))
	65	+	}
	66	+
	67	+	func TestStartupTracePreservesProcessAndConfigTimestamps(t *testing.T) {
	68	+	processEntry := time.Unix(100, 0)
	69	+	configComplete := processEntry.Add(1500 * time.Microsecond)
	70	+	now := configComplete.Add(900 * time.Microsecond)
	71	+	trace := newStartupTrace(func() time.Time { return now }, processEntry)
	72	+
	73	+	require.True(t, trace.markAt("process_entry", processEntry))
	74	+	require.True(t, trace.markAt("config_complete", configComplete))
	75	+
	76	+	require.Equal(t, int64(0), trace.milestones[0].Elapsed.Milliseconds())
	77	+	require.Equal(t, int64(0), trace.milestones[0].Delta.Milliseconds())
	78	+	require.Equal(t, int64(1), trace.milestones[1].Elapsed.Milliseconds())
	79	+	require.Equal(t, int64(1), trace.milestones[1].Delta.Milliseconds())
	80	+	}
	81	+
	82	+	func TestStartupTraceReservesFirstGTKPresentationForAfterPaint(t *testing.T) {
	83	+	now := time.Unix(100, 0)
	84	+	trace := newStartupTrace(func() time.Time { return now }, now)
	85	+
	86	+	for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] {
	87	+	now = now.Add(time.Millisecond)
	88	+	require.True(t, trace.Mark(name))
	89	+	}
	90	+
	91	+	require.Len(t, trace.milestones, len(startupMilestoneOrder)-1)
	92	+	require.False(t, trace.Mark("first_gtk_presentation"), "only the CEF-to-GTK after-paint hook can record the reserved milestone")
	93	+	require.False(t, trace.summaryEmitted)
	94	+	require.True(t, trace.MarkGTKAfterPaint(), "only the after-paint hook may record this milestone")
	95	+	}
	96	+
	97	+	func TestStartupTraceEmitsOneNormalSummaryAtFirstPresentation(t *testing.T) {
	98	+	var output bytes.Buffer
	99	+	logger := zerolog.New(&output)
	100	+	now := time.Unix(100, 0)
	101	+	trace := newStartupTrace(func() time.Time { return now }, now)
	102	+	trace.SetBackend("gdk-dmabuf")
	103	+	trace.SetLogger(&logger)
	104	+
	105	+	for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] {
	106	+	now = now.Add(time.Millisecond)
	107	+	require.True(t, trace.Mark(name))
	108	+	}
	109	+	now = now.Add(time.Millisecond)
	110	+	require.True(t, trace.MarkGTKAfterPaint())
	111	+	trace.MarkGTKAfterPaint()
	112	+
	113	+	require.Contains(t, output.String(), `"message":"startup_trace: first presentation"`)
	114	+	require.Contains(t, output.String(), `"backend":"gdk-dmabuf"`)
	115	+	require.Equal(t, 1, bytes.Count(output.Bytes(), []byte(`"message":"startup_trace: first presentation"`)))
	116	+	}

D internal/logging/startup_trace.go +0 -203

@@ -1,203 +0,0 @@
1	-	package logging
2	-
3	-	import (
4	-	"sync"
5	-	"time"
6	-
7	-	"github.com/rs/zerolog"
8	-	)
9	-
10	-	// CEFStartupTrace records the accelerated CEF/DMABUF/GTK path from process
11	-	// entry to the first GTK presentation. It deliberately rejects unknown,
12	-	// duplicate, and out-of-order milestones. Accepting a convenient timestamp
13	-	// would make the result unsuitable for cold-start measurement.
14	-	type CEFStartupTrace struct {
15	-	mu sync.Mutex
16	-	now func() time.Time
17	-	t0 time.Time
18	-	milestones []CEFStartupMilestone
19	-	logger *zerolog.Logger
20	-	buffered []CEFStartupMilestone
21	-	backend string
22	-	incompleteReason string
23	-	summaryEmitted bool
24	-	}
25	-
26	-	// CEFStartupMilestone represents a timing checkpoint from process entry.
27	-	type CEFStartupMilestone struct {
28	-	Name string
29	-	Elapsed time.Duration
30	-	Delta time.Duration
31	-	}
32	-
33	-	var cefStartupMilestoneOrder = []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",
42	-	}
43	-
44	-	var (
45	-	globalCEFTrace *CEFStartupTrace
46	-	globalCEFTraceMu sync.Mutex
47	-	globalCEFTraceOnce sync.Once
48	-	)
49	-
50	-	func newCEFStartupTrace(now func() time.Time) *CEFStartupTrace {
51	-	start := now()
52	-	return &CEFStartupTrace{
53	-	now: now,
54	-	t0: start,
55	-	milestones: make([]CEFStartupMilestone, 0, len(cefStartupMilestoneOrder)),
56	-	buffered: make([]CEFStartupMilestone, 0, len(cefStartupMilestoneOrder)),
57	-	}
58	-	}
59	-
60	-	// NewCEFStartupTrace creates an isolated accelerated CEF/DMABUF/GTK trace.
61	-	// Production startup uses InitCEFStartupTrace and CEFTrace.
62	-	func NewCEFStartupTrace() *CEFStartupTrace { return newCEFStartupTrace(time.Now) }
63	-
64	-	// InitCEFStartupTrace begins the CEF/DMABUF/GTK measurement at process entry.
65	-	// It is intentionally safe to call again during GUI bootstrap.
66	-	func InitCEFStartupTrace() {
67	-	globalCEFTraceOnce.Do(func() {
68	-	trace := newCEFStartupTrace(time.Now)
69	-	globalCEFTraceMu.Lock()
70	-	globalCEFTrace = trace
71	-	globalCEFTraceMu.Unlock()
72	-	})
73	-	}
74	-
75	-	// CEFTrace returns the accelerated CEF/DMABUF/GTK trace. Callers before
76	-	// initialization get a harmless trace which rejects all transitions.
77	-	func CEFTrace() *CEFStartupTrace {
78	-	globalCEFTraceMu.Lock()
79	-	defer globalCEFTraceMu.Unlock()
80	-	if globalCEFTrace == nil {
81	-	return &CEFStartupTrace{}
82	-	}
83	-	return globalCEFTrace
84	-	}
85	-
86	-	// SetLogger makes buffered milestones available to the process logger.
87	-	func (st CEFStartupTrace) SetLogger(logger zerolog.Logger) {
88	-	if st == nil \|\| logger == nil {
89	-	return
90	-	}
91	-	st.mu.Lock()
92	-	defer st.mu.Unlock()
93	-	st.logger = logger
94	-	for _, milestone := range st.buffered {
95	-	st.emitCEFStartupMilestone(milestone)
96	-	}
97	-	st.buffered = nil
98	-	st.emitSummaryLocked()
99	-	}
100	-
101	-	// SetBackend records the selected presentation backend for the final summary.
102	-	func (st *CEFStartupTrace) SetBackend(backend string) {
103	-	if st == nil {
104	-	return
105	-	}
106	-	st.mu.Lock()
107	-	defer st.mu.Unlock()
108	-	st.backend = backend
109	-	}
110	-
111	-	// SetIncompleteReason records why a trace cannot reach a valid DMABUF result.
112	-	func (st *CEFStartupTrace) SetIncompleteReason(reason string) {
113	-	if st == nil {
114	-	return
115	-	}
116	-	st.mu.Lock()
117	-	defer st.mu.Unlock()
118	-	if st.incompleteReason == "" {
119	-	st.incompleteReason = reason
120	-	}
121	-	}
122	-
123	-	// Mark accepts exactly the next non-presentation startup milestone and returns
124	-	// whether it was recorded. first_gtk_presentation is reserved for the GTK
125	-	// frame-clock after-paint hook through MarkGTKAfterPaint.
126	-	func (st *CEFStartupTrace) Mark(name string) bool {
127	-	if name == "first_gtk_presentation" {
128	-	return false
129	-	}
130	-	return st.mark(name)
131	-	}
132	-
133	-	// MarkGTKAfterPaint records the final milestone. It is called only from the
134	-	// upstream CEF-to-GTK bridge's first frame-clock after-paint callback.
135	-	func (st *CEFStartupTrace) MarkGTKAfterPaint() bool {
136	-	return st.mark("first_gtk_presentation")
137	-	}
138	-
139	-	// mark accepts the next milestone and is safe for callbacks from CEF and GTK
140	-	// threads.
141	-	func (st *CEFStartupTrace) mark(name string) bool {
142	-	if st == nil \|\| st.now == nil {
143	-	return false
144	-	}
145	-	st.mu.Lock()
146	-	defer st.mu.Unlock()
147	-	if len(st.milestones) >= len(cefStartupMilestoneOrder) \|\| name != cefStartupMilestoneOrder[len(st.milestones)] {
148	-	return false
149	-	}
150	-
151	-	now := st.now()
152	-	milestone := CEFStartupMilestone{Name: name, Elapsed: now.Sub(st.t0)}
153	-	// Published fields are integer milliseconds. Compute delta on that same
154	-	// scale so delta_ms always exactly reconstructs t_ms in collected evidence.
155	-	previousMilliseconds := int64(0)
156	-	if len(st.milestones) > 0 {
157	-	previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()
158	-	}
159	-	milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond
160	-	st.milestones = append(st.milestones, milestone)
161	-	if st.logger == nil {
162	-	st.buffered = append(st.buffered, milestone)
163	-	} else {
164	-	st.emitCEFStartupMilestone(milestone)
165	-	}
166	-	st.emitSummaryLocked()
167	-	return true
168	-	}
169	-
170	-	func (st *CEFStartupTrace) emitCEFStartupMilestone(m CEFStartupMilestone) {
171	-	if st.logger == nil {
172	-	return
173	-	}
174	-	st.logger.Debug().
175	-	Str("milestone", m.Name).
176	-	Int64("t_ms", m.Elapsed.Milliseconds()).
177	-	Int64("delta_ms", m.Delta.Milliseconds()).
178	-	Msg("startup_trace: milestone")
179	-	}
180	-
181	-	func (st *CEFStartupTrace) emitSummaryLocked() {
182	-	if st.summaryEmitted \|\| st.logger == nil \|\| len(st.milestones) != len(cefStartupMilestoneOrder) {
183	-	return
184	-	}
185	-	st.summaryEmitted = true
186	-	st.logger.Info().
187	-	Str("backend", st.backend).
188	-	Str("incomplete_reason", st.incompleteReason).
189	-	Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()).
190	-	Interface("milestones", st.milestones).
191	-	Msg("startup_trace: first presentation")
192	-	}
193	-
194	-	func (st *CEFStartupTrace) Enabled() bool { return st != nil && st.now != nil }
195	-
196	-	func (st *CEFStartupTrace) TotalElapsed() time.Duration {
197	-	if st == nil \|\| st.now == nil {
198	-	return 0
199	-	}
200	-	st.mu.Lock()
201	-	defer st.mu.Unlock()
202	-	return st.now().Sub(st.t0)
203	-	}

@@ -1,203 +0,0 @@
1	-	package logging
2	-
3	-	import (
4	-	"sync"
5	-	"time"
6	-
7	-	"github.com/rs/zerolog"
8	-	)
9	-
10	-	// CEFStartupTrace records the accelerated CEF/DMABUF/GTK path from process
11	-	// entry to the first GTK presentation. It deliberately rejects unknown,
12	-	// duplicate, and out-of-order milestones. Accepting a convenient timestamp
13	-	// would make the result unsuitable for cold-start measurement.
14	-	type CEFStartupTrace struct {
15	-	mu sync.Mutex
16	-	now func() time.Time
17	-	t0 time.Time
18	-	milestones []CEFStartupMilestone
19	-	logger *zerolog.Logger
20	-	buffered []CEFStartupMilestone
21	-	backend string
22	-	incompleteReason string
23	-	summaryEmitted bool
24	-	}
25	-
26	-	// CEFStartupMilestone represents a timing checkpoint from process entry.
27	-	type CEFStartupMilestone struct {
28	-	Name string
29	-	Elapsed time.Duration
30	-	Delta time.Duration
31	-	}
32	-
33	-	var cefStartupMilestoneOrder = []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",
42	-	}
43	-
44	-	var (
45	-	globalCEFTrace *CEFStartupTrace
46	-	globalCEFTraceMu sync.Mutex
47	-	globalCEFTraceOnce sync.Once
48	-	)
49	-
50	-	func newCEFStartupTrace(now func() time.Time) *CEFStartupTrace {
51	-	start := now()
52	-	return &CEFStartupTrace{
53	-	now: now,
54	-	t0: start,
55	-	milestones: make([]CEFStartupMilestone, 0, len(cefStartupMilestoneOrder)),
56	-	buffered: make([]CEFStartupMilestone, 0, len(cefStartupMilestoneOrder)),
57	-	}
58	-	}
59	-
60	-	// NewCEFStartupTrace creates an isolated accelerated CEF/DMABUF/GTK trace.
61	-	// Production startup uses InitCEFStartupTrace and CEFTrace.
62	-	func NewCEFStartupTrace() *CEFStartupTrace { return newCEFStartupTrace(time.Now) }
63	-
64	-	// InitCEFStartupTrace begins the CEF/DMABUF/GTK measurement at process entry.
65	-	// It is intentionally safe to call again during GUI bootstrap.
66	-	func InitCEFStartupTrace() {
67	-	globalCEFTraceOnce.Do(func() {
68	-	trace := newCEFStartupTrace(time.Now)
69	-	globalCEFTraceMu.Lock()
70	-	globalCEFTrace = trace
71	-	globalCEFTraceMu.Unlock()
72	-	})
73	-	}
74	-
75	-	// CEFTrace returns the accelerated CEF/DMABUF/GTK trace. Callers before
76	-	// initialization get a harmless trace which rejects all transitions.
77	-	func CEFTrace() *CEFStartupTrace {
78	-	globalCEFTraceMu.Lock()
79	-	defer globalCEFTraceMu.Unlock()
80	-	if globalCEFTrace == nil {
81	-	return &CEFStartupTrace{}
82	-	}
83	-	return globalCEFTrace
84	-	}
85	-
86	-	// SetLogger makes buffered milestones available to the process logger.
87	-	func (st CEFStartupTrace) SetLogger(logger zerolog.Logger) {
88	-	if st == nil \|\| logger == nil {
89	-	return
90	-	}
91	-	st.mu.Lock()
92	-	defer st.mu.Unlock()
93	-	st.logger = logger
94	-	for _, milestone := range st.buffered {
95	-	st.emitCEFStartupMilestone(milestone)
96	-	}
97	-	st.buffered = nil
98	-	st.emitSummaryLocked()
99	-	}
100	-
101	-	// SetBackend records the selected presentation backend for the final summary.
102	-	func (st *CEFStartupTrace) SetBackend(backend string) {
103	-	if st == nil {
104	-	return
105	-	}
106	-	st.mu.Lock()
107	-	defer st.mu.Unlock()
108	-	st.backend = backend
109	-	}
110	-
111	-	// SetIncompleteReason records why a trace cannot reach a valid DMABUF result.
112	-	func (st *CEFStartupTrace) SetIncompleteReason(reason string) {
113	-	if st == nil {
114	-	return
115	-	}
116	-	st.mu.Lock()
117	-	defer st.mu.Unlock()
118	-	if st.incompleteReason == "" {
119	-	st.incompleteReason = reason
120	-	}
121	-	}
122	-
123	-	// Mark accepts exactly the next non-presentation startup milestone and returns
124	-	// whether it was recorded. first_gtk_presentation is reserved for the GTK
125	-	// frame-clock after-paint hook through MarkGTKAfterPaint.
126	-	func (st *CEFStartupTrace) Mark(name string) bool {
127	-	if name == "first_gtk_presentation" {
128	-	return false
129	-	}
130	-	return st.mark(name)
131	-	}
132	-
133	-	// MarkGTKAfterPaint records the final milestone. It is called only from the
134	-	// upstream CEF-to-GTK bridge's first frame-clock after-paint callback.
135	-	func (st *CEFStartupTrace) MarkGTKAfterPaint() bool {
136	-	return st.mark("first_gtk_presentation")
137	-	}
138	-
139	-	// mark accepts the next milestone and is safe for callbacks from CEF and GTK
140	-	// threads.
141	-	func (st *CEFStartupTrace) mark(name string) bool {
142	-	if st == nil \|\| st.now == nil {
143	-	return false
144	-	}
145	-	st.mu.Lock()
146	-	defer st.mu.Unlock()
147	-	if len(st.milestones) >= len(cefStartupMilestoneOrder) \|\| name != cefStartupMilestoneOrder[len(st.milestones)] {
148	-	return false
149	-	}
150	-
151	-	now := st.now()
152	-	milestone := CEFStartupMilestone{Name: name, Elapsed: now.Sub(st.t0)}
153	-	// Published fields are integer milliseconds. Compute delta on that same
154	-	// scale so delta_ms always exactly reconstructs t_ms in collected evidence.
155	-	previousMilliseconds := int64(0)
156	-	if len(st.milestones) > 0 {
157	-	previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()
158	-	}
159	-	milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond
160	-	st.milestones = append(st.milestones, milestone)
161	-	if st.logger == nil {
162	-	st.buffered = append(st.buffered, milestone)
163	-	} else {
164	-	st.emitCEFStartupMilestone(milestone)
165	-	}
166	-	st.emitSummaryLocked()
167	-	return true
168	-	}
169	-
170	-	func (st *CEFStartupTrace) emitCEFStartupMilestone(m CEFStartupMilestone) {
171	-	if st.logger == nil {
172	-	return
173	-	}
174	-	st.logger.Debug().
175	-	Str("milestone", m.Name).
176	-	Int64("t_ms", m.Elapsed.Milliseconds()).
177	-	Int64("delta_ms", m.Delta.Milliseconds()).
178	-	Msg("startup_trace: milestone")
179	-	}
180	-
181	-	func (st *CEFStartupTrace) emitSummaryLocked() {
182	-	if st.summaryEmitted \|\| st.logger == nil \|\| len(st.milestones) != len(cefStartupMilestoneOrder) {
183	-	return
184	-	}
185	-	st.summaryEmitted = true
186	-	st.logger.Info().
187	-	Str("backend", st.backend).
188	-	Str("incomplete_reason", st.incompleteReason).
189	-	Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()).
190	-	Interface("milestones", st.milestones).
191	-	Msg("startup_trace: first presentation")
192	-	}
193	-
194	-	func (st *CEFStartupTrace) Enabled() bool { return st != nil && st.now != nil }
195	-
196	-	func (st *CEFStartupTrace) TotalElapsed() time.Duration {
197	-	if st == nil \|\| st.now == nil {
198	-	return 0
199	-	}
200	-	st.mu.Lock()
201	-	defer st.mu.Unlock()
202	-	return st.now().Sub(st.t0)
203	-	}

D internal/logging/startup_trace_test.go +0 -88

@@ -1,88 +0,0 @@
1	-	package logging
2	-
3	-	import (
4	-	"bytes"
5	-	"testing"
6	-	"time"
7	-
8	-	"github.com/rs/zerolog"
9	-	"github.com/stretchr/testify/require"
10	-	)
11	-
12	-	func TestCEFStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) {
13	-	now := time.Unix(100, 0)
14	-	trace := newCEFStartupTrace(func() time.Time { return now })
15	-
16	-	require.True(t, trace.Mark("process_entry"))
17	-	require.False(t, trace.Mark("cef_initialized"), "out-of-order transition must be rejected")
18	-	require.False(t, trace.Mark("process_entry"), "duplicate transition must be rejected")
19	-
20	-	for _, name := range []string{
21	-	"config_complete",
22	-	"cef_library_load_begin",
23	-	"cef_initialized",
24	-	"browser_create_requested",
25	-	"first_accelerated_paint_received",
26	-	"first_dmabuf_texture_swap",
27	-	"first_gtk_presentation",
28	-	} {
29	-	now = now.Add(time.Millisecond)
30	-	if name == "first_gtk_presentation" {
31	-	require.Truef(t, trace.MarkGTKAfterPaint(), "milestone %s should be accepted", name)
32	-	} else {
33	-	require.Truef(t, trace.Mark(name), "milestone %s should be accepted", name)
34	-	}
35	-	}
36	-	require.False(t, trace.Mark("first_gtk_presentation"))
37	-	}
38	-
39	-	func TestCEFStartupTraceQuantizesDeltaToPublishedMilliseconds(t *testing.T) {
40	-	now := time.Unix(100, 0)
41	-	trace := newCEFStartupTrace(func() time.Time { return now })
42	-
43	-	now = now.Add(1500 * time.Microsecond)
44	-	require.True(t, trace.Mark("process_entry"))
45	-	now = now.Add(900 * time.Microsecond)
46	-	require.True(t, trace.Mark("config_complete"))
47	-
48	-	require.Equal(t, int64(1), trace.milestones[0].Elapsed.Milliseconds())
49	-	require.Equal(t, int64(1), trace.milestones[0].Delta.Milliseconds())
50	-	require.Equal(t, int64(2), trace.milestones[1].Elapsed.Milliseconds())
51	-	require.Equal(t, int64(1), trace.milestones[1].Delta.Milliseconds())
52	-	}
53	-
54	-	func TestCEFStartupTraceReservesFirstGTKPresentationForAfterPaint(t *testing.T) {
55	-	now := time.Unix(100, 0)
56	-	trace := newCEFStartupTrace(func() time.Time { return now })
57	-
58	-	for _, name := range cefStartupMilestoneOrder[:len(cefStartupMilestoneOrder)-1] {
59	-	now = now.Add(time.Millisecond)
60	-	require.True(t, trace.Mark(name))
61	-	}
62	-
63	-	require.Len(t, trace.milestones, len(cefStartupMilestoneOrder)-1)
64	-	require.False(t, trace.Mark("first_gtk_presentation"), "only the CEF-to-GTK after-paint hook can record the reserved milestone")
65	-	require.False(t, trace.summaryEmitted)
66	-	require.True(t, trace.MarkGTKAfterPaint(), "only the after-paint hook may record this milestone")
67	-	}
68	-
69	-	func TestCEFStartupTraceEmitsOneNormalSummaryAtFirstPresentation(t *testing.T) {
70	-	var output bytes.Buffer
71	-	logger := zerolog.New(&output)
72	-	now := time.Unix(100, 0)
73	-	trace := newCEFStartupTrace(func() time.Time { return now })
74	-	trace.SetBackend("gdk-dmabuf")
75	-	trace.SetLogger(&logger)
76	-
77	-	for _, name := range cefStartupMilestoneOrder[:len(cefStartupMilestoneOrder)-1] {
78	-	now = now.Add(time.Millisecond)
79	-	require.True(t, trace.Mark(name))
80	-	}
81	-	now = now.Add(time.Millisecond)
82	-	require.True(t, trace.MarkGTKAfterPaint())
83	-	trace.MarkGTKAfterPaint()
84	-
85	-	require.Contains(t, output.String(), `"message":"startup_trace: first presentation"`)
86	-	require.Contains(t, output.String(), `"backend":"gdk-dmabuf"`)
87	-	require.Equal(t, 1, bytes.Count(output.Bytes(), []byte(`"message":"startup_trace: first presentation"`)))
88	-	}

@@ -1,88 +0,0 @@
1	-	package logging
2	-
3	-	import (
4	-	"bytes"
5	-	"testing"
6	-	"time"
7	-
8	-	"github.com/rs/zerolog"
9	-	"github.com/stretchr/testify/require"
10	-	)
11	-
12	-	func TestCEFStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) {
13	-	now := time.Unix(100, 0)
14	-	trace := newCEFStartupTrace(func() time.Time { return now })
15	-
16	-	require.True(t, trace.Mark("process_entry"))
17	-	require.False(t, trace.Mark("cef_initialized"), "out-of-order transition must be rejected")
18	-	require.False(t, trace.Mark("process_entry"), "duplicate transition must be rejected")
19	-
20	-	for _, name := range []string{
21	-	"config_complete",
22	-	"cef_library_load_begin",
23	-	"cef_initialized",
24	-	"browser_create_requested",
25	-	"first_accelerated_paint_received",
26	-	"first_dmabuf_texture_swap",
27	-	"first_gtk_presentation",
28	-	} {
29	-	now = now.Add(time.Millisecond)
30	-	if name == "first_gtk_presentation" {
31	-	require.Truef(t, trace.MarkGTKAfterPaint(), "milestone %s should be accepted", name)
32	-	} else {
33	-	require.Truef(t, trace.Mark(name), "milestone %s should be accepted", name)
34	-	}
35	-	}
36	-	require.False(t, trace.Mark("first_gtk_presentation"))
37	-	}
38	-
39	-	func TestCEFStartupTraceQuantizesDeltaToPublishedMilliseconds(t *testing.T) {
40	-	now := time.Unix(100, 0)
41	-	trace := newCEFStartupTrace(func() time.Time { return now })
42	-
43	-	now = now.Add(1500 * time.Microsecond)
44	-	require.True(t, trace.Mark("process_entry"))
45	-	now = now.Add(900 * time.Microsecond)
46	-	require.True(t, trace.Mark("config_complete"))
47	-
48	-	require.Equal(t, int64(1), trace.milestones[0].Elapsed.Milliseconds())
49	-	require.Equal(t, int64(1), trace.milestones[0].Delta.Milliseconds())
50	-	require.Equal(t, int64(2), trace.milestones[1].Elapsed.Milliseconds())
51	-	require.Equal(t, int64(1), trace.milestones[1].Delta.Milliseconds())
52	-	}
53	-
54	-	func TestCEFStartupTraceReservesFirstGTKPresentationForAfterPaint(t *testing.T) {
55	-	now := time.Unix(100, 0)
56	-	trace := newCEFStartupTrace(func() time.Time { return now })
57	-
58	-	for _, name := range cefStartupMilestoneOrder[:len(cefStartupMilestoneOrder)-1] {
59	-	now = now.Add(time.Millisecond)
60	-	require.True(t, trace.Mark(name))
61	-	}
62	-
63	-	require.Len(t, trace.milestones, len(cefStartupMilestoneOrder)-1)
64	-	require.False(t, trace.Mark("first_gtk_presentation"), "only the CEF-to-GTK after-paint hook can record the reserved milestone")
65	-	require.False(t, trace.summaryEmitted)
66	-	require.True(t, trace.MarkGTKAfterPaint(), "only the after-paint hook may record this milestone")
67	-	}
68	-
69	-	func TestCEFStartupTraceEmitsOneNormalSummaryAtFirstPresentation(t *testing.T) {
70	-	var output bytes.Buffer
71	-	logger := zerolog.New(&output)
72	-	now := time.Unix(100, 0)
73	-	trace := newCEFStartupTrace(func() time.Time { return now })
74	-	trace.SetBackend("gdk-dmabuf")
75	-	trace.SetLogger(&logger)
76	-
77	-	for _, name := range cefStartupMilestoneOrder[:len(cefStartupMilestoneOrder)-1] {
78	-	now = now.Add(time.Millisecond)
79	-	require.True(t, trace.Mark(name))
80	-	}
81	-	now = now.Add(time.Millisecond)
82	-	require.True(t, trace.MarkGTKAfterPaint())
83	-	trace.MarkGTKAfterPaint()
84	-
85	-	require.Contains(t, output.String(), `"message":"startup_trace: first presentation"`)
86	-	require.Contains(t, output.String(), `"backend":"gdk-dmabuf"`)
87	-	require.Equal(t, 1, bytes.Count(output.Bytes(), []byte(`"message":"startup_trace: first presentation"`)))
88	-	}