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

Avoid expensive log.Valuer evaluation for disallowed level #6322

Merged
merged 1 commit into from
May 4, 2023
Merged

Avoid expensive log.Valuer evaluation for disallowed level #6322

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
1 change: 1 addition & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -42,6 +42,7 @@ We use *breaking :warning:* to mark changes that are not backward compatible (re
- [#6071](https://github.com/thanos-io/thanos/pull/6071) Query Frontend: *breaking :warning:* Add experimental native histogram support for which we updated and aligned with the [Prometheus common](https://github.com/prometheus/common) model, which is used for caching so a cache reset required.
- [#6163](https://github.com/thanos-io/thanos/pull/6163) Receiver: changed max backoff from 30s to 5s for forwarding requests. Can be configured with `--receive-forward-max-backoff`.
- [#6327](https://github.com/thanos-io/thanos/pull/6327) *: *breaking :warning:* Use histograms instead of summaries for instrumented handlers.
- [#6322](https://github.com/thanos-io/thanos/pull/6322) Logging: Avoid expensive log.Valuer evaluation for disallowed levels.

### Removed

Expand Down
5 changes: 4 additions & 1 deletion pkg/logging/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,11 +46,14 @@ func NewLogger(logLevel, logFormat, debugName string) log.Logger {
logger = log.NewJSONLogger(log.NewSyncWriter(os.Stderr))
}

// Sort the logger chain to avoid expensive log.Valuer evaluation for disallowed level.
// Ref: https://github.com/go-kit/log/issues/14#issuecomment-945038252
logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(5))
Copy link
Member

Choose a reason for hiding this comment

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

Why is it log.Caller(5) now instead of log.Caller(3) (which is the default caller)?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Because the NewFilter wraps next(the logger) and implements level filtering.

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.

Copy link
Member

Choose a reason for hiding this comment

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

I see, that's smart and totally makes sense 🙇

logger = level.NewFilter(logger, lvl)

if debugName != "" {
logger = log.With(logger, "name", debugName)
}

return log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
return logger
}
19 changes: 19 additions & 0 deletions pkg/logging/logger_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
// Copyright (c) The Thanos Authors.
// Licensed under the Apache License 2.0.

package logging

import (
"testing"

"github.com/go-kit/log/level"
)

func BenchmarkDisallowedLogLevels(b *testing.B) {
logger := NewLogger("warn", "logfmt", "benchmark")

for i := 0; i < b.N; i++ {
level.Info(logger).Log("hello", "world", "number", i)
level.Debug(logger).Log("hello", "world", "number", i)
}
}