// The suggested increment frequency for PowerPC's time base register is
// 512 MHz according to Power ISA v2.07 section 6.2, so we use 16 on ppc64
// and ppc64le.
- // Tracing won't work reliably for architectures where cputicks is emulated
- // by nanotime, so the value doesn't matter for those architectures.
- traceTickDiv = 16 + 48*(goarch.Is386|goarch.IsAmd64)
+ traceTimeDiv = 16 + 48*(goarch.Is386|goarch.IsAmd64)
// Maximum number of PCs in a single stack trace.
// Since events contain only stack id rather than whole stack trace,
// we can allow quite large values here.
footerWritten bool // whether ReadTrace has emitted trace footer
shutdownSema uint32 // used to wait for ReadTrace completion
seqStart uint64 // sequence number when tracing was started
- ticksStart int64 // cputicks when tracing was started
- ticksEnd int64 // cputicks when tracing was stopped
- timeStart int64 // nanotime when tracing was started
- timeEnd int64 // nanotime when tracing was stopped
+ startTicks int64 // cputicks when tracing was started
+ endTicks int64 // cputicks when tracing was stopped
+ startNanotime int64 // nanotime when tracing was started
+ endNanotime int64 // nanotime when tracing was stopped
+ startTime traceTime // traceClockNow when tracing started
+ endTime traceTime // traceClockNow when tracing stopped
seqGC uint64 // GC start/done sequencer
reading traceBufPtr // buffer currently handed off to user
empty traceBufPtr // stack of empty buffers
// gTraceState is per-G state for the tracer.
type gTraceState struct {
- sysExitTicks int64 // cputicks when syscall has returned
- tracedSyscallEnter bool // syscall or cgo was entered while trace was enabled or StartTrace has emitted EvGoInSyscall about this goroutine
- seq uint64 // trace event sequencer
- lastP puintptr // last P emitted an event for this goroutine
+ sysExitTime traceTime // timestamp when syscall has returned
+ tracedSyscallEnter bool // syscall or cgo was entered while trace was enabled or StartTrace has emitted EvGoInSyscall about this goroutine
+ seq uint64 // trace event sequencer
+ lastP puintptr // last P emitted an event for this goroutine
}
// mTraceState is per-M state for the tracer.
// traceBufHeader is per-P tracing buffer.
type traceBufHeader struct {
- link traceBufPtr // in trace.empty/full
- lastTicks uint64 // when we wrote the last event
- pos int // next write offset in arr
- stk [traceStackSize]uintptr // scratch buffer for traceback
+ link traceBufPtr // in trace.empty/full
+ lastTime traceTime // when we wrote the last event
+ pos int // next write offset in arr
+ stk [traceStackSize]uintptr // scratch buffer for traceback
}
// traceBuf is per-P tracing buffer.
})
traceProcStart()
traceGoStart()
- // Note: ticksStart needs to be set after we emit traceEvGoInSyscall events.
+ // Note: startTicks 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.
+ // query sysExitTime after startTicks but before traceEvGoInSyscall timestamp.
// It will lead to a false conclusion that cputicks is broken.
- trace.ticksStart = cputicks()
- trace.timeStart = nanotime()
+ trace.startTime = traceClockNow()
+ trace.startTicks = cputicks()
+ trace.startNanotime = nanotime()
trace.headerWritten = false
trace.footerWritten = false
}
for {
- trace.ticksEnd = cputicks()
- trace.timeEnd = nanotime()
+ trace.endTime = traceClockNow()
+ trace.endTicks = cputicks()
+ trace.endNanotime = nanotime()
// Windows time can tick only every 15ms, wait for at least one tick.
- if trace.timeEnd != trace.timeStart {
+ if trace.endNanotime != trace.startNanotime {
break
}
osyield()
// Write footer with timer frequency.
if !trace.footerWritten {
trace.footerWritten = true
- // Use float64 because (trace.ticksEnd - trace.ticksStart) * 1e9 can overflow int64.
- freq := float64(trace.ticksEnd-trace.ticksStart) * 1e9 / float64(trace.timeEnd-trace.timeStart) / traceTickDiv
+ freq := (float64(trace.endTicks-trace.startTicks) / traceTimeDiv) / (float64(trace.endNanotime-trace.startNanotime) / 1e9)
if freq <= 0 {
throw("trace: ReadTrace got invalid frequency")
}
bufp.set(buf)
}
- // NOTE: ticks might be same after tick division, although the real cputicks is
- // linear growth.
- ticks := uint64(cputicks()) / traceTickDiv
- tickDiff := ticks - buf.lastTicks
- if tickDiff == 0 {
- ticks = buf.lastTicks + 1
- tickDiff = 1
+ ts := traceClockNow()
+ if ts <= buf.lastTime {
+ ts = buf.lastTime + 1
}
-
- buf.lastTicks = ticks
+ tsDiff := uint64(ts - buf.lastTime)
+ buf.lastTime = ts
narg := byte(len(args))
if stackID != 0 || skip >= 0 {
narg++
buf.varint(0)
lenp = &buf.arr[buf.pos-1]
}
- buf.varint(tickDiff)
+ buf.varint(tsDiff)
for _, a := range args {
buf.varint(a)
}
}
// Match the clock used in traceEventLocked
- now := cputicks()
+ now := traceClockNow()
// The "header" here is the ID of the P that was running the profiled code,
// followed by the ID of the goroutine. (For normal CPU profiling, it's
// usually the number of samples with the given stack.) Near syscalls, pp
// Note: we don't pass a tag pointer here (how should profiling tags
// interact with the execution tracer?), but if we did we'd need to be
// careful about write barriers. See the long comment in profBuf.write.
- log.write(nil, now, hdr[:], stk)
+ log.write(nil, int64(now), hdr[:], stk)
}
trace.signalLock.Store(0)
}
stackID := trace.stackTab.put(buf.stk[:nstk])
- traceEventLocked(0, nil, 0, bufp, traceEvCPUSample, stackID, 1, timestamp/traceTickDiv, ppid, goid)
+ traceEventLocked(0, nil, 0, bufp, traceEvCPUSample, stackID, 1, uint64(timestamp), ppid, goid)
}
}
}
bufp.pos = 0
// initialize the buffer for a new batch
- ticks := uint64(cputicks()) / traceTickDiv
- if ticks == bufp.lastTicks {
- ticks = bufp.lastTicks + 1
+ ts := traceClockNow()
+ if ts <= bufp.lastTime {
+ ts = bufp.lastTime + 1
}
- bufp.lastTicks = ticks
+ bufp.lastTime = ts
bufp.byte(traceEvBatch | 1<<traceArgCountShift)
bufp.varint(uint64(pid))
- bufp.varint(ticks)
+ bufp.varint(uint64(ts))
if dolock {
unlock(&trace.lock)
return
}
gp.trace.tracedSyscallEnter = false
- ts := gp.trace.sysExitTicks
- if ts != 0 && ts < trace.ticksStart {
- // There is a race between the code that initializes sysExitTicks
+ ts := gp.trace.sysExitTime
+ if ts != 0 && ts < trace.startTime {
+ // There is a race between the code that initializes sysExitTimes
// (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
+ // a new trace. The recorded sysExitTime 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
// aka right now), and assign a fresh time stamp to keep the log consistent.
ts = 0
}
- gp.trace.sysExitTicks = 0
+ gp.trace.sysExitTime = 0
gp.trace.seq++
gp.trace.lastP = gp.m.p
- traceEvent(traceEvGoSysExit, -1, gp.goid, gp.trace.seq, uint64(ts)/traceTickDiv)
+ traceEvent(traceEvGoSysExit, -1, gp.goid, gp.trace.seq, uint64(ts))
}
func traceGoSysBlock(pp *p) {
gp.trace.seq++
traceEvent(traceEvGoInSyscall, -1, gp.goid)
}
+
+// traceTime represents a timestamp for the trace.
+type traceTime uint64
+
+// traceClockNow returns a monotonic timestamp. The clock this function gets
+// the timestamp from is specific to tracing, and shouldn't be mixed with other
+// clock sources.
+func traceClockNow() traceTime {
+ return traceTime(cputicks() / traceTimeDiv)
+}