Improve cache related trace logging.

This adds trace logs to the solver's cache manager to assist debugging
cache misses+hits.

It also replace the LazyStackTrace struct with a function that returns a
stack trace string only if trace level is enabled, an empty string
otherwise. This makes it easier to use with logrus hooks that pass the
fields around to different goroutines without needing to try to "unlazy"
the fields first.

Signed-off-by: Erik Sipsma <[email protected]>

Author: sipsma

cache/refs.go

@@ -444,7 +444,7 @@ func (cr *cacheRecord) remove(ctx context.Context, removeSnapshot bool) (rerr er
 			"id":             cr.ID(),
 			"refCount":       len(cr.refs),
 			"removeSnapshot": removeSnapshot,
-			"stack":          bklog.LazyStackTrace{},
+			"stack":          bklog.TraceLevelOnlyStack(),
 		})
 		if rerr != nil {
 			l = l.WithError(rerr)
@@ -488,7 +488,7 @@ func (sr *immutableRef) traceLogFields() logrus.Fields {
 		"refID":       fmt.Sprintf("%p", sr),
 		"newRefCount": len(sr.refs),
 		"mutable":     false,
-		"stack":       bklog.LazyStackTrace{},
+		"stack":       bklog.TraceLevelOnlyStack(),
 	}
 	if sr.equalMutable != nil {
 		m["equalMutableID"] = sr.equalMutable.ID()
@@ -628,7 +628,7 @@ func (sr *mutableRef) traceLogFields() logrus.Fields {
 		"refID":       fmt.Sprintf("%p", sr),
 		"newRefCount": len(sr.refs),
 		"mutable":     true,
-		"stack":       bklog.LazyStackTrace{},
+		"stack":       bklog.TraceLevelOnlyStack(),
 	}
 	if sr.equalMutable != nil {
 		m["equalMutableID"] = sr.equalMutable.ID()

solver/cachekey.go

@@ -24,19 +24,56 @@ type CacheKeyWithSelector struct {
 	CacheKey ExportableCacheKey
 }
 
+func (ck CacheKeyWithSelector) TraceFields() map[string]any {
+	fields := ck.CacheKey.TraceFields()
+	fields["selector"] = ck.Selector.String()
+	return fields
+}
+
 type CacheKey struct {
 	mu sync.RWMutex
 
-	ID     string
-	deps   [][]CacheKeyWithSelector // only [][]*inMemoryCacheKey
+	ID   string
+	deps [][]CacheKeyWithSelector
+	// digest is the digest returned by the CacheMap implementation of this op
 	digest digest.Digest
+	// vtx is the LLB digest that this op was created for
 	vtx    digest.Digest
 	output Index
 	ids    map[*cacheManager]string
 
 	indexIDs []string
 }
 
+func (ck *CacheKey) TraceFields() map[string]any {
+	ck.mu.RLock()
+	defer ck.mu.RUnlock()
+	idsMap := map[string]string{}
+	for cm, id := range ck.ids {
+		idsMap[cm.ID()] = id
+	}
+
+	// don't recurse more than one level in showing deps
+	depsMap := make([]map[string]string, len(ck.deps))
+	for i, deps := range ck.deps {
+		depsMap[i] = map[string]string{}
+		for _, ck := range deps {
+			depsMap[i]["id"] = ck.CacheKey.ID
+			depsMap[i]["selector"] = ck.Selector.String()
+		}
+	}
+
+	return map[string]any{
+		"id":       ck.ID,
+		"digest":   ck.digest,
+		"vtx":      ck.vtx,
+		"output":   ck.output,
+		"indexIDs": ck.indexIDs,
+		"ids":      idsMap,
+		"deps":     depsMap,
+	}
+}
+
 func (ck *CacheKey) Deps() [][]CacheKeyWithSelector {
 	ck.mu.RLock()
 	defer ck.mu.RUnlock()

solver/cachemanager.go

@@ -10,6 +10,7 @@ import (
 	"github.com/moby/buildkit/identity"
 	"github.com/moby/buildkit/util/bklog"
 	digest "github.com/opencontainers/go-digest"
+	"github.com/sirupsen/logrus"
 )
 
 // NewInMemoryCacheManager creates a new in-memory cache manager
@@ -55,7 +56,28 @@ func (c *cacheManager) ID() string {
 	return c.id
 }
 
-func (c *cacheManager) Query(deps []CacheKeyWithSelector, input Index, dgst digest.Digest, output Index) ([]*CacheKey, error) {
+func (c *cacheManager) Query(deps []CacheKeyWithSelector, input Index, dgst digest.Digest, output Index) (rcks []*CacheKey, rerr error) {
+	depsField := make([]map[string]any, len(deps))
+	for i, dep := range deps {
+		depsField[i] = dep.TraceFields()
+	}
+	lg := bklog.G(context.TODO()).WithFields(logrus.Fields{
+		"cache_manager": c.id,
+		"op":            "query",
+		"deps":          depsField,
+		"input":         input,
+		"digest":        dgst,
+		"output":        output,
+		"stack":         bklog.TraceLevelOnlyStack(),
+	})
+	defer func() {
+		rcksField := make([]map[string]any, len(rcks))
+		for i, rck := range rcks {
+			rcksField[i] = rck.TraceFields()
+		}
+		lg.WithError(rerr).WithField("return_cachekeys", rcksField).Trace("cache manager")
+	}()
+
 	c.mu.RLock()
 	defer c.mu.RUnlock()
 
@@ -112,7 +134,21 @@ func (c *cacheManager) Query(deps []CacheKeyWithSelector, input Index, dgst dige
 	return keys, nil
 }
 
-func (c *cacheManager) Records(ctx context.Context, ck *CacheKey) ([]*CacheRecord, error) {
+func (c *cacheManager) Records(ctx context.Context, ck *CacheKey) (rrecs []*CacheRecord, rerr error) {
+	lg := bklog.G(context.TODO()).WithFields(logrus.Fields{
+		"cache_manager": c.id,
+		"op":            "records",
+		"cachekey":      ck.TraceFields(),
+		"stack":         bklog.TraceLevelOnlyStack(),
+	})
+	defer func() {
+		rrercsField := make([]map[string]any, len(rrecs))
+		for i, rrec := range rrecs {
+			rrercsField[i] = rrec.TraceFields()
+		}
+		lg.WithError(rerr).WithField("return_records", rrercsField).Trace("cache manager")
+	}()
+
 	outs := make([]*CacheRecord, 0)
 	if err := c.backend.WalkResults(c.getID(ck), func(r CacheResult) error {
 		if c.results.Exists(ctx, r.ID) {
@@ -132,7 +168,17 @@ func (c *cacheManager) Records(ctx context.Context, ck *CacheKey) ([]*CacheRecor
 	return outs, nil
 }
 
-func (c *cacheManager) Load(ctx context.Context, rec *CacheRecord) (Result, error) {
+func (c *cacheManager) Load(ctx context.Context, rec *CacheRecord) (rres Result, rerr error) {
+	lg := bklog.G(context.TODO()).WithFields(logrus.Fields{
+		"cache_manager": c.id,
+		"op":            "load",
+		"record":        rec.TraceFields(),
+		"stack":         bklog.TraceLevelOnlyStack(),
+	})
+	defer func() {
+		lg.WithError(rerr).WithField("return_result", rres.ID()).Trace("cache manager")
+	}()
+
 	c.mu.RLock()
 	defer c.mu.RUnlock()
 
@@ -150,6 +196,14 @@ type LoadedResult struct {
 	CacheKey    *CacheKey
 }
 
+func (r *LoadedResult) TraceFields() map[string]any {
+	return map[string]any{
+		"result":       r.Result.ID(),
+		"cache_result": r.CacheResult.ID,
+		"cache_key":    r.CacheKey.TraceFields(),
+	}
+}
+
 func (c *cacheManager) filterResults(m map[string]Result, ck *CacheKey, visited map[string]struct{}) (results []LoadedResult, err error) {
 	id := c.getID(ck)
 	if _, ok := visited[id]; ok {
@@ -187,7 +241,21 @@ func (c *cacheManager) filterResults(m map[string]Result, ck *CacheKey, visited
 	return
 }
 
-func (c *cacheManager) LoadWithParents(ctx context.Context, rec *CacheRecord) ([]LoadedResult, error) {
+func (c *cacheManager) LoadWithParents(ctx context.Context, rec *CacheRecord) (rres []LoadedResult, rerr error) {
+	lg := bklog.G(context.TODO()).WithFields(logrus.Fields{
+		"cache_manager": c.id,
+		"op":            "load_with_parents",
+		"record":        rec.TraceFields(),
+		"stack":         bklog.TraceLevelOnlyStack(),
+	})
+	defer func() {
+		rresField := make([]map[string]any, len(rres))
+		for i, rres := range rres {
+			rresField[i] = rres.TraceFields()
+		}
+		lg.WithError(rerr).WithField("return_results", rresField).Trace("cache manager")
+	}()
+
 	lwp, ok := c.results.(interface {
 		LoadWithParents(context.Context, CacheResult) (map[string]Result, error)
 	})
@@ -226,7 +294,17 @@ func (c *cacheManager) LoadWithParents(ctx context.Context, rec *CacheRecord) ([
 	return results, nil
 }
 
-func (c *cacheManager) Save(k *CacheKey, r Result, createdAt time.Time) (*ExportableCacheKey, error) {
+func (c *cacheManager) Save(k *CacheKey, r Result, createdAt time.Time) (rck *ExportableCacheKey, rerr error) {
+	lg := bklog.G(context.TODO()).WithFields(logrus.Fields{
+		"cache_manager": c.id,
+		"op":            "save",
+		"result":        r.ID(),
+		"stack":         bklog.TraceLevelOnlyStack(),
+	})
+	defer func() {
+		lg.WithError(rerr).WithField("return_cachekey", rck.TraceFields()).Trace("cache manager")
+	}()
+
 	c.mu.Lock()
 	defer c.mu.Unlock()
 

solver/llbsolver/mounts/mount.go

@@ -483,7 +483,7 @@ type cacheRefShare struct {
 func (r *cacheRefShare) clone(ctx context.Context) cache.MutableRef {
 	bklog.G(ctx).WithFields(map[string]any{
 		"key":   r.key,
-		"stack": bklog.LazyStackTrace{},
+		"stack": bklog.TraceLevelOnlyStack(),
 	}).Trace("cloning cache mount ref share")
 	cacheRef := &cacheRef{cacheRefShare: r}
 	if cacheRefCloneHijack != nil {
@@ -498,7 +498,7 @@ func (r *cacheRefShare) clone(ctx context.Context) cache.MutableRef {
 func (r *cacheRefShare) release(ctx context.Context) error {
 	bklog.G(ctx).WithFields(map[string]any{
 		"key":   r.key,
-		"stack": bklog.LazyStackTrace{},
+		"stack": bklog.TraceLevelOnlyStack(),
 	}).Trace("releasing cache mount ref share main")
 	if r.main != nil {
 		delete(r.main.shares, r.key)
@@ -516,7 +516,7 @@ type cacheRef struct {
 func (r *cacheRef) Release(ctx context.Context) error {
 	bklog.G(ctx).WithFields(map[string]any{
 		"key":   r.key,
-		"stack": bklog.LazyStackTrace{},
+		"stack": bklog.TraceLevelOnlyStack(),
 	}).Trace("releasing cache mount ref share")
 	if r.main != nil {
 		r.main.mu.Lock()

solver/types.go

@@ -228,6 +228,17 @@ type CacheRecord struct {
 	key          *CacheKey
 }
 
+func (ck *CacheRecord) TraceFields() map[string]any {
+	return map[string]any{
+		"id":            ck.ID,
+		"size":          ck.Size,
+		"createdAt":     ck.CreatedAt,
+		"priority":      ck.Priority,
+		"cache_manager": ck.cacheManager.ID(),
+		"cache_key":     ck.key.TraceFields(),
+	}
+}
+
 // CacheManager determines if there is a result that matches the cache keys
 // generated during the build that could be reused instead of fully
 // reevaluating the vertex and its inputs. There can be multiple cache

util/bklog/log.go

@@ -63,14 +63,13 @@ func GetLogger(ctx context.Context) (l *logrus.Entry) {
 	return l
 }
 
-// LazyStackTrace lets you include a stack trace as a field's value in a log but only
-// call it when the log level is actually enabled.
-type LazyStackTrace struct{}
-
-func (LazyStackTrace) String() string {
-	return string(debug.Stack())
-}
-
-func (LazyStackTrace) MarshalText() ([]byte, error) {
-	return debug.Stack(), nil
+// TraceLevelOnlyStack returns a stack trace for the current goroutine only if
+// trace level logs are enabled; otherwise it returns an empty string. This ensure
+// we only pay the cost of generating a stack trace when the log entry will actually
+// be emitted.
+func TraceLevelOnlyStack() string {
+	if logrus.GetLevel() == logrus.TraceLevel {
+		return string(debug.Stack())
+	}
+	return ""
 }