feat(logging): add startup trace for cold start performance tracking

commit: 428bf7318c9540f4e128333176da64a8669a384b
author: brice · 9mo ago · 2026-01-23 05:51 UTC
parent: 1dedbbf
signature: GPG VerifiedCD88F9E564E0102646FB6077A1A07C7C7C3E349D · arch-gpg Verified for the committer email

5 files · +262 -0

M cmd/dumber/main.go +14 -0


@@ -75,11 +75,20 @@ func runGUI() int {
75	75		cfg := initConfig()
76	76		timer.Mark("config")
77	77
	78	+	// Initialize startup trace for cold start tracking (debug/trace only)
	79	+	logging.InitStartupTrace(cfg.Logging.Level)
	80	+	logging.Trace().Mark("config_loaded")
	81	+
78	82		ctx := initStartupContext(cfg)
79	83		timer.Mark("logger")
80	84		bootstrapLog := logging.FromContext(ctx)
81	85
	86	+	// Set logger for startup trace and mark logger init
	87	+	logging.Trace().SetLogger(bootstrapLog)
	88	+	logging.Trace().Mark("logger_init")
	89	+
82	90		// Parallel phase: directories and theme setup
	91	+	logging.Trace().Mark("parallel_start")
83	92		initResult, err := bootstrap.RunParallelInit(bootstrap.ParallelInitInput{
84	93		Ctx: ctx,
85	94		Config: cfg,

@@ -89,6 +98,7 @@ func runGUI() int {
89	98		return 1
90	99		}
91	100		timer.MarkDuration("parallel_phase", initResult.Duration)
	101	+	logging.Trace().Mark("parallel_done")
92	102
93	103		needsEagerDB := restoreSessionID != "" \|\| cfg.Session.AutoRestore
94	104

@@ -113,6 +123,10 @@ func runGUI() int {
113	123
114	124		ctx = sessionCtx
115	125		log := logging.FromContext(ctx)
	126	+
	127	+	// Update startup trace with session logger so milestones go to log file
	128	+	logging.Trace().UpdateLogger(log)
	129	+
116	130		if stack.MessageRouter != nil {
117	131		stack.MessageRouter.SetBaseContext(ctx)
118	132		}


@@ -75,11 +75,20 @@ func runGUI() int {
75	cfg := initConfig()	75		cfg := initConfig()
76	timer.Mark("config")	76		timer.Mark("config")
77		77
		78	+	// Initialize startup trace for cold start tracking (debug/trace only)
		79	+	logging.InitStartupTrace(cfg.Logging.Level)
		80	+	logging.Trace().Mark("config_loaded")
		81	+
78	ctx := initStartupContext(cfg)	82		ctx := initStartupContext(cfg)
79	timer.Mark("logger")	83		timer.Mark("logger")
80	bootstrapLog := logging.FromContext(ctx)	84		bootstrapLog := logging.FromContext(ctx)
81		85
		86	+	// Set logger for startup trace and mark logger init
		87	+	logging.Trace().SetLogger(bootstrapLog)
		88	+	logging.Trace().Mark("logger_init")
		89	+
82	// Parallel phase: directories and theme setup	90		// Parallel phase: directories and theme setup
		91	+	logging.Trace().Mark("parallel_start")
83	initResult, err := bootstrap.RunParallelInit(bootstrap.ParallelInitInput{	92		initResult, err := bootstrap.RunParallelInit(bootstrap.ParallelInitInput{
84	Ctx: ctx,	93		Ctx: ctx,
85	Config: cfg,	94		Config: cfg,

@@ -89,6 +98,7 @@ func runGUI() int {
89	return 1	98		return 1
90	}	99		}
91	timer.MarkDuration("parallel_phase", initResult.Duration)	100		timer.MarkDuration("parallel_phase", initResult.Duration)
		101	+	logging.Trace().Mark("parallel_done")
92		102
93	needsEagerDB := restoreSessionID != "" \|\| cfg.Session.AutoRestore	103		needsEagerDB := restoreSessionID != "" \|\| cfg.Session.AutoRestore
94		104

@@ -113,6 +123,10 @@ func runGUI() int {
113		123
114	ctx = sessionCtx	124		ctx = sessionCtx
115	log := logging.FromContext(ctx)	125		log := logging.FromContext(ctx)
		126	+
		127	+	// Update startup trace with session logger so milestones go to log file
		128	+	logging.Trace().UpdateLogger(log)
		129	+
116	if stack.MessageRouter != nil {	130		if stack.MessageRouter != nil {
117	stack.MessageRouter.SetBaseContext(ctx)	131		stack.MessageRouter.SetBaseContext(ctx)
118	}	132		}

M internal/bootstrap/webkit_stack.go +9 -0


@@ -44,9 +44,11 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
44	44		themeManager := input.ThemeManager
45	45		colorResolver := input.ColorResolver
46	46		logger := input.Logger
	47	+
47	48		// Detect hardware for performance profile scaling
48	49		hwSurveyor := env.NewHardwareSurveyor()
49	50		hwInfo := hwSurveyor.Survey(ctx)
	51	+	logging.Trace().Mark("hardware_survey")
50	52		logger.Info().
51	53		Int("cpu_cores", hwInfo.CPUCores).
52	54		Int("cpu_threads", hwInfo.CPUThreads).

@@ -57,6 +59,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
57	59
58	60		// Resolve performance profile to get actual settings
59	61		perfSettings := config.ResolvePerformanceProfile(&cfg.Performance, &hwInfo)
	62	+	logging.Trace().Mark("performance_profile")
60	63		logger.Info().
61	64		Str("profile", string(cfg.Performance.Profile)).
62	65		Int("skia_cpu_threads", perfSettings.SkiaCPUPaintingThreads).

@@ -66,6 +69,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
66	69
67	70		// Configure rendering environment (must happen before WebKit/GTK init)
68	71		configureRenderingEnvironment(ctx, cfg, &perfSettings, logger)
	72	+	logging.Trace().Mark("render_env")
69	73
70	74		// Build WebKitContext options with memory pressure settings
71	75		wkOpts := port.WebKitContextOptions{

@@ -97,6 +101,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
97	101		if err != nil {
98	102		logger.Fatal().Err(err).Msg("failed to initialize WebKit context")
99	103		}
	104	+	logging.Trace().Mark("webkit_context")
100	105
101	106		filterStoreDir := filepath.Join(dataDir, "filters", "store")
102	107		filterJSONDir := filepath.Join(dataDir, "filters", "json")

@@ -113,6 +118,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
113	118		logger.Warn().Err(err).Msg("failed to initialize filters, will load async")
114	119		}
115	120		}
	121	+	logging.Trace().Mark("filter_manager")
116	122
117	123		schemeHandler := webkit.NewDumbSchemeHandler(ctx)
118	124		schemeHandler.SetAssets(assets.WebUIAssets)

@@ -133,6 +139,8 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
133	139		}
134	140
135	141		messageRouter := webkit.NewMessageRouter(ctx)
	142	+	logging.Trace().Mark("settings_manager")
	143	+
136	144		poolCfg := webkit.DefaultPoolConfig()
137	145		// Override prewarm count from resolved profile settings
138	146		if perfSettings.WebViewPoolPrewarmCount > 0 {

@@ -153,6 +161,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
153	161		if err := pool.PrewarmFirst(ctx); err != nil {
154	162		logger.Warn().Err(err).Msg("failed to prewarm first webview, first tab may be slower")
155	163		}
	164	+	logging.Trace().Mark("pool_prewarm_first")
156	165
157	166		return WebKitStack{
158	167		Context: wkCtx,


@@ -44,9 +44,11 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
44	themeManager := input.ThemeManager	44		themeManager := input.ThemeManager
45	colorResolver := input.ColorResolver	45		colorResolver := input.ColorResolver
46	logger := input.Logger	46		logger := input.Logger
		47	+
47	// Detect hardware for performance profile scaling	48		// Detect hardware for performance profile scaling
48	hwSurveyor := env.NewHardwareSurveyor()	49		hwSurveyor := env.NewHardwareSurveyor()
49	hwInfo := hwSurveyor.Survey(ctx)	50		hwInfo := hwSurveyor.Survey(ctx)
		51	+	logging.Trace().Mark("hardware_survey")
50	logger.Info().	52		logger.Info().
51	Int("cpu_cores", hwInfo.CPUCores).	53		Int("cpu_cores", hwInfo.CPUCores).
52	Int("cpu_threads", hwInfo.CPUThreads).	54		Int("cpu_threads", hwInfo.CPUThreads).

@@ -57,6 +59,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
57		59
58	// Resolve performance profile to get actual settings	60		// Resolve performance profile to get actual settings
59	perfSettings := config.ResolvePerformanceProfile(&cfg.Performance, &hwInfo)	61		perfSettings := config.ResolvePerformanceProfile(&cfg.Performance, &hwInfo)
		62	+	logging.Trace().Mark("performance_profile")
60	logger.Info().	63		logger.Info().
61	Str("profile", string(cfg.Performance.Profile)).	64		Str("profile", string(cfg.Performance.Profile)).
62	Int("skia_cpu_threads", perfSettings.SkiaCPUPaintingThreads).	65		Int("skia_cpu_threads", perfSettings.SkiaCPUPaintingThreads).

@@ -66,6 +69,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
66		69
67	// Configure rendering environment (must happen before WebKit/GTK init)	70		// Configure rendering environment (must happen before WebKit/GTK init)
68	configureRenderingEnvironment(ctx, cfg, &perfSettings, logger)	71		configureRenderingEnvironment(ctx, cfg, &perfSettings, logger)
		72	+	logging.Trace().Mark("render_env")
69		73
70	// Build WebKitContext options with memory pressure settings	74		// Build WebKitContext options with memory pressure settings
71	wkOpts := port.WebKitContextOptions{	75		wkOpts := port.WebKitContextOptions{

@@ -97,6 +101,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
97	if err != nil {	101		if err != nil {
98	logger.Fatal().Err(err).Msg("failed to initialize WebKit context")	102		logger.Fatal().Err(err).Msg("failed to initialize WebKit context")
99	}	103		}
		104	+	logging.Trace().Mark("webkit_context")
100		105
101	filterStoreDir := filepath.Join(dataDir, "filters", "store")	106		filterStoreDir := filepath.Join(dataDir, "filters", "store")
102	filterJSONDir := filepath.Join(dataDir, "filters", "json")	107		filterJSONDir := filepath.Join(dataDir, "filters", "json")

@@ -113,6 +118,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
113	logger.Warn().Err(err).Msg("failed to initialize filters, will load async")	118		logger.Warn().Err(err).Msg("failed to initialize filters, will load async")
114	}	119		}
115	}	120		}
		121	+	logging.Trace().Mark("filter_manager")
116		122
117	schemeHandler := webkit.NewDumbSchemeHandler(ctx)	123		schemeHandler := webkit.NewDumbSchemeHandler(ctx)
118	schemeHandler.SetAssets(assets.WebUIAssets)	124		schemeHandler.SetAssets(assets.WebUIAssets)

@@ -133,6 +139,8 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
133	}	139		}
134		140
135	messageRouter := webkit.NewMessageRouter(ctx)	141		messageRouter := webkit.NewMessageRouter(ctx)
		142	+	logging.Trace().Mark("settings_manager")
		143	+
136	poolCfg := webkit.DefaultPoolConfig()	144		poolCfg := webkit.DefaultPoolConfig()
137	// Override prewarm count from resolved profile settings	145		// Override prewarm count from resolved profile settings
138	if perfSettings.WebViewPoolPrewarmCount > 0 {	146		if perfSettings.WebViewPoolPrewarmCount > 0 {

@@ -153,6 +161,7 @@ func BuildWebKitStack(input WebKitStackInput) WebKitStack {
153	if err := pool.PrewarmFirst(ctx); err != nil {	161		if err := pool.PrewarmFirst(ctx); err != nil {
154	logger.Warn().Err(err).Msg("failed to prewarm first webview, first tab may be slower")	162		logger.Warn().Err(err).Msg("failed to prewarm first webview, first tab may be slower")
155	}	163		}
		164	+	logging.Trace().Mark("pool_prewarm_first")
156		165
157	return WebKitStack{	166		return WebKitStack{
158	Context: wkCtx,	167		Context: wkCtx,

A internal/logging/startup_trace.go +220 -0

@@ -0,0 +1,220 @@
	1	+	package logging
	2	+
	3	+	import (
	4	+	"fmt"
	5	+	"strings"
	6	+	"sync"
	7	+	"time"
	8	+
	9	+	"github.com/rs/zerolog"
	10	+	)
	11	+
	12	+	// StartupTrace tracks cold start milestones from process launch to first paint.
	13	+	// Thread-safe for use across goroutines.
	14	+	// Enabled only when log level is debug or trace.
	15	+	type StartupTrace struct {
	16	+	mu sync.Mutex
	17	+	t0 time.Time
	18	+	milestones []Milestone
	19	+	enabled bool
	20	+	logger *zerolog.Logger
	21	+	buffered []Milestone // milestones recorded before logger is set
	22	+	finished bool
	23	+	}
	24	+
	25	+	// Milestone represents a timing checkpoint during startup.
	26	+	type Milestone struct {
	27	+	Name string
	28	+	Elapsed time.Duration // time since t0
	29	+	Delta time.Duration // time since previous milestone
	30	+	}
	31	+
	32	+	var (
	33	+	globalTrace *StartupTrace
	34	+	globalTraceMu sync.Mutex
	35	+	globalTraceOnce sync.Once
	36	+	)
	37	+
	38	+	// InitStartupTrace initializes the global startup trace.
	39	+	// Call this as early as possible in main() to capture T0.
	40	+	// The trace is enabled only if the given log level is debug or trace.
	41	+	func InitStartupTrace(logLevel string) {
	42	+	globalTraceOnce.Do(func() {
	43	+	enabled := logLevel == "debug" \|\| logLevel == "trace"
	44	+	globalTraceMu.Lock()
	45	+	globalTrace = &StartupTrace{
	46	+	t0: time.Now(),
	47	+	milestones: make([]Milestone, 0, 32),
	48	+	enabled: enabled,
	49	+	buffered: make([]Milestone, 0, 8),
	50	+	}
	51	+	globalTraceMu.Unlock()
	52	+
	53	+	if enabled {
	54	+	// Record process_start as first milestone
	55	+	globalTrace.Mark("process_start")
	56	+	}
	57	+	})
	58	+	}
	59	+
	60	+	// Trace returns the global startup trace instance.
	61	+	// Returns a no-op trace if not initialized or disabled.
	62	+	func Trace() *StartupTrace {
	63	+	globalTraceMu.Lock()
	64	+	defer globalTraceMu.Unlock()
	65	+	if globalTrace == nil {
	66	+	// Return a disabled no-op trace
	67	+	return &StartupTrace{enabled: false}
	68	+	}
	69	+	return globalTrace
	70	+	}
	71	+
	72	+	// SetLogger sets the logger for emitting milestone logs.
	73	+	// Flushes any buffered milestones that were recorded before the logger was set.
	74	+	func (st StartupTrace) SetLogger(logger zerolog.Logger) {
	75	+	if st == nil \|\| !st.enabled {
	76	+	return
	77	+	}
	78	+
	79	+	st.mu.Lock()
	80	+	defer st.mu.Unlock()
	81	+
	82	+	st.logger = logger
	83	+
	84	+	// Flush buffered milestones
	85	+	for _, m := range st.buffered {
	86	+	st.emitMilestone(m)
	87	+	}
	88	+	st.buffered = nil
	89	+	}
	90	+
	91	+	// UpdateLogger updates the logger and re-emits all milestones to the new logger.
	92	+	// Call this after the session file logger is available to capture milestones in the log file.
	93	+	func (st StartupTrace) UpdateLogger(logger zerolog.Logger) {
	94	+	if st == nil \|\| !st.enabled {
	95	+	return
	96	+	}
	97	+
	98	+	st.mu.Lock()
	99	+	defer st.mu.Unlock()
	100	+
	101	+	st.logger = logger
	102	+
	103	+	// Re-emit all milestones to the new logger
	104	+	for _, m := range st.milestones {
	105	+	st.emitMilestone(m)
	106	+	}
	107	+	}
	108	+
	109	+	// Mark records a milestone with the given name.
	110	+	// Emits a debug log line showing elapsed time and delta from previous milestone.
	111	+	func (st *StartupTrace) Mark(name string) {
	112	+	if st == nil \|\| !st.enabled {
	113	+	return
	114	+	}
	115	+
	116	+	st.mu.Lock()
	117	+	defer st.mu.Unlock()
	118	+
	119	+	if st.finished {
	120	+	return
	121	+	}
	122	+
	123	+	now := time.Now()
	124	+	elapsed := now.Sub(st.t0)
	125	+
	126	+	var delta time.Duration
	127	+	if len(st.milestones) > 0 {
	128	+	delta = elapsed - st.milestones[len(st.milestones)-1].Elapsed
	129	+	}
	130	+
	131	+	m := Milestone{
	132	+	Name: name,
	133	+	Elapsed: elapsed,
	134	+	Delta: delta,
	135	+	}
	136	+	st.milestones = append(st.milestones, m)
	137	+
	138	+	if st.logger != nil {
	139	+	st.emitMilestone(m)
	140	+	} else {
	141	+	// Buffer until logger is set
	142	+	st.buffered = append(st.buffered, m)
	143	+	}
	144	+	}
	145	+
	146	+	// emitMilestone logs a single milestone. Caller must hold mutex.
	147	+	func (st *StartupTrace) emitMilestone(m Milestone) {
	148	+	if st.logger == nil {
	149	+	return
	150	+	}
	151	+
	152	+	elapsedMs := m.Elapsed.Milliseconds()
	153	+
	154	+	event := st.logger.Debug().
	155	+	Str("milestone", m.Name).
	156	+	Int64("t_ms", elapsedMs)
	157	+
	158	+	if m.Delta > 0 {
	159	+	event = event.Int64("delta_ms", m.Delta.Milliseconds())
	160	+	}
	161	+
	162	+	// Format: startup_trace: milestone_name (T+123ms, +45ms)
	163	+	if m.Delta > 0 {
	164	+	event.Msgf("startup_trace: %s (T+%dms, +%dms)", m.Name, elapsedMs, m.Delta.Milliseconds())
	165	+	} else {
	166	+	event.Msgf("startup_trace: %s (T+%dms)", m.Name, elapsedMs)
	167	+	}
	168	+	}
	169	+
	170	+	// Finish marks the startup trace as complete and emits a summary.
	171	+	// Called on first_paint milestone.
	172	+	func (st *StartupTrace) Finish() {
	173	+	if st == nil \|\| !st.enabled {
	174	+	return
	175	+	}
	176	+
	177	+	st.mu.Lock()
	178	+	defer st.mu.Unlock()
	179	+
	180	+	if st.finished {
	181	+	return
	182	+	}
	183	+	st.finished = true
	184	+
	185	+	if st.logger == nil {
	186	+	return
	187	+	}
	188	+
	189	+	// Build summary string
	190	+	total := time.Since(st.t0)
	191	+	var parts []string
	192	+	for _, m := range st.milestones {
	193	+	parts = append(parts, fmt.Sprintf("%s:%d", m.Name, m.Elapsed.Milliseconds()))
	194	+	}
	195	+	summary := strings.Join(parts, ",")
	196	+
	197	+	st.logger.Info().
	198	+	Int64("total_ms", total.Milliseconds()).
	199	+	Str("milestones", summary).
	200	+	Msg("startup_trace: cold start complete")
	201	+	}
	202	+
	203	+	// Enabled returns whether the trace is active.
	204	+	func (st *StartupTrace) Enabled() bool {
	205	+	if st == nil {
	206	+	return false
	207	+	}
	208	+	return st.enabled
	209	+	}
	210	+
	211	+	// TotalElapsed returns the total time since T0.
	212	+	func (st *StartupTrace) TotalElapsed() time.Duration {
	213	+	if st == nil \|\| !st.enabled {
	214	+	return 0
	215	+	}
	216	+
	217	+	st.mu.Lock()
	218	+	defer st.mu.Unlock()
	219	+	return time.Since(st.t0)
	220	+	}

@@ -0,0 +1,220 @@
	1	+	package logging
	2	+
	3	+	import (
	4	+	"fmt"
	5	+	"strings"
	6	+	"sync"
	7	+	"time"
	8	+
	9	+	"github.com/rs/zerolog"
	10	+	)
	11	+
	12	+	// StartupTrace tracks cold start milestones from process launch to first paint.
	13	+	// Thread-safe for use across goroutines.
	14	+	// Enabled only when log level is debug or trace.
	15	+	type StartupTrace struct {
	16	+	mu sync.Mutex
	17	+	t0 time.Time
	18	+	milestones []Milestone
	19	+	enabled bool
	20	+	logger *zerolog.Logger
	21	+	buffered []Milestone // milestones recorded before logger is set
	22	+	finished bool
	23	+	}
	24	+
	25	+	// Milestone represents a timing checkpoint during startup.
	26	+	type Milestone struct {
	27	+	Name string
	28	+	Elapsed time.Duration // time since t0
	29	+	Delta time.Duration // time since previous milestone
	30	+	}
	31	+
	32	+	var (
	33	+	globalTrace *StartupTrace
	34	+	globalTraceMu sync.Mutex
	35	+	globalTraceOnce sync.Once
	36	+	)
	37	+
	38	+	// InitStartupTrace initializes the global startup trace.
	39	+	// Call this as early as possible in main() to capture T0.
	40	+	// The trace is enabled only if the given log level is debug or trace.
	41	+	func InitStartupTrace(logLevel string) {
	42	+	globalTraceOnce.Do(func() {
	43	+	enabled := logLevel == "debug" \|\| logLevel == "trace"
	44	+	globalTraceMu.Lock()
	45	+	globalTrace = &StartupTrace{
	46	+	t0: time.Now(),
	47	+	milestones: make([]Milestone, 0, 32),
	48	+	enabled: enabled,
	49	+	buffered: make([]Milestone, 0, 8),
	50	+	}
	51	+	globalTraceMu.Unlock()
	52	+
	53	+	if enabled {
	54	+	// Record process_start as first milestone
	55	+	globalTrace.Mark("process_start")
	56	+	}
	57	+	})
	58	+	}
	59	+
	60	+	// Trace returns the global startup trace instance.
	61	+	// Returns a no-op trace if not initialized or disabled.
	62	+	func Trace() *StartupTrace {
	63	+	globalTraceMu.Lock()
	64	+	defer globalTraceMu.Unlock()
	65	+	if globalTrace == nil {
	66	+	// Return a disabled no-op trace
	67	+	return &StartupTrace{enabled: false}
	68	+	}
	69	+	return globalTrace
	70	+	}
	71	+
	72	+	// SetLogger sets the logger for emitting milestone logs.
	73	+	// Flushes any buffered milestones that were recorded before the logger was set.
	74	+	func (st StartupTrace) SetLogger(logger zerolog.Logger) {
	75	+	if st == nil \|\| !st.enabled {
	76	+	return
	77	+	}
	78	+
	79	+	st.mu.Lock()
	80	+	defer st.mu.Unlock()
	81	+
	82	+	st.logger = logger
	83	+
	84	+	// Flush buffered milestones
	85	+	for _, m := range st.buffered {
	86	+	st.emitMilestone(m)
	87	+	}
	88	+	st.buffered = nil
	89	+	}
	90	+
	91	+	// UpdateLogger updates the logger and re-emits all milestones to the new logger.
	92	+	// Call this after the session file logger is available to capture milestones in the log file.
	93	+	func (st StartupTrace) UpdateLogger(logger zerolog.Logger) {
	94	+	if st == nil \|\| !st.enabled {
	95	+	return
	96	+	}
	97	+
	98	+	st.mu.Lock()
	99	+	defer st.mu.Unlock()
	100	+
	101	+	st.logger = logger
	102	+
	103	+	// Re-emit all milestones to the new logger
	104	+	for _, m := range st.milestones {
	105	+	st.emitMilestone(m)
	106	+	}
	107	+	}
	108	+
	109	+	// Mark records a milestone with the given name.
	110	+	// Emits a debug log line showing elapsed time and delta from previous milestone.
	111	+	func (st *StartupTrace) Mark(name string) {
	112	+	if st == nil \|\| !st.enabled {
	113	+	return
	114	+	}
	115	+
	116	+	st.mu.Lock()
	117	+	defer st.mu.Unlock()
	118	+
	119	+	if st.finished {
	120	+	return
	121	+	}
	122	+
	123	+	now := time.Now()
	124	+	elapsed := now.Sub(st.t0)
	125	+
	126	+	var delta time.Duration
	127	+	if len(st.milestones) > 0 {
	128	+	delta = elapsed - st.milestones[len(st.milestones)-1].Elapsed
	129	+	}
	130	+
	131	+	m := Milestone{
	132	+	Name: name,
	133	+	Elapsed: elapsed,
	134	+	Delta: delta,
	135	+	}
	136	+	st.milestones = append(st.milestones, m)
	137	+
	138	+	if st.logger != nil {
	139	+	st.emitMilestone(m)
	140	+	} else {
	141	+	// Buffer until logger is set
	142	+	st.buffered = append(st.buffered, m)
	143	+	}
	144	+	}
	145	+
	146	+	// emitMilestone logs a single milestone. Caller must hold mutex.
	147	+	func (st *StartupTrace) emitMilestone(m Milestone) {
	148	+	if st.logger == nil {
	149	+	return
	150	+	}
	151	+
	152	+	elapsedMs := m.Elapsed.Milliseconds()
	153	+
	154	+	event := st.logger.Debug().
	155	+	Str("milestone", m.Name).
	156	+	Int64("t_ms", elapsedMs)
	157	+
	158	+	if m.Delta > 0 {
	159	+	event = event.Int64("delta_ms", m.Delta.Milliseconds())
	160	+	}
	161	+
	162	+	// Format: startup_trace: milestone_name (T+123ms, +45ms)
	163	+	if m.Delta > 0 {
	164	+	event.Msgf("startup_trace: %s (T+%dms, +%dms)", m.Name, elapsedMs, m.Delta.Milliseconds())
	165	+	} else {
	166	+	event.Msgf("startup_trace: %s (T+%dms)", m.Name, elapsedMs)
	167	+	}
	168	+	}
	169	+
	170	+	// Finish marks the startup trace as complete and emits a summary.
	171	+	// Called on first_paint milestone.
	172	+	func (st *StartupTrace) Finish() {
	173	+	if st == nil \|\| !st.enabled {
	174	+	return
	175	+	}
	176	+
	177	+	st.mu.Lock()
	178	+	defer st.mu.Unlock()
	179	+
	180	+	if st.finished {
	181	+	return
	182	+	}
	183	+	st.finished = true
	184	+
	185	+	if st.logger == nil {
	186	+	return
	187	+	}
	188	+
	189	+	// Build summary string
	190	+	total := time.Since(st.t0)
	191	+	var parts []string
	192	+	for _, m := range st.milestones {
	193	+	parts = append(parts, fmt.Sprintf("%s:%d", m.Name, m.Elapsed.Milliseconds()))
	194	+	}
	195	+	summary := strings.Join(parts, ",")
	196	+
	197	+	st.logger.Info().
	198	+	Int64("total_ms", total.Milliseconds()).
	199	+	Str("milestones", summary).
	200	+	Msg("startup_trace: cold start complete")
	201	+	}
	202	+
	203	+	// Enabled returns whether the trace is active.
	204	+	func (st *StartupTrace) Enabled() bool {
	205	+	if st == nil {
	206	+	return false
	207	+	}
	208	+	return st.enabled
	209	+	}
	210	+
	211	+	// TotalElapsed returns the total time since T0.
	212	+	func (st *StartupTrace) TotalElapsed() time.Duration {
	213	+	if st == nil \|\| !st.enabled {
	214	+	return 0
	215	+	}
	216	+
	217	+	st.mu.Lock()
	218	+	defer st.mu.Unlock()
	219	+	return time.Since(st.t0)
	220	+	}

M internal/ui/app.go +4 -0


@@ -182,6 +182,7 @@ func (a *App) Run(ctx context.Context, args []string) int {
182	182		// Initialize libadwaita once (required before using StyleManager).
183	183		// This also initializes GTK implicitly.
184	184		adw.Init()
	185	+	logging.Trace().Mark("gtk_init")
185	186
186	187		// Mark adwaita detector as available now that adw.Init() is complete.
187	188		// This enables the highest-priority color scheme detector.

@@ -203,6 +204,7 @@ func (a *App) Run(ctx context.Context, args []string) int {
203	204		return 1
204	205		}
205	206		defer a.gtkApp.Unref()
	207	+	logging.Trace().Mark("gtk_app_created")
206	208
207	209		// Connect activate signal
208	210		activateCb := func(_ gio.Application) {

@@ -236,6 +238,7 @@ func (a *App) onActivate(ctx context.Context) {
236	238		log.Error().Err(err).Msg("failed to create main window")
237	239		return
238	240		}
	241	+	logging.Trace().Mark("window_created")
239	242
240	243		a.initLayoutInfrastructure()
241	244		a.initAppToasterOverlay()

@@ -244,6 +247,7 @@ func (a *App) onActivate(ctx context.Context) {
244	247		a.initDownloadHandler(ctx)
245	248
246	249		a.initCoordinators(ctx)
	250	+	logging.Trace().Mark("coordinators_init")
247	251		a.initKeyboardHandler(ctx)
248	252		a.initOmniboxConfig(ctx)
249	253		a.initFindBarConfig()


@@ -182,6 +182,7 @@ func (a *App) Run(ctx context.Context, args []string) int {
182	// Initialize libadwaita once (required before using StyleManager).	182		// Initialize libadwaita once (required before using StyleManager).
183	// This also initializes GTK implicitly.	183		// This also initializes GTK implicitly.
184	adw.Init()	184		adw.Init()
		185	+	logging.Trace().Mark("gtk_init")
185		186
186	// Mark adwaita detector as available now that adw.Init() is complete.	187		// Mark adwaita detector as available now that adw.Init() is complete.
187	// This enables the highest-priority color scheme detector.	188		// This enables the highest-priority color scheme detector.

@@ -203,6 +204,7 @@ func (a *App) Run(ctx context.Context, args []string) int {
203	return 1	204		return 1
204	}	205		}
205	defer a.gtkApp.Unref()	206		defer a.gtkApp.Unref()
		207	+	logging.Trace().Mark("gtk_app_created")
206		208
207	// Connect activate signal	209		// Connect activate signal
208	activateCb := func(_ gio.Application) {	210		activateCb := func(_ gio.Application) {

@@ -236,6 +238,7 @@ func (a *App) onActivate(ctx context.Context) {
236	log.Error().Err(err).Msg("failed to create main window")	238		log.Error().Err(err).Msg("failed to create main window")
237	return	239		return
238	}	240		}
		241	+	logging.Trace().Mark("window_created")
239		242
240	a.initLayoutInfrastructure()	243		a.initLayoutInfrastructure()
241	a.initAppToasterOverlay()	244		a.initAppToasterOverlay()

@@ -244,6 +247,7 @@ func (a *App) onActivate(ctx context.Context) {
244	a.initDownloadHandler(ctx)	247		a.initDownloadHandler(ctx)
245		248
246	a.initCoordinators(ctx)	249		a.initCoordinators(ctx)
		250	+	logging.Trace().Mark("coordinators_init")
247	a.initKeyboardHandler(ctx)	251		a.initKeyboardHandler(ctx)
248	a.initOmniboxConfig(ctx)	252		a.initOmniboxConfig(ctx)
249	a.initFindBarConfig()	253		a.initFindBarConfig()

M internal/ui/coordinator/content.go +15 -0


@@ -188,10 +188,16 @@ func (c *ContentCoordinator) EnsureWebView(ctx context.Context, paneID entity.Pa
188	188		return nil, fmt.Errorf("webview pool not configured")
189	189		}
190	190
	191	+	// Mark tab_created on first webview (first tab)
	192	+	if len(c.webViews) == 0 {
	193	+	logging.Trace().Mark("tab_created")
	194	+	}
	195	+
191	196		wv, err := c.pool.Acquire(ctx)
192	197		if err != nil {
193	198		return nil, err
194	199		}
	200	+	logging.Trace().Mark("webview_acquired")
195	201
196	202		c.webViews[paneID] = wv
197	203

@@ -334,6 +340,7 @@ func (c ContentCoordinator) AttachToWorkspace(ctx context.Context, ws entity.W
334	340		if err := wsView.SetWebViewWidget(pane.ID, widget); err != nil {
335	341		log.Warn().Err(err).Str("pane_id", string(pane.ID)).Msg("failed to attach webview widget")
336	342		}
	343	+	logging.Trace().Mark("webview_attached")
337	344		}
338	345		}
339	346

@@ -911,6 +918,7 @@ func (c *ContentCoordinator) PreloadCachedFavicon(ctx context.Context, paneID en
911	918		// Also shows the WebView widget (it's hidden during creation to avoid white flash).
912	919		func (c ContentCoordinator) onLoadCommitted(ctx context.Context, paneID entity.PaneID, wv webkit.WebView) {
913	920		log := logging.FromContext(ctx)
	921	+	logging.Trace().Mark("load_committed")
914	922
915	923		url := wv.URI()
916	924		if url == "" {

@@ -1023,6 +1031,8 @@ func (c *ContentCoordinator) updatePaneURI(paneID entity.PaneID, url string) {
1023	1031
1024	1032		// onLoadStarted shows the progress bar when page loading begins.
1025	1033		func (c *ContentCoordinator) onLoadStarted(paneID entity.PaneID) {
	1034	+	logging.Trace().Mark("load_started")
	1035	+
1026	1036		_, wsView := c.getActiveWS()
1027	1037		if wsView == nil {
1028	1038		return

@@ -1109,6 +1119,11 @@ func (c *ContentCoordinator) revealIfPending(ctx context.Context, paneID entity.
1109	1119		Str("reason", reason).
1110	1120		Msg("webview revealed")
1111	1121		}
	1122	+
	1123	+	// Mark first_paint and finish startup trace
	1124	+	logging.Trace().Mark("first_paint")
	1125	+	logging.Trace().Finish()
	1126	+
1112	1127		if c.onWebViewShown != nil {
1113	1128		c.onWebViewShown(paneID)
1114	1129		}


@@ -188,10 +188,16 @@ func (c *ContentCoordinator) EnsureWebView(ctx context.Context, paneID entity.Pa
188	return nil, fmt.Errorf("webview pool not configured")	188		return nil, fmt.Errorf("webview pool not configured")
189	}	189		}
190		190
		191	+	// Mark tab_created on first webview (first tab)
		192	+	if len(c.webViews) == 0 {
		193	+	logging.Trace().Mark("tab_created")
		194	+	}
		195	+
191	wv, err := c.pool.Acquire(ctx)	196		wv, err := c.pool.Acquire(ctx)
192	if err != nil {	197		if err != nil {
193	return nil, err	198		return nil, err
194	}	199		}
		200	+	logging.Trace().Mark("webview_acquired")
195		201
196	c.webViews[paneID] = wv	202		c.webViews[paneID] = wv
197		203

@@ -334,6 +340,7 @@ func (c ContentCoordinator) AttachToWorkspace(ctx context.Context, ws entity.W
334	if err := wsView.SetWebViewWidget(pane.ID, widget); err != nil {	340		if err := wsView.SetWebViewWidget(pane.ID, widget); err != nil {
335	log.Warn().Err(err).Str("pane_id", string(pane.ID)).Msg("failed to attach webview widget")	341		log.Warn().Err(err).Str("pane_id", string(pane.ID)).Msg("failed to attach webview widget")
336	}	342		}
		343	+	logging.Trace().Mark("webview_attached")
337	}	344		}
338	}	345		}
339		346

@@ -911,6 +918,7 @@ func (c *ContentCoordinator) PreloadCachedFavicon(ctx context.Context, paneID en
911	// Also shows the WebView widget (it's hidden during creation to avoid white flash).	918		// Also shows the WebView widget (it's hidden during creation to avoid white flash).
912	func (c ContentCoordinator) onLoadCommitted(ctx context.Context, paneID entity.PaneID, wv webkit.WebView) {	919		func (c ContentCoordinator) onLoadCommitted(ctx context.Context, paneID entity.PaneID, wv webkit.WebView) {
913	log := logging.FromContext(ctx)	920		log := logging.FromContext(ctx)
		921	+	logging.Trace().Mark("load_committed")
914		922
915	url := wv.URI()	923		url := wv.URI()
916	if url == "" {	924		if url == "" {

@@ -1023,6 +1031,8 @@ func (c *ContentCoordinator) updatePaneURI(paneID entity.PaneID, url string) {
1023		1031
1024	// onLoadStarted shows the progress bar when page loading begins.	1032		// onLoadStarted shows the progress bar when page loading begins.
1025	func (c *ContentCoordinator) onLoadStarted(paneID entity.PaneID) {	1033		func (c *ContentCoordinator) onLoadStarted(paneID entity.PaneID) {
		1034	+	logging.Trace().Mark("load_started")
		1035	+
1026	_, wsView := c.getActiveWS()	1036		_, wsView := c.getActiveWS()
1027	if wsView == nil {	1037		if wsView == nil {
1028	return	1038		return

@@ -1109,6 +1119,11 @@ func (c *ContentCoordinator) revealIfPending(ctx context.Context, paneID entity.
1109	Str("reason", reason).	1119		Str("reason", reason).
1110	Msg("webview revealed")	1120		Msg("webview revealed")
1111	}	1121		}
		1122	+
		1123	+	// Mark first_paint and finish startup trace
		1124	+	logging.Trace().Mark("first_paint")
		1125	+	logging.Trace().Finish()
		1126	+
1112	if c.onWebViewShown != nil {	1127		if c.onWebViewShown != nil {
1113	c.onWebViewShown(paneID)	1128		c.onWebViewShown(paneID)
1114	}	1129		}