runtime: add minimal debug tracing of runtime timers

Toggled by a compile-time const, so there should be no
runtime footprint in ordinary builds.

Change-Id: I7751847524f4fda3853388d3e5a18188bd737c27
Reviewed-on: https://go-review.googlesource.com/c/go/+/570336
Auto-Submit: Russ Cox <rsc@golang.org>
Reviewed-by: Ian Lance Taylor <iant@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Austin Clements <austin@google.com>

diff --git a/src/runtime/time.go b/src/runtime/time.go
index 6802cc4b2944fb15382ac33ef5dbb8f56865e61c..adbe8ac126e0ebc4c4e82fb5b030c04edb490b15 100644 (file)
--- a/src/runtime/time.go
+++ b/src/runtime/time.go
@@ -133,13 +133,43 @@ const (
        timerZombie
 )
 
+// timerDebug enables printing a textual debug trace of all timer operations to stderr.
+const timerDebug = false
+
+func (t *timer) trace(op string) {
+       if timerDebug {
+               t.trace1(op)
+       }
+}
+
+func (t *timer) trace1(op string) {
+       if !timerDebug {
+               return
+       }
+       bits := [3]string{"h", "m", "z"}
+       for i := range bits {
+               if t.state&(1<<i) == 0 {
+                       bits[i] = "-"
+               }
+       }
+       print("T ", t, " ", bits[0], bits[1], bits[2], " ", op, "\n")
+}
+
+func (ts *timers) trace(op string) {
+       if timerDebug {
+               println("TS", ts, op)
+       }
+}
+
 // lock locks the timer, allowing reading or writing any of the timer fields.
 func (t *timer) lock() {
        lock(&t.mu)
+       t.trace("lock")
 }
 
 // unlock updates t.astate and unlocks the timer.
 func (t *timer) unlock() {
+       t.trace("unlock")
        // Let heap fast paths know whether t.whenHeap is accurate.
        t.astate.Store(t.state)
        unlock(&t.mu)
@@ -154,6 +184,7 @@ func (t *timer) unlock() {
 // temporarily not maintaining its invariant, such as during timers.adjust).
 func (t *timer) updateHeap(ts *timers) (updated bool) {
        assertWorldStoppedOrLockHeld(&t.mu)
+       t.trace("updateHeap")
        if ts != nil {
                if t.ts != ts || t != ts.heap[0] {
                        badTimer()
@@ -249,6 +280,7 @@ type timeTimer struct {
 func newTimer(when, period int64, f func(any, uintptr), arg any) *timeTimer {
        t := new(timeTimer)
        t.timer.init(nil, nil)
+       t.trace("new")
        if raceenabled {
                racerelease(unsafe.Pointer(&t.timer))
        }
@@ -315,6 +347,7 @@ func (ts *timers) addHeap(t *timer) {
 // Reports whether the timer was stopped before it was run.
 func (t *timer) stop() bool {
        t.lock()
+       t.trace("stop")
        if t.state&timerHeaped != 0 {
                t.state |= timerModified
                if t.state&timerZombie == 0 {
@@ -366,6 +399,7 @@ func (t *timer) modify(when, period int64, f func(any, uintptr), arg any, seq ui
        }
 
        t.lock()
+       t.trace("modify")
        t.period = period
        if f != nil {
                t.f = f
@@ -408,7 +442,13 @@ func (t *timer) modify(when, period int64, f func(any, uintptr), arg any, seq ui
 // t must be locked.
 func (t *timer) needsAdd() bool {
        assertLockHeld(&t.mu)
-       return t.state&timerHeaped == 0 && t.when > 0
+       need := t.state&timerHeaped == 0 && t.when > 0
+       if need {
+               t.trace("needsAdd+")
+       } else {
+               t.trace("needsAdd-")
+       }
+       return need
 }
 
 // maybeAdd adds t to the local timers heap if it needs to be in a heap.
@@ -434,6 +474,7 @@ func (t *timer) maybeAdd() {
        ts.lock()
        ts.cleanHead()
        t.lock()
+       t.trace("maybeAdd")
        when := int64(0)
        if t.needsAdd() {
                t.state |= timerHeaped
@@ -459,6 +500,7 @@ func (t *timer) reset(when, period int64) bool {
 // slows down heap operations.
 // The caller must have locked ts.
 func (ts *timers) cleanHead() {
+       ts.trace("cleanHead")
        assertLockHeld(&ts.mu)
        gp := getg()
        for {
@@ -500,6 +542,7 @@ func (ts *timers) cleanHead() {
 // The caller must not have locked either timers.
 // For now this is only called when the world is stopped.
 func (ts *timers) take(src *timers) {
+       ts.trace("take")
        assertWorldStopped()
        if len(src.heap) > 0 {
                // The world is stopped, so we ignore the locking of ts and src here.
@@ -535,6 +578,7 @@ func (ts *timers) move(timers []*timer) {
 // it also moves timers that have been modified to run later,
 // and removes deleted timers. The caller must have locked ts.
 func (ts *timers) adjust(now int64, force bool) {
+       ts.trace("adjust")
        assertLockHeld(&ts.mu)
        // If we haven't yet reached the time of the earliest modified
        // timer, don't do anything. This speeds up programs that adjust
@@ -664,6 +708,7 @@ func (ts *timers) wakeTime() int64 {
 //
 //go:yeswritebarrierrec
 func (ts *timers) check(now int64) (rnow, pollUntil int64, ran bool) {
+       ts.trace("check")
        // If it's not yet time for the first timer, or the first adjusted
        // timer, then there is nothing to do.
        next := ts.wakeTime()
@@ -718,6 +763,7 @@ func (ts *timers) check(now int64) (rnow, pollUntil int64, ran bool) {
 //
 //go:systemstack
 func (ts *timers) run(now int64) int64 {
+       ts.trace("run")
        assertLockHeld(&ts.mu)
 Redo:
        if len(ts.heap) == 0 {
@@ -763,6 +809,7 @@ Redo:
 //
 //go:systemstack
 func (t *timer) unlockAndRun(now int64) {
+       t.trace("unlockAndRun")
        assertLockHeld(&t.mu)
        if t.ts != nil {
                assertLockHeld(&t.ts.mu)