diff --git a/cmd/dumber/main.go b/cmd/dumber/main.go index 003665fc..47d64172 100644 --- a/cmd/dumber/main.go +++ b/cmd/dumber/main.go @@ -10,6 +10,7 @@ import ( "runtime" "strings" "syscall" + "time" "github.com/bnema/dumber/internal/application/port" "github.com/bnema/dumber/internal/application/usecase" @@ -140,11 +141,16 @@ func configureBrowserLaunchRelay(cfg *config.Config) { browserLaunchRelay = relay } +type startupTiming struct { + processEntry time.Time + configComplete time.Time +} + 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 is not known until configuration is complete. Keep these neutral + // timestamps so a CEF GUI trace can be seeded truthfully without creating + // one for WebKit, the standalone omnibox, CLI, or CEF helper processes. + timing := startupTiming{processEntry: time.Now()} // CEF subprocess handling: when CEF re-launches this binary with // --type=renderer/gpu/etc, we must call ExecuteProcess before anything @@ -175,6 +181,7 @@ func main() { // Run GUI mode for browse command if mode == launchModeBrowse { cfg := initConfig() + timing.configComplete = time.Now() configureBrowserLaunchRelay(cfg) startupURL := domainurl.ResolveBrowserStartupURL(browseURL) if forwarded, err := tryForwardBrowseURLToRunningInstance(context.Background(), browserLaunchRelay, startupURL); err != nil { @@ -191,7 +198,7 @@ func main() { initialURL = startupURL restoreSessionID = os.Getenv("DUMBER_RESTORE_SESSION") os.Args = os.Args[:1] - os.Exit(runGUI(cfg)) + os.Exit(runGUI(cfg, timing)) return } @@ -212,7 +219,7 @@ func main() { cmd.Execute() } -func runGUI(cfg *config.Config) int { +func runGUI(cfg *config.Config, timing startupTiming) int { bootstrap.ApplyGTKIMModuleFallbackDefault(os.Stderr) runtime.LockOSThread() @@ -221,12 +228,13 @@ func runGUI(cfg *config.Config) int { if cfg == nil { cfg = initConfig() + timing.configComplete = time.Now() configureBrowserLaunchRelay(cfg) } - logging.Trace().Mark("config_complete") timer.Mark("config") - ctx := initStartupContextWithTrace(cfg) + ctx := initStartupContext(cfg) + activateCEFStartupTraceForGUI(cfg, timing, logging.FromContext(ctx), infracef.ActivateStartupTrace) applyCEFRenderStackDefault(ctx, cfg) timer.Mark("logger") bootstrapLog := logging.FromContext(ctx) @@ -259,7 +267,6 @@ func runGUI(cfg *config.Config) int { timer.Mark("session") log := logging.FromContext(ctx) - logging.Trace().UpdateLogger(log) logCoreDumpLimits(ctx) engine.SetHandlerContext(ctx) @@ -303,7 +310,7 @@ func runStandaloneOmnibox() int { cfg := initConfig() configureBrowserLaunchRelay(cfg) - ctx := initStartupContextWithTrace(cfg) + ctx := initStartupContext(cfg) applyCEFRenderStackDefault(ctx, cfg) initResult, err := runParallelInitPhase(ctx, cfg) @@ -418,20 +425,19 @@ func resolveCurrentExecutable(executable func() (string, error)) (string, error) return executable() } -func initStartupContextWithTrace(cfg *config.Config) context.Context { - logging.InitStartupTrace(cfg.Logging.Level) - - ctx := initStartupContext(cfg) - bootstrapLog := logging.FromContext(ctx) - - logging.Trace().SetLogger(bootstrapLog) - logging.Trace().Mark("logger_init") - - return ctx +func activateCEFStartupTraceForGUI( + cfg *config.Config, + timing startupTiming, + logger *zerolog.Logger, + activate func(time.Time, time.Time, *zerolog.Logger), +) { + if cfg == nil || cfg.Engine.ResolveEngineType() != config.EngineTypeCEF { + return + } + activate(timing.processEntry, timing.configComplete, logger) } func runParallelInitPhase(ctx context.Context, cfg *config.Config) (*bootstrap.ParallelInitResult, error) { - logging.Trace().Mark("parallel_start") initResult, err := bootstrap.RunParallelInit(bootstrap.ParallelInitInput{ Ctx: ctx, Config: cfg, @@ -440,7 +446,6 @@ func runParallelInitPhase(ctx context.Context, cfg *config.Config) (*bootstrap.P handleParallelInitError(ctx, err) return nil, err } - logging.Trace().Mark("parallel_done") return initResult, nil } diff --git a/cmd/dumber/main_test.go b/cmd/dumber/main_test.go index 0f32e825..48b8a5f9 100644 --- a/cmd/dumber/main_test.go +++ b/cmd/dumber/main_test.go @@ -4,12 +4,14 @@ import ( "context" "errors" "testing" + "time" "github.com/bnema/dumber/internal/application/port/mocks" "github.com/bnema/dumber/internal/bootstrap" "github.com/bnema/dumber/internal/infrastructure/colorscheme" "github.com/bnema/dumber/internal/infrastructure/config" "github.com/bnema/dumber/internal/infrastructure/desktop" + "github.com/rs/zerolog" ) func TestLaunchModeFromArgs_DetectsStandaloneOmnibox(t *testing.T) { @@ -172,6 +174,20 @@ func TestResolveCurrentExecutable_PropagatesError(t *testing.T) { } } +func TestWebKitGUIStartupDoesNotActivateCEFTrace(t *testing.T) { + cfg := &config.Config{} + cfg.Engine.Type = config.EngineTypeWebKit + activationCalls := 0 + + activateCEFStartupTraceForGUI(cfg, startupTiming{}, nil, func(time.Time, time.Time, *zerolog.Logger) { + activationCalls++ + }) + + if activationCalls != 0 { + t.Fatal("WebKit GUI startup must not initialize, record, or summarize the CEF first-presentation trace") + } +} + func TestPreInitializeAdwaitaForCEF_InitializesAndMarksDetector(t *testing.T) { initResult := &bootstrap.ParallelInitResult{ AdwaitaDetector: colorscheme.NewAdwaitaDetector(), diff --git a/docs/first-presentation.md b/docs/first-presentation.md index dd4e5426..ac106801 100644 --- a/docs/first-presentation.md +++ b/docs/first-presentation.md @@ -1,7 +1,14 @@ -# First presentation startup trace +# CEF accelerated first-presentation startup trace -Dumber records one cold-start timeline for each GUI process. The trace begins -at `process_entry`, before CEF subprocess handling, and accepts these one-shot +Dumber records this cold-start timeline **only for the accelerated CEF → DMABUF +→ 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 selected CEF GUI process, Dumber captures neutral `process_entry` and +`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` @@ -13,11 +20,19 @@ milestones only in order: 7. `first_dmabuf_texture_swap` (after `GtkPicture.SetPaintable` succeeds) 8. `first_gtk_presentation` (the subsequent GTK frame-clock after-paint) -CEF library-load completion is intentionally not recorded: `InitWithApp` is an +The CEF-to-GTK bridge owns the native accelerated-paint, DMABUF texture-swap, +and GTK presentation boundaries. Dumber records the bridge's ordered callbacks; +it does not synthesize them for another engine or rendering path. CEF +library-load completion is intentionally not recorded: `InitWithApp` is an opaque operation. Duplicate, unknown, and out-of-order transitions are rejected. At the last milestone Dumber emits exactly one normal-level JSON -summary (`startup_trace: first presentation`) with the selected `backend`, an -`incomplete_reason`, total milliseconds, and monotonic milestones. +summary (`startup_trace: first presentation`) with the selected CEF render +backend, an `incomplete_reason`, total milliseconds, and monotonic milestones. + +A non-DMABUF CEF backend or a missing accelerated callback does not produce a +complete summary and is not comparable with this measurement. In particular, +WebKit startup must be measured with a separately defined WebKit-specific +contract rather than this CEF trace. ## Reproducible collection @@ -29,7 +44,8 @@ DUMBER_MACHINE_GPU_PROFILE=integrated-gpu \ scripts/collect_first_presentation.sh ``` -By default each collection is a fresh directory below +The collector is for the accelerated CEF/DMABUF/GTK contract above. By default +each collection is a fresh directory below `$XDG_STATE_HOME/dumber/roadmap-evidence` (or `$HOME/.local/state/dumber/roadmap-evidence` when `XDG_STATE_HOME` is unset), not in the repository. `DUMBER_FIRST_PRESENTATION_OUTPUT` may override it only diff --git a/internal/infrastructure/cef/engine_init.go b/internal/infrastructure/cef/engine_init.go index f3ad8593..92718f3d 100644 --- a/internal/infrastructure/cef/engine_init.go +++ b/internal/infrastructure/cef/engine_init.go @@ -56,7 +56,7 @@ func NewEngine( return nil, err } cef2gtk.ConfigureRenderStackEnvironment(renderStackPlan) - logging.Trace().SetBackend(renderStackPlan.Backend.String()) + activeStartupTrace().SetBackend(renderStackPlan.Backend.String()) settings, err := prepareCEFSettings(opts, paths, cfg, logger) if err != nil { @@ -218,11 +218,11 @@ func initializeCEF(eng *Engine, settings purecef.Settings, logger *zerolog.Logge logger.Debug().Msg("cef: calling InitWithApp") // InitWithApp encapsulates loading libcef, so only the begin boundary is // observable here; do not invent a separate library-load completion event. - logging.Trace().Mark("cef_library_load_begin") + activeStartupTrace().Mark("cef_library_load_begin") if err := purecef.InitWithApp(settings, app); err != nil { return fmt.Errorf("cef.InitWithApp: %w", err) } - logging.Trace().Mark("cef_initialized") + activeStartupTrace().Mark("cef_initialized") if libcefPath := loadedLibCEFPath(); libcefPath != "" { logger.Info().Str("libcef_path", libcefPath).Msg("cef: runtime library loaded") } else { diff --git a/internal/infrastructure/cef/factory.go b/internal/infrastructure/cef/factory.go index 6b9c944a..276e4956 100644 --- a/internal/infrastructure/cef/factory.go +++ b/internal/infrastructure/cef/factory.go @@ -279,7 +279,7 @@ func (f *WebViewFactory) postPendingBrowserCreate(ctx context.Context, wv *WebVi // OnAfterCreated once the host is fully wired. initialURL := "about:blank" // This is the request boundary, not the later OnAfterCreated callback. - logging.Trace().Mark("browser_create_requested") + activeStartupTrace().Mark("browser_create_requested") result := cefBrowserHostCreateBrowser( pc.windowInfo, pc.client, diff --git a/internal/logging/first_presentation_collector_test.go b/internal/infrastructure/cef/first_presentation_collector_test.go similarity index 96% rename from internal/logging/first_presentation_collector_test.go rename to internal/infrastructure/cef/first_presentation_collector_test.go index 81ee73d0..05edc22a 100644 --- a/internal/logging/first_presentation_collector_test.go +++ b/internal/infrastructure/cef/first_presentation_collector_test.go @@ -1,4 +1,4 @@ -package logging +package cef import ( "encoding/json" @@ -23,7 +23,7 @@ const validFirstPresentationLog = `{"message":"startup_trace: milestone","milest {"message":"startup_trace: first presentation","backend":"gdk-dmabuf","incomplete_reason":"","total_ms":7,"host":"alice"}` func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) script, err := os.ReadFile(filepath.Join(repoRoot, "scripts", "collect_first_presentation.sh")) require.NoError(t, err) @@ -32,7 +32,7 @@ func TestFirstPresentationCollectorNeverRecursivelyDeletesCallerOutput(t *testin } func TestFirstPresentationCollectorRejectsUnsafeOutputPaths(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) temp := t.TempDir() runtime := filepath.Join(temp, "cef-147-runtime") @@ -109,7 +109,7 @@ func requireFileContents(t *testing.T, path, want string) { } func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) temp := t.TempDir() runtime := filepath.Join(temp, "cef-147-runtime") @@ -169,7 +169,7 @@ func TestFirstPresentationCollectorSanitizesMachineLocalValues(t *testing.T) { } func TestFirstPresentationCollectorDerivesSelectedImmutableModuleProvenance(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) temp := t.TempDir() runtime := filepath.Join(temp, "cef-147-runtime") @@ -218,7 +218,7 @@ func TestFirstPresentationCollectorDerivesSelectedImmutableModuleProvenance(t *t } func TestFirstPresentationCollectorRejectsNonImmutableModuleProvenanceWithoutLeaks(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) for _, test := range []struct { @@ -298,7 +298,7 @@ exit 1 } func TestFirstPresentationCollectorDefaultsToXDGStateEvidenceDirectory(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) temp := t.TempDir() runtime := filepath.Join(temp, "cef-147-runtime") @@ -342,7 +342,7 @@ func envWithout(name string) []string { } func TestFirstPresentationCollectorReadsProvenanceWithScopedGitSafeDirectory(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) temp := t.TempDir() runtime := filepath.Join(temp, "cef-147-runtime") @@ -386,7 +386,7 @@ exit 128 } func TestFirstPresentationCollectorRejectsInconsistentTiming(t *testing.T) { - repoRoot, err := filepath.Abs(filepath.Join("..", "..")) + repoRoot, err := filepath.Abs(filepath.Join("..", "..", "..")) require.NoError(t, err) for _, test := range []struct { diff --git a/internal/infrastructure/cef/render_handler_adapter.go b/internal/infrastructure/cef/render_handler_adapter.go index f4497b68..7c1fe378 100644 --- a/internal/infrastructure/cef/render_handler_adapter.go +++ b/internal/infrastructure/cef/render_handler_adapter.go @@ -26,19 +26,19 @@ 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 { +func startupPresentationHooks(trace *startupTrace) cef2gtk.Hooks { return cef2gtk.Hooks{ OnFirstAcceleratedPaint: func() { - logging.Trace().Mark("first_accelerated_paint_received") + trace.Mark("first_accelerated_paint_received") }, OnFirstDMABUFTextureSwap: func() { - logging.Trace().Mark("first_dmabuf_texture_swap") + trace.Mark("first_dmabuf_texture_swap") }, OnFirstPresentation: func() { - logging.Trace().MarkGTKAfterPaint() + trace.MarkGTKAfterPaint() }, OnDMABUFUnsupported: func() { - logging.Trace().SetIncompleteReason("dmabuf_texture_swap_unavailable") + trace.SetIncompleteReason("dmabuf_texture_swap_unavailable") }, } } @@ -50,7 +50,7 @@ func newDumberRenderHandler(wv *WebView) purecef.RenderHandler { h := &dumberRenderHandler{wv: wv} var unsupportedPaintOnce sync.Once - hooks := startupPresentationHooks() + hooks := startupPresentationHooks(activeStartupTrace()) hooks.OnUnsupportedPaint = func() { unsupportedPaintOnce.Do(func() { if wv.ctx != nil { diff --git a/internal/infrastructure/cef/startup_presentation_hooks_test.go b/internal/infrastructure/cef/startup_presentation_hooks_test.go index 53ad3253..a7f31af1 100644 --- a/internal/infrastructure/cef/startup_presentation_hooks_test.go +++ b/internal/infrastructure/cef/startup_presentation_hooks_test.go @@ -1,16 +1,79 @@ package cef import ( + "bytes" + "encoding/json" + "strings" "testing" + "time" + "github.com/rs/zerolog" "github.com/stretchr/testify/require" ) func TestStartupPresentationHooksWireEveryUpstreamFirstPresentationCallback(t *testing.T) { - hooks := startupPresentationHooks() + var output bytes.Buffer + trace := newStartupTrace(time.Now, time.Now()) + trace.SetBackend("gdk-dmabuf") + logger := zerolog.New(&output) + trace.SetLogger(&logger) + for _, milestone := range []string{ + "process_entry", + "config_complete", + "cef_library_load_begin", + "cef_initialized", + "browser_create_requested", + } { + require.Truef(t, trace.Mark(milestone), "seed milestone %q", milestone) + } + hooks := startupPresentationHooks(trace) require.NotNil(t, hooks.OnFirstAcceleratedPaint) require.NotNil(t, hooks.OnFirstDMABUFTextureSwap) require.NotNil(t, hooks.OnFirstPresentation) require.NotNil(t, hooks.OnDMABUFUnsupported) + + // The unsupported fact may arrive before the successful presentation path. + // Each callback is invoked twice to make no-op, swapped, and duplicate bodies + // observable through the exact trace output below. + hooks.OnDMABUFUnsupported() + hooks.OnDMABUFUnsupported() + hooks.OnFirstAcceleratedPaint() + hooks.OnFirstAcceleratedPaint() + hooks.OnFirstDMABUFTextureSwap() + hooks.OnFirstDMABUFTextureSwap() + hooks.OnFirstPresentation() + hooks.OnFirstPresentation() + + var milestones []string + summaryCount := 0 + var incompleteReason string + for _, line := range strings.Split(strings.TrimSpace(output.String()), "\n") { + var event struct { + Message string `json:"message"` + Milestone string `json:"milestone"` + IncompleteReason string `json:"incomplete_reason"` + } + require.NoError(t, json.Unmarshal([]byte(line), &event)) + switch event.Message { + case "startup_trace: milestone": + milestones = append(milestones, event.Milestone) + case "startup_trace: first presentation": + summaryCount++ + incompleteReason = event.IncompleteReason + } + } + + require.Equal(t, []string{ + "process_entry", + "config_complete", + "cef_library_load_begin", + "cef_initialized", + "browser_create_requested", + "first_accelerated_paint_received", + "first_dmabuf_texture_swap", + "first_gtk_presentation", + }, milestones) + require.Equal(t, "dmabuf_texture_swap_unavailable", incompleteReason) + require.Equal(t, 1, summaryCount) } diff --git a/internal/infrastructure/cef/startup_trace.go b/internal/infrastructure/cef/startup_trace.go new file mode 100644 index 00000000..3c662e9d --- /dev/null +++ b/internal/infrastructure/cef/startup_trace.go @@ -0,0 +1,199 @@ +package cef + +import ( + "sync" + "time" + + "github.com/rs/zerolog" +) + +// startupTrace records the accelerated CEF/DMABUF/GTK path from process entry +// to the first GTK presentation. It deliberately rejects unknown, duplicate, +// and out-of-order milestones so collected cold-start measurements remain +// truthful. +type startupTrace struct { + mu sync.Mutex + now func() time.Time + t0 time.Time + milestones []startupMilestone + logger *zerolog.Logger + buffered []startupMilestone + backend string + incompleteReason string + summaryEmitted bool +} + +type startupMilestone struct { + Name string + Elapsed time.Duration + Delta time.Duration +} + +var startupMilestoneOrder = []string{ + "process_entry", + "config_complete", + "cef_library_load_begin", + "cef_initialized", + "browser_create_requested", + "first_accelerated_paint_received", + "first_dmabuf_texture_swap", + "first_gtk_presentation", +} + +var processStartupTrace struct { + sync.Mutex + trace *startupTrace +} + +func newStartupTrace(now func() time.Time, processEntry time.Time) *startupTrace { + return &startupTrace{ + now: now, + t0: processEntry, + milestones: make([]startupMilestone, 0, len(startupMilestoneOrder)), + buffered: make([]startupMilestone, 0, len(startupMilestoneOrder)), + } +} + +// ActivateStartupTrace starts the CEF-only first-presentation trace after GUI +// engine selection. The supplied timestamps are captured by the application at +// process entry and configuration completion, before CEF initialization. +func ActivateStartupTrace(processEntry, configComplete time.Time, logger *zerolog.Logger) { + if processEntry.IsZero() || configComplete.IsZero() { + return + } + + processStartupTrace.Lock() + defer processStartupTrace.Unlock() + if processStartupTrace.trace != nil { + return + } + + trace := newStartupTrace(time.Now, processEntry) + if !trace.markAt("process_entry", processEntry) || !trace.markAt("config_complete", configComplete) { + return + } + trace.SetLogger(logger) + processStartupTrace.trace = trace +} + +func activeStartupTrace() *startupTrace { + processStartupTrace.Lock() + defer processStartupTrace.Unlock() + return processStartupTrace.trace +} + +func (st *startupTrace) SetLogger(logger *zerolog.Logger) { + if st == nil || logger == nil { + return + } + st.mu.Lock() + defer st.mu.Unlock() + st.logger = logger + for _, milestone := range st.buffered { + st.emitMilestone(milestone) + } + st.buffered = nil + st.emitSummaryLocked() +} + +func (st *startupTrace) SetBackend(backend string) { + if st == nil { + return + } + st.mu.Lock() + defer st.mu.Unlock() + st.backend = backend +} + +func (st *startupTrace) SetIncompleteReason(reason string) { + if st == nil { + return + } + st.mu.Lock() + defer st.mu.Unlock() + if st.incompleteReason == "" { + st.incompleteReason = reason + } +} + +// Mark accepts exactly the next non-presentation startup milestone. +func (st *startupTrace) Mark(name string) bool { + if name == "first_gtk_presentation" { + return false + } + return st.markAt(name, st.currentTime()) +} + +// MarkGTKAfterPaint records the final milestone from the CEF-to-GTK bridge's +// first frame-clock after-paint callback. +func (st *startupTrace) MarkGTKAfterPaint() bool { + return st.markAt("first_gtk_presentation", st.currentTime()) +} + +func (st *startupTrace) currentTime() time.Time { + if st == nil || st.now == nil { + return time.Time{} + } + return st.now() +} + +func (st *startupTrace) markAt(name string, at time.Time) bool { + if st == nil || st.now == nil || at.IsZero() { + return false + } + st.mu.Lock() + defer st.mu.Unlock() + if at.Before(st.t0) || len(st.milestones) >= len(startupMilestoneOrder) || name != startupMilestoneOrder[len(st.milestones)] { + return false + } + + milestone := startupMilestone{Name: name, Elapsed: at.Sub(st.t0)} + previousMilliseconds := int64(0) + if len(st.milestones) > 0 { + previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds() + } + milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond + st.milestones = append(st.milestones, milestone) + if st.logger == nil { + st.buffered = append(st.buffered, milestone) + } else { + st.emitMilestone(milestone) + } + st.emitSummaryLocked() + return true +} + +func (st *startupTrace) emitMilestone(m startupMilestone) { + if st.logger == nil { + return + } + st.logger.Debug(). + Str("milestone", m.Name). + Int64("t_ms", m.Elapsed.Milliseconds()). + Int64("delta_ms", m.Delta.Milliseconds()). + Msg("startup_trace: milestone") +} + +func (st *startupTrace) emitSummaryLocked() { + if st.summaryEmitted || st.logger == nil || len(st.milestones) != len(startupMilestoneOrder) { + return + } + st.summaryEmitted = true + st.logger.Info(). + Str("backend", st.backend). + Str("incomplete_reason", st.incompleteReason). + Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()). + Interface("milestones", st.milestones). + Msg("startup_trace: first presentation") +} + +func (st *startupTrace) Enabled() bool { return st != nil && st.now != nil } + +func (st *startupTrace) TotalElapsed() time.Duration { + if st == nil || st.now == nil { + return 0 + } + st.mu.Lock() + defer st.mu.Unlock() + return st.now().Sub(st.t0) +} diff --git a/internal/logging/startup_trace_test.go b/internal/infrastructure/cef/startup_trace_test.go similarity index 50% rename from internal/logging/startup_trace_test.go rename to internal/infrastructure/cef/startup_trace_test.go index 23eefc3d..72adb54a 100644 --- a/internal/logging/startup_trace_test.go +++ b/internal/infrastructure/cef/startup_trace_test.go @@ -1,4 +1,4 @@ -package logging +package cef import ( "bytes" @@ -9,9 +9,37 @@ import ( "github.com/stretchr/testify/require" ) +func TestActivateStartupTraceSeedsNeutralProcessAndConfigTiming(t *testing.T) { + processStartupTrace.Lock() + previous := processStartupTrace.trace + processStartupTrace.trace = nil + processStartupTrace.Unlock() + t.Cleanup(func() { + processStartupTrace.Lock() + processStartupTrace.trace = previous + processStartupTrace.Unlock() + }) + + processEntry := time.Unix(100, 0) + configComplete := processEntry.Add(15 * time.Millisecond) + var output bytes.Buffer + logger := zerolog.New(&output).Level(zerolog.DebugLevel) + + ActivateStartupTrace(processEntry, configComplete, &logger) + trace := activeStartupTrace() + + require.NotNil(t, trace) + require.Equal(t, []string{"process_entry", "config_complete"}, []string{trace.milestones[0].Name, trace.milestones[1].Name}) + require.Equal(t, int64(0), trace.milestones[0].Elapsed.Milliseconds()) + require.Equal(t, int64(15), trace.milestones[1].Elapsed.Milliseconds()) + require.Contains(t, output.String(), `"milestone":"process_entry"`) + require.Contains(t, output.String(), `"milestone":"config_complete"`) + require.NotContains(t, output.String(), `"message":"startup_trace: first presentation"`) +} + func TestStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) { now := time.Unix(100, 0) - trace := newStartupTrace(func() time.Time { return now }) + trace := newStartupTrace(func() time.Time { return now }, now) require.True(t, trace.Mark("process_entry")) require.False(t, trace.Mark("cef_initialized"), "out-of-order transition must be rejected") @@ -36,33 +64,32 @@ func TestStartupTraceAcceptsOnlyOrderedOneShotMilestones(t *testing.T) { require.False(t, trace.Mark("first_gtk_presentation")) } -func TestStartupTraceQuantizesDeltaToPublishedMilliseconds(t *testing.T) { - now := time.Unix(100, 0) - trace := newStartupTrace(func() time.Time { return now }) +func TestStartupTracePreservesProcessAndConfigTimestamps(t *testing.T) { + processEntry := time.Unix(100, 0) + configComplete := processEntry.Add(1500 * time.Microsecond) + now := configComplete.Add(900 * time.Microsecond) + trace := newStartupTrace(func() time.Time { return now }, processEntry) - now = now.Add(1500 * time.Microsecond) - require.True(t, trace.Mark("process_entry")) - now = now.Add(900 * time.Microsecond) - require.True(t, trace.Mark("config_complete")) + require.True(t, trace.markAt("process_entry", processEntry)) + require.True(t, trace.markAt("config_complete", configComplete)) - require.Equal(t, int64(1), trace.milestones[0].Elapsed.Milliseconds()) - require.Equal(t, int64(1), trace.milestones[0].Delta.Milliseconds()) - require.Equal(t, int64(2), trace.milestones[1].Elapsed.Milliseconds()) + require.Equal(t, int64(0), trace.milestones[0].Elapsed.Milliseconds()) + require.Equal(t, int64(0), trace.milestones[0].Delta.Milliseconds()) + require.Equal(t, int64(1), trace.milestones[1].Elapsed.Milliseconds()) require.Equal(t, int64(1), trace.milestones[1].Delta.Milliseconds()) } -func TestStartupTraceFinishCannotFabricateFirstGTKPresentation(t *testing.T) { +func TestStartupTraceReservesFirstGTKPresentationForAfterPaint(t *testing.T) { now := time.Unix(100, 0) - trace := newStartupTrace(func() time.Time { return now }) + trace := newStartupTrace(func() time.Time { return now }, now) for _, name := range startupMilestoneOrder[:len(startupMilestoneOrder)-1] { now = now.Add(time.Millisecond) require.True(t, trace.Mark(name)) } - trace.Finish() // Legacy callers do not observe the upstream GTK after-paint. require.Len(t, trace.milestones, len(startupMilestoneOrder)-1) - require.False(t, trace.Mark("first_gtk_presentation"), "generic callers cannot record the reserved milestone") + require.False(t, trace.Mark("first_gtk_presentation"), "only the CEF-to-GTK after-paint hook can record the reserved milestone") require.False(t, trace.summaryEmitted) require.True(t, trace.MarkGTKAfterPaint(), "only the after-paint hook may record this milestone") } @@ -71,7 +98,7 @@ func TestStartupTraceEmitsOneNormalSummaryAtFirstPresentation(t *testing.T) { var output bytes.Buffer logger := zerolog.New(&output) now := time.Unix(100, 0) - trace := newStartupTrace(func() time.Time { return now }) + trace := newStartupTrace(func() time.Time { return now }, now) trace.SetBackend("gdk-dmabuf") trace.SetLogger(&logger) diff --git a/internal/infrastructure/webkit/engine_init.go b/internal/infrastructure/webkit/engine_init.go index 81ab178a..62a6bcf2 100644 --- a/internal/infrastructure/webkit/engine_init.go +++ b/internal/infrastructure/webkit/engine_init.go @@ -40,7 +40,6 @@ func NewEngine( // --- Configure rendering environment (must be before GTK/WebKit init) --- engineConfigureRenderingEnvironment(ctx, cfg, wkCfg, &perfSettings, logger) - logging.Trace().Mark("render_env") // --- Build webKitContextOptions from opts + wkCfg + perfSettings --- wkOpts := engineBuildContextOptions(opts, profile, wkCfg, &perfSettings) @@ -53,7 +52,6 @@ func NewEngine( if err != nil { return nil, err } - logging.Trace().Mark("webkit_context") // --- Filter manager --- filterManager := engineInitFilterManager(ctx, cfg, profile.Shared.DataDir, logger) @@ -77,7 +75,6 @@ func NewEngine( } messageRouter := NewMessageRouter(ctx) - logging.Trace().Mark("settings_manager") // --- WebView pool --- poolCfg := DefaultPoolConfig() @@ -100,7 +97,6 @@ func NewEngine( } else { logger.Warn().Msg("skipping first webview prewarm: no GDK display available yet") } - logging.Trace().Mark("pool_prewarm_first") // --- WebView factory --- factory := NewWebViewFactory(wkCtx, settings, pool, injector, messageRouter) @@ -147,7 +143,6 @@ func engineSurveyHardwareAndResolveProfile( ) config.ResolvedPerformanceSettings { hwSurveyor := env.NewHardwareSurveyor() hwInfo := hwSurveyor.Survey(ctx) - logging.Trace().Mark("hardware_survey") logger.Info(). Int("cpu_cores", hwInfo.CPUCores). Int("cpu_threads", hwInfo.CPUThreads). @@ -158,7 +153,6 @@ func engineSurveyHardwareAndResolveProfile( perfCfg := config.PerformanceConfigFromEngine(&cfg.Engine) perfSettings := config.ResolvePerformanceProfile(&perfCfg, &hwInfo) - logging.Trace().Mark("performance_profile") logger.Info(). Str("profile", string(cfg.Engine.Profile)). Int("skia_cpu_threads", perfSettings.SkiaCPUPaintingThreads). @@ -284,7 +278,6 @@ func engineInitFilterManager(ctx context.Context, cfg *config.Config, dataDir st if err := filterManager.Initialize(ctx); err != nil { logger.Warn().Err(err).Msg("failed to initialize filters, will load async") } - logging.Trace().Mark("filter_manager") return filterManager } diff --git a/internal/logging/startup_trace.go b/internal/logging/startup_trace.go deleted file mode 100644 index 2fcf543a..00000000 --- a/internal/logging/startup_trace.go +++ /dev/null @@ -1,208 +0,0 @@ -package logging - -import ( - "sync" - "time" - - "github.com/rs/zerolog" -) - -// StartupTrace records the single truthful path from process entry to the first -// GTK presentation. It deliberately rejects unknown, duplicate, and out of -// order milestones: accepting a convenient timestamp would make the result -// unsuitable for cold-start measurement. -type StartupTrace struct { - mu sync.Mutex - now func() time.Time - t0 time.Time - milestones []Milestone - logger *zerolog.Logger - buffered []Milestone - backend string - incompleteReason string - summaryEmitted bool -} - -// Milestone represents a timing checkpoint measured from process entry. -type Milestone struct { - Name string - Elapsed time.Duration - Delta time.Duration -} - -var startupMilestoneOrder = []string{ - "process_entry", - "config_complete", - "cef_library_load_begin", - "cef_initialized", - "browser_create_requested", - "first_accelerated_paint_received", - "first_dmabuf_texture_swap", - "first_gtk_presentation", -} - -var ( - globalTrace *StartupTrace - globalTraceMu sync.Mutex - globalTraceOnce sync.Once -) - -func newStartupTrace(now func() time.Time) *StartupTrace { - start := now() - return &StartupTrace{ - now: now, - t0: start, - milestones: make([]Milestone, 0, len(startupMilestoneOrder)), - buffered: make([]Milestone, 0, len(startupMilestoneOrder)), - } -} - -// InitStartupTrace must be called at the first instruction in main. logLevel is -// retained for source compatibility; this measurement is always collected so -// its final structured summary is available at normal log level. -func InitStartupTrace(_ string) { - globalTraceOnce.Do(func() { - trace := newStartupTrace(time.Now) - globalTraceMu.Lock() - globalTrace = trace - globalTraceMu.Unlock() - }) -} - -// Trace returns the process startup trace. Callers before initialization get a -// harmless trace which rejects all transitions. -func Trace() *StartupTrace { - globalTraceMu.Lock() - defer globalTraceMu.Unlock() - if globalTrace == nil { - return &StartupTrace{} - } - return globalTrace -} - -// SetLogger makes buffered milestones available to the process logger. -func (st *StartupTrace) SetLogger(logger *zerolog.Logger) { - if st == nil || logger == nil { - return - } - st.mu.Lock() - defer st.mu.Unlock() - st.logger = logger - for _, milestone := range st.buffered { - st.emitMilestone(milestone) - } - st.buffered = nil - st.emitSummaryLocked() -} - -// UpdateLogger switches the destination without replaying events. Replaying -// would violate the one-shot property in session logs. -func (st *StartupTrace) UpdateLogger(logger *zerolog.Logger) { st.SetLogger(logger) } - -// SetBackend records the selected presentation backend for the final summary. -func (st *StartupTrace) SetBackend(backend string) { - if st == nil { - return - } - st.mu.Lock() - defer st.mu.Unlock() - st.backend = backend -} - -// SetIncompleteReason records why a trace cannot reach a valid DMABUF result. -func (st *StartupTrace) SetIncompleteReason(reason string) { - if st == nil { - return - } - st.mu.Lock() - defer st.mu.Unlock() - if st.incompleteReason == "" { - st.incompleteReason = reason - } -} - -// Mark accepts exactly the next non-presentation startup milestone and returns -// whether it was recorded. first_gtk_presentation is reserved for the GTK -// frame-clock after-paint hook through MarkGTKAfterPaint. -func (st *StartupTrace) Mark(name string) bool { - if name == "first_gtk_presentation" { - return false - } - return st.mark(name) -} - -// MarkGTKAfterPaint records the final milestone. It is called only from the -// upstream CEF-to-GTK bridge's first frame-clock after-paint callback. -func (st *StartupTrace) MarkGTKAfterPaint() bool { - return st.mark("first_gtk_presentation") -} - -// mark accepts the next milestone and is safe for callbacks from CEF and GTK -// threads. -func (st *StartupTrace) mark(name string) bool { - if st == nil || st.now == nil { - return false - } - st.mu.Lock() - defer st.mu.Unlock() - if len(st.milestones) >= len(startupMilestoneOrder) || name != startupMilestoneOrder[len(st.milestones)] { - return false - } - - now := st.now() - milestone := Milestone{Name: name, Elapsed: now.Sub(st.t0)} - // Published fields are integer milliseconds. Compute delta on that same - // scale so delta_ms always exactly reconstructs t_ms in collected evidence. - previousMilliseconds := int64(0) - if len(st.milestones) > 0 { - previousMilliseconds = st.milestones[len(st.milestones)-1].Elapsed.Milliseconds() - } - milestone.Delta = time.Duration(milestone.Elapsed.Milliseconds()-previousMilliseconds) * time.Millisecond - st.milestones = append(st.milestones, milestone) - if st.logger == nil { - st.buffered = append(st.buffered, milestone) - } else { - st.emitMilestone(milestone) - } - st.emitSummaryLocked() - return true -} - -func (st *StartupTrace) emitMilestone(m Milestone) { - if st.logger == nil { - return - } - st.logger.Debug(). - Str("milestone", m.Name). - Int64("t_ms", m.Elapsed.Milliseconds()). - Int64("delta_ms", m.Delta.Milliseconds()). - Msg("startup_trace: milestone") -} - -func (st *StartupTrace) emitSummaryLocked() { - if st.summaryEmitted || st.logger == nil || len(st.milestones) != len(startupMilestoneOrder) { - return - } - st.summaryEmitted = true - st.logger.Info(). - Str("backend", st.backend). - Str("incomplete_reason", st.incompleteReason). - Int64("total_ms", st.milestones[len(st.milestones)-1].Elapsed.Milliseconds()). - Interface("milestones", st.milestones). - Msg("startup_trace: first presentation") -} - -// Finish is retained as a harmless compatibility no-op. The only valid source -// for first_gtk_presentation is the upstream GTK frame-clock after-paint hook. -func (*StartupTrace) Finish() {} - -func (st *StartupTrace) Enabled() bool { return st != nil && st.now != nil } - -func (st *StartupTrace) TotalElapsed() time.Duration { - if st == nil || st.now == nil { - return 0 - } - st.mu.Lock() - defer st.mu.Unlock() - return st.now().Sub(st.t0) -} diff --git a/internal/ui/app.go b/internal/ui/app.go index ce2082a9..b5b8541d 100644 --- a/internal/ui/app.go +++ b/internal/ui/app.go @@ -295,7 +295,6 @@ func (a *App) Run(ctx context.Context, args []string) int { // Initialize libadwaita once (required before using StyleManager). // This also initializes GTK implicitly. EnsureAdwaitaInitialized() - logging.Trace().Mark("gtk_init") // Mark adwaita detector as available now that adw.Init() is complete. // This enables the highest-priority color scheme detector. @@ -317,7 +316,6 @@ func (a *App) Run(ctx context.Context, args []string) int { return 1 } defer a.gtkApp.Unref() - logging.Trace().Mark("gtk_app_created") a.dispatchOnMainThread = a.runOnMainThread // Connect activate signal @@ -353,7 +351,6 @@ func (a *App) onActivate(ctx context.Context) { log.Error().Err(err).Msg("failed to create main window") return } - logging.Trace().Mark("window_created") a.installCrashReportNotifier(ctx) a.initFocusManager() @@ -362,7 +359,6 @@ func (a *App) onActivate(ctx context.Context) { a.initCoordinators(ctx) a.wireWebRTCPermissionIndicator() - logging.Trace().Mark("coordinators_init") a.initKeyboardHandler(ctx) a.initOmniboxConfig(ctx) a.initFindBarConfig(ctx) diff --git a/internal/ui/coordinator/content/coordinator.go b/internal/ui/coordinator/content/coordinator.go index b1a27f1d..a33c6650 100644 --- a/internal/ui/coordinator/content/coordinator.go +++ b/internal/ui/coordinator/content/coordinator.go @@ -314,12 +314,6 @@ func (c *Coordinator) activePaneOverrideID() (entity.PaneID, bool) { return c.activePaneOverride, true } -func (c *Coordinator) webViewCount() int { - c.webViewsMu.RLock() - defer c.webViewsMu.RUnlock() - return len(c.webViews) -} - func (c *Coordinator) getWebViewLocked(paneID entity.PaneID) port.WebView { c.webViewsMu.RLock() defer c.webViewsMu.RUnlock() diff --git a/internal/ui/coordinator/content/lifecycle.go b/internal/ui/coordinator/content/lifecycle.go index 319c01e9..dc3ba4dd 100644 --- a/internal/ui/coordinator/content/lifecycle.go +++ b/internal/ui/coordinator/content/lifecycle.go @@ -28,16 +28,10 @@ func (c *Coordinator) EnsureWebView(ctx context.Context, paneID entity.PaneID) ( return nil, fmt.Errorf("webview pool not configured") } - // Mark tab_created on first webview (first tab) - if c.webViewCount() == 0 { - logging.Trace().Mark("tab_created") - } - wv, err := c.pool.Acquire(ctx) if err != nil { return nil, err } - logging.Trace().Mark("webview_acquired") // setWebViewLocked atomically resets presentation state for the acquired // WebView, including a pooled instance previously revealed in another pane. @@ -144,7 +138,6 @@ func (c *Coordinator) AttachToWorkspace(ctx context.Context, ws *entity.Workspac log.Warn().Err(err).Str("pane_id", string(pane.ID)).Msg("failed to attach webview widget") continue } - logging.Trace().Mark("webview_attached") } } diff --git a/internal/ui/coordinator/content/navigation.go b/internal/ui/coordinator/content/navigation.go index 5a03a8cb..83e96408 100644 --- a/internal/ui/coordinator/content/navigation.go +++ b/internal/ui/coordinator/content/navigation.go @@ -19,7 +19,6 @@ import ( // Also shows the WebView widget (it's hidden during creation to avoid white flash). func (c *Coordinator) onLoadCommitted(ctx context.Context, paneID entity.PaneID, wv port.WebView, identity webViewIdentity) { log := logging.FromContext(ctx) - logging.Trace().Mark("load_committed") uri := wv.URI() if uri == "" { @@ -177,8 +176,6 @@ func (c *Coordinator) updatePaneURI(paneID entity.PaneID, uri string) { // onLoadStarted shows the progress bar when page loading begins. func (c *Coordinator) onLoadStarted(paneID entity.PaneID) { - logging.Trace().Mark("load_started") - // Trigger deferred initialization on first load_started. // This ensures non-critical init runs after initial navigation starts. c.loadStartedOnce.Do(func() {