Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve cache related trace logging. #4109

Merged
merged 1 commit into from
Aug 7, 2023
Merged

Improve cache related trace logging. #4109

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions cache/refs.go
View file
Open in desktop
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
Open in desktop
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))
jedevc marked this conversation as resolved.
Show resolved Hide resolved
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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.
Comment on lines -66 to -67
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not too familiar with logrus internals, but I'm curious as to why this doesn't work in hooks?

It appears that the hooks get called before formatting the logs, within the same call to .Log. So surely to get the stack trace, you'd just need to call .String within the hook (though if the hook does something like spawn a goroutine, I guess that confuses it)?

If we can, I'd rather not add additional indentation for checks for if logrus.GetLevel() == logrus.TraceLevel: instead of doing that, we could preserve the spirit of the original by doing something like:

func lazyStackTrace() string {
	if logrus.GetLevel() == logrus.TraceLevel {
		return string(debug.Stack())
	}
	return ""
}

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we could use a hook like https://github.com/docker/buildx/blob/50fbdd86f928f9ed9c858e401783021264462077/commands/root.go#L47-L53

See https://github.com/docker/buildx/blob/50fbdd86f928f9ed9c858e401783021264462077/util/logutil/filter.go#L10-L38

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So surely to get the stack trace, you'd just need to call .String within the hook (though if the hook does something like spawn a goroutine, I guess that confuses it)?

Yeah my phrasing in the commit message wasn't super accurate, it's not hooks in and of themselves that are the problem but more that the hook has to be sure the field gets "unlazied" before passing it off to a separate goroutine despite all the values being of type any. That's possible but also just sort of a huge gotcha (which is my fault since I added LazyStackTrace, just trying to correct my own mistakes here 😅).

E.g. the relevant line in Dagger is here. I think we'd need to either iterate over all the fields, doing a type assertion and calling .String() one-by-one, or do a full json marshal/unmarshal cycle every time.

Either way, I think your suggestion of func lazyStackTrace() string is much better, I'll update to do that.

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 ""
}