// 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 {
l = (*dlogger)(sysAlloc(unsafe.Sizeof(dlogger{}), nil))
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 interface{}) *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()))
case debugLogTraceback:
n := int(r.uvarint())
for i := 0; i < n; i++ {
print("\n\t")
printDebugLogPC(uintptr(r.uvarint()))
}
}
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
}
state1 := sysAlloc(unsafe.Sizeof(readState{})*uintptr(n), nil)
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
}
print(string(itoaDiv(tmpbuf[:], uint64(pnano), 9)))
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()
}
func printDebugLogPC(pc uintptr) {
print(hex(pc))
fn := findfunc(pc)
if !fn.valid() {
print(" [unknown PC]")
} else {
name := funcname(fn)
file, line := funcline(fn, pc)
print(" [", name, "+", hex(pc-fn.entry),
" ", file, ":", line, "]")
}
}
|
