[draft/wip] Adding (initial) fortio.org/log entry

README.md

@@ -66,41 +66,44 @@ Log a message and 10 fields:
 
 | Package | Time | Time % to zap | Objects Allocated |
 | :------ | :--: | :-----------: | :---------------: |
-| :zap: zap | 1744 ns/op | +0% | 5 allocs/op
-| :zap: zap (sugared) | 2483 ns/op | +42% | 10 allocs/op
-| zerolog | 918 ns/op | -47% | 1 allocs/op
-| go-kit | 5590 ns/op | +221% | 57 allocs/op
-| slog | 5640 ns/op | +223% | 40 allocs/op
-| apex/log | 21184 ns/op | +1115% | 63 allocs/op
-| logrus | 24338 ns/op | +1296% | 79 allocs/op
-| log15 | 26054 ns/op | +1394% | 74 allocs/op
+| :zap: zap | 626 ns/op | +0% | 5 allocs/op
+| :zap: zap (sugared) | 982 ns/op | +57% | 11 allocs/op
+| zerolog | 236 ns/op | -62% | 1 allocs/op
+| go-kit | 2174 ns/op | +247% | 58 allocs/op
+| slog | 2175 ns/op | +247% | 40 allocs/op
+| fortio log | 5659 ns/op | +804% | 140 allocs/op
+| apex/log | 9934 ns/op | +1487% | 64 allocs/op
+| log15 | 11288 ns/op | +1703% | 75 allocs/op
+| logrus | 12118 ns/op | +1836% | 80 allocs/op
 
 Log a message with a logger that already has 10 fields of context:
 
 | Package | Time | Time % to zap | Objects Allocated |
 | :------ | :--: | :-----------: | :---------------: |
-| :zap: zap | 193 ns/op | +0% | 0 allocs/op
-| :zap: zap (sugared) | 227 ns/op | +18% | 1 allocs/op
-| zerolog | 81 ns/op | -58% | 0 allocs/op
-| slog | 322 ns/op | +67% | 0 allocs/op
-| go-kit | 5377 ns/op | +2686% | 56 allocs/op
-| apex/log | 19518 ns/op | +10013% | 53 allocs/op
-| log15 | 19812 ns/op | +10165% | 70 allocs/op
-| logrus | 21997 ns/op | +11297% | 68 allocs/op
+| :zap: zap | 63 ns/op | +0% | 0 allocs/op
+| :zap: zap (sugared) | 82 ns/op | +30% | 1 allocs/op
+| zerolog | 18 ns/op | -71% | 0 allocs/op
+| slog | 242 ns/op | +284% | 0 allocs/op
+| go-kit | 2341 ns/op | +3616% | 56 allocs/op
+| fortio log | 5162 ns/op | +8094% | 131 allocs/op
+| log15 | 9321 ns/op | +14695% | 70 allocs/op
+| apex/log | 9421 ns/op | +14854% | 53 allocs/op
+| logrus | 10950 ns/op | +17281% | 68 allocs/op
 
 Log a static string, without any context or `printf`-style templating:
 
 | Package | Time | Time % to zap | Objects Allocated |
 | :------ | :--: | :-----------: | :---------------: |
-| :zap: zap | 165 ns/op | +0% | 0 allocs/op
-| :zap: zap (sugared) | 212 ns/op | +28% | 1 allocs/op
-| zerolog | 95 ns/op | -42% | 0 allocs/op
-| slog | 296 ns/op | +79% | 0 allocs/op
-| go-kit | 415 ns/op | +152% | 9 allocs/op
-| standard library | 422 ns/op | +156% | 2 allocs/op
-| apex/log | 1601 ns/op | +870% | 5 allocs/op
-| logrus | 3017 ns/op | +1728% | 23 allocs/op
-| log15 | 3469 ns/op | +2002% | 20 allocs/op
+| :zap: zap | 52 ns/op | +0% | 0 allocs/op
+| :zap: zap (sugared) | 80 ns/op | +54% | 1 allocs/op
+| zerolog | 17 ns/op | -67% | 0 allocs/op
+| slog | 230 ns/op | +342% | 0 allocs/op
+| go-kit | 243 ns/op | +367% | 9 allocs/op
+| standard library | 309 ns/op | +494% | 2 allocs/op
+| apex/log | 787 ns/op | +1413% | 5 allocs/op
+| fortio log | 827 ns/op | +1490% | 2 allocs/op
+| logrus | 1495 ns/op | +2775% | 23 allocs/op
+| log15 | 2030 ns/op | +3804% | 20 allocs/op
 
 ## Development Status: Stable
 

benchmarks/fortio_test.go

@@ -0,0 +1,79 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package benchmarks
+
+import (
+	"io"
+
+	"fortio.org/log"
+)
+
+type shmLogger struct {
+	fields []log.KeyVal
+}
+
+var fLog = &shmLogger{}
+
+func (l *shmLogger) Infof(msg string, fields ...interface{}) {
+	log.Infof(msg, fields...)
+}
+
+func (l *shmLogger) InfoS(msg string, fields ...log.KeyVal) {
+	log.S(log.Info, msg, fields...)
+}
+
+func (l *shmLogger) InfoContext(msg string) {
+	log.S(log.Info, msg, l.fields...)
+}
+
+func newFortiolog(fields ...log.KeyVal) *shmLogger {
+	log.Config = log.DefaultConfig()
+	log.Config.LogFileAndLine = false // file/line extraction implies bad perf
+	log.Config.JSON = true            // structured logging comparison
+	log.Config.GoroutineID = false    // other loggers don't have that
+	log.SetOutput(io.Discard)
+	log.Color = false // should already be but just in case
+	fLog.fields = fields
+	log.SetLogLevel(log.Info)
+	return fLog
+}
+
+func newDisabledFortiolog(fields ...log.KeyVal) *shmLogger {
+	logger := newFortiolog()
+	log.SetLogLevel(log.Error)
+	logger.fields = fields
+	return logger
+}
+
+func fakeFortiologFields() []log.KeyVal {
+	return []log.KeyVal{
+		log.Attr("int", _tenInts[0]),
+		log.Attr("ints", _tenInts),
+		log.Str("string", _tenStrings[0]),
+		log.Attr("strings", _tenStrings),
+		log.Attr("time", _tenTimes[0]),
+		log.Attr("times", _tenTimes),
+		log.Attr("user1", _oneUser),
+		log.Attr("user2", _oneUser),
+		log.Attr("users", _tenUsers),
+		log.Attr("error", errExample),
+	}
+}

benchmarks/go.mod

@@ -5,6 +5,7 @@ go 1.19
 replace go.uber.org/zap => ../
 
 require (
+	fortio.org/log v1.11.0
 	github.com/apex/log v1.9.0
 	github.com/go-kit/log v0.2.1
 	github.com/rs/zerolog v1.28.0
@@ -15,6 +16,9 @@ require (
 	gopkg.in/inconshreveable/log15.v2 v2.0.0-20221122034931-555555054819
 )
 
+//	fortio.org/log => ../../../fortio.org/log
+replace go.ubder.org/zap => ../
+
 require (
 	github.com/benbjohnson/clock v1.3.0 // indirect
 	github.com/go-logfmt/logfmt v0.5.1 // indirect

benchmarks/go.sum

@@ -1,3 +1,5 @@
+fortio.org/log v1.11.0 h1:w7ueGPGbXz0A3+ApMz/5Q9gwEMrwSo/ohTlLo2Um6dU=
+fortio.org/log v1.11.0/go.mod h1:u/8/2lyczXq52aT5Nw6reD+3cR6m/EbS2jBiIYhgiTU=
 github.com/apex/log v1.9.0 h1:FHtw/xuaM8AgmvDDTI9fiwoAL25Sq2cxojnZICUU8l0=
 github.com/apex/log v1.9.0/go.mod h1:m82fZlWIuiWzWP04XCTXmnX0xRkYYbCdYn8jbJeLBEA=
 github.com/apex/logs v1.0.0/go.mod h1:XzxuLZ5myVHDy9SAmYpamKKRNApGj54PfYLcFrXqDwo=

benchmarks/scenario_bench_test.go

@@ -104,6 +104,15 @@ func BenchmarkDisabledWithoutFields(b *testing.B) {
 			}
 		})
 	})
+	b.Run("fortio.org/log", func(b *testing.B) {
+		logger := newDisabledFortiolog()
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				logger.InfoS(getMessage(0))
+			}
+		})
+	})
 
 }
 
@@ -183,7 +192,15 @@ func BenchmarkDisabledAccumulatedContext(b *testing.B) {
 			}
 		})
 	})
-
+	b.Run("fortio.org/log", func(b *testing.B) {
+		logger := newDisabledFortiolog(fakeFortiologFields()...)
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				logger.InfoContext(getMessage(0))
+			}
+		})
+	})
 }
 
 func BenchmarkDisabledAddingFields(b *testing.B) {
@@ -253,7 +270,15 @@ func BenchmarkDisabledAddingFields(b *testing.B) {
 			}
 		})
 	})
-
+	b.Run("fortio.org/log", func(b *testing.B) {
+		logger := newDisabledFortiolog()
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				logger.InfoS(getMessage(0), fakeFortiologFields()...)
+			}
+		})
+	})
 }
 
 func BenchmarkWithoutFields(b *testing.B) {
@@ -401,7 +426,15 @@ func BenchmarkWithoutFields(b *testing.B) {
 			}
 		})
 	})
-
+	b.Run("fortio.org/log", func(b *testing.B) {
+		logger := newFortiolog()
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				logger.Infof(getMessage(0))
+			}
+		})
+	})
 }
 
 func BenchmarkAccumulatedContext(b *testing.B) {
@@ -531,6 +564,15 @@ func BenchmarkAccumulatedContext(b *testing.B) {
 			}
 		})
 	})
+	b.Run("fortio.org/log", func(b *testing.B) {
+		logger := newFortiolog(fakeFortiologFields()...)
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				logger.InfoContext(getMessage(0))
+			}
+		})
+	})
 
 }
 
@@ -643,5 +685,13 @@ func BenchmarkAddingFields(b *testing.B) {
 			}
 		})
 	})
-
+	b.Run("fortio.org/log", func(b *testing.B) {
+		logger := newFortiolog()
+		b.ResetTimer()
+		b.RunParallel(func(pb *testing.PB) {
+			for pb.Next() {
+				logger.InfoS(getMessage(0), fakeFortiologFields()...)
+			}
+		})
+	})
 }

benchmarks/slog_test.go

@@ -21,17 +21,16 @@
 package benchmarks
 
 import (
-	"io"
-
+	"go.uber.org/zap/internal/ztest"
 	"golang.org/x/exp/slog"
 )
 
 func newSlog(fields ...slog.Attr) *slog.Logger {
-	return slog.New(slog.NewJSONHandler(io.Discard).WithAttrs(fields))
+	return slog.New(slog.NewJSONHandler(&ztest.Discarder{}).WithAttrs(fields))
 }
 
 func newDisabledSlog(fields ...slog.Attr) *slog.Logger {
-	return slog.New(slog.HandlerOptions{Level: slog.LevelError}.NewJSONHandler(io.Discard).WithAttrs(fields))
+	return slog.New(slog.HandlerOptions{Level: slog.LevelError}.NewJSONHandler(&ztest.Discarder{}).WithAttrs(fields))
 }
 
 func fakeSlogFields() []slog.Attr {

benchmarks/zap_test.go

@@ -34,20 +34,21 @@ import (
 var (
 	errExample = errors.New("fail")
 
-	_messages   = fakeMessages(1000)
-	_tenInts    = []int{1, 2, 3, 4, 5, 6, 7, 8, 9, 0}
+	_messages = fakeMessages(1000)
+	// Go optimizes away allocations for numbers below 256
+	_tenInts    = []int{1001, 1002, 1003, 1004, 1005, 1006, 1007, 1008, 1009, 1010}
 	_tenStrings = []string{"a", "b", "c", "d", "e", "f", "g", "h", "i", "j"}
 	_tenTimes   = []time.Time{
-		time.Unix(0, 0),
-		time.Unix(1, 0),
-		time.Unix(2, 0),
-		time.Unix(3, 0),
-		time.Unix(4, 0),
-		time.Unix(5, 0),
-		time.Unix(6, 0),
-		time.Unix(7, 0),
-		time.Unix(8, 0),
-		time.Unix(9, 0),
+		time.Unix(1000, 0),
+		time.Unix(1001, 0),
+		time.Unix(1002, 0),
+		time.Unix(1003, 0),
+		time.Unix(1004, 0),
+		time.Unix(1005, 0),
+		time.Unix(1006, 0),
+		time.Unix(1007, 0),
+		time.Unix(1008, 0),
+		time.Unix(1009, 0),
 	}
 	_oneUser = &user{
 		Name:      "Jane Doe",
@@ -110,6 +111,7 @@ func newZapLogger(lvl zapcore.Level) *zap.Logger {
 	enc := zapcore.NewJSONEncoder(ec)
 	return zap.New(zapcore.NewCore(
 		enc,
+		// os.Stderr, // for real/checking the output
 		&ztest.Discarder{},
 		lvl,
 	))

internal/readme/readme.go

@@ -46,6 +46,7 @@ var (
 		"apex/log":              "apex/log",
 		"rs/zerolog":            "zerolog",
 		"slog":                  "slog",
+		"fortio.org/log":        "fortio log",
 	}
 )