Add WithLazy Logger method #1319

jquirke · 2023-08-14T01:43:55Z

As per internal Uber discussion

logger.go

rabbbit

My internal comment was meant as "we should report this before making internal changes", so you went further than I thought we would here - thanks!

It does look surprisingly clean, I thought it'd be more painful.

logger.go

rabbbit · 2023-08-14T07:22:25Z

zapcore/deferred_with.go

+	})
+}
+
+func (d *deferredWithCore) With(fields []Field) Core {


from internal discussion

I still wonder if this couldn't do something like

func (d *deferredWithCore) With(fields []Field) Core { return &deferredWithCore{ Core: core, fields: d.fields+fields, // paraphrasing, likely as a new copy }

it should be cheaper to both create, but also use later on?

Yeah I like it, its even more performant on the Benchmark5WithsDeferredUsed, I just need to think through it a bit more carefully, is it correct in all cases?

goos: darwin goarch: arm64 pkg: go.uber.org/zap Benchmark5WithsUsed-10 496836 2543 ns/op Benchmark5WithsNotUsed-10 570384 2251 ns/op Benchmark5WithsDeferredUsed-10 770275 1456 ns/op Benchmark5WithsDeferredNotUsed-10 2621470 464.9 ns/op

Seems to be, added another test TestLoggerChainedWith

wait, so you totally gave up on this? What's the reasoning?

It could still have worked, you just needed to return a new core, right?

I haven't given up.
I wish to write the tests that show the difference in behaviour first with the sync.Once core, and then port in the "mway" style pattern in zapfx context_core.go once I have confidence in the tests. Just been busy with day to day tasks :)

I updated the tests - TestLoggerDeferredWithCapture

They are still using the "sync.Once" new core pattern, please check if the behaviour looks correct. Then I will try the mway pattern.

Using your pattern, there seems to be a regression

--- FAIL: TestLoggerDeferredWithCapture (0.00s) --- FAIL: TestLoggerDeferredWithCapture/deferred_logger_evaluates_at_time_of_logging,_and_stops_deferring_on_children (0.00s) logger_test.go:221: Error Trace: /Users/qjeremy/zap/logger_test.go:221 Error: Not equal: expected: zap.res{A:[]int{2}, B:[]int{2}, C:[]int{2}, D:[]int{3}, E:[]int{4}} actual : zap.res{A:[]int{4}, B:[]int{4}, C:[]int{2}, D:[]int{4}, E:[]int{4}} Diff: --- Expected +++ Actual @@ -2,6 +2,6 @@ A: ([]int) (len=1) { - (int) 2 + (int) 4 }, B: ([]int) (len=1) { - (int) 2 + (int) 4 }, @@ -11,3 +11,3 @@ D: ([]int) (len=1) { - (int) 3 + (int) 4 }, Test: TestLoggerDeferredWithCapture/deferred_logger_evaluates_at_time_of_logging,_and_stops_deferring_on_children

codecov · 2023-08-14T10:07:07Z

Codecov Report

Merging #1319 (f5b6618) into master (99f1811) will increase coverage by 0.00%.
The diff coverage is 100.00%.

@@           Coverage Diff           @@
##           master    #1319   +/-   ##
=======================================
  Coverage   98.41%   98.42%           
=======================================
  Files          52       53    +1     
  Lines        3471     3493   +22     
=======================================
+ Hits         3416     3438   +22     
  Misses         46       46           
  Partials        9        9

Files Changed	Coverage Δ
logger.go	`96.66% <100.00%> (+0.11%)`	⬆️
zapcore/lazy_with.go	`100.00% <100.00%> (ø)`

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

abhinav

The With state tracking isn't right.

Separately from that, you can probably drop the synchronization and the overhead of the atomic sync.Once if you do something like @mway's context core.

As a reminder, the contract for writing with Cores is:

if ce := core.Check(e, ce); ce != nil { ce.Write(fields) }

Where core.Check is responsible for adding the core to the CheckedEntry with CheckedEntry.AddCore, and ce.Write eventually calls Core.Write on all added cores.

@mway's context core takes advantage of the fact that Core.Write will never be called directly, only after being added to the CheckedEntry with AddCore. It does so by splitting the core into two: the bit that just tracks Withs and everything else, and the writer bit that is used with Check and Write.

So the way that works out is something like this:

type myCore struct{ /* some state */ }

func (*myCore) With(fields []Field) Core { return &myCore{...} }

func (c *myCore) Check(e Entry, ce *CheckedEntry) *CheckedEntry {
  ce.AddCore(&myCoreWriter{c: c.wrappedCore, /* stuff */})
  // This is the important bit.
  // The core added to the CheckedEntry
  // is a completely different object that has the relevant state
  // computed.
  // You can even pool relevant things here,
  // and release them in myCoreWriter.Write.
}

type myCoreWriter struct{ /* state */ }

func (*myCoreWriter) Write(fields []Field) {
  // ...
}

The Write method on myCore panics because that's invalid usage that breaks the contract. The non-Write methods on myCoreWriter delegate or panic as necessary.

abhinav · 2023-08-14T12:23:26Z

zapcore/deferred_with.go

+	d.fields = allFields
+	return d


This isn't right. With should return a new core, not modify the original core.

This will break if, e.g.

parent := // ... child1 := parent.With([]Field{f1, f2}) child2 := parent.With([]Field{f3, f4})

zap/zapcore/core.go

Lines 81 to 85 in 5da8736

func (c *ioCore) With(fields []Field) Core {

clone := c.clone()

addFields(clone.enc, fields)

return clone

}

interestingly its not breaking, which surprised me (see the cross talk test)
I'll have to have a look into why later with the debugger

EDIT: Oh I see, its because the test case is testing the Logger, not the Core, so the With's are isolated, but I agree, it is not correct.

abhinav · 2023-08-14T12:42:53Z

Also, API-wise, I'm happy to be convinced otherwise, but my gut says this shouldn't be an Option.
I'll welcome input from others here as well, but I don't think this is a global logger-level choice.
I would guess this is a per-With call choice?
Because whether those fields can be deferred or not, what their lifetimes are, that's known separately at each call site.
Would a logger.WithDeferred (or something similarly named) that initializes the deferred core be more appropriate?

rabbbit · 2023-08-14T13:01:34Z

Because whether those fields can be deferred or not, what their lifetimes are, that's known separately at each call site.

Yeah, this was a bit unclear. And you can implicitly end up with some loggers behaving differently than others.

On the other hand, having it per-logger means you can write logger.With(String("a", "b").With(String("c", "d") and the optimization still holds. Having explicit WithDeferred on each call site will likely be hard to remember, and then unused.

We were wondering - what's the exact reason for not deferring always? Would that be a very strongly impossible option?

abhinav · 2023-08-14T13:25:12Z

We were wondering - what's the exact reason for not deferring always? Would that be a very strongly impossible option?

The contract right of With right now is that the value inside Field is evaluated "right now" and then it's yours to do whatever with -- modify state, etc. So if you have a value in the Interface field that is modified after the With, it'll behave differently.

For example, here's a convoluted test that passes today:

func Example_modifyAfterWith() {
	logger := zap.NewExample()
	defer logger.Sync()

	var x int
	arr := zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error {
		enc.AppendInt(x)
		return nil
	})

	logger = logger.With(zap.Array("a", arr))
	x = 1
	logger = logger.With(zap.Array("b", arr))
	x = 2
	logger.Info("hello", zap.Array("c", arr))

	// Output:
	// {"level":"info","msg":"hello","a":[0],"b":[1],"c":[2]}
}

If you always defer Withs (by adding the option to the logger), you'll get:

{"level":"info","msg":"hello","a":[2],"b":[2],"c":[2]}

jquirke · 2023-08-14T18:10:18Z

The contract right of With right now is that the value inside Field is evaluated "right now" and then it's yours to do whatever with -- modify state, etc. So if you have a value in the Interface field that is modified after the With, it'll behave differently.

Do you think then that perhaps we express in documentation and tests that this difference in behaviour will result and the consumer can then decide whether it is the right approach for them?

jquirke · 2023-08-14T18:15:35Z

On the other hand, having it per-logger means you can write logger.With(String("a", "b").With(String("c", "d") and the optimization still holds. Having explicit WithDeferred on each call site will likely be hard to remember, and then unused

I mean the inspiration for this was for 99% cases, this greatly reduced heap allocations across the application, I tested this simply by doing

fx.Decorate(func(l *zap.Logger) *zap.Logger {
   return l.WithOptions(zap.DeferWith())
}),

At the same time however, a global change to the top level logger may have unexpected behaviour as you mention with the way that Withs are evaluated. However, the most common case of this is an internal zapfx.Context(...) use case at Uber which is very expensive to pre-evaluate

jquirke · 2023-09-03T22:24:29Z

Bump, whats the verdict on this. I've provided and implemented a menu of choices and there is no consensus reached and it looks like this PR might otherwise end up on the graveyard.

1/ Logger level option: we all agreed its wrong.
da9f746

2/ "Breaking" change (adding zap/Logger.WithLazy). Can't realise benefits immediately.
1505868

EDIT: adding a method to a struct is a breaking change, but it is a "weaker" breaking change and it seems that the history shows it is permitted without bumping the major version (e.g. #1273) in this project

3/ /exp/ Wrapper implementing WithLazy for immediate use. Rather cumbersome to consume in client code due to the enclosing type.
ba51079

4/ With level option e.g. logger.WithOption(LazyFields(....))). Not breaking, but needs to be supported forever. Can realise benefits immediately. Syntax is clunkier. Maybe not too hard in practice.
78257ca

5/ Internal fork of our (Uber) own OSS project, but this seems absurd

sywhang · 2023-09-07T20:31:56Z

Sorry I'm late to the game here. Looked through the different options @jquirke put up, and IMO the best option here is 1505868 (adding WithLazy method to Logger). As I chatted offline with Jeremy, this level of change is something we've done in the past and is compatible enough for us to accept.

As for putting in exp/ i don't see much benefit added from doing so, since the API seems pretty solid. For other things we put in exp/ it was either because it depended on experimental packages itself (i.e. slog) or only for a temporary solution to bake things in a bit.

Thoughts? @abhinav @mway @prashantv

jquirke · 2023-09-07T22:06:46Z

Sorry I'm late to the game here. Looked through the different options @jquirke put up, and IMO the best option here is 1505868 (adding WithLazy method to Logger). As I chatted offline with Jeremy, this level of change is something we've done in the past and is compatible enough for us to accept.

Cool. Switched to the WithLazy implementation without exp (2)

abhinav · 2023-09-08T00:45:31Z

[..] IMO the best option here is 1505868 (adding WithLazy method to Logger). [..]

Thoughts? @abhinav @mway @prashantv

Agreed.
I haven't had a chance to review the change again since the original couple iterations, but yeah, I'm on-board with a WithLazy method.

One common performance problem we see is that Loggers and their children may be composed with one or more With() invocations, but the logger/s is/are not used in most invocations of the function. For example, an author might initialise a logger with some function-scoped contexttual information at the start of a function: ``` l := logger.With(zap.String("tripID", trip.ID)) ``` but never use 'l' except in seldom taken branches. However, in the majority cases the expensive with operation has been performed which can result in the wasted effort (in terms of alloc, CPU) of cloning (e.g of the JSON encoder). This commit adds a new method on Logger, WithLazy, which defers all of this expense until the time of first use. This creates considerable performance improvement for the cases where a logger is not regularly used. This does require an explicit opt in, because the author must be aware there is the possibility of objects living longer than the scope of the method wherein WithLazy is called. Additionally, cases such as logging objects where the object is modified between the WithLazy and logging that will reflect the state of the field at log time, rather than With time, which is something authors need to be aware of. ``` % go test -bench=Benchmark5With goos: darwin goarch: arm64 pkg: go.uber.org/zap/exp/lazylogger Benchmark5WithsUsed-10 527385 2390 ns/op Benchmark5WithsNotUsed-10 563468 2246 ns/op Benchmark5WithLazysUsed-10 475064 2642 ns/op Benchmark5WithLazysNotUsed-10 2255786 527.4 ns/op PASS ``` Furthermore, one core microservice in Uber has seen a reduction of 10% heap allocation by simply using this feature.

abhinav

I'm a bit busy this week, so I can't give it a full review. I've pushed a couple minor tweaks.

I don't know if the tests already cover this but I want to make sure at least the following are handled, specifically with regards to evaluation of fields.

WithLazy.With
WithLazy.WithLazy

logger_test.go

This makes for slightly more readable code.

Excessive detail in var name.

Test and assert behaviour of .With.WithLazy, .WithLazy.WithLazy, .WithLazy.With combinations.

jquirke · 2023-09-10T02:24:04Z

WithLazy.With

WithLazy.WithLazy

Added test for With.WithLazy, WithLazy.With, WithLazy.WithLazy
Also sorry I force pushed, overwriting your doco cleanup. If you have the commit locally do you mind putting it back, apologies.

Split the doc strings into multiple paragraphs, adjust the wording.

abhinav · 2023-09-10T03:57:16Z

Also sorry I force pushed, overwriting your doco cleanup. If you have the commit locally do you mind putting it back, apologies.

Not a problem! Pushed it back.

sywhang · 2023-09-14T20:13:24Z

The table tests hurts the readability of the tests a little bit, but we can address these later.

Thanks!

jquirke commented Aug 14, 2023

View reviewed changes

logger.go Outdated Show resolved Hide resolved

logger.go Outdated Show resolved Hide resolved

logger.go Outdated Show resolved Hide resolved

logger.go Outdated Show resolved Hide resolved

jquirke commented Aug 14, 2023

View reviewed changes

logger.go Outdated Show resolved Hide resolved

jquirke force-pushed the master branch 5 times, most recently from 34182f2 to 2d6ccc7 Compare August 14, 2023 03:24

jquirke changed the title ~~[Work in progress] Proof of concept deferred withs~~ Add an option to defer expensive With operations Aug 14, 2023

jquirke force-pushed the master branch 7 times, most recently from f36dab4 to 2892baa Compare August 14, 2023 06:35

rabbbit reviewed Aug 14, 2023

View reviewed changes

jquirke force-pushed the master branch 4 times, most recently from 7ffacf5 to ce273cd Compare August 14, 2023 09:48

jquirke force-pushed the master branch 3 times, most recently from e3cba1e to 33743dc Compare August 14, 2023 10:46

abhinav reviewed Aug 14, 2023

View reviewed changes

jquirke force-pushed the master branch from 78257ca to 1505868 Compare September 7, 2023 22:06

jquirke force-pushed the master branch from 1505868 to c4cb8bc Compare September 7, 2023 22:08

jquirke changed the title ~~Add LazyFields Logger option~~ Add WithLazy Logger method Sep 8, 2023

jquirke force-pushed the master branch 4 times, most recently from f8116ee to a4d3109 Compare September 8, 2023 07:43

jquirke force-pushed the master branch from a4d3109 to f600804 Compare September 8, 2023 18:35

abhinav mentioned this pull request Sep 9, 2023

support non-clone zapcore #1348

Open

abhinav reviewed Sep 9, 2023

View reviewed changes

logger_test.go Outdated Show resolved Hide resolved

Explicitly place table tests in named variable

edc75e6

This makes for slightly more readable code.

jquirke force-pushed the master branch from b538e82 to edc75e6 Compare September 10, 2023 01:25

jquirke and others added 4 commits September 9, 2023 18:34

Merge branch 'uber-go:master' into master

c3f187d

Reduce verbosity of test name variable

7389c46

Excessive detail in var name.

gofmt

c3eec45

Add coverage of chained With/WithLazy combinations

cfeb077

Test and assert behaviour of .With.WithLazy, .WithLazy.WithLazy, .WithLazy.With combinations.

abhinav added 2 commits September 9, 2023 20:54

doc(WithLazy): Split into multiple paragraphs

1d9848c

Split the doc strings into multiple paragraphs, adjust the wording.

chore(bench): withMethodExpr => withMethod

f5b6618

sywhang approved these changes Sep 10, 2023

View reviewed changes

sywhang merged commit c17272e into uber-go:master Sep 14, 2023
6 checks passed

defval mentioned this pull request Oct 31, 2023

Extend WithLazy method to SugaredLogger #1377

Closed

markuspeloquin mentioned this pull request Apr 3, 2024

Race using WithLazy #1426

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add WithLazy Logger method #1319

Add WithLazy Logger method #1319

jquirke commented Aug 14, 2023

rabbbit left a comment

rabbbit Aug 14, 2023

jquirke Aug 14, 2023

jquirke Aug 14, 2023

rabbbit Aug 16, 2023

jquirke Aug 17, 2023

jquirke Aug 17, 2023

jquirke Aug 17, 2023 •

edited

codecov bot commented Aug 14, 2023 •

edited

abhinav left a comment

abhinav Aug 14, 2023

jquirke Aug 14, 2023 •

edited

abhinav commented Aug 14, 2023

rabbbit commented Aug 14, 2023

abhinav commented Aug 14, 2023

jquirke commented Aug 14, 2023 •

edited

jquirke commented Aug 14, 2023

jquirke commented Sep 3, 2023 •

edited

sywhang commented Sep 7, 2023

jquirke commented Sep 7, 2023

abhinav commented Sep 8, 2023

abhinav left a comment

jquirke commented Sep 10, 2023

abhinav commented Sep 10, 2023

sywhang commented Sep 14, 2023

	func (c *ioCore) With(fields []Field) Core {
	clone := c.clone()
	addFields(clone.enc, fields)
	return clone
	}

Add WithLazy Logger method #1319

Add WithLazy Logger method #1319

Conversation

jquirke commented Aug 14, 2023

rabbbit left a comment

Choose a reason for hiding this comment

rabbbit Aug 14, 2023

Choose a reason for hiding this comment

jquirke Aug 14, 2023

Choose a reason for hiding this comment

jquirke Aug 14, 2023

Choose a reason for hiding this comment

rabbbit Aug 16, 2023

Choose a reason for hiding this comment

jquirke Aug 17, 2023

Choose a reason for hiding this comment

jquirke Aug 17, 2023

Choose a reason for hiding this comment

jquirke Aug 17, 2023 • edited

Choose a reason for hiding this comment

codecov bot commented Aug 14, 2023 • edited

Codecov Report

abhinav left a comment

Choose a reason for hiding this comment

abhinav Aug 14, 2023

Choose a reason for hiding this comment

jquirke Aug 14, 2023 • edited

Choose a reason for hiding this comment

abhinav commented Aug 14, 2023

rabbbit commented Aug 14, 2023

abhinav commented Aug 14, 2023

jquirke commented Aug 14, 2023 • edited

jquirke commented Aug 14, 2023

jquirke commented Sep 3, 2023 • edited

sywhang commented Sep 7, 2023

jquirke commented Sep 7, 2023

abhinav commented Sep 8, 2023

abhinav left a comment

Choose a reason for hiding this comment

jquirke commented Sep 10, 2023

abhinav commented Sep 10, 2023

sywhang commented Sep 14, 2023

jquirke Aug 17, 2023 •

edited

codecov bot commented Aug 14, 2023 •

edited

jquirke Aug 14, 2023 •

edited

jquirke commented Aug 14, 2023 •

edited

jquirke commented Sep 3, 2023 •

edited