Add a sync.Pool for Entry passed to HandleLog

This commit does several things:

* Makes it into one Entry strcut
* Creates a object pool for Entry objects passed to HandleLog
* This means that if someone wants to use an Event after HandleLog, he/she needs to make a copy via entry.Clone.
* This is unfortunate, but the performance benefits are obvious, especially when the common context (fields) are big.

```bash
name                                  old time/op    new time/op    delta
Logger_common_context-10                 118ns ± 9%      62ns ± 4%   -47.23%  (p=0.029 n=4+4)
Logger_common_context_many_fields-10    2.35µs ± 0%    2.17µs ± 0%    -7.79%  (p=0.029 n=4+4)

name                                  old alloc/op   new alloc/op   delta
Logger_common_context-10                  176B ± 0%        0B       -100.00%  (p=0.029 n=4+4)
Logger_common_context_many_fields-10    1.49kB ± 0%    0.00kB       -100.00%  (p=0.029 n=4+4)

name                                  old allocs/op  new allocs/op  delta
Logger_common_context-10                  2.00 ± 0%      0.00       -100.00%  (p=0.029 n=4+4)
Logger_common_context_many_fields-10      2.00 ± 0%      0.00       -100.00%  (p=0.029 n=4+4)
```

And the "Zap benchmarks":

```bash
name                                   old time/op    new time/op    delta
DisabledWithoutFields/bep/log-10         0.27ns ± 2%    0.29ns ± 3%   +7.22%  (p=0.029 n=4+4)
DisabledAccumulatedContext/bep/log-10    0.25ns ± 2%    0.26ns ± 2%   +2.45%  (p=0.029 n=4+4)
DisabledAddingFields/bep/log-10          0.38ns ± 1%    0.39ns ± 2%     ~     (p=0.057 n=4+4)
WithoutFields/bep/log-10                  336ns ± 1%     302ns ± 1%  -10.20%  (p=0.029 n=4+4)
AccumulatedContext/bep/log-10            4.68µs ± 3%    4.36µs ± 2%   -6.73%  (p=0.029 n=4+4)
AddingFields/bep/log-10                  5.11µs ± 1%    5.06µs ± 1%     ~     (p=0.057 n=4+4)

name                                   old alloc/op   new alloc/op   delta
DisabledWithoutFields/bep/log-10          0.00B          0.00B          ~     (all equal)
DisabledAccumulatedContext/bep/log-10     0.00B          0.00B          ~     (all equal)
DisabledAddingFields/bep/log-10           0.00B          0.00B          ~     (all equal)
WithoutFields/bep/log-10                   465B ± 0%      385B ± 0%  -17.20%  (p=0.029 n=4+4)
AccumulatedContext/bep/log-10            5.49kB ± 0%    5.09kB ± 0%   -7.32%  (p=0.029 n=4+4)
AddingFields/bep/log-10                  6.36kB ± 0%    5.96kB ± 0%   -6.23%  (p=0.029 n=4+4)

name                                   old allocs/op  new allocs/op  delta
DisabledWithoutFields/bep/log-10           0.00           0.00          ~     (all equal)
DisabledAccumulatedContext/bep/log-10      0.00           0.00          ~     (all equal)
DisabledAddingFields/bep/log-10            0.00           0.00          ~     (all equal)
WithoutFields/bep/log-10                   7.00 ± 0%      6.00 ± 0%  -14.29%  (p=0.029 n=4+4)
AccumulatedContext/bep/log-10              56.0 ± 0%      54.0 ± 0%   -3.57%  (p=0.029 n=4+4)
AddingFields/bep/log-10                    65.0 ± 0%      63.0 ± 0%   -3.08%  (p=0.029 n=4+4)
```

Author: bep

entry.go

