summaryrefslogtreecommitdiffstats
path: root/src/runtime/debuglog.go
diff options
context:
space:
mode:
Diffstat (limited to '')
-rw-r--r--src/runtime/debuglog.go825
1 files changed, 825 insertions, 0 deletions
diff --git a/src/runtime/debuglog.go b/src/runtime/debuglog.go
new file mode 100644
index 0000000..ca1a791
--- /dev/null
+++ b/src/runtime/debuglog.go
@@ -0,0 +1,825 @@
+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// This file provides an internal debug logging facility. The debug
+// log is a lightweight, in-memory, per-M ring buffer. By default, the
+// runtime prints the debug log on panic.
+//
+// To print something to the debug log, call dlog to obtain a dlogger
+// and use the methods on that to add values. The values will be
+// space-separated in the output (much like println).
+//
+// This facility can be enabled by passing -tags debuglog when
+// building. Without this tag, dlog calls compile to nothing.
+
+package runtime
+
+import (
+ "runtime/internal/atomic"
+ "unsafe"
+)
+
+// debugLogBytes is the size of each per-M ring buffer. This is
+// allocated off-heap to avoid blowing up the M and hence the GC'd
+// heap size.
+const debugLogBytes = 16 << 10
+
+// debugLogStringLimit is the maximum number of bytes in a string.
+// Above this, the string will be truncated with "..(n more bytes).."
+const debugLogStringLimit = debugLogBytes / 8
+
+// dlog returns a debug logger. The caller can use methods on the
+// returned logger to add values, which will be space-separated in the
+// final output, much like println. The caller must call end() to
+// finish the message.
+//
+// dlog can be used from highly-constrained corners of the runtime: it
+// is safe to use in the signal handler, from within the write
+// barrier, from within the stack implementation, and in places that
+// must be recursively nosplit.
+//
+// This will be compiled away if built without the debuglog build tag.
+// However, argument construction may not be. If any of the arguments
+// are not literals or trivial expressions, consider protecting the
+// call with "if dlogEnabled".
+//
+//go:nosplit
+//go:nowritebarrierrec
+func dlog() *dlogger {
+ if !dlogEnabled {
+ return nil
+ }
+
+ // Get the time.
+ tick, nano := uint64(cputicks()), uint64(nanotime())
+
+ // Try to get a cached logger.
+ l := getCachedDlogger()
+
+ // If we couldn't get a cached logger, try to get one from the
+ // global pool.
+ if l == nil {
+ allp := (*uintptr)(unsafe.Pointer(&allDloggers))
+ all := (*dlogger)(unsafe.Pointer(atomic.Loaduintptr(allp)))
+ for l1 := all; l1 != nil; l1 = l1.allLink {
+ if atomic.Load(&l1.owned) == 0 && atomic.Cas(&l1.owned, 0, 1) {
+ l = l1
+ break
+ }
+ }
+ }
+
+ // If that failed, allocate a new logger.
+ if l == nil {
+ // Use sysAllocOS instead of sysAlloc because we want to interfere
+ // with the runtime as little as possible, and sysAlloc updates accounting.
+ l = (*dlogger)(sysAllocOS(unsafe.Sizeof(dlogger{})))
+ if l == nil {
+ throw("failed to allocate debug log")
+ }
+ l.w.r.data = &l.w.data
+ l.owned = 1
+
+ // Prepend to allDloggers list.
+ headp := (*uintptr)(unsafe.Pointer(&allDloggers))
+ for {
+ head := atomic.Loaduintptr(headp)
+ l.allLink = (*dlogger)(unsafe.Pointer(head))
+ if atomic.Casuintptr(headp, head, uintptr(unsafe.Pointer(l))) {
+ break
+ }
+ }
+ }
+
+ // If the time delta is getting too high, write a new sync
+ // packet. We set the limit so we don't write more than 6
+ // bytes of delta in the record header.
+ const deltaLimit = 1<<(3*7) - 1 // ~2ms between sync packets
+ if tick-l.w.tick > deltaLimit || nano-l.w.nano > deltaLimit {
+ l.w.writeSync(tick, nano)
+ }
+
+ // Reserve space for framing header.
+ l.w.ensure(debugLogHeaderSize)
+ l.w.write += debugLogHeaderSize
+
+ // Write record header.
+ l.w.uvarint(tick - l.w.tick)
+ l.w.uvarint(nano - l.w.nano)
+ gp := getg()
+ if gp != nil && gp.m != nil && gp.m.p != 0 {
+ l.w.varint(int64(gp.m.p.ptr().id))
+ } else {
+ l.w.varint(-1)
+ }
+
+ return l
+}
+
+// A dlogger writes to the debug log.
+//
+// To obtain a dlogger, call dlog(). When done with the dlogger, call
+// end().
+//
+//go:notinheap
+type dlogger struct {
+ w debugLogWriter
+
+ // allLink is the next dlogger in the allDloggers list.
+ allLink *dlogger
+
+ // owned indicates that this dlogger is owned by an M. This is
+ // accessed atomically.
+ owned uint32
+}
+
+// allDloggers is a list of all dloggers, linked through
+// dlogger.allLink. This is accessed atomically. This is prepend only,
+// so it doesn't need to protect against ABA races.
+var allDloggers *dlogger
+
+//go:nosplit
+func (l *dlogger) end() {
+ if !dlogEnabled {
+ return
+ }
+
+ // Fill in framing header.
+ size := l.w.write - l.w.r.end
+ if !l.w.writeFrameAt(l.w.r.end, size) {
+ throw("record too large")
+ }
+
+ // Commit the record.
+ l.w.r.end = l.w.write
+
+ // Attempt to return this logger to the cache.
+ if putCachedDlogger(l) {
+ return
+ }
+
+ // Return the logger to the global pool.
+ atomic.Store(&l.owned, 0)
+}
+
+const (
+ debugLogUnknown = 1 + iota
+ debugLogBoolTrue
+ debugLogBoolFalse
+ debugLogInt
+ debugLogUint
+ debugLogHex
+ debugLogPtr
+ debugLogString
+ debugLogConstString
+ debugLogStringOverflow
+
+ debugLogPC
+ debugLogTraceback
+)
+
+//go:nosplit
+func (l *dlogger) b(x bool) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ if x {
+ l.w.byte(debugLogBoolTrue)
+ } else {
+ l.w.byte(debugLogBoolFalse)
+ }
+ return l
+}
+
+//go:nosplit
+func (l *dlogger) i(x int) *dlogger {
+ return l.i64(int64(x))
+}
+
+//go:nosplit
+func (l *dlogger) i8(x int8) *dlogger {
+ return l.i64(int64(x))
+}
+
+//go:nosplit
+func (l *dlogger) i16(x int16) *dlogger {
+ return l.i64(int64(x))
+}
+
+//go:nosplit
+func (l *dlogger) i32(x int32) *dlogger {
+ return l.i64(int64(x))
+}
+
+//go:nosplit
+func (l *dlogger) i64(x int64) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ l.w.byte(debugLogInt)
+ l.w.varint(x)
+ return l
+}
+
+//go:nosplit
+func (l *dlogger) u(x uint) *dlogger {
+ return l.u64(uint64(x))
+}
+
+//go:nosplit
+func (l *dlogger) uptr(x uintptr) *dlogger {
+ return l.u64(uint64(x))
+}
+
+//go:nosplit
+func (l *dlogger) u8(x uint8) *dlogger {
+ return l.u64(uint64(x))
+}
+
+//go:nosplit
+func (l *dlogger) u16(x uint16) *dlogger {
+ return l.u64(uint64(x))
+}
+
+//go:nosplit
+func (l *dlogger) u32(x uint32) *dlogger {
+ return l.u64(uint64(x))
+}
+
+//go:nosplit
+func (l *dlogger) u64(x uint64) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ l.w.byte(debugLogUint)
+ l.w.uvarint(x)
+ return l
+}
+
+//go:nosplit
+func (l *dlogger) hex(x uint64) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ l.w.byte(debugLogHex)
+ l.w.uvarint(x)
+ return l
+}
+
+//go:nosplit
+func (l *dlogger) p(x any) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ l.w.byte(debugLogPtr)
+ if x == nil {
+ l.w.uvarint(0)
+ } else {
+ v := efaceOf(&x)
+ switch v._type.kind & kindMask {
+ case kindChan, kindFunc, kindMap, kindPtr, kindUnsafePointer:
+ l.w.uvarint(uint64(uintptr(v.data)))
+ default:
+ throw("not a pointer type")
+ }
+ }
+ return l
+}
+
+//go:nosplit
+func (l *dlogger) s(x string) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ str := stringStructOf(&x)
+ datap := &firstmoduledata
+ if len(x) > 4 && datap.etext <= uintptr(str.str) && uintptr(str.str) < datap.end {
+ // String constants are in the rodata section, which
+ // isn't recorded in moduledata. But it has to be
+ // somewhere between etext and end.
+ l.w.byte(debugLogConstString)
+ l.w.uvarint(uint64(str.len))
+ l.w.uvarint(uint64(uintptr(str.str) - datap.etext))
+ } else {
+ l.w.byte(debugLogString)
+ var b []byte
+ bb := (*slice)(unsafe.Pointer(&b))
+ bb.array = str.str
+ bb.len, bb.cap = str.len, str.len
+ if len(b) > debugLogStringLimit {
+ b = b[:debugLogStringLimit]
+ }
+ l.w.uvarint(uint64(len(b)))
+ l.w.bytes(b)
+ if len(b) != len(x) {
+ l.w.byte(debugLogStringOverflow)
+ l.w.uvarint(uint64(len(x) - len(b)))
+ }
+ }
+ return l
+}
+
+//go:nosplit
+func (l *dlogger) pc(x uintptr) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ l.w.byte(debugLogPC)
+ l.w.uvarint(uint64(x))
+ return l
+}
+
+//go:nosplit
+func (l *dlogger) traceback(x []uintptr) *dlogger {
+ if !dlogEnabled {
+ return l
+ }
+ l.w.byte(debugLogTraceback)
+ l.w.uvarint(uint64(len(x)))
+ for _, pc := range x {
+ l.w.uvarint(uint64(pc))
+ }
+ return l
+}
+
+// A debugLogWriter is a ring buffer of binary debug log records.
+//
+// A log record consists of a 2-byte framing header and a sequence of
+// fields. The framing header gives the size of the record as a little
+// endian 16-bit value. Each field starts with a byte indicating its
+// type, followed by type-specific data. If the size in the framing
+// header is 0, it's a sync record consisting of two little endian
+// 64-bit values giving a new time base.
+//
+// Because this is a ring buffer, new records will eventually
+// overwrite old records. Hence, it maintains a reader that consumes
+// the log as it gets overwritten. That reader state is where an
+// actual log reader would start.
+//
+//go:notinheap
+type debugLogWriter struct {
+ write uint64
+ data debugLogBuf
+
+ // tick and nano are the time bases from the most recently
+ // written sync record.
+ tick, nano uint64
+
+ // r is a reader that consumes records as they get overwritten
+ // by the writer. It also acts as the initial reader state
+ // when printing the log.
+ r debugLogReader
+
+ // buf is a scratch buffer for encoding. This is here to
+ // reduce stack usage.
+ buf [10]byte
+}
+
+//go:notinheap
+type debugLogBuf [debugLogBytes]byte
+
+const (
+ // debugLogHeaderSize is the number of bytes in the framing
+ // header of every dlog record.
+ debugLogHeaderSize = 2
+
+ // debugLogSyncSize is the number of bytes in a sync record.
+ debugLogSyncSize = debugLogHeaderSize + 2*8
+)
+
+//go:nosplit
+func (l *debugLogWriter) ensure(n uint64) {
+ for l.write+n >= l.r.begin+uint64(len(l.data)) {
+ // Consume record at begin.
+ if l.r.skip() == ^uint64(0) {
+ // Wrapped around within a record.
+ //
+ // TODO(austin): It would be better to just
+ // eat the whole buffer at this point, but we
+ // have to communicate that to the reader
+ // somehow.
+ throw("record wrapped around")
+ }
+ }
+}
+
+//go:nosplit
+func (l *debugLogWriter) writeFrameAt(pos, size uint64) bool {
+ l.data[pos%uint64(len(l.data))] = uint8(size)
+ l.data[(pos+1)%uint64(len(l.data))] = uint8(size >> 8)
+ return size <= 0xFFFF
+}
+
+//go:nosplit
+func (l *debugLogWriter) writeSync(tick, nano uint64) {
+ l.tick, l.nano = tick, nano
+ l.ensure(debugLogHeaderSize)
+ l.writeFrameAt(l.write, 0)
+ l.write += debugLogHeaderSize
+ l.writeUint64LE(tick)
+ l.writeUint64LE(nano)
+ l.r.end = l.write
+}
+
+//go:nosplit
+func (l *debugLogWriter) writeUint64LE(x uint64) {
+ var b [8]byte
+ b[0] = byte(x)
+ b[1] = byte(x >> 8)
+ b[2] = byte(x >> 16)
+ b[3] = byte(x >> 24)
+ b[4] = byte(x >> 32)
+ b[5] = byte(x >> 40)
+ b[6] = byte(x >> 48)
+ b[7] = byte(x >> 56)
+ l.bytes(b[:])
+}
+
+//go:nosplit
+func (l *debugLogWriter) byte(x byte) {
+ l.ensure(1)
+ pos := l.write
+ l.write++
+ l.data[pos%uint64(len(l.data))] = x
+}
+
+//go:nosplit
+func (l *debugLogWriter) bytes(x []byte) {
+ l.ensure(uint64(len(x)))
+ pos := l.write
+ l.write += uint64(len(x))
+ for len(x) > 0 {
+ n := copy(l.data[pos%uint64(len(l.data)):], x)
+ pos += uint64(n)
+ x = x[n:]
+ }
+}
+
+//go:nosplit
+func (l *debugLogWriter) varint(x int64) {
+ var u uint64
+ if x < 0 {
+ u = (^uint64(x) << 1) | 1 // complement i, bit 0 is 1
+ } else {
+ u = (uint64(x) << 1) // do not complement i, bit 0 is 0
+ }
+ l.uvarint(u)
+}
+
+//go:nosplit
+func (l *debugLogWriter) uvarint(u uint64) {
+ i := 0
+ for u >= 0x80 {
+ l.buf[i] = byte(u) | 0x80
+ u >>= 7
+ i++
+ }
+ l.buf[i] = byte(u)
+ i++
+ l.bytes(l.buf[:i])
+}
+
+type debugLogReader struct {
+ data *debugLogBuf
+
+ // begin and end are the positions in the log of the beginning
+ // and end of the log data, modulo len(data).
+ begin, end uint64
+
+ // tick and nano are the current time base at begin.
+ tick, nano uint64
+}
+
+//go:nosplit
+func (r *debugLogReader) skip() uint64 {
+ // Read size at pos.
+ if r.begin+debugLogHeaderSize > r.end {
+ return ^uint64(0)
+ }
+ size := uint64(r.readUint16LEAt(r.begin))
+ if size == 0 {
+ // Sync packet.
+ r.tick = r.readUint64LEAt(r.begin + debugLogHeaderSize)
+ r.nano = r.readUint64LEAt(r.begin + debugLogHeaderSize + 8)
+ size = debugLogSyncSize
+ }
+ if r.begin+size > r.end {
+ return ^uint64(0)
+ }
+ r.begin += size
+ return size
+}
+
+//go:nosplit
+func (r *debugLogReader) readUint16LEAt(pos uint64) uint16 {
+ return uint16(r.data[pos%uint64(len(r.data))]) |
+ uint16(r.data[(pos+1)%uint64(len(r.data))])<<8
+}
+
+//go:nosplit
+func (r *debugLogReader) readUint64LEAt(pos uint64) uint64 {
+ var b [8]byte
+ for i := range b {
+ b[i] = r.data[pos%uint64(len(r.data))]
+ pos++
+ }
+ return uint64(b[0]) | uint64(b[1])<<8 |
+ uint64(b[2])<<16 | uint64(b[3])<<24 |
+ uint64(b[4])<<32 | uint64(b[5])<<40 |
+ uint64(b[6])<<48 | uint64(b[7])<<56
+}
+
+func (r *debugLogReader) peek() (tick uint64) {
+ // Consume any sync records.
+ size := uint64(0)
+ for size == 0 {
+ if r.begin+debugLogHeaderSize > r.end {
+ return ^uint64(0)
+ }
+ size = uint64(r.readUint16LEAt(r.begin))
+ if size != 0 {
+ break
+ }
+ if r.begin+debugLogSyncSize > r.end {
+ return ^uint64(0)
+ }
+ // Sync packet.
+ r.tick = r.readUint64LEAt(r.begin + debugLogHeaderSize)
+ r.nano = r.readUint64LEAt(r.begin + debugLogHeaderSize + 8)
+ r.begin += debugLogSyncSize
+ }
+
+ // Peek tick delta.
+ if r.begin+size > r.end {
+ return ^uint64(0)
+ }
+ pos := r.begin + debugLogHeaderSize
+ var u uint64
+ for i := uint(0); ; i += 7 {
+ b := r.data[pos%uint64(len(r.data))]
+ pos++
+ u |= uint64(b&^0x80) << i
+ if b&0x80 == 0 {
+ break
+ }
+ }
+ if pos > r.begin+size {
+ return ^uint64(0)
+ }
+ return r.tick + u
+}
+
+func (r *debugLogReader) header() (end, tick, nano uint64, p int) {
+ // Read size. We've already skipped sync packets and checked
+ // bounds in peek.
+ size := uint64(r.readUint16LEAt(r.begin))
+ end = r.begin + size
+ r.begin += debugLogHeaderSize
+
+ // Read tick, nano, and p.
+ tick = r.uvarint() + r.tick
+ nano = r.uvarint() + r.nano
+ p = int(r.varint())
+
+ return
+}
+
+func (r *debugLogReader) uvarint() uint64 {
+ var u uint64
+ for i := uint(0); ; i += 7 {
+ b := r.data[r.begin%uint64(len(r.data))]
+ r.begin++
+ u |= uint64(b&^0x80) << i
+ if b&0x80 == 0 {
+ break
+ }
+ }
+ return u
+}
+
+func (r *debugLogReader) varint() int64 {
+ u := r.uvarint()
+ var v int64
+ if u&1 == 0 {
+ v = int64(u >> 1)
+ } else {
+ v = ^int64(u >> 1)
+ }
+ return v
+}
+
+func (r *debugLogReader) printVal() bool {
+ typ := r.data[r.begin%uint64(len(r.data))]
+ r.begin++
+
+ switch typ {
+ default:
+ print("<unknown field type ", hex(typ), " pos ", r.begin-1, " end ", r.end, ">\n")
+ return false
+
+ case debugLogUnknown:
+ print("<unknown kind>")
+
+ case debugLogBoolTrue:
+ print(true)
+
+ case debugLogBoolFalse:
+ print(false)
+
+ case debugLogInt:
+ print(r.varint())
+
+ case debugLogUint:
+ print(r.uvarint())
+
+ case debugLogHex, debugLogPtr:
+ print(hex(r.uvarint()))
+
+ case debugLogString:
+ sl := r.uvarint()
+ if r.begin+sl > r.end {
+ r.begin = r.end
+ print("<string length corrupted>")
+ break
+ }
+ for sl > 0 {
+ b := r.data[r.begin%uint64(len(r.data)):]
+ if uint64(len(b)) > sl {
+ b = b[:sl]
+ }
+ r.begin += uint64(len(b))
+ sl -= uint64(len(b))
+ gwrite(b)
+ }
+
+ case debugLogConstString:
+ len, ptr := int(r.uvarint()), uintptr(r.uvarint())
+ ptr += firstmoduledata.etext
+ str := stringStruct{
+ str: unsafe.Pointer(ptr),
+ len: len,
+ }
+ s := *(*string)(unsafe.Pointer(&str))
+ print(s)
+
+ case debugLogStringOverflow:
+ print("..(", r.uvarint(), " more bytes)..")
+
+ case debugLogPC:
+ printDebugLogPC(uintptr(r.uvarint()), false)
+
+ case debugLogTraceback:
+ n := int(r.uvarint())
+ for i := 0; i < n; i++ {
+ print("\n\t")
+ // gentraceback PCs are always return PCs.
+ // Convert them to call PCs.
+ //
+ // TODO(austin): Expand inlined frames.
+ printDebugLogPC(uintptr(r.uvarint()), true)
+ }
+ }
+
+ return true
+}
+
+// printDebugLog prints the debug log.
+func printDebugLog() {
+ if !dlogEnabled {
+ return
+ }
+
+ // This function should not panic or throw since it is used in
+ // the fatal panic path and this may deadlock.
+
+ printlock()
+
+ // Get the list of all debug logs.
+ allp := (*uintptr)(unsafe.Pointer(&allDloggers))
+ all := (*dlogger)(unsafe.Pointer(atomic.Loaduintptr(allp)))
+
+ // Count the logs.
+ n := 0
+ for l := all; l != nil; l = l.allLink {
+ n++
+ }
+ if n == 0 {
+ printunlock()
+ return
+ }
+
+ // Prepare read state for all logs.
+ type readState struct {
+ debugLogReader
+ first bool
+ lost uint64
+ nextTick uint64
+ }
+ // Use sysAllocOS instead of sysAlloc because we want to interfere
+ // with the runtime as little as possible, and sysAlloc updates accounting.
+ state1 := sysAllocOS(unsafe.Sizeof(readState{}) * uintptr(n))
+ if state1 == nil {
+ println("failed to allocate read state for", n, "logs")
+ printunlock()
+ return
+ }
+ state := (*[1 << 20]readState)(state1)[:n]
+ {
+ l := all
+ for i := range state {
+ s := &state[i]
+ s.debugLogReader = l.w.r
+ s.first = true
+ s.lost = l.w.r.begin
+ s.nextTick = s.peek()
+ l = l.allLink
+ }
+ }
+
+ // Print records.
+ for {
+ // Find the next record.
+ var best struct {
+ tick uint64
+ i int
+ }
+ best.tick = ^uint64(0)
+ for i := range state {
+ if state[i].nextTick < best.tick {
+ best.tick = state[i].nextTick
+ best.i = i
+ }
+ }
+ if best.tick == ^uint64(0) {
+ break
+ }
+
+ // Print record.
+ s := &state[best.i]
+ if s.first {
+ print(">> begin log ", best.i)
+ if s.lost != 0 {
+ print("; lost first ", s.lost>>10, "KB")
+ }
+ print(" <<\n")
+ s.first = false
+ }
+
+ end, _, nano, p := s.header()
+ oldEnd := s.end
+ s.end = end
+
+ print("[")
+ var tmpbuf [21]byte
+ pnano := int64(nano) - runtimeInitTime
+ if pnano < 0 {
+ // Logged before runtimeInitTime was set.
+ pnano = 0
+ }
+ pnanoBytes := itoaDiv(tmpbuf[:], uint64(pnano), 9)
+ print(slicebytetostringtmp((*byte)(noescape(unsafe.Pointer(&pnanoBytes[0]))), len(pnanoBytes)))
+ print(" P ", p, "] ")
+
+ for i := 0; s.begin < s.end; i++ {
+ if i > 0 {
+ print(" ")
+ }
+ if !s.printVal() {
+ // Abort this P log.
+ print("<aborting P log>")
+ end = oldEnd
+ break
+ }
+ }
+ println()
+
+ // Move on to the next record.
+ s.begin = end
+ s.end = oldEnd
+ s.nextTick = s.peek()
+ }
+
+ printunlock()
+}
+
+// printDebugLogPC prints a single symbolized PC. If returnPC is true,
+// pc is a return PC that must first be converted to a call PC.
+func printDebugLogPC(pc uintptr, returnPC bool) {
+ fn := findfunc(pc)
+ if returnPC && (!fn.valid() || pc > fn.entry()) {
+ // TODO(austin): Don't back up if the previous frame
+ // was a sigpanic.
+ pc--
+ }
+
+ print(hex(pc))
+ if !fn.valid() {
+ print(" [unknown PC]")
+ } else {
+ name := funcname(fn)
+ file, line := funcline(fn, pc)
+ print(" [", name, "+", hex(pc-fn.entry()),
+ " ", file, ":", line, "]")
+ }
+}
generated by cgit v1.2.3 (git 2.39.1) at 2024-11-19 13:35:58 +0000