aboutsummaryrefslogtreecommitdiff
path: root/src/runtime/trace.go
diff options
context:
space:
mode:
Diffstat (limited to 'src/runtime/trace.go')
-rw-r--r--src/runtime/trace.go217
1 files changed, 152 insertions, 65 deletions
diff --git a/src/runtime/trace.go b/src/runtime/trace.go
index 805c34f483..092f941f0c 100644
--- a/src/runtime/trace.go
+++ b/src/runtime/trace.go
@@ -13,7 +13,6 @@
package runtime
import (
- "runtime/internal/atomic"
"runtime/internal/sys"
"unsafe"
)
@@ -23,25 +22,25 @@ const (
traceEvNone = 0 // unused
traceEvBatch = 1 // start of per-P batch of events [pid, timestamp]
traceEvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)]
- traceEvStack = 3 // stack [stack id, number of PCs, array of PCs]
+ traceEvStack = 3 // stack [stack id, number of PCs, array of {PC, func string ID, file string ID, line}]
traceEvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id]
traceEvProcStart = 5 // start of P [timestamp, thread id]
traceEvProcStop = 6 // stop of P [timestamp]
- traceEvGCStart = 7 // GC start [timestamp, stack id]
+ traceEvGCStart = 7 // GC start [timestamp, seq, stack id]
traceEvGCDone = 8 // GC done [timestamp]
traceEvGCScanStart = 9 // GC scan start [timestamp]
traceEvGCScanDone = 10 // GC scan done [timestamp]
traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id]
traceEvGCSweepDone = 12 // GC sweep done [timestamp]
- traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id]
- traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id]
+ traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id]
+ traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq]
traceEvGoEnd = 15 // goroutine ends [timestamp]
traceEvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack]
traceEvGoSched = 17 // goroutine calls Gosched [timestamp, stack]
traceEvGoPreempt = 18 // goroutine is preempted [timestamp, stack]
traceEvGoSleep = 19 // goroutine calls Sleep [timestamp, stack]
traceEvGoBlock = 20 // goroutine blocks [timestamp, stack]
- traceEvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, stack]
+ traceEvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, seq, stack]
traceEvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack]
traceEvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack]
traceEvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack]
@@ -49,15 +48,19 @@ const (
traceEvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack]
traceEvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack]
traceEvGoSysCall = 28 // syscall enter [timestamp, stack]
- traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id, real timestamp]
+ traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id, seq, real timestamp]
traceEvGoSysBlock = 30 // syscall blocks [timestamp]
- traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [goroutine id]
- traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id]
+ traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id]
+ traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id]
traceEvHeapAlloc = 33 // memstats.heap_live change [timestamp, heap_alloc]
traceEvNextGC = 34 // memstats.next_gc change [timestamp, next_gc]
traceEvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id]
traceEvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp]
- traceEvCount = 37
+ traceEvString = 37 // string dictionary entry [ID, length, string]
+ traceEvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id]
+ traceEvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack]
+ traceEvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp]
+ traceEvCount = 41
)
const (
@@ -104,6 +107,7 @@ var trace struct {
ticksEnd int64 // cputicks when tracing was stopped
timeStart int64 // nanotime when tracing was started
timeEnd int64 // nanotime when tracing was stopped
+ seqGC uint64 // GC start/done sequencer
reading traceBufPtr // buffer currently handed off to user
empty traceBufPtr // stack of empty buffers
fullHead traceBufPtr // queue of full buffers
@@ -111,35 +115,19 @@ var trace struct {
reader *g // goroutine that called ReadTrace, or nil
stackTab traceStackTable // maps stack traces to unique ids
+ // Dictionary for traceEvString.
+ // Currently this is used only for func/file:line info after tracing session,
+ // so we assume single-threaded access.
+ strings map[string]uint64
+ stringSeq uint64
+
bufLock mutex // protects buf
buf traceBufPtr // global trace buffer, used when running without a p
}
-var traceseq uint64 // global trace sequence number
-
-// tracestamp returns a consistent sequence number, time stamp pair
-// for use in a trace. We need to make sure that time stamp ordering
-// (assuming synchronized CPUs) and sequence ordering match.
-// To do that, we increment traceseq, grab ticks, and increment traceseq again.
-// We treat odd traceseq as a sign that another thread is in the middle
-// of the sequence and spin until it is done.
-// Not splitting stack to avoid preemption, just in case the call sites
-// that used to call xadd64 and cputicks are sensitive to that.
-//go:nosplit
-func tracestamp() (seq uint64, ts int64) {
- seq = atomic.Load64(&traceseq)
- for seq&1 != 0 || !atomic.Cas64(&traceseq, seq, seq+1) {
- seq = atomic.Load64(&traceseq)
- }
- ts = cputicks()
- atomic.Store64(&traceseq, seq+2)
- return seq >> 1, ts
-}
-
// traceBufHeader is per-P tracing buffer.
type traceBufHeader struct {
link traceBufPtr // in trace.empty/full
- lastSeq uint64 // sequence number of last event
lastTicks uint64 // when we wrote the last event
pos int // next write offset in arr
stk [traceStackSize]uintptr // scratch buffer for traceback
@@ -187,11 +175,6 @@ func StartTrace() error {
return errorString("tracing is already enabled")
}
- trace.seqStart, trace.ticksStart = tracestamp()
- trace.timeStart = nanotime()
- trace.headerWritten = false
- trace.footerWritten = false
-
// Can't set trace.enabled yet. While the world is stopped, exitsyscall could
// already emit a delayed event (see exitTicks in exitsyscall) if we set trace.enabled here.
// That would lead to an inconsistent trace:
@@ -204,12 +187,15 @@ func StartTrace() error {
for _, gp := range allgs {
status := readgstatus(gp)
if status != _Gdead {
- traceGoCreate(gp, gp.startpc)
+ traceGoCreate(gp, gp.startpc) // also resets gp.traceseq/tracelastp
}
if status == _Gwaiting {
+ // traceEvGoWaiting is implied to have seq=1.
+ gp.traceseq++
traceEvent(traceEvGoWaiting, -1, uint64(gp.goid))
}
if status == _Gsyscall {
+ gp.traceseq++
traceEvent(traceEvGoInSyscall, -1, uint64(gp.goid))
} else {
gp.sysblocktraced = false
@@ -217,6 +203,17 @@ func StartTrace() error {
}
traceProcStart()
traceGoStart()
+ // Note: ticksStart needs to be set after we emit traceEvGoInSyscall events.
+ // If we do it the other way around, it is possible that exitsyscall will
+ // query sysexitticks after ticksStart but before traceEvGoInSyscall timestamp.
+ // It will lead to a false conclusion that cputicks is broken.
+ trace.ticksStart = cputicks()
+ trace.timeStart = nanotime()
+ trace.headerWritten = false
+ trace.footerWritten = false
+ trace.strings = make(map[string]uint64)
+ trace.stringSeq = 0
+ trace.seqGC = 0
_g_.m.startingtrace = false
trace.enabled = true
@@ -272,8 +269,6 @@ func StopTrace() {
trace.enabled = false
trace.shutdown = true
- trace.stackTab.dump()
-
unlock(&trace.bufLock)
startTheWorld()
@@ -309,6 +304,7 @@ func StopTrace() {
trace.empty = buf.ptr().link
sysFree(unsafe.Pointer(buf), unsafe.Sizeof(*buf.ptr()), &memstats.other_sys)
}
+ trace.strings = nil
trace.shutdown = false
unlock(&trace.lock)
}
@@ -348,7 +344,7 @@ func ReadTrace() []byte {
trace.headerWritten = true
trace.lockOwner = nil
unlock(&trace.lock)
- return []byte("go 1.5 trace\x00\x00\x00\x00")
+ return []byte("go 1.7 trace\x00\x00\x00\x00")
}
// Wait for new data.
if trace.fullHead == 0 && !trace.shutdown {
@@ -374,12 +370,13 @@ func ReadTrace() []byte {
var data []byte
data = append(data, traceEvFrequency|0<<traceArgCountShift)
data = traceAppend(data, uint64(freq))
- data = traceAppend(data, 0)
if timers.gp != nil {
data = append(data, traceEvTimerGoroutine|0<<traceArgCountShift)
data = traceAppend(data, uint64(timers.gp.goid))
- data = traceAppend(data, 0)
}
+ // This will emit a bunch of full buffers, we will pick them up
+ // on the next iteration.
+ trace.stackTab.dump()
return data
}
// Done.
@@ -483,19 +480,14 @@ func traceEvent(ev byte, skip int, args ...uint64) {
(*bufp).set(buf)
}
- seq, ticksraw := tracestamp()
- seqDiff := seq - buf.lastSeq
- ticks := uint64(ticksraw) / traceTickDiv
+ ticks := uint64(cputicks()) / traceTickDiv
tickDiff := ticks - buf.lastTicks
if buf.pos == 0 {
buf.byte(traceEvBatch | 1<<traceArgCountShift)
buf.varint(uint64(pid))
- buf.varint(seq)
buf.varint(ticks)
- seqDiff = 0
tickDiff = 0
}
- buf.lastSeq = seq
buf.lastTicks = ticks
narg := byte(len(args))
if skip >= 0 {
@@ -514,7 +506,6 @@ func traceEvent(ev byte, skip int, args ...uint64) {
buf.varint(0)
lenp = &buf.arr[buf.pos-1]
}
- buf.varint(seqDiff)
buf.varint(tickDiff)
for _, a := range args {
buf.varint(a)
@@ -603,6 +594,29 @@ func traceFlush(buf traceBufPtr) traceBufPtr {
return buf
}
+func traceString(buf *traceBuf, s string) (uint64, *traceBuf) {
+ if s == "" {
+ return 0, buf
+ }
+ if id, ok := trace.strings[s]; ok {
+ return id, buf
+ }
+
+ trace.stringSeq++
+ id := trace.stringSeq
+ trace.strings[s] = id
+
+ size := 1 + 2*traceBytesPerNumber + len(s)
+ if len(buf.arr)-buf.pos < size {
+ buf = traceFlush(traceBufPtrOf(buf)).ptr()
+ }
+ buf.byte(traceEvString)
+ buf.varint(id)
+ buf.varint(uint64(len(s)))
+ buf.pos += copy(buf.arr[buf.pos:], s)
+ return id, buf
+}
+
// traceAppend appends v to buf in little-endian-base-128 encoding.
func traceAppend(buf []byte, v uint64) []byte {
for ; v >= 0x80; v >>= 7 {
@@ -716,23 +730,28 @@ func (tab *traceStackTable) newStack(n int) *traceStack {
// dump writes all previously cached stacks to trace buffers,
// releases all memory and resets state.
func (tab *traceStackTable) dump() {
- var tmp [(2 + traceStackSize) * traceBytesPerNumber]byte
+ frames := make(map[uintptr]traceFrame)
+ var tmp [(2 + 4*traceStackSize) * traceBytesPerNumber]byte
buf := traceFlush(0).ptr()
for _, stk := range tab.tab {
stk := stk.ptr()
for ; stk != nil; stk = stk.link.ptr() {
- maxSize := 1 + (3+stk.n)*traceBytesPerNumber
- if len(buf.arr)-buf.pos < maxSize {
- buf = traceFlush(traceBufPtrOf(buf)).ptr()
- }
- // Form the event in the temp buffer, we need to know the actual length.
tmpbuf := tmp[:0]
tmpbuf = traceAppend(tmpbuf, uint64(stk.id))
tmpbuf = traceAppend(tmpbuf, uint64(stk.n))
for _, pc := range stk.stack() {
+ var frame traceFrame
+ frame, buf = traceFrameForPC(buf, frames, pc)
tmpbuf = traceAppend(tmpbuf, uint64(pc))
+ tmpbuf = traceAppend(tmpbuf, uint64(frame.funcID))
+ tmpbuf = traceAppend(tmpbuf, uint64(frame.fileID))
+ tmpbuf = traceAppend(tmpbuf, uint64(frame.line))
}
// Now copy to the buffer.
+ size := 1 + traceBytesPerNumber + len(tmpbuf)
+ if len(buf.arr)-buf.pos < size {
+ buf = traceFlush(traceBufPtrOf(buf)).ptr()
+ }
buf.byte(traceEvStack | 3<<traceArgCountShift)
buf.varint(uint64(len(tmpbuf)))
buf.pos += copy(buf.arr[buf.pos:], tmpbuf)
@@ -747,6 +766,39 @@ func (tab *traceStackTable) dump() {
*tab = traceStackTable{}
}
+type traceFrame struct {
+ funcID uint64
+ fileID uint64
+ line uint64
+}
+
+func traceFrameForPC(buf *traceBuf, frames map[uintptr]traceFrame, pc uintptr) (traceFrame, *traceBuf) {
+ if frame, ok := frames[pc]; ok {
+ return frame, buf
+ }
+
+ var frame traceFrame
+ f := findfunc(pc)
+ if f == nil {
+ frames[pc] = frame
+ return frame, buf
+ }
+
+ fn := funcname(f)
+ const maxLen = 1 << 10
+ if len(fn) > maxLen {
+ fn = fn[len(fn)-maxLen:]
+ }
+ frame.funcID, buf = traceString(buf, fn)
+ file, line := funcline(f, pc-sys.PCQuantum)
+ frame.line = uint64(line)
+ if len(file) > maxLen {
+ file = file[len(file)-maxLen:]
+ }
+ frame.fileID, buf = traceString(buf, file)
+ return frame, buf
+}
+
// traceAlloc is a non-thread-safe region allocator.
// It holds a linked list of traceAllocBlock.
type traceAlloc struct {
@@ -820,7 +872,8 @@ func traceProcStop(pp *p) {
}
func traceGCStart() {
- traceEvent(traceEvGCStart, 3)
+ traceEvent(traceEvGCStart, 3, trace.seqGC)
+ trace.seqGC++
}
func traceGCDone() {
@@ -844,11 +897,23 @@ func traceGCSweepDone() {
}
func traceGoCreate(newg *g, pc uintptr) {
- traceEvent(traceEvGoCreate, 2, uint64(newg.goid), uint64(pc))
+ newg.traceseq = 0
+ newg.tracelastp = getg().m.p
+ // +PCQuantum because traceFrameForPC expects return PCs and subtracts PCQuantum.
+ id := trace.stackTab.put([]uintptr{pc + sys.PCQuantum})
+ traceEvent(traceEvGoCreate, 2, uint64(newg.goid), uint64(id))
}
func traceGoStart() {
- traceEvent(traceEvGoStart, -1, uint64(getg().m.curg.goid))
+ _g_ := getg().m.curg
+ _p_ := _g_.m.p
+ _g_.traceseq++
+ if _g_.tracelastp == _p_ {
+ traceEvent(traceEvGoStartLocal, -1, uint64(_g_.goid))
+ } else {
+ _g_.tracelastp = _p_
+ traceEvent(traceEvGoStart, -1, uint64(_g_.goid), _g_.traceseq)
+ }
}
func traceGoEnd() {
@@ -856,10 +921,14 @@ func traceGoEnd() {
}
func traceGoSched() {
+ _g_ := getg()
+ _g_.tracelastp = _g_.m.p
traceEvent(traceEvGoSched, 1)
}
func traceGoPreempt() {
+ _g_ := getg()
+ _g_.tracelastp = _g_.m.p
traceEvent(traceEvGoPreempt, 1)
}
@@ -871,19 +940,37 @@ func traceGoPark(traceEv byte, skip int, gp *g) {
}
func traceGoUnpark(gp *g, skip int) {
- traceEvent(traceEvGoUnblock, skip, uint64(gp.goid))
+ _p_ := getg().m.p
+ gp.traceseq++
+ if gp.tracelastp == _p_ {
+ traceEvent(traceEvGoUnblockLocal, skip, uint64(gp.goid))
+ } else {
+ gp.tracelastp = _p_
+ traceEvent(traceEvGoUnblock, skip, uint64(gp.goid), gp.traceseq)
+ }
}
func traceGoSysCall() {
traceEvent(traceEvGoSysCall, 1)
}
-func traceGoSysExit(seq uint64, ts int64) {
- if int64(seq)-int64(trace.seqStart) < 0 {
- // The timestamp was obtained during a previous tracing session, ignore.
- return
+func traceGoSysExit(ts int64) {
+ if ts != 0 && ts < trace.ticksStart {
+ // There is a race between the code that initializes sysexitticks
+ // (in exitsyscall, which runs without a P, and therefore is not
+ // stopped with the rest of the world) and the code that initializes
+ // a new trace. The recorded sysexitticks must therefore be treated
+ // as "best effort". If they are valid for this trace, then great,
+ // use them for greater accuracy. But if they're not valid for this
+ // trace, assume that the trace was started after the actual syscall
+ // exit (but before we actually managed to start the goroutine,
+ // aka right now), and assign a fresh time stamp to keep the log consistent.
+ ts = 0
}
- traceEvent(traceEvGoSysExit, -1, uint64(getg().m.curg.goid), seq, uint64(ts)/traceTickDiv)
+ _g_ := getg().m.curg
+ _g_.traceseq++
+ _g_.tracelastp = _g_.m.p
+ traceEvent(traceEvGoSysExit, -1, uint64(_g_.goid), _g_.traceseq, uint64(ts)/traceTickDiv)
}
func traceGoSysBlock(pp *p) {
generated by cgit v1.3 (git 2.53.0) at 2026-04-16 02:18:01 +0000