Skip to content

This issue was moved to a discussion.

You can continue the conversation there. Go to discussion →

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

Filtered-out log.Level lines still cost #14

Closed
bboreham opened this issue Oct 15, 2021 · 2 comments
Closed

Filtered-out log.Level lines still cost #14

bboreham opened this issue Oct 15, 2021 · 2 comments

Comments

@bboreham
Copy link

I noticed a portion of our CPU was going into level.Debug(...).Log() lines, although that level wasn't enabled.

I think what is happening is the Log() call goes into context.Log() first, which calls bindValues which is the expensive part, calling runtime.Caller, formatting a timestamp, etc., then after that it goes to level.Log() which discards everything.

I looked around but didn't find any previous debate on this point. Am I holding it wrong? Is this expected?

Since we are using a wrapper, something like go-kit/kit#322 would let us work around the problem by checking before doing the work, but that was rejected.

@ChrisHines
Copy link
Member

@bboreham I wouldn't say you are holding it wrong, but there may be one tweak to improve it. More on that later.

First, let me say up front, that the level package is not designed for raw performance, the behavior you describe is expected. But the level package is also separate from the log package precisely because we believed that there was no best way to approach it that would suit everyone's needs. My statement in go-kit/kit#322 (comment) still stands:

I do think that this is a viable approach for applications that require optimal performance when logging is disabled. There is no reason an application or organization can't use the technique in their own code, but I don't think the need is common enough to promote this pattern in Go kit.

If you just want better performance, and you don't need optimal performance, then there is one thing you can do, though. You noted that runtime.Caller is rather expensive, which is true. So setting up your logger chain to put that "below" the level filtering will help. For example, in the below program, the last line that logs at debug level should do a couple allocations to create a keyvals []interface{} that gets passed to the level filter, but should not format the timestamp or call runtime.Caller. It's not going to be as cheap as some other logging packages make it, but it should be cheaper than what you described and maybe it's good enough for your application. You'll have to profile it and see what you think.

Playground link for the below code: https://play.golang.org/p/Z3nf1G9jvR0

logger := log.NewLogfmtLogger(os.Stdout)
logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(5))
logger = level.NewFilter(logger, level.AllowInfo())

level.Info(logger).Log("msg", "Hello, world!")
level.Debug(logger).Log("msg", "Goodbye, world!")

Note that you cannot use log.DefaultCaller in this case, because the level filter separates the log.With that sets up the caller Valuer from the calls to log.With inside the level.Info and level.Debug calls. So there are two additional stack frames for log.Caller to skip before getting back to the call-site of the Log methods.

bboreham added a commit to weaveworks/common that referenced this issue Oct 17, 2021
This saves a lot of work walking the stack to find the caller, and a bit
more to format the timestamp.

Recommended at go-kit/log#14 (comment)

Signed-off-by: Bryan Boreham <bjboreham@gmail.com>
@bboreham
Copy link
Author

Thank you, swapping the filter to last does indeed take out the bulk of the overhead.

Would it be better to put the filter last in the example?

log/level/doc.go

Lines 6 to 8 in 71fa7d7

// logger = log.NewLogfmtLogger(os.Stderr)
// logger = level.NewFilter(logger, level.AllowInfo()) // <--
// logger = log.With(logger, "ts", log.DefaultTimestampUTC)

There is no reason an application or organization can't use the technique in their own code

I found that, because the go-kit level package relies on an unexported levelValue struct, there was no way to extend it or use a different one in part of the code; you have to replace all uses throughout any program that uses it.

@go-kit go-kit locked and limited conversation to collaborators Oct 17, 2021

This issue was moved to a discussion.

You can continue the conversation there. Go to discussion →

Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants