Add file name and line number to context about log15 HOT 16 CLOSED

I guess the third option is something like this: https://github.com/wyc/funclog

from log15.

As an attempt to measure the minimum overhead implied by approach 3 I wrote this:

func BenchmarkLinenum(b *testing.B) {
    lg := New()
    lg.SetHandler(DiscardHandler())

    for i := 0; i < b.N; i++ {
        _, file, line, _ := runtime.Caller(0)
        lg.Info("test message", "file", file, "line", line)
    }
}

Which resulted in:

BenchmarkDiscard     5000000           444 ns/op
BenchmarkLinenum     1000000          2011 ns/op

from log15.

So it's about 4 times more expensive? And I guess we really have to stretch things to have it calculate the runtime caller only the first time then store it somewhere? At least then the overhead would be minimal.

from log15.

@ChrisHines Can you open a pull request to include that benchmark? I'd like to include it in the test suite.

That seems like significant overhead, but the truth is that the JsonFromat and LogfmtFormat are so slow right now that the cost is not that bad compared to what they cost. It would look bad if we eventually make them faster, though.

@gust1n I like the caching approach a lot. We'd have to limit size of the cache, but I doubt it would ever come close to being full because the number of logging call sites in a program is small (even for large projects). The other caveat is that cache access would need to be faster than the cost of runtime.

There's a fourth option, which is more unorthodox: offer a command that does a source transformation to automatically add in filename and line number as context to every logging call. This would increase binary size (again by a small amount) and require an extra build step (until go generate becomes a thing), but it would have zero runtime cpu/memory cost.

from log15.

PR #19 contains the new benchmark.

from log15.

But getting the cache address must be faster, right? Since (as you said) the number of log calls is probably at most in the hundreds or even <100. But how would we key the cache to differentiate the calls?

from log15.

Here is another data point. I added another benchmark to measure the overhead of just passing two context values separate from calling runtime.Caller to get the values:

func BenchmarkTwoCtxVals(b *testing.B) {
    lg := New()
    lg.SetHandler(DiscardHandler())

    for i := 0; i < b.N; i++ {
        file, line := "bench_test.go", 36
        lg.Info("test message", "file", file, "line", line)
    }
}

Which resulted in:

BenchmarkDiscard         5000000               433 ns/op
BenchmarkTwoCtxVals      1000000              1359 ns/op
BenchmarkLinenum         1000000              2000 ns/op

So the majority of the overhead is in passing the additional arguments to the logger. If we were to collect line number information on every call I wonder if adding two fields to the Record struct would be more efficient.

from log15.

Interesting. Yeah, after doing some benchmarking myself, it looks like when you're just passing through a line/number as part of the context you're dealing with overhead from the normalize step + appending to the logger's existing context.

That being said, here's some perspective:

BenchmarkDiscard    10000000           351 ns/op
BenchmarkLinenum     1000000          1445 ns/op
BenchmarkLogfmtNoCtx      500000          5170 ns/op
BenchmarkJsonNoCtx    500000          6360 ns/op
BenchmarkTwoCtxVals  2000000           847 ns/op

Adding linenumbers is a small overhead compared to the current cost of formatting that I think it makes sense to worry about optimizing later if it ever becomes an issue for someone.

We can add them as fields in the Record structure. The question is how to include them in the output. We could do:

