Filtered-out log.Level lines still cost #14

Activity

1. ChrisHines commented on Oct 17, 2021

   

   ChrisHines

   on Oct 17, 2021

   Member

   More actions

   @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.
2. bboreham

   added a commit that references this issue on Oct 17, 2021

   Filter by log level before anything else

   ...

   5ac183a
3. bboreham commented on Oct 17, 2021

   

   bboreham

   on Oct 17, 2021

   Author

   More actions

   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.
4. bboreham

   closed this as completedon Oct 17, 2021
5. go-kit

   locked and limited conversation to collaborators on Oct 17, 2021