rs / xlog

xlog is a logger for net/context aware HTTP applications
MIT License
139 stars 13 forks source link

Add option to opt-out of sync.Pool use #17

Closed kevinconway closed 7 years ago

kevinconway commented 7 years ago

When the http.Handler wrapped by the xlog middleware returns the internal state of the logger is cleared and the instance is returned to the pool. However, there are quite a few cases in which a reference to the logger escapes the context of the handler and ends up in a background task.

When passing instances between goroutines we've established the habbit of making a copy to pass along to avoid this issue. However, when interacting with third party code we don't always have this as an option. For cases when it's absolutely necessary, we'd like to disable the sync.Pool optimisation in favour of persistent logger references.

This patch adds the option in a backwards compatible way. The default behaviour is maintained and only adding a new, explicit option to disable the optimisation will trigger the new behaviour.

kevinconway commented 7 years ago

We recently experimented with disabling the pool and could clearly see the GC and memory impact. It's certainly not a free option. However, we're finding that it's easier to pay the higher memory and CPU cost than it is to modify 3rd party libs that may hold onto logger references and the cognitive cost on developers to remember which cases need a call to xlog.Copy and which ones don't.

If this PR is acceptable then I'd like to offer the same option in xstats as we are experiencing similar issues there.

kevinconway commented 7 years ago

This PR and the PR to xstats are failing in the pre-1.7 jobs due to context. However, I can't see in my PRs where I've modified the imports in a way that would cause this. Is it possible the test runner had a regression since the last PR went through?

rs commented 7 years ago

You may want to migrate to github.com/rs/zerolog which does not require a pool and is gc friendly.

kevinconway commented 7 years ago

The issues with zerolog adoption are that 1) it's a significantly more amount work to commit a team to compared to adjusting our existing configuration and 2) the feature set offered by zerolog is not a perfect match to xlog.

One feature we use, in particular, is the ability to add a field to the logger reference and see that field appear in logs emitted by other code using the same logger reference. It makes the SetFiedl() call bi-directional with respect to a middleware chain. We use this feature extensively to annotate access logs with additional correlating fields that aren't known until the wrapped handler executes in order to make operations and log searching easier.

As far as I can tell, the zerolog package does not allow for mutation of a logger in-place and enforces that we create a child logger with new fields that is inaccessible to middleware like the HTTP access logger.

rs commented 7 years ago

That is a very good point and I think this is a lack in the zerolog documentation. If you make a copy of the logger with more fields and store it back in the context, it will update the original pointer, making this change visible to all your middleware. See by yourself: https://github.com/rs/zerolog/blob/2ed2f2c974489526d10329dae76d0f175684109a/ctx.go#L16.

I will update the documentation to explain this better.

kevinconway commented 7 years ago

That's good to know. I think that will provide us a migration path in the long term. However, it's still a non-trivial amount of work to change tooling. If at all possible, I'd like to find a way of introducing this feature so we can cut down on the panics caused by concurrent use of the logger by goroutines and the handler goroutine when it attempts to clear the logger state.

rs commented 7 years ago

Ok. Please remove the two versions of Go from travis that make the tests fail and resubmit so I can merge.

kevinconway commented 7 years ago

Done. I did the same for the PR to xstats as well.