Source file
src/runtime/tracecpu.go
1 // Copyright 2023 The Go Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style
3 // license that can be found in the LICENSE file.
4
5 // CPU profile -> trace
6
7 package runtime
8
9 import "internal/trace/tracev2"
10
11 // traceInitReadCPU initializes CPU profile -> tracer state for tracing.
12 //
13 // Returns a profBuf for reading from.
14 func traceInitReadCPU() {
15 if traceEnabled() {
16 throw("traceInitReadCPU called with trace enabled")
17 }
18 // Create new profBuf for CPU samples that will be emitted as events.
19 // Format: after the timestamp, header is [pp.id, gp.goid, mp.procid].
20 trace.cpuLogRead[0] = newProfBuf(3, profBufWordCount, profBufTagCount)
21 trace.cpuLogRead[1] = newProfBuf(3, profBufWordCount, profBufTagCount)
22 // We must not acquire trace.signalLock outside of a signal handler: a
23 // profiling signal may arrive at any time and try to acquire it, leading to
24 // deadlock. Because we can't use that lock to protect updates to
25 // trace.cpuLogWrite (only use of the structure it references), reads and
26 // writes of the pointer must be atomic. (And although this field is never
27 // the sole pointer to the profBuf value, it's best to allow a write barrier
28 // here.)
29 trace.cpuLogWrite[0].Store(trace.cpuLogRead[0])
30 trace.cpuLogWrite[1].Store(trace.cpuLogRead[1])
31 }
32
33 // traceStartReadCPU creates a goroutine to start reading CPU profile
34 // data into an active trace.
35 //
36 // traceAdvanceSema must be held.
37 func traceStartReadCPU() {
38 if !traceEnabled() {
39 throw("traceStartReadCPU called with trace disabled")
40 }
41 // Spin up the logger goroutine.
42 trace.cpuSleep = newWakeableSleep()
43 done := make(chan struct{}, 1)
44 go func() {
45 for traceEnabled() {
46 // Sleep here because traceReadCPU is non-blocking. This mirrors
47 // how the runtime/pprof package obtains CPU profile data.
48 //
49 // We can't do a blocking read here because Darwin can't do a
50 // wakeup from a signal handler, so all CPU profiling is just
51 // non-blocking. See #61768 for more details.
52 //
53 // Like the runtime/pprof package, even if that bug didn't exist
54 // we would still want to do a goroutine-level sleep in between
55 // reads to avoid frequent wakeups.
56 trace.cpuSleep.sleep(100_000_000)
57
58 tl := traceAcquire()
59 if !tl.ok() {
60 // Tracing disabled.
61 break
62 }
63 keepGoing := traceReadCPU(tl.gen)
64 traceRelease(tl)
65 if !keepGoing {
66 break
67 }
68 }
69 done <- struct{}{}
70 }()
71 trace.cpuLogDone = done
72 }
73
74 // traceStopReadCPU blocks until the trace CPU reading goroutine exits.
75 //
76 // traceAdvanceSema must be held, and tracing must be disabled.
77 func traceStopReadCPU() {
78 if traceEnabled() {
79 throw("traceStopReadCPU called with trace enabled")
80 }
81
82 // Once we close the profbuf, we'll be in one of two situations:
83 // - The logger goroutine has already exited because it observed
84 // that the trace is disabled.
85 // - The logger goroutine is asleep.
86 //
87 // Wake the goroutine so it can observe that their the buffer is
88 // closed an exit.
89 trace.cpuLogWrite[0].Store(nil)
90 trace.cpuLogWrite[1].Store(nil)
91 trace.cpuLogRead[0].close()
92 trace.cpuLogRead[1].close()
93 trace.cpuSleep.wake()
94
95 // Wait until the logger goroutine exits.
96 <-trace.cpuLogDone
97
98 // Clear state for the next trace.
99 trace.cpuLogDone = nil
100 trace.cpuLogRead[0] = nil
101 trace.cpuLogRead[1] = nil
102 trace.cpuSleep.close()
103 }
104
105 // traceReadCPU attempts to read from the provided profBuf[gen%2] and write
106 // into the trace. Returns true if there might be more to read or false
107 // if the profBuf is closed or the caller should otherwise stop reading.
108 //
109 // The caller is responsible for ensuring that gen does not change. Either
110 // the caller must be in a traceAcquire/traceRelease block, or must be calling
111 // with traceAdvanceSema held.
112 //
113 // No more than one goroutine may be in traceReadCPU for the same
114 // profBuf at a time.
115 //
116 // Must not run on the system stack because profBuf.read performs race
117 // operations.
118 func traceReadCPU(gen uintptr) bool {
119 var pcBuf [tracev2.MaxFramesPerStack]uintptr
120
121 data, tags, eof := trace.cpuLogRead[gen%2].read(profBufNonBlocking)
122 for len(data) > 0 {
123 if len(data) < 4 || data[0] > uint64(len(data)) {
124 break // truncated profile
125 }
126 if data[0] < 4 || tags != nil && len(tags) < 1 {
127 break // malformed profile
128 }
129 if len(tags) < 1 {
130 break // mismatched profile records and tags
131 }
132
133 // Deserialize the data in the profile buffer.
134 recordLen := data[0]
135 timestamp := data[1]
136 ppid := data[2] >> 1
137 if hasP := (data[2] & 0b1) != 0; !hasP {
138 ppid = ^uint64(0)
139 }
140 goid := data[3]
141 mpid := data[4]
142 stk := data[5:recordLen]
143
144 // Overflow records always have their headers contain
145 // all zeroes.
146 isOverflowRecord := len(stk) == 1 && data[2] == 0 && data[3] == 0 && data[4] == 0
147
148 // Move the data iterator forward.
149 data = data[recordLen:]
150 // No support here for reporting goroutine tags at the moment; if
151 // that information is to be part of the execution trace, we'd
152 // probably want to see when the tags are applied and when they
153 // change, instead of only seeing them when we get a CPU sample.
154 tags = tags[1:]
155
156 if isOverflowRecord {
157 // Looks like an overflow record from the profBuf. Not much to
158 // do here, we only want to report full records.
159 continue
160 }
161
162 // Construct the stack for insertion to the stack table.
163 nstk := 1
164 pcBuf[0] = logicalStackSentinel
165 for ; nstk < len(pcBuf) && nstk-1 < len(stk); nstk++ {
166 pcBuf[nstk] = uintptr(stk[nstk-1])
167 }
168
169 // Write out a trace event.
170 w := unsafeTraceWriter(gen, trace.cpuBuf[gen%2])
171
172 // Ensure we have a place to write to.
173 var flushed bool
174 w, flushed = w.ensure(2 + 5*traceBytesPerNumber /* tracev2.EvCPUSamples + tracev2.EvCPUSample + timestamp + g + m + p + stack ID */)
175 if flushed {
176 // Annotate the batch as containing strings.
177 w.byte(byte(tracev2.EvCPUSamples))
178 }
179
180 // Add the stack to the table.
181 stackID := trace.stackTab[gen%2].put(pcBuf[:nstk])
182
183 // Write out the CPU sample.
184 w.byte(byte(tracev2.EvCPUSample))
185 w.varint(timestamp)
186 w.varint(mpid)
187 w.varint(ppid)
188 w.varint(goid)
189 w.varint(stackID)
190
191 trace.cpuBuf[gen%2] = w.traceBuf
192 }
193 return !eof
194 }
195
196 // traceCPUFlush flushes trace.cpuBuf[gen%2]. The caller must be certain that gen
197 // has completed and that there are no more writers to it.
198 func traceCPUFlush(gen uintptr) {
199 // Flush any remaining trace buffers containing CPU samples.
200 if buf := trace.cpuBuf[gen%2]; buf != nil {
201 systemstack(func() {
202 lock(&trace.lock)
203 traceBufFlush(buf, gen)
204 unlock(&trace.lock)
205 trace.cpuBuf[gen%2] = nil
206 })
207 }
208 }
209
210 // traceCPUSample writes a CPU profile sample stack to the execution tracer's
211 // profiling buffer. It is called from a signal handler, so is limited in what
212 // it can do. mp must be the thread that is currently stopped in a signal.
213 func traceCPUSample(gp *g, mp *m, pp *p, stk []uintptr) {
214 if !traceEnabled() {
215 // Tracing is usually turned off; don't spend time acquiring the signal
216 // lock unless it's active.
217 return
218 }
219 if mp == nil {
220 // Drop samples that don't have an identifiable thread. We can't render
221 // this in any useful way anyway.
222 return
223 }
224
225 // We're going to conditionally write to one of two buffers based on the
226 // generation. To make sure we write to the correct one, we need to make
227 // sure this thread's trace write flag is set. If it already is, then we're
228 // in the tracer and we can just take advantage of that. If it isn't, then
229 // we need to acquire it and read the generation.
230 locked := false
231 if !mp.trace.writing.Load() {
232 mp.trace.writing.Store(true)
233 locked = true
234 }
235 gen := trace.gen.Load()
236 if gen == 0 {
237 // Tracing is disabled, as it turns out. Clear the write flag if necessary
238 // and exit.
239 if locked {
240 mp.trace.writing.Store(false)
241 }
242 return
243 }
244
245 now := traceClockNow()
246 // The "header" here is the ID of the M that was running the profiled code,
247 // followed by the IDs of the P and goroutine. (For normal CPU profiling, it's
248 // usually the number of samples with the given stack.) Near syscalls, pp
249 // may be nil. Reporting goid of 0 is fine for either g0 or a nil gp.
250 var hdr [3]uint64
251 if pp != nil {
252 // Overflow records in profBuf have all header values set to zero. Make
253 // sure that real headers have at least one bit set.
254 hdr[0] = uint64(pp.id)<<1 | 0b1
255 } else {
256 hdr[0] = 0b10
257 }
258 if gp != nil {
259 hdr[1] = gp.goid
260 }
261 hdr[2] = mp.procid
262
263 // Allow only one writer at a time
264 for !trace.signalLock.CompareAndSwap(0, 1) {
265 // TODO: Is it safe to osyield here? https://go.dev/issue/52672
266 osyield()
267 }
268
269 if log := trace.cpuLogWrite[gen%2].Load(); log != nil {
270 // Note: we don't pass a tag pointer here (how should profiling tags
271 // interact with the execution tracer?), but if we did we'd need to be
272 // careful about write barriers. See the long comment in profBuf.write.
273 log.write(nil, int64(now), hdr[:], stk)
274 }
275
276 trace.signalLock.Store(0)
277
278 // Clear the write flag if we set it earlier.
279 if locked {
280 mp.trace.writing.Store(false)
281 }
282 }
283
View as plain text