1package logging
2
3import (
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.
15type 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.
26type Milestone struct {
27 Name string
28 Elapsed time.Duration // time since t0
29 Delta time.Duration // time since previous milestone
30}
31
32var (
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.
41func 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.
62func 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.
74func (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.
93func (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.
111func (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.
147func (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.
172func (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.
204func (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.
212func (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}