func SrcInfoHandler(h Handler) Handler {
    return FuncHandler(func (r *Record) {
        r.Ctx = append(r.Ctx, "src", r.SrcFile, "line", r.SrcLine)
        h.Log(r)
    }
}

This will work with no API changes for all formatting handlers. But conceptually, it feels like this is just a formatting issue and should be an option to the various formatters like:

func JsonFormatEx(pretty, lineSeparated, includeSrcInfo bool) Format

This would have to be added to each formatter, though, and necessitate an API change.

Thoughts?

from log15.

I would go with your first suggestion. It has the benefits of not breaking the current API and sticking with the overall architecture of wrapped handlers, which is more flexible.

I don't agree that it is conceptually a formatting issue. In my mind Handlers are concerned with routing and content, and Formatters are concerned with layout. The choice to include some fields or not seems more like a content choice. Besides that, adding a special bool argument to all the formatters seems wrong because it isn't related to the other functionality of the formatters. Why should a JsonFormatter need to know whether to include the source fields. It should be focused on outputing Json for all the fields given to it.

Inspired by gust1n's example linked above I also think we should collect the pc value returned from runtime.Callers. That would allow handlers or formatters to derive additional information using runtime.FuncForPC. That opens the door to automatically logging the function name if desired.

from log15.

Can't we simply add a method that acts as that bool value in option 2, either making it a global option like

log.IncludeSrcInfo = true

which will include it in all handlers or extending the Handler interface to something like

Log(r *Record)
IncludeSrcInfo(include bool)

I guess option 2 is way to clunky and also forces anyone with custom handlers to implement this new method. But somehow it feels right to have this as an option, probably even with default = false, I don't think all people want this feature.

from log15.

I agree with the goal of keeping it optional.

I don't like adding a method to the Handler interface, it breaks the API and most handlers are not concerned with the choice to include source info anyway. It would also lead to confusion for the handlers that wrap other handlers. What happens if each handler in a chain had a different idea about whether to include source info?

Perhaps this design seems difficult only because the Handler and Format interfaces are too similar.

type Handler interface {
    Log(r *Record) error
}

type Format interface {
    Format(r *Record) []byte
}

If we were to break the API, I would propose a more fundamental change. Change Format to

type Format interface {
    Format(ctx []interface{}) []byte
}

At the same time we would write Handlers that controlled which of the Time, Lvl, Msg, [PC, Src, Linenum] were passed to the Formats.

This change removes the ambiguity about which part of the package is responsible for processing Records. There is already evidence that the code wants to go this direction in the LogfmtFormat:

func LogfmtFormat() Format {
    return FormatFunc(func(r *Record) []byte {
        common := []interface{}{"t", r.Time, "lvl", r.Lvl, "msg", r.Msg}
        buf := &bytes.Buffer{}
        logfmt(buf, append(common, r.Ctx...), 0)
        return buf.Bytes()
    })
}

This change would make Handlers and Formats more orthogonal.

from log15.

I agree completely. You guys have articulated this better than I could have. @ChrisHines I like your suggestions for the next API rev to make them more orthogonal. @gust1n yes, I agree these should be optionally included in your context. I'm proposing the following:

3 new fields in *Record.

type Record struct {
   ...
   CallFile string
   CallLine int
   CallPC int
}

And a new handler to optionally include these values in the context:

func AddCallCtxHandler(h Handler) Handler {
    return FuncHandler(func (r *Record) {
        r.Ctx = append(r.Ctx, "src", r.SrcFile, "line", r.SrcLine)
        h.Log(r)
    }
}

Thoughts on names for these? "src" seems okay, but "call" might describe this better. "AddCallCtxHandler" is a little too verbose for my taste, but I've already unfortunately committed to a 'Handler' suffix. Suggestions?

EDIT: accidentally submitted this before I'd finished writing

from log15.

I agree with your proposal with one minor nit.

The CallPC field should be of type uintptr to match the type returned from runtime.Caller.

Names are always hard. I suggest that whatever key names the Handler is adding to the context are a good hint to the name of the Handler. If we go with "src" and "line" then AddSrcLineHandler seems appropriate. My initial thought was to use "file" instead of "src", but "file" could easily collide with a common key name in client code. Another (perhaps less pure) approach would be to only add one key to the context like so:

func AddCallHandler(h Handler) Handler {
    return FuncHandler(func (r *Record) {
        r.Ctx = append(r.Ctx, "call", fmt.Sprintf("%s:%d", r.CallFile, r.CallLine))
        h.Log(r)
    }
}

from log15.

Going one step farther we can add optional support for including the function name. I wrote a quick benchmark and learned that calling runtime.FuncForPC to retrieve the function name incurs almost no overhead (less than adding an additional key/value pair to the context).

func AddCallHandler(h Handler, withFunc bool) Handler {
    return FuncHandler(func (r *Record) {
        r.Ctx = append(r.Ctx, "call", fmt.Sprintf("%s:%d", r.CallFile, r.CallLine))
        if withFunc {
            if fn := runtime.FuncForPC(r.PC); fn != nil {
                r.Ctx = append(r.Ctx, "func", fn.Name())
            }
        }
        h.Log(r)
    }
}

from log15.

👍

from log15.

I'm going to work on a PR for this issue.

from log15.