logger_bench_test.go

Documentation: go.uber.org/zap

     1  // Copyright (c) 2016 Uber Technologies, Inc.
     2  //
     3  // Permission is hereby granted, free of charge, to any person obtaining a copy
     4  // of this software and associated documentation files (the "Software"), to deal
     5  // in the Software without restriction, including without limitation the rights
     6  // to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
     7  // copies of the Software, and to permit persons to whom the Software is
     8  // furnished to do so, subject to the following conditions:
     9  //
    10  // The above copyright notice and this permission notice shall be included in
    11  // all copies or substantial portions of the Software.
    12  //
    13  // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
    14  // IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
    15  // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
    16  // AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
    17  // LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
    18  // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
    19  // THE SOFTWARE.
    20  
    21  package zap
    22  
    23  import (
    24  	"errors"
    25  	"runtime"
    26  	"strconv"
    27  	"sync"
    28  	"testing"
    29  	"time"
    30  
    31  	"go.uber.org/zap/internal/ztest"
    32  	"go.uber.org/zap/zapcore"
    33  )
    34  
    35  type user struct {
    36  	Name      string
    37  	Email     string
    38  	CreatedAt time.Time
    39  }
    40  
    41  func (u *user) MarshalLogObject(enc zapcore.ObjectEncoder) error {
    42  	enc.AddString("name", u.Name)
    43  	enc.AddString("email", u.Email)
    44  	enc.AddInt64("created_at", u.CreatedAt.UnixNano())
    45  	return nil
    46  }
    47  
    48  var _jane = &user{
    49  	Name:      "Jane Doe",
    50  	Email:     "jane@test.com",
    51  	CreatedAt: time.Date(1980, 1, 1, 12, 0, 0, 0, time.UTC),
    52  }
    53  
    54  func withBenchedLogger(b *testing.B, f func(*Logger)) {
    55  	logger := New(
    56  		zapcore.NewCore(
    57  			zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
    58  			&ztest.Discarder{},
    59  			DebugLevel,
    60  		))
    61  	b.ResetTimer()
    62  	b.RunParallel(func(pb *testing.PB) {
    63  		for pb.Next() {
    64  			f(logger)
    65  		}
    66  	})
    67  }
    68  
    69  func BenchmarkNoContext(b *testing.B) {
    70  	withBenchedLogger(b, func(log *Logger) {
    71  		log.Info("No context.")
    72  	})
    73  }
    74  
    75  func BenchmarkBoolField(b *testing.B) {
    76  	withBenchedLogger(b, func(log *Logger) {
    77  		log.Info("Boolean.", Bool("foo", true))
    78  	})
    79  }
    80  
    81  func BenchmarkByteStringField(b *testing.B) {
    82  	val := []byte("bar")
    83  	withBenchedLogger(b, func(log *Logger) {
    84  		log.Info("ByteString.", ByteString("foo", val))
    85  	})
    86  }
    87  
    88  func BenchmarkFloat64Field(b *testing.B) {
    89  	withBenchedLogger(b, func(log *Logger) {
    90  		log.Info("Floating point.", Float64("foo", 3.14))
    91  	})
    92  }
    93  
    94  func BenchmarkIntField(b *testing.B) {
    95  	withBenchedLogger(b, func(log *Logger) {
    96  		log.Info("Integer.", Int("foo", 42))
    97  	})
    98  }
    99  
   100  func BenchmarkInt64Field(b *testing.B) {
   101  	withBenchedLogger(b, func(log *Logger) {
   102  		log.Info("64-bit integer.", Int64("foo", 42))
   103  	})
   104  }
   105  
   106  func BenchmarkStringField(b *testing.B) {
   107  	withBenchedLogger(b, func(log *Logger) {
   108  		log.Info("Strings.", String("foo", "bar"))
   109  	})
   110  }
   111  
   112  func BenchmarkStringerField(b *testing.B) {
   113  	withBenchedLogger(b, func(log *Logger) {
   114  		log.Info("Level.", Stringer("foo", InfoLevel))
   115  	})
   116  }
   117  
   118  func BenchmarkTimeField(b *testing.B) {
   119  	t := time.Unix(0, 0)
   120  	withBenchedLogger(b, func(log *Logger) {
   121  		log.Info("Time.", Time("foo", t))
   122  	})
   123  }
   124  
   125  func BenchmarkDurationField(b *testing.B) {
   126  	withBenchedLogger(b, func(log *Logger) {
   127  		log.Info("Duration", Duration("foo", time.Second))
   128  	})
   129  }
   130  
   131  func BenchmarkErrorField(b *testing.B) {
   132  	err := errors.New("egad")
   133  	withBenchedLogger(b, func(log *Logger) {
   134  		log.Info("Error.", Error(err))
   135  	})
   136  }
   137  
   138  func BenchmarkErrorsField(b *testing.B) {
   139  	errs := []error{
   140  		errors.New("egad"),
   141  		errors.New("oh no"),
   142  		errors.New("dear me"),
   143  		errors.New("such fail"),
   144  	}
   145  	withBenchedLogger(b, func(log *Logger) {
   146  		log.Info("Errors.", Errors("errors", errs))
   147  	})
   148  }
   149  
   150  func BenchmarkStackField(b *testing.B) {
   151  	withBenchedLogger(b, func(log *Logger) {
   152  		log.Info("Error.", Stack("stacktrace"))
   153  	})
   154  }
   155  
   156  func BenchmarkObjectField(b *testing.B) {
   157  	withBenchedLogger(b, func(log *Logger) {
   158  		log.Info("Arbitrary ObjectMarshaler.", Object("user", _jane))
   159  	})
   160  }
   161  
   162  func BenchmarkReflectField(b *testing.B) {
   163  	withBenchedLogger(b, func(log *Logger) {
   164  		log.Info("Reflection-based serialization.", Reflect("user", _jane))
   165  	})
   166  }
   167  
   168  func BenchmarkAddCallerHook(b *testing.B) {
   169  	logger := New(
   170  		zapcore.NewCore(
   171  			zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
   172  			&ztest.Discarder{},
   173  			InfoLevel,
   174  		),
   175  		AddCaller(),
   176  	)
   177  	b.ResetTimer()
   178  	b.RunParallel(func(pb *testing.PB) {
   179  		for pb.Next() {
   180  			logger.Info("Caller.")
   181  		}
   182  	})
   183  }
   184  
   185  func BenchmarkAddCallerAndStacktrace(b *testing.B) {
   186  	logger := New(
   187  		zapcore.NewCore(
   188  			zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
   189  			&ztest.Discarder{},
   190  			InfoLevel,
   191  		),
   192  		AddCaller(),
   193  		AddStacktrace(WarnLevel),
   194  	)
   195  	b.ResetTimer()
   196  	b.RunParallel(func(pb *testing.PB) {
   197  		for pb.Next() {
   198  			logger.Warn("Caller and stacktrace.")
   199  		}
   200  	})
   201  }
   202  
   203  func Benchmark5WithsUsed(b *testing.B) {
   204  	benchmarkWithUsed(b, (*Logger).With, 5, true)
   205  }
   206  
   207  // This benchmark will be used in future as a
   208  // baseline for improving
   209  func Benchmark5WithsNotUsed(b *testing.B) {
   210  	benchmarkWithUsed(b, (*Logger).With, 5, false)
   211  }
   212  
   213  func Benchmark5WithLazysUsed(b *testing.B) {
   214  	benchmarkWithUsed(b, (*Logger).WithLazy, 5, true)
   215  }
   216  
   217  // This benchmark will be used in future as a
   218  // baseline for improving
   219  func Benchmark5WithLazysNotUsed(b *testing.B) {
   220  	benchmarkWithUsed(b, (*Logger).WithLazy, 5, false)
   221  }
   222  
   223  func benchmarkWithUsed(b *testing.B, withMethod func(*Logger, ...zapcore.Field) *Logger, N int, use bool) {
   224  	keys := make([]string, N)
   225  	values := make([]string, N)
   226  	for i := 0; i < N; i++ {
   227  		keys[i] = "k" + strconv.Itoa(i)
   228  		values[i] = "v" + strconv.Itoa(i)
   229  	}
   230  
   231  	b.ResetTimer()
   232  
   233  	withBenchedLogger(b, func(log *Logger) {
   234  		for i := 0; i < N; i++ {
   235  			log = withMethod(log, String(keys[i], values[i]))
   236  		}
   237  		if use {
   238  			log.Info("used")
   239  			return
   240  		}
   241  		runtime.KeepAlive(log)
   242  	})
   243  }
   244  
   245  func Benchmark10Fields(b *testing.B) {
   246  	withBenchedLogger(b, func(log *Logger) {
   247  		log.Info("Ten fields, passed at the log site.",
   248  			Int("one", 1),
   249  			Int("two", 2),
   250  			Int("three", 3),
   251  			Int("four", 4),
   252  			Int("five", 5),
   253  			Int("six", 6),
   254  			Int("seven", 7),
   255  			Int("eight", 8),
   256  			Int("nine", 9),
   257  			Int("ten", 10),
   258  		)
   259  	})
   260  }
   261  
   262  func Benchmark100Fields(b *testing.B) {
   263  	const batchSize = 50
   264  	logger := New(zapcore.NewCore(
   265  		zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
   266  		&ztest.Discarder{},
   267  		DebugLevel,
   268  	))
   269  
   270  	// Don't include allocating these helper slices in the benchmark. Since
   271  	// access to them isn't synchronized, we can't run the benchmark in
   272  	// parallel.
   273  	first := make([]Field, batchSize)
   274  	second := make([]Field, batchSize)
   275  	b.ResetTimer()
   276  
   277  	for i := 0; i < b.N; i++ {
   278  		for i := 0; i < batchSize; i++ {
   279  			// We're duplicating keys, but that doesn't affect performance.
   280  			first[i] = Int("foo", i)
   281  			second[i] = Int("foo", i+batchSize)
   282  		}
   283  		logger.With(first...).Info("Child loggers with lots of context.", second...)
   284  	}
   285  }
   286  
   287  func BenchmarkAny(b *testing.B) {
   288  	key := "some-long-string-longer-than-16"
   289  
   290  	tests := []struct {
   291  		name   string
   292  		typed  func() Field
   293  		anyArg any
   294  	}{
   295  		{
   296  			name:   "string",
   297  			typed:  func() Field { return String(key, "yet-another-long-string") },
   298  			anyArg: "yet-another-long-string",
   299  		},
   300  		{
   301  			name:   "stringer",
   302  			typed:  func() Field { return Stringer(key, InfoLevel) },
   303  			anyArg: InfoLevel,
   304  		},
   305  	}
   306  
   307  	for _, tt := range tests {
   308  		b.Run(tt.name, func(b *testing.B) {
   309  			b.Run("field-only", func(b *testing.B) {
   310  				b.Run("typed", func(b *testing.B) {
   311  					withBenchedLogger(b, func(log *Logger) {
   312  						f := tt.typed()
   313  						runtime.KeepAlive(f)
   314  					})
   315  				})
   316  				b.Run("any", func(b *testing.B) {
   317  					withBenchedLogger(b, func(log *Logger) {
   318  						f := Any(key, tt.anyArg)
   319  						runtime.KeepAlive(f)
   320  					})
   321  				})
   322  			})
   323  			b.Run("log", func(b *testing.B) {
   324  				b.Run("typed", func(b *testing.B) {
   325  					withBenchedLogger(b, func(log *Logger) {
   326  						log.Info("", tt.typed())
   327  					})
   328  				})
   329  				b.Run("any", func(b *testing.B) {
   330  					withBenchedLogger(b, func(log *Logger) {
   331  						log.Info("", Any(key, tt.anyArg))
   332  					})
   333  				})
   334  			})
   335  			b.Run("log-go", func(b *testing.B) {
   336  				b.Run("typed", func(b *testing.B) {
   337  					withBenchedLogger(b, func(log *Logger) {
   338  						var wg sync.WaitGroup
   339  						wg.Add(1)
   340  						go func() {
   341  							log.Info("", tt.typed())
   342  							wg.Done()
   343  						}()
   344  						wg.Wait()
   345  					})
   346  				})
   347  				b.Run("any", func(b *testing.B) {
   348  					withBenchedLogger(b, func(log *Logger) {
   349  						var wg sync.WaitGroup
   350  						wg.Add(1)
   351  						go func() {
   352  							log.Info("", Any(key, tt.anyArg))
   353  							wg.Done()
   354  						}()
   355  						wg.Wait()
   356  					})
   357  				})
   358  			})
   359  		})
   360  	}
   361  }
   362
View as plain text