@@ -9,34 +9,22 @@ import (
 
 // assert interface compliance.
 var (
-	_ LevelLogger = (*EntryFields)(nil)
 	_ LevelLogger = (*Entry)(nil)
 )
 
-// EntryFields represents a single log entry at a given log level.
-type EntryFields struct {
-	Logger *logger `json:"-"`
-	Fields Fields  `json:"-"`
-	Level  Level   `json:"level"`
-}
-
-// Entry holds a Entry with a Message and a Timestamp.
-// This is what is actually logged.
+// Entry represents a single log entry at a given log level.
 type Entry struct {
-	*EntryFields
+	logger *logger
+
 	Timestamp time.Time `json:"timestamp"`
+	Level     Level     `json:"level"`
+	Fields    Fields    `json:"-"`
 	Message   string    `json:"message"`
 }
 
-// FieldsDistinct returns a list of fields with duplicate names removed,
-// keeping the last.
-func (e *EntryFields) FieldsDistinct() Fields {
-	return e.distinctFieldsLastByName()
-}
-
 func (e Entry) MarshalJSON() ([]byte, error) {
 	fields := make(map[string]any)
-	for _, f := range e.FieldsDistinct() {
+	for _, f := range e.Fields {
 		fields[f.Name] = f.Value
 	}
 
@@ -51,18 +39,18 @@ func (e Entry) MarshalJSON() ([]byte, error) {
 }
 
 // NewEntry returns a new entry for `log`.
-func NewEntry(log *logger) *EntryFields {
-	return &EntryFields{
-		Logger: log,
+func NewEntry(log *logger) *Entry {
+	return &Entry{
+		logger: log,
 	}
 }
 
-func (e EntryFields) WithLevel(level Level) *EntryFields {
+func (e Entry) WithLevel(level Level) *Entry {
 	e.Level = level
 	return &e
 }
 
-func (e *EntryFields) WithFields(fielder Fielder) *EntryFields {
+func (e *Entry) WithFields(fielder Fielder) *Entry {
 	if e.isLevelDisabled() {
 		return e
 	}
@@ -71,14 +59,14 @@ func (e *EntryFields) WithFields(fielder Fielder) *EntryFields {
 	return &x
 }
 
-func (e *EntryFields) WithField(key string, value any) *EntryFields {
+func (e *Entry) WithField(key string, value any) *Entry {
 	if e.isLevelDisabled() {
 		return e
 	}
 	return e.WithFields(Fields{{key, value}})
 }
 
-func (e *EntryFields) WithDuration(d time.Duration) *EntryFields {
+func (e *Entry) WithDuration(d time.Duration) *Entry {
 	if e.isLevelDisabled() {
 		return e
 	}
@@ -89,7 +77,7 @@ func (e *EntryFields) WithDuration(d time.Duration) *EntryFields {
 //
 // The given error may implement .Fielder, if it does the method
 // will add all its `.Fields()` into the returned entry.
-func (e *EntryFields) WithError(err error) *EntryFields {
+func (e *Entry) WithError(err error) *Entry {
 	if err == nil || e.isLevelDisabled() {
 		return e
 	}
@@ -118,48 +106,52 @@ func (e *EntryFields) WithError(err error) *EntryFields {
 	return ctx
 }
 
-func (e *EntryFields) isLevelDisabled() bool {
-	return e.Level < e.Logger.Level
+func (e *Entry) isLevelDisabled() bool {
+	return e.Level < e.logger.Level
 }
 
 // Log a message at the given level.
-func (e *EntryFields) Log(s fmt.Stringer) {
-	e.Logger.log(e, s)
+func (e *Entry) Log(s fmt.Stringer) {
+	e.logger.log(e, s)
+}
+
+// Clone returns a new Entry with the same fields.
+func (e *Entry) Clone() *Entry {
+	x := *e
+	x.Fields = make(Fields, len(e.Fields))
+	copy(x.Fields, e.Fields)
+	return &x
 }
 
-// distinctFieldsLastByName returns the fields with duplicate names removed,
-// keeping the rightmost field (last) with a given name.
-func (e *EntryFields) distinctFieldsLastByName() Fields {
-	fields := make(Fields, 0, len(e.Fields))
+func (e *Entry) reset() {
+	e.logger = nil
+	e.Level = 0
+	e.Fields = e.Fields[:0]
+	e.Message = ""
+	e.Timestamp = time.Time{}
+}
+
+// finalize populates dst with Level and  Fields merged from e and Message and Timestamp set.
+func (e *Entry) finalize(dst *Entry, msg string) {
+	dst.Message = msg
+	dst.Timestamp = e.logger.Clock.Now()
+	dst.Level = e.Level
+
+	// There mau be fields logged with the same name, keep the latest.
 	for i := len(e.Fields) - 1; i >= 0; i-- {
 		f := e.Fields[i]
 		var seen bool
-		for _, f2 := range fields {
+		for _, f2 := range dst.Fields {
 			if f.Name == f2.Name {
 				seen = true
 				break
 			}
 		}
 		if !seen {
 			// Insert first.
-			fields = append(fields, Field{})
-			copy(fields[1:], fields[:])
-			fields[0] = f
+			dst.Fields = append(dst.Fields, Field{})
+			copy(dst.Fields[1:], dst.Fields[:])
+			dst.Fields[0] = f
 		}
 	}
-
-	if len(fields) == 0 {
-		return nil
-	}
-
-	return fields
-}
-
-// finalize returns a copy of the Entry with Fields merged.
-func (e *EntryFields) finalize(msg string) *Entry {
-	return &Entry{
-		EntryFields: e,
-		Message:     msg,
-		Timestamp:   e.Logger.Clock.Now(),
-	}
 }

entry_test.go

@@ -15,38 +15,38 @@ func TestEntry_WithFields(t *testing.T) {
 
 	c := a.WithFields(Fields{{"foo", "hello"}, {"bar", "world"}})
 	d := c.WithFields(Fields{{"baz", "jazz"}})
-	qt.Assert(t, b.distinctFieldsLastByName(), qt.DeepEquals, Fields{{"foo", "bar"}})
-	qt.Assert(t, c.distinctFieldsLastByName(), qt.DeepEquals, Fields{{"foo", "hello"}, {"bar", "world"}})
-	qt.Assert(t, d.distinctFieldsLastByName(), qt.DeepEquals, Fields{{"foo", "hello"}, {"bar", "world"}, {"baz", "jazz"}})
+	qt.Assert(t, b.Fields, qt.DeepEquals, Fields{{"foo", "bar"}})
+	qt.Assert(t, c.Fields, qt.DeepEquals, Fields{{"foo", "hello"}, {"bar", "world"}})
+	qt.Assert(t, d.Fields, qt.DeepEquals, Fields{{"foo", "hello"}, {"bar", "world"}, {"baz", "jazz"}})
 
-	e := c.finalize("upload")
+	/*e := c.finalize("upload")
 	qt.Assert(t, "upload", qt.Equals, e.Message)
 	qt.Assert(t, Fields{{"foo", "hello"}, {"bar", "world"}}, qt.DeepEquals, e.Fields)
 	qt.Assert(t, InfoLevel, qt.Equals, e.Level)
-	qt.Assert(t, time.Now().IsZero(), qt.IsFalse)
+	qt.Assert(t, time.Now().IsZero(), qt.IsFalse)*/
 }
 
 func TestEntry_WithField(t *testing.T) {
 	a := NewLogger(LoggerConfig{Handler: NoopHandler, Level: InfoLevel}).WithLevel(InfoLevel)
 	b := a.WithField("foo", "baz").WithField("foo", "bar")
-	qt.Assert(t, a.distinctFieldsLastByName(), qt.IsNil)
-	qt.Assert(t, b.distinctFieldsLastByName(), qt.DeepEquals, Fields{{"foo", "bar"}})
+	qt.Assert(t, a.Fields, qt.IsNil)
+	qt.Assert(t, b.Fields, qt.DeepEquals, Fields{{"foo", "bar"}})
 }
 
 func TestEntry_WithError(t *testing.T) {
 	a := NewLogger(LoggerConfig{Handler: NoopHandler, Level: InfoLevel}).WithLevel(InfoLevel)
 	b := a.WithError(fmt.Errorf("boom"))
-	qt.Assert(t, a.distinctFieldsLastByName(), qt.IsNil)
-	qt.Assert(t, b.distinctFieldsLastByName(), qt.DeepEquals, Fields{{"error", "boom"}})
+	qt.Assert(t, a.Fields, qt.IsNil)
+	qt.Assert(t, b.Fields, qt.DeepEquals, Fields{{"error", "boom"}})
 }
 
 func TestEntry_WithError_fields(t *testing.T) {
 	a := NewLogger(LoggerConfig{Handler: NoopHandler, Level: InfoLevel}).WithLevel(InfoLevel)
 	b := a.WithError(errFields("boom"))
-	qt.Assert(t, a.distinctFieldsLastByName(), qt.IsNil)
+	qt.Assert(t, a.Fields, qt.IsNil)
 	qt.Assert(t,
 
-		b.distinctFieldsLastByName(), qt.DeepEquals, Fields{
+		b.Fields, qt.DeepEquals, Fields{
 			{"error", "boom"},
 			{"reason", "timeout"},
 		})
@@ -56,14 +56,14 @@ func TestEntry_WithError_fields(t *testing.T) {
 func TestEntry_WithError_nil(t *testing.T) {
 	a := NewLogger(LoggerConfig{Handler: NoopHandler, Level: InfoLevel}).WithLevel(InfoLevel)
 	b := a.WithError(nil)
-	qt.Assert(t, a.distinctFieldsLastByName(), qt.IsNil)
-	qt.Assert(t, b.distinctFieldsLastByName(), qt.IsNil)
+	qt.Assert(t, a.Fields, qt.IsNil)
+	qt.Assert(t, b.Fields, qt.IsNil)
 }
 
 func TestEntry_WithDuration(t *testing.T) {
 	a := NewLogger(LoggerConfig{Handler: NoopHandler, Level: InfoLevel}).WithLevel(InfoLevel)
 	b := a.WithDuration(time.Second * 2)
-	qt.Assert(t, b.distinctFieldsLastByName(), qt.DeepEquals, Fields{{"duration", int64(2000)}})
+	qt.Assert(t, b.Fields, qt.DeepEquals, Fields{{"duration", int64(2000)}})
 }
 
 type errFields string

handlers/cli/cli.go

@@ -67,7 +67,7 @@ func (h *Handler) HandleLog(e *log.Entry) error {
 
 	color.Fprintf(h.Writer, "%s %-25s", bold.Sprintf("%*s", h.Padding+1, level), e.Message)
 
-	for _, field := range e.FieldsDistinct() {
+	for _, field := range e.Fields {
 		if field.Name == "source" {
 			continue
 		}

handlers/memory/memory.go

@@ -23,6 +23,6 @@ func New() *Handler {
 func (h *Handler) HandleLog(e *log.Entry) error {
 	h.mu.Lock()
 	defer h.mu.Unlock()
-	h.Entries = append(h.Entries, e)
+	h.Entries = append(h.Entries, e.Clone())
 	return nil
 }

handlers/text/text.go

@@ -69,7 +69,7 @@ func (h *Handler) HandleLog(e *log.Entry) error {
 	ts := time.Since(start) / time.Second
 	fmt.Fprintf(h.Writer, "\033[%dm%6s\033[0m[%04d] %-25s", color, level, ts, e.Message)
 
-	for _, f := range e.FieldsDistinct() {
+	for _, f := range e.Fields {
 		fmt.Fprintf(h.Writer, " \033[%dm%s\033[0m=%v", color, f.Name, f.Value)
 	}
 

interface.go

@@ -8,7 +8,7 @@ import (
 // Logger is the main interface for the logger.
 type Logger interface {
 	// WithLevel returns a new entry with `level` set.
-	WithLevel(Level) *EntryFields
+	WithLevel(Level) *Entry
 }
 
 // LevelLogger
@@ -18,22 +18,22 @@ type LevelLogger interface {
 	Log(s fmt.Stringer)
 
 	// WithLevel returns a new entry with `level` set.
-	WithLevel(Level) *EntryFields
+	WithLevel(Level) *Entry
 
 	// WithFields returns a new entry with the`fields` in fields set.
 	// This is a noop if LevelLogger's level is less than Logger's.
-	WithFields(fields Fielder) *EntryFields
+	WithFields(fields Fielder) *Entry
 
 	// WithLevel returns a new entry with the field f set with value v
 	// This is a noop if LevelLogger's level is less than Logger's.
-	WithField(f string, v any) *EntryFields
+	WithField(f string, v any) *Entry
 
 	// WithDuration returns a new entry with the "duration" field set
 	// to the given duration in milliseconds.
 	// This is a noop if LevelLogger's level is less than Logger's.
-	WithDuration(time.Duration) *EntryFields
+	WithDuration(time.Duration) *Entry
 
 	// WithError returns a new entry with the "error" set to `err`.
 	// This is a noop if err is nil or  LevelLogger's level is less than Logger's.
-	WithError(error) *EntryFields
+	WithError(error) *Entry
 }

levels_test.go

@@ -39,9 +39,7 @@ func TestParseLevel(t *testing.T) {
 func TestLevel_MarshalJSON(t *testing.T) {
 	e := Entry{
 		Message: "hello",
-		EntryFields: &EntryFields{
-			Level: InfoLevel,
-		},
+		Level:   InfoLevel,
 	}
 
 	expect := `{"fields":{},"level":"info","timestamp":"0001-01-01T00:00:00Z","message":"hello"}`

logger.go

@@ -79,7 +79,11 @@ func (f HandlerFunc) HandleLog(e *Entry) error {
 //
 // It is left up to Handlers to implement thread-safety.
 type Handler interface {
-	HandleLog(*Entry) error
+	// HandleLog is invoked for each log event.
+	// Note that i e is going to be used after the call to HandleLog returns,
+	// it must be cloned with e.Clone().
+	// TODO(bep) interface?
+	HandleLog(e *Entry) error
 }
 
 // NoopHandler is a no-op handler that discards all log messages.
@@ -139,43 +143,45 @@ type Clock interface {
 }
 
 // WithLevel returns a new entry with `level` set.
-func (l *logger) WithLevel(level Level) *EntryFields {
+func (l *logger) WithLevel(level Level) *Entry {
 	return NewEntry(l).WithLevel(level)
 }
 
 // WithFields returns a new entry with `fields` set.
-func (l *logger) WithFields(fields Fielder) *EntryFields {
+func (l *logger) WithFields(fields Fielder) *Entry {
 	return NewEntry(l).WithFields(fields.Fields())
 }
 
 // WithField returns a new entry with the `key` and `value` set.
 //
 // Note that the `key` should not have spaces in it - use camel
 // case or underscores
-func (l *logger) WithField(key string, value any) *EntryFields {
+func (l *logger) WithField(key string, value any) *Entry {
 	return NewEntry(l).WithField(key, value)
 }
 
 // WithDuration returns a new entry with the "duration" field set
 // to the given duration in milliseconds.
-func (l *logger) WithDuration(d time.Duration) *EntryFields {
+func (l *logger) WithDuration(d time.Duration) *Entry {
 	return NewEntry(l).WithDuration(d)
 }
 
 // WithError returns a new entry with the "error" set to `err`.
-func (l *logger) WithError(err error) *EntryFields {
+func (l *logger) WithError(err error) *Entry {
 	return NewEntry(l).WithError(err)
 }
 
-// log the message, invoking the handler. We clone the entry here
-// to bypass the overhead in Entry methods when the level is not
-// met.
-func (l *logger) log(e *EntryFields, s fmt.Stringer) {
+// log the message, invoking the handler.
+func (l *logger) log(e *Entry, s fmt.Stringer) {
 	if e.Level < l.Level {
 		return
 	}
 
-	if err := l.Handler.HandleLog(e.finalize(s.String())); err != nil {
+	finalized := objectPools.GetEntry()
+	defer objectPools.PutEntry(finalized)
+	e.finalize(finalized, s.String())
+
+	if err := l.Handler.HandleLog(finalized); err != nil {
 		stdlog.Printf("error logging: %s", err)
 	}