Skip to content

Commit

Permalink
Improve cache related trace logging.
Browse files Browse the repository at this point in the history 
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]>
  • Loading branch information
@sipsma
sipsma committed Aug 7, 2023
1 parent a1deb3e commit 45b19d3
Show file tree
Hide file tree
Showing 6 changed files with 148 additions and 23 deletions.
6 changes: 3 additions & 3 deletions cache/refs.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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()
Expand Down
41 changes: 39 additions & 2 deletions solver/cachekey.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down
88 changes: 83 additions & 5 deletions solver/cachemanager.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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()

Expand Down Expand Up @@ -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) {
Expand All @@ -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()

Expand All @@ -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 {
Expand Down Expand Up @@ -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)
})
Expand Down Expand Up @@ -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()

Expand Down
6 changes: 3 additions & 3 deletions solver/llbsolver/mounts/mount.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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)
Expand All @@ -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()
Expand Down
11 changes: 11 additions & 0 deletions solver/types.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
19 changes: 9 additions & 10 deletions util/bklog/log.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 ""
}

0 comments on commit 45b19d3

Please sign in to comment.