From df43be8e154b7e3861c85bedd2af62cd07bd3f45 Mon Sep 17 00:00:00 2001 From: instabledesign Date: Fri, 29 Oct 2021 20:21:56 +0200 Subject: [PATCH] Rework bench (#79) --- Makefile | 5 +- benchmark_test.go | 125 +++++++++++++++++++++++++++ benchmarks/context_test.go | 27 ------ benchmarks/formatter/default_test.go | 19 ---- benchmarks/formatter/gelf_test.go | 20 ----- benchmarks/formatter/json_test.go | 19 ---- benchmarks/formatter/line_test.go | 19 ---- benchmarks/handler/group_test.go | 22 ----- benchmarks/handler/stream_test.go | 25 ------ benchmarks/logger_test.go | 81 ----------------- benchmarks/middleware/filter_test.go | 34 -------- entry.go | 4 +- formatter/benchmark_test.go | 73 ++++++++++++++++ formatter/default_test.go | 3 +- formatter/json_test.go | 5 +- formatter/line.go | 6 ++ formatter/line_test.go | 11 ++- handler/benchmark_test.go | 63 ++++++++++++++ handler/fake_format_test | 0 middleware/benchmark_test.go | 73 ++++++++++++++++ 20 files changed, 355 insertions(+), 279 deletions(-) create mode 100644 benchmark_test.go delete mode 100644 benchmarks/context_test.go delete mode 100644 benchmarks/formatter/default_test.go delete mode 100644 benchmarks/formatter/gelf_test.go delete mode 100644 benchmarks/formatter/json_test.go delete mode 100644 benchmarks/formatter/line_test.go delete mode 100644 benchmarks/handler/group_test.go delete mode 100644 benchmarks/handler/stream_test.go delete mode 100644 benchmarks/logger_test.go delete mode 100644 benchmarks/middleware/filter_test.go create mode 100644 formatter/benchmark_test.go create mode 100644 handler/benchmark_test.go create mode 100644 handler/fake_format_test create mode 100644 middleware/benchmark_test.go diff --git a/Makefile b/Makefile index 0d138d6..5af86f8 100644 --- a/Makefile +++ b/Makefile @@ -1,2 +1,5 @@ test: - go test --race -gcflags=-l -v ./... + go test --race -gcflags=-l ./... + +bench: + go test -bench=. -gcflags=-l ./... diff --git a/benchmark_test.go b/benchmark_test.go new file mode 100644 index 0000000..7266bf6 --- /dev/null +++ b/benchmark_test.go @@ -0,0 +1,125 @@ +package logger_test + +import ( + "errors" + "testing" + "time" + + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/formatter" + "github.com/gol4ng/logger/handler" + "github.com/gol4ng/logger/middleware" +) + +type NopWriter struct{} + +func (w *NopWriter) Write(_ []byte) (n int, err error) { + return 0, nil +} + +type loggerToTest struct { + name string + logger logger.LoggerInterface +} + +func loggersToBench() []loggerToTest { + return []loggerToTest{ + { + "nop", + logger.NewNopLogger(), + }, + { + "stream line", + logger.NewLogger( + handler.Stream(&NopWriter{}, formatter.NewLine("%[2]s | %[1]s")), + ), + }, + { + "min level filter", + logger.NewLogger(middleware.MinLevelFilter(logger.WarningLevel)(logger.NopHandler)), + }, + { + "max level filter", + logger.NewLogger(middleware.MaxLevelFilter(logger.WarningLevel)(logger.NopHandler)), + }, + { + "range level filter", + logger.NewLogger(middleware.RangeLevelFilter(logger.WarningLevel, logger.InfoLevel)(logger.NopHandler)), + }, + { + "placeholder", + logger.NewLogger(middleware.Placeholder()(logger.NopHandler)), + }, + } +} + +func getEntries() []logger.Entry { + return []logger.Entry{ + { + Message: "test %my_key% message", + Level: logger.WarningLevel, + Context: logger.NewContext(). + Add("my_key", "my_value"). + Add("my_key2", "my_value2"). + Add("my_key3", "my_value3"). + Add("my_key4", "my_value4"). + Add("my_key5", "my_value5"), + }, + } +} + +func BenchmarkMiddleware(b *testing.B) { + for _, entry := range getEntries() { + for _, m := range loggersToBench() { + b.Run(m.name+"_"+entry.Message, func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + m.logger.Log(entry.Message, entry.Level, *(entry.Context.Slice())...) + } + }) + } + } +} + +func BenchmarkContext_Add(b *testing.B) { + tests := []struct { + name string + data interface{} + }{ + {name: "nil", data: nil}, + {name: "boolean", data: false}, + {name: "int", data: 1234}, + {name: "int8", data: int8(123)}, + {name: "int16", data: int16(1234)}, + {name: "int32", data: int32(1234)}, + {name: "int64", data: int64(1234)}, + {name: "uint8", data: uint8(123)}, + {name: "uint16", data: uint16(1234)}, + {name: "uint32", data: uint32(1234)}, + {name: "uint64", data: uint64(1234)}, + {name: "uintptr", data: uintptr(1234)}, + {name: "float32", data: float32(1234.56)}, + {name: "float64", data: float64(1234.56)}, + {name: "complex64", data: complex64(123)}, + {name: "complex128", data: complex128(123)}, + {name: "string", data: "example"}, + {name: "[]byte", data: []byte("example")}, + {name: "error", data: errors.New("example")}, + {name: "time", data: time.Now()}, + {name: "duration", data: time.Second}, + {name: "stringer", data: MyStringer{}}, + {name: "reflect", data: struct{}{}}, + } + ctx := logger.NewContext() + + for _, tt := range tests { + b.Run("context_add_"+tt.name, func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + ctx.Add("my_message", tt.data) + } + }) + } +} diff --git a/benchmarks/context_test.go b/benchmarks/context_test.go deleted file mode 100644 index a44bce3..0000000 --- a/benchmarks/context_test.go +++ /dev/null @@ -1,27 +0,0 @@ -package benchmarks_test - -import ( - "testing" - - "github.com/gol4ng/logger" -) - -func Benchmark_Context_Typed(b *testing.B) { - b.ReportAllocs() - b.ResetTimer() - for n := 0; n < b.N; n++ { - logger.NewContext(). - Binary("my binary", []byte{1, 2, 3}). // 2 allocations - ByteString("my byte string", []byte{1, 2, 3}) // 2 allocations - } -} - -func Benchmark_Context_Add(b *testing.B) { - b.ReportAllocs() - b.ResetTimer() - for n := 0; n < b.N; n++ { - logger.NewContext(). - Add("my binary", []byte{1, 2, 3}). // 3 allocations - Add("my byte string", []byte{1, 2, 3}) // 3 allocations - } -} diff --git a/benchmarks/formatter/default_test.go b/benchmarks/formatter/default_test.go deleted file mode 100644 index d3edf08..0000000 --- a/benchmarks/formatter/default_test.go +++ /dev/null @@ -1,19 +0,0 @@ -package benchmark_formatter_test - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" -) - -func BenchmarkDefaultFormatter(b *testing.B) { - b.ReportAllocs() - - jsonFormatter := formatter.NewJSONEncoder() - - b.ResetTimer() - for n := 0; n < b.N; n++ { - jsonFormatter.Format(logger.Entry{Message: "This log message is really logged.", Level: logger.InfoLevel}) - } -} diff --git a/benchmarks/formatter/gelf_test.go b/benchmarks/formatter/gelf_test.go deleted file mode 100644 index ef690a7..0000000 --- a/benchmarks/formatter/gelf_test.go +++ /dev/null @@ -1,20 +0,0 @@ -package benchmark_formatter_test - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" -) - -func BenchmarkGelfFormatter(b *testing.B) { - b.ReportAllocs() - - gelfFormatter := formatter.NewGelf() - e := logger.Entry{Message: "This log message is really logged.", Level: logger.InfoLevel} - - b.ResetTimer() - for n := 0; n < b.N; n++ { - gelfFormatter.Format(e) - } -} diff --git a/benchmarks/formatter/json_test.go b/benchmarks/formatter/json_test.go deleted file mode 100644 index 68c6028..0000000 --- a/benchmarks/formatter/json_test.go +++ /dev/null @@ -1,19 +0,0 @@ -package benchmark_formatter_test - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" -) - -func BenchmarkJsonFormatter(b *testing.B) { - b.ReportAllocs() - - jsonFormatter := formatter.NewJSONEncoder() - - b.ResetTimer() - for n := 0; n < b.N; n++ { - jsonFormatter.Format(logger.Entry{Message: "This log message is really logged.", Level: logger.InfoLevel}) - } -} diff --git a/benchmarks/formatter/line_test.go b/benchmarks/formatter/line_test.go deleted file mode 100644 index 7fdee23..0000000 --- a/benchmarks/formatter/line_test.go +++ /dev/null @@ -1,19 +0,0 @@ -package benchmark_formatter_test - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" -) - -func BenchmarkLineFormatter(b *testing.B) { - b.ReportAllocs() - - lineFormatter := formatter.NewLine("%s %s %s") - - b.ResetTimer() - for n := 0; n < b.N; n++ { - lineFormatter.Format(logger.Entry{Message: "This log message is really logged.", Level: logger.InfoLevel}) - } -} diff --git a/benchmarks/handler/group_test.go b/benchmarks/handler/group_test.go deleted file mode 100644 index e045843..0000000 --- a/benchmarks/handler/group_test.go +++ /dev/null @@ -1,22 +0,0 @@ -package benchmark_handler - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/handler" -) - -func BenchmarkGroupHandler(b *testing.B) { - b.ReportAllocs() - - groupHandler := handler.Group( - logger.NopHandler, - logger.NopHandler, - ) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - _ = groupHandler(logger.Entry{Message: "This log message goes nowhere.", Level: logger.InfoLevel}) - } -} diff --git a/benchmarks/handler/stream_test.go b/benchmarks/handler/stream_test.go deleted file mode 100644 index ed2eb31..0000000 --- a/benchmarks/handler/stream_test.go +++ /dev/null @@ -1,25 +0,0 @@ -package benchmark_handler_test - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/handler" -) - -type NopWriter struct{} - -func (w *NopWriter) Write(_ []byte) (n int, err error) { - return 0, nil -} - -func BenchmarkStdoutStreamHandler(b *testing.B) { - b.ReportAllocs() - - streamHandler := handler.Stream(&NopWriter{}, logger.NewNopFormatter()) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - _ = streamHandler(logger.Entry{Message: "This log message goes nowhere.", Level: logger.InfoLevel}) - } -} diff --git a/benchmarks/logger_test.go b/benchmarks/logger_test.go deleted file mode 100644 index 6b038ac..0000000 --- a/benchmarks/logger_test.go +++ /dev/null @@ -1,81 +0,0 @@ -package benchmarks_test - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/formatter" - "github.com/gol4ng/logger/handler" - "github.com/gol4ng/logger/middleware" -) - -type NopWriter struct{} - -func (w *NopWriter) Write(_ []byte) (n int, err error) { - return 0, nil -} - -func BenchmarkNopLogger(b *testing.B) { - b.ReportAllocs() - - myLogger := logger.NewNopLogger() - - b.ResetTimer() - for n := 0; n < b.N; n++ { - myLogger.Info("This log message go anywhere.") - } -} - -func BenchmarkLoggerLineFormatter(b *testing.B) { - b.ReportAllocs() - - myLogger := logger.NewLogger( - handler.Stream(&NopWriter{}, formatter.NewLine("%[2]s | %[1]s")), - ) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - myLogger.Info("Log example") - } -} - -func BenchmarkLoggerJsonFormatter(b *testing.B) { - b.ReportAllocs() - - myLogger := logger.NewLogger( - handler.Stream(&NopWriter{}, formatter.NewJSONEncoder()), - ) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - myLogger.Info("Log example") - } -} - -func BenchmarkLoggerMinLevelFilterHandler(b *testing.B) { - b.ReportAllocs() - - myLogger := logger.NewLogger( - middleware.MinLevelFilter(logger.InfoLevel)(logger.NopHandler), - ) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - myLogger.Debug("Log example") - myLogger.Info("Log example") - } -} - -func BenchmarkLoggerGroupHandler(b *testing.B) { - b.ReportAllocs() - - myLogger := logger.NewLogger(handler.Group( - handler.Stream(&NopWriter{}, &logger.NopFormatter{}), - handler.Stream(&NopWriter{}, &logger.NopFormatter{}), - )) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - myLogger.Debug("Log example") - } -} diff --git a/benchmarks/middleware/filter_test.go b/benchmarks/middleware/filter_test.go deleted file mode 100644 index 1873d9b..0000000 --- a/benchmarks/middleware/filter_test.go +++ /dev/null @@ -1,34 +0,0 @@ -package middleware_test - -import ( - "testing" - - "github.com/gol4ng/logger" - "github.com/gol4ng/logger/middleware" -) - -func BenchmarkMinLevelFilterHandler(b *testing.B) { - b.ReportAllocs() - - minLvlFilterHandler := middleware.MinLevelFilter(logger.InfoLevel)(logger.NopHandler) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - _ = minLvlFilterHandler(logger.Entry{Message: "This log message is really logged.", Level: logger.InfoLevel}) - _ = minLvlFilterHandler(logger.Entry{Message: "This log message will be excluded.", Level: logger.DebugLevel}) - } -} - -func BenchmarkRangeLevelFilterHandler(b *testing.B) { - b.ReportAllocs() - - rangeLevelHandler := middleware.RangeLevelFilter(logger.InfoLevel, logger.WarningLevel)(logger.NopHandler) - - b.ResetTimer() - for n := 0; n < b.N; n++ { - _ = rangeLevelHandler(logger.Entry{Message: "This log message is really logged.", Level: logger.InfoLevel}) - _ = rangeLevelHandler(logger.Entry{Message: "This log message is really logged.", Level: logger.WarningLevel}) - _ = rangeLevelHandler(logger.Entry{Message: "This log message will be excluded.", Level: logger.DebugLevel}) - _ = rangeLevelHandler(logger.Entry{Message: "This log message will be excluded.", Level: logger.ErrorLevel}) - } -} diff --git a/entry.go b/entry.go index da67818..6653c3b 100644 --- a/entry.go +++ b/entry.go @@ -1,6 +1,8 @@ package logger -import "strings" +import ( + "strings" +) // Entry represents a log in its entirety // it is composed of a level, a message and a context diff --git a/formatter/benchmark_test.go b/formatter/benchmark_test.go new file mode 100644 index 0000000..cd9e1a6 --- /dev/null +++ b/formatter/benchmark_test.go @@ -0,0 +1,73 @@ +package formatter_test + +import ( + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/formatter" + "testing" +) + +type formatterToTest struct { + name string + formatter logger.FormatterInterface +} + +func formattersToBench() []formatterToTest { + return []formatterToTest{ + { + "default", + formatter.NewDefaultFormatter(), + }, + { + "default colored", + formatter.NewDefaultFormatter(formatter.WithColor(true)), + }, + { + "default context", + formatter.NewDefaultFormatter(formatter.WithContext(true)), + }, + { + "default full", + formatter.NewDefaultFormatter(formatter.WithContext(true), formatter.WithColor(true)), + }, + {"gelf", + formatter.NewGelf(), + }, + { + "json", + formatter.NewJSONEncoder(), + }, + { + "line", + formatter.NewLine(formatter.LineFormatLevelFirst), + }, + } +} + +func getEntries() []logger.Entry { + return []logger.Entry{ + { + Message: "test message", + Level: logger.WarningLevel, + Context: logger.NewContext(). + Add("my_key", "my_value"). + Add("my_key2", "my_value2"). + Add("my_key3", "my_value3"). + Add("my_key4", "my_value4"). + Add("my_key5", "my_value5"), + }, + } +} + +func BenchmarkFormatter_Format(b *testing.B) { + for _, entry := range getEntries() { + for _, f := range formattersToBench() { + b.Run(f.name+"_"+entry.Message, func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + f.formatter.Format(entry) + } + }) + } + } +} diff --git a/formatter/default_test.go b/formatter/default_test.go index 9df3b25..92de2b0 100644 --- a/formatter/default_test.go +++ b/formatter/default_test.go @@ -4,10 +4,9 @@ import ( "fmt" "testing" - "github.com/stretchr/testify/assert" - "github.com/gol4ng/logger" "github.com/gol4ng/logger/formatter" + "github.com/stretchr/testify/assert" ) func TestDefaultFormatter_Format(t *testing.T) { diff --git a/formatter/json_test.go b/formatter/json_test.go index b5c557c..ce34b02 100644 --- a/formatter/json_test.go +++ b/formatter/json_test.go @@ -7,10 +7,9 @@ import ( "testing" "time" - "github.com/stretchr/testify/assert" - "github.com/gol4ng/logger" "github.com/gol4ng/logger/formatter" + "github.com/stretchr/testify/assert" ) func TestJson_Format(t *testing.T) { @@ -95,7 +94,7 @@ func ExampleJsonFormatter() { fmt.Println(jsonFormatter.Format( logger.Entry{ Message: "My log message", - Level: logger.InfoLevel, + Level: logger.InfoLevel, Context: logger.NewContext().Add("my_key", "my_value"), }, )) diff --git a/formatter/line.go b/formatter/line.go index f746ed8..0bccafc 100644 --- a/formatter/line.go +++ b/formatter/line.go @@ -6,6 +6,12 @@ import ( "github.com/gol4ng/logger" ) +const ( + LineFormatDefault = "%s %s %s" // test message warning + LineFormatLevelInt = "%s %d %s" // test message 4 + LineFormatLevelFirst = "%[2]s %[1]s %[3]s" // warning test message +) + // Line formatter will transform log Entry into string type Line struct { format string diff --git a/formatter/line_test.go b/formatter/line_test.go index df606cc..fafe6db 100644 --- a/formatter/line_test.go +++ b/formatter/line_test.go @@ -4,10 +4,9 @@ import ( "fmt" "testing" - "github.com/stretchr/testify/assert" - "github.com/gol4ng/logger" "github.com/gol4ng/logger/formatter" + "github.com/stretchr/testify/assert" ) func TestLine_Format(t *testing.T) { @@ -18,17 +17,17 @@ func TestLine_Format(t *testing.T) { }{ { name: "test simple format 1", - format: "%s %s %s", + format: formatter.LineFormatDefault, expected: "test message warning ", }, { name: "test simple format 2", - format: "%s %d %s", + format: formatter.LineFormatLevelInt, expected: "test message 4 ", }, { name: "test simple format", - format: "%[2]s %[1]s %[3]s", + format: formatter.LineFormatLevelFirst, expected: "warning test message ", }, } @@ -52,7 +51,7 @@ func ExampleLineFormatter() { fmt.Println(lineFormatter.Format( logger.Entry{ Message: "My log message", - Level: logger.InfoLevel, + Level: logger.InfoLevel, Context: logger.NewContext().Add("my_key", "my_value"), }, )) diff --git a/handler/benchmark_test.go b/handler/benchmark_test.go new file mode 100644 index 0000000..630ad4a --- /dev/null +++ b/handler/benchmark_test.go @@ -0,0 +1,63 @@ +package handler_test + +import ( + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/handler" + "testing" +) + +type NopWriter struct{} + +func (w *NopWriter) Write(_ []byte) (n int, err error) { + return 0, nil +} + +type handlerToTest struct { + name string + handler logger.HandlerInterface +} + +func handlersToBench() []handlerToTest { + return []handlerToTest{ + { + "group nop", + handler.Group( + logger.NopHandler, + logger.NopHandler, + ), + }, + { + "stream nop formatter nop writer", + handler.Stream(&NopWriter{}, logger.NewNopFormatter()), + }, + } +} + +func getEntries() []logger.Entry { + return []logger.Entry{ + { + Message: "test message", + Level: logger.WarningLevel, + Context: logger.NewContext(). + Add("my_key", "my_value"). + Add("my_key2", "my_value2"). + Add("my_key3", "my_value3"). + Add("my_key4", "my_value4"). + Add("my_key5", "my_value5"), + }, + } +} + +func BenchmarkHandler_Handle(b *testing.B) { + for _, entry := range getEntries() { + for _, h := range handlersToBench() { + b.Run(h.name+"_"+entry.Message, func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + _ = h.handler(entry) + } + }) + } + } +} diff --git a/handler/fake_format_test b/handler/fake_format_test new file mode 100644 index 0000000..e69de29 diff --git a/middleware/benchmark_test.go b/middleware/benchmark_test.go new file mode 100644 index 0000000..8bae2ac --- /dev/null +++ b/middleware/benchmark_test.go @@ -0,0 +1,73 @@ +package middleware_test + +import ( + "github.com/gol4ng/logger" + "github.com/gol4ng/logger/middleware" + "testing" +) + +type middlewareToTest struct { + name string + middleware logger.MiddlewareInterface +} + +func middlewaresToBench() []middlewareToTest { + return []middlewareToTest{ + { + "caller 0", + middleware.Caller(0), + }, + { + "context", + middleware.Context(logger.NewContext( + logger.String("my_base_key_1", "my_base_value_1"), + logger.String("my_base_key_2", "my_base_value_2"), + )), + }, + { + "min level filter", + middleware.MinLevelFilter(logger.WarningLevel), + }, + { + "max level filter", + middleware.MaxLevelFilter(logger.WarningLevel), + }, + { + "range level filter", + middleware.RangeLevelFilter(logger.WarningLevel, logger.InfoLevel), + }, + { + "placeholder", + middleware.Placeholder(), + }, + } +} + +func getEntries() []logger.Entry { + return []logger.Entry{ + { + Message: "test %my_key% message", + Level: logger.WarningLevel, + Context: logger.NewContext(). + Add("my_key", "my_value"). + Add("my_key2", "my_value2"). + Add("my_key3", "my_value3"). + Add("my_key4", "my_value4"). + Add("my_key5", "my_value5"), + }, + } +} + +func BenchmarkMiddleware(b *testing.B) { + for _, entry := range getEntries() { + for _, m := range middlewaresToBench() { + b.Run(m.name+"_"+entry.Message, func(b *testing.B) { + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + m.middleware(logger.NopHandler)(entry) + } + }) + } + } +}