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.

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

Conversation

sipsma
Copy link
Collaborator

@sipsma sipsma commented Aug 4, 2023

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.

@sipsma sipsma requested review from tonistiigi and jedevc August 4, 2023 23:28
solver/cachekey.go Show resolved Hide resolved
Comment on lines -66 to -67
// 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.
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.

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.

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]>
@sipsma sipsma force-pushed the cache-debug-logs branch from df1dbfe to 45b19d3 Compare August 7, 2023 14:25
@sipsma sipsma requested a review from jedevc August 7, 2023 14:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants