Add logging option to leak checker.

Also refactor the template and CheckedObject interface to make this cleaner.

Updates #1486.

PiperOrigin-RevId: 339577120

3 files changed, 104 insertions, 48 deletions

diff --git a/pkg/refsvfs2/BUILD b/pkg/refsvfs2/BUILD
index 245e33d2d..bfa1daa10 100644
--- a/pkg/refsvfs2/BUILD
+++ b/pkg/refsvfs2/BUILD
@@ -8,6 +8,9 @@ go_template(
     srcs = [
         "refs_template.go",
     ],
+    opt_consts = [
+        "logTrace",
+    ],
     types = [
         "T",
     ],
diff --git a/pkg/refsvfs2/refs_map.go b/pkg/refsvfs2/refs_map.go
index be75b0cc2..57938d2f0 100644
--- a/pkg/refsvfs2/refs_map.go
+++ b/pkg/refsvfs2/refs_map.go
@@ -37,61 +37,98 @@ var (
 // CheckedObject represents a reference-counted object with an informative
 // leak detection message.
 type CheckedObject interface {
+	// RefType is the type of the reference-counted object.
+	RefType() string
+
 	// LeakMessage supplies a warning to be printed upon leak detection.
 	LeakMessage() string
+
+	// LogRefs indicates whether reference-related events should be logged.
+	LogRefs() bool
 }
 
 func init() {
 	liveObjects = make(map[CheckedObject]struct{})
 }
 
-// LeakCheckEnabled returns whether leak checking is enabled. The following
+// leakCheckEnabled returns whether leak checking is enabled. The following
 // functions should only be called if it returns true.
-func LeakCheckEnabled() bool {
+func leakCheckEnabled() bool {
 	return refs_vfs1.GetLeakMode() != refs_vfs1.NoLeakChecking
 }
 
 // Register adds obj to the live object map.
-func Register(obj CheckedObject, typ string) {
-	for _, str := range ignored {
-		if strings.Contains(typ, str) {
-			return
+func Register(obj CheckedObject) {
+	if leakCheckEnabled() {
+		for _, str := range ignored {
+			if strings.Contains(obj.RefType(), str) {
+				return
+			}
 		}
+		liveObjectsMu.Lock()
+		if _, ok := liveObjects[obj]; ok {
+			panic(fmt.Sprintf("Unexpected entry in leak checking map: reference %p already added", obj))
+		}
+		liveObjects[obj] = struct{}{}
+		liveObjectsMu.Unlock()
+		logEvent(obj, "registered")
 	}
-	liveObjectsMu.Lock()
-	if _, ok := liveObjects[obj]; ok {
-		panic(fmt.Sprintf("Unexpected entry in leak checking map: reference %p already added", obj))
-	}
-	liveObjects[obj] = struct{}{}
-	liveObjectsMu.Unlock()
 }
 
 // Unregister removes obj from the live object map.
-func Unregister(obj CheckedObject, typ string) {
-	liveObjectsMu.Lock()
-	defer liveObjectsMu.Unlock()
-	if _, ok := liveObjects[obj]; !ok {
-		for _, str := range ignored {
-			if strings.Contains(typ, str) {
-				return
+func Unregister(obj CheckedObject) {
+	if leakCheckEnabled() {
+		liveObjectsMu.Lock()
+		defer liveObjectsMu.Unlock()
+		if _, ok := liveObjects[obj]; !ok {
+			for _, str := range ignored {
+				if strings.Contains(obj.RefType(), str) {
+					return
+				}
 			}
+			panic(fmt.Sprintf("Expected to find entry in leak checking map for reference %p", obj))
 		}
-		panic(fmt.Sprintf("Expected to find entry in leak checking map for reference %p", obj))
+		delete(liveObjects, obj)
+		logEvent(obj, "unregistered")
+	}
+}
+
+// LogIncRef logs a reference increment.
+func LogIncRef(obj CheckedObject, refs int64) {
+	logEvent(obj, fmt.Sprintf("IncRef to %d", refs))
+}
+
+// LogTryIncRef logs a successful TryIncRef call.
+func LogTryIncRef(obj CheckedObject, refs int64) {
+	logEvent(obj, fmt.Sprintf("TryIncRef to %d", refs))
+}
+
+// LogDecRef logs a reference decrement.
+func LogDecRef(obj CheckedObject, refs int64) {
+	logEvent(obj, fmt.Sprintf("DecRef to %d", refs))
+}
+
+// logEvent logs a message for the given reference-counted object.
+func logEvent(obj CheckedObject, msg string) {
+	if obj.LogRefs() {
+		log.Infof("[%s %p] %s:", obj.RefType(), obj, msg)
+		log.Infof(refs_vfs1.FormatStack(refs_vfs1.RecordStack()))
 	}
-	delete(liveObjects, obj)
 }
 
 // DoLeakCheck iterates through the live object map and logs a message for each
 // object. It is called once no reference-counted objects should be reachable
 // anymore, at which point anything left in the map is considered a leak.
 func DoLeakCheck() {
-	liveObjectsMu.Lock()
-	defer liveObjectsMu.Unlock()
-	leaked := len(liveObjects)
-	if leaked > 0 {
-		log.Warningf("Leak checking detected %d leaked objects:", leaked)
-		for obj := range liveObjects {
-			log.Warningf(obj.LeakMessage())
+	if leakCheckEnabled() {
+		liveObjectsMu.Lock()
+		defer liveObjectsMu.Unlock()
+		leaked := len(liveObjects)
+		if leaked > 0 {
+			log.Warningf("Leak checking detected %d leaked objects:", leaked)
+			for obj := range liveObjects {
+				log.Warningf(obj.LeakMessage())
+			}
 		}
 	}
 }
diff --git a/pkg/refsvfs2/refs_template.go b/pkg/refsvfs2/refs_template.go
index ec295ef5b..8f50b4ee6 100644
--- a/pkg/refsvfs2/refs_template.go
+++ b/pkg/refsvfs2/refs_template.go
@@ -26,13 +26,19 @@ import (
 	"gvisor.dev/gvisor/pkg/refsvfs2"
 )
 
+// enableLogging indicates whether reference-related events should be logged (with
+// stack traces). This is false by default and should only be set to true for
+// debugging purposes, as it can generate an extremely large amount of output
+// and drastically degrade performance.
+const enableLogging = false
+
 // T is the type of the reference counted object. It is only used to customize
 // debug output when leak checking.
 type T interface{}
 
-// ownerType is used to customize logging. Note that we use a pointer to T so
-// that we do not copy the entire object when passed as a format parameter.
-var ownerType *T
+// obj is used to customize logging. Note that we use a pointer to T so that
+// we do not copy the entire object when passed as a format parameter.
+var obj *T
 
 // Refs implements refs.RefCounter. It keeps a reference count using atomic
 // operations and calls the destructor when the count reaches zero.
@@ -52,16 +58,24 @@ type Refs struct {
 	refCount int64
 }
 
-// EnableLeakCheck enables reference leak checking on r.
-func (r *Refs) EnableLeakCheck() {
-	if refsvfs2.LeakCheckEnabled() {
-		refsvfs2.Register(r, fmt.Sprintf("%T", ownerType))
-	}
+// RefType implements refsvfs2.CheckedObject.RefType.
+func (r *Refs) RefType() string {
+	return fmt.Sprintf("%T", obj)[1:]
 }
 
 // LeakMessage implements refsvfs2.CheckedObject.LeakMessage.
 func (r *Refs) LeakMessage() string {
-	return fmt.Sprintf("%T %p: reference count of %d instead of 0", ownerType, r, r.ReadRefs())
+	return fmt.Sprintf("[%s %p] reference count of %d instead of 0", r.RefType(), r, r.ReadRefs())
+}
+
+// LogRefs implements refsvfs2.CheckedObject.LogRefs.
+func (r *Refs) LogRefs() bool {
+	return enableLogging
+}
+
+// EnableLeakCheck enables reference leak checking on r.
+func (r *Refs) EnableLeakCheck() {
+	refsvfs2.Register(r)
 }
 
 // ReadRefs returns the current number of references. The returned count is
@@ -75,8 +89,10 @@ func (r *Refs) ReadRefs() int64 {
 //
 //go:nosplit
 func (r *Refs) IncRef() {
-	if v := atomic.AddInt64(&r.refCount, 1); v <= 0 {
-		panic(fmt.Sprintf("Incrementing non-positive count %p on %T", r, ownerType))
+	v := atomic.AddInt64(&r.refCount, 1)
+	refsvfs2.LogIncRef(r, v+1)
+	if v <= 0 {
+		panic(fmt.Sprintf("Incrementing non-positive count %p on %s", r, r.RefType()))
 	}
 }
 
@@ -89,15 +105,15 @@ func (r *Refs) IncRef() {
 //go:nosplit
 func (r *Refs) TryIncRef() bool {
 	const speculativeRef = 1 << 32
-	v := atomic.AddInt64(&r.refCount, speculativeRef)
-	if int32(v) < 0 {
+	if v := atomic.AddInt64(&r.refCount, speculativeRef); int32(v) < 0 {
 		// This object has already been freed.
 		atomic.AddInt64(&r.refCount, -speculativeRef)
 		return false
 	}
 
 	// Turn into a real reference.
-	atomic.AddInt64(&r.refCount, -speculativeRef+1)
+	v := atomic.AddInt64(&r.refCount, -speculativeRef+1)
+	refsvfs2.LogTryIncRef(r, v+1)
 	return true
 }
 
@@ -114,14 +130,14 @@ func (r *Refs) TryIncRef() bool {
 //
 //go:nosplit
 func (r *Refs) DecRef(destroy func()) {
-	switch v := atomic.AddInt64(&r.refCount, -1); {
+	v := atomic.AddInt64(&r.refCount, -1)
+	refsvfs2.LogDecRef(r, v+1)
+	switch {
 	case v < -1:
-		panic(fmt.Sprintf("Decrementing non-positive ref count %p, owned by %T", r, ownerType))
+		panic(fmt.Sprintf("Decrementing non-positive ref count %p, owned by %s", r, r.RefType()))
 
 	case v == -1:
-		if refsvfs2.LeakCheckEnabled() {
-			refsvfs2.Unregister(r, fmt.Sprintf("%T", ownerType))
-		}
+		refsvfs2.Unregister(r)
 		// Call the destructor.
 		if destroy != nil {
 			destroy()
@@ -130,7 +146,7 @@ func (r *Refs) DecRef(destroy func()) {
 }
 
 func (r *Refs) afterLoad() {
-	if refsvfs2.LeakCheckEnabled() && r.ReadRefs() > 0 {
+	if r.ReadRefs() > 0 {
 		r.EnableLeakCheck()
 	}
 }