Optimize zap.Any to use less mamory on stack (intermediate props vers…

…ion)

This is an alternative to:
- #1301 and #1302 and #1304 - a series of PRs that are faster than this
  one. However, they rely on unsafe.
- #1303 - my own PR that uses closures, to reduce the stack size by 60%.
- #1305 - my own PR that inline bunch of loops
- https://github.com/uber-go/zap/compare/pawel/any-int5 that does the
  same as above, but is slightly easier to parse
- #1307 - a reflect.TypeOf lookup version

THIS PR IS INCOMPLETE - it shows a possible approach, but I wanted to
get reviewers thoughts before typing everything in.

I originally thought we can use a `type props strucy` intermediary
struct to store the data, but that hits the same problem: every `props`
would get it's own slot on the stack. This avoids this by returning
the raw data.

Pros:
- the implementation is shared between `Any` and strongly typed Fields
- no reflect or unsafe
- reduced the stack significantly - we should be able to get to the same
  ~180 bytes as ~1305.
- no peft penalty for strongly typed versions, at least on ARM64 it's
  compiled away.

Cons:
- the code gets a bit harder to maintain. It's significantly better than
  #1305 I would say though.

field.go

@@ -37,6 +37,20 @@ var (
 	_maxTimeInt64 = time.Unix(0, math.MaxInt64)
 )
 
+// toField converts props to a Field.
+// This is syntastic sugar that allows implementation sharing between
+// strongly typed methods and zap.Any. We expect `toField` to be inlined
+// and have no cost.
+func toField(key string, t zapcore.FieldType, i int64, s string, iface any) Field {
+	return Field{
+		Key:       key,
+		Type:      t,
+		Integer:   i,
+		String:    s,
+		Interface: iface,
+	}
+}
+
 // Skip constructs a no-op field, which is often useful when handling invalid
 // inputs in other Field constructors.
 func Skip() Field {
@@ -49,38 +63,62 @@ func Skip() Field {
 // implementation here should be changed to reflect that.
 func nilField(key string) Field { return Reflect(key, nil) }
 
+func nilProps() (zapcore.FieldType, int64, string, any) {
+	return zapcore.ReflectType, 0, "", nil
+}
+
 // Binary constructs a field that carries an opaque binary blob.
 //
 // Binary data is serialized in an encoding-appropriate format. For example,
 // zap's JSON encoder base64-encodes binary blobs. To log UTF-8 encoded text,
 // use ByteString.
 func Binary(key string, val []byte) Field {
-	return Field{Key: key, Type: zapcore.BinaryType, Interface: val}
+	t, i, s, iface := binaryProps(val)
+	return toField(key, t, i, s, iface)
+}
+
+func binaryProps(val []byte) (zapcore.FieldType, int64, string, any) {
+	return zapcore.BinaryType, 0, "", val
 }
 
 // Bool constructs a field that carries a bool.
 func Bool(key string, val bool) Field {
+	t, i, s, iface := boolProps(val)
+	return toField(key, t, i, s, iface)
+}
+
+func boolProps(val bool) (zapcore.FieldType, int64, string, any) {
 	var ival int64
 	if val {
 		ival = 1
 	}
-	return Field{Key: key, Type: zapcore.BoolType, Integer: ival}
+	return zapcore.BoolType, ival, "", nil
 }
 
 // Boolp constructs a field that carries a *bool. The returned Field will safely
 // and explicitly represent `nil` when appropriate.
 func Boolp(key string, val *bool) Field {
+	t, i, s, iface := boolpProps(val)
+	return toField(key, t, i, s, iface)
+}
+
+func boolpProps(val *bool) (zapcore.FieldType, int64, string, any) {
 	if val == nil {
-		return nilField(key)
+		return nilProps()
 	}
-	return Bool(key, *val)
+	return boolProps(*val)
 }
 
 // ByteString constructs a field that carries UTF-8 encoded text as a []byte.
 // To log opaque binary blobs (which aren't necessarily valid UTF-8), use
 // Binary.
 func ByteString(key string, val []byte) Field {
-	return Field{Key: key, Type: zapcore.ByteStringType, Interface: val}
+	t, i, s, iface := byteStringProps(val)
+	return toField(key, t, i, s, iface)
+}
+
+func byteStringProps(val []byte) (zapcore.FieldType, int64, string, any) {
+	return zapcore.ByteStringType, 0, "", val
 }
 
 // Complex128 constructs a field that carries a complex number. Unlike most
@@ -219,7 +257,12 @@ func Int8p(key string, val *int8) Field {
 
 // String constructs a field with the given key and value.
 func String(key string, val string) Field {
-	return Field{Key: key, Type: zapcore.StringType, String: val}
+	t, i, s, iface := stringProps(val)
+	return toField(key, t, i, s, iface)
+}
+
+func stringProps(val string) (zapcore.FieldType, int64, string, any) {
+	return zapcore.StringType, 0, val, nil
 }
 
 // Stringp constructs a field that carries a *string. The returned Field will safely
@@ -418,15 +461,27 @@ func Inline(val zapcore.ObjectMarshaler) Field {
 // them. To minimize surprises, []byte values are treated as binary blobs, byte
 // values are treated as uint8, and runes are always treated as integers.
 func Any(key string, value interface{}) Field {
+	// Most of the code below is to work around go compiler assigning unreasonably
+	// large space on stack (5kb, one `Field` per arm of the switch statement)
+	// which can trigger perf degradation if `Any` is used in a brand new goroutine.
+	var (
+		t     zapcore.FieldType
+		i     int64
+		s     string
+		iface any
+	)
+
+	// temporary hack as "not found"
+	i = -1
 	switch val := value.(type) {
 	case zapcore.ObjectMarshaler:
 		return Object(key, val)
 	case zapcore.ArrayMarshaler:
 		return Array(key, val)
 	case bool:
-		return Bool(key, val)
+		t, i, s, iface = boolProps(val)
 	case *bool:
-		return Boolp(key, val)
+		t, i, s, iface = boolpProps(val)
 	case []bool:
 		return Bools(key, val)
 	case complex128:
@@ -484,7 +539,7 @@ func Any(key string, value interface{}) Field {
 	case []int8:
 		return Int8s(key, val)
 	case string:
-		return String(key, val)
+		t, i, s, iface = stringProps(val)
 	case *string:
 		return Stringp(key, val)
 	case []string:
@@ -518,7 +573,7 @@ func Any(key string, value interface{}) Field {
 	case *uint8:
 		return Uint8p(key, val)
 	case []byte:
-		return Binary(key, val)
+		t, i, s, iface = binaryProps(val)
 	case uintptr:
 		return Uintptr(key, val)
 	case *uintptr:
@@ -543,7 +598,12 @@ func Any(key string, value interface{}) Field {
 		return Errors(key, val)
 	case fmt.Stringer:
 		return Stringer(key, val)
-	default:
-		return Reflect(key, val)
 	}
+
+	// Temporary, will be gone if we re-write all of the above to use props.
+	if i == -1 {
+		return Reflect(key, value)
+	}
+
+	return toField(key, t, i, s, iface)
 }

field_test.go

@@ -86,6 +86,7 @@ func TestFieldConstructors(t *testing.T) {
 		uint16Val     = uint16(1)
 		uint8Val      = uint8(1)
 		uintptrVal    = uintptr(1)
+		nilErr        error
 	)
 
 	tests := []struct {
@@ -166,6 +167,7 @@ func TestFieldConstructors(t *testing.T) {
 		{"Any:Uintptr", Any("k", uintptr(1)), Uintptr("k", 1)},
 		{"Any:Uintptrs", Any("k", []uintptr{1}), Uintptrs("k", []uintptr{1})},
 		{"Any:Time", Any("k", time.Unix(0, 0)), Time("k", time.Unix(0, 0))},
+		{"Any:Time-FullType", Any("k", time.Time{}), Time("k", time.Time{})},
 		{"Any:Times", Any("k", []time.Time{time.Unix(0, 0)}), Times("k", []time.Time{time.Unix(0, 0)})},
 		{"Any:Duration", Any("k", time.Second), Duration("k", time.Second)},
 		{"Any:Durations", Any("k", []time.Duration{time.Second}), Durations("k", []time.Duration{time.Second})},
@@ -222,6 +224,7 @@ func TestFieldConstructors(t *testing.T) {
 		{"Ptr:Time", Timep("k", &timeVal), Time("k", timeVal)},
 		{"Any:PtrTime", Any("k", (*time.Time)(nil)), nilField("k")},
 		{"Any:PtrTime", Any("k", &timeVal), Time("k", timeVal)},
+		{"Any:PtrTime-FullType", Any("k", &time.Time{}), Time("k", time.Time{})},
 		{"Ptr:Uint", Uintp("k", nil), nilField("k")},
 		{"Ptr:Uint", Uintp("k", &uintVal), Uint("k", uintVal)},
 		{"Any:PtrUint", Any("k", (*uint)(nil)), nilField("k")},
@@ -246,6 +249,8 @@ func TestFieldConstructors(t *testing.T) {
 		{"Ptr:Uintptr", Uintptrp("k", &uintptrVal), Uintptr("k", uintptrVal)},
 		{"Any:PtrUintptr", Any("k", (*uintptr)(nil)), nilField("k")},
 		{"Any:PtrUintptr", Any("k", &uintptrVal), Uintptr("k", uintptrVal)},
+		{"Any:Error-nil", Any("k", nilErr), nilField("k")},
+		{"Any:Error-nil", Any("k", (error)(nil)), nilField("k")},
 		{"Namespace", Namespace("k"), Field{Key: "k", Type: zapcore.NamespaceType}},
 	}
 

logger_bench_test.go

@@ -22,6 +22,8 @@ package zap
 
 import (
 	"errors"
+	"runtime"
+	"sync"
 	"testing"
 	"time"
 
@@ -238,3 +240,108 @@ func Benchmark100Fields(b *testing.B) {
 		logger.With(first...).Info("Child loggers with lots of context.", second...)
 	}
 }
+
+func dummy(wg *sync.WaitGroup, s string, i int) string {
+	if i == 0 {
+		wg.Wait()
+		return "1" + s
+	}
+	return dummy(wg, s, i-1)
+}
+
+func stackGrower(n int) *sync.WaitGroup {
+	wg := sync.WaitGroup{}
+	wg.Add(1)
+
+	go dummy(&wg, "hi", n)
+	return &wg
+}
+
+func BenchmarkAny(b *testing.B) {
+	logger := New(
+		zapcore.NewCore(
+			zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
+			&ztest.Discarder{},
+			DebugLevel,
+		),
+	)
+
+	b.Run("str-no-logger", func(b *testing.B) {
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			f := String("some-string-longer-than-16", "yet-another-long-string")
+			runtime.KeepAlive(f)
+		}
+	})
+	b.Run("any-no-logger", func(b *testing.B) {
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			f := Any("some-string-longer-than-16", "yet-another-long-string")
+			runtime.KeepAlive(f)
+		}
+	})
+	b.Run("str-with-logger", func(b *testing.B) {
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			logger.Info("", String("some-string-longer-than-16", "yet-another-long-string"))
+		}
+	})
+	b.Run("any-with-logger", func(b *testing.B) {
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			logger.Info("", String("some-string-longer-than-16", "yet-another-long-string"))
+		}
+	})
+	b.Run("str-in-go", func(b *testing.B) {
+		wg := sync.WaitGroup{}
+		wg.Add(b.N)
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			go func() {
+				logger.Info("", String("some-string-longer-than-16", "yet-another-long-string"))
+				wg.Done()
+			}()
+		}
+		wg.Wait()
+	})
+	b.Run("any-in-go", func(b *testing.B) {
+		wg := sync.WaitGroup{}
+		wg.Add(b.N)
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			go func() {
+				logger.Info("", Any("some-string-longer-than-16", "yet-another-long-string"))
+				wg.Done()
+			}()
+		}
+		wg.Wait()
+	})
+	b.Run("str-in-go-with-stack", func(b *testing.B) {
+		wg := sync.WaitGroup{}
+		wg.Add(b.N)
+		defer stackGrower(2000).Done()
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			go func() {
+				logger.Info("", String("some-string-longer-than-16", "yet-another-long-string"))
+				wg.Done()
+			}()
+		}
+		wg.Wait()
+		b.StopTimer()
+	})
+	b.Run("any-in-go-with-stack", func(b *testing.B) {
+		wg := sync.WaitGroup{}
+		wg.Add(b.N)
+		defer stackGrower(2000).Done()
+		b.ResetTimer()
+		for i := 0; i < b.N; i++ {
+			go func() {
+				logger.Info("", Any("some-string-longer-than-16", "yet-another-long-string"))
+				wg.Done()
+			}()
+		}
+		wg.Wait()
+		b.StopTimer()
+	})
+}