Optimizations and benchmark upgrades

.gitignore

@@ -0,0 +1 @@
+scripts/*.txt

BENCH.md

@@ -0,0 +1,44 @@
+# Benchmark Results
+
+CPU: Apple M5
+
+## vs main
+
+| Benchmark | main | current | Delta |
+|:----------|----------:|----------:|------:|
+| JSON | 228.0n ±3% | 199.9n ±0% | **-12.31%** |
+| Bare | 141.6n ±2% | 130.7n ±1% | **-7.70%** |
+| Optimized | 175.4n ±1% | 163.8n ±2% | **-6.64%** |
+| Pretty | 252.4n ±2% | 170.5n ±1% | **-32.44%** |
+| PrettySorted | 251.5n ±2% | 174.6n ±1% | **-30.58%** |
+| PrettySortedContext | 318.1n ±1% | 254.1n ±2% | **-20.14%** |
+| JSONNoFields | — | 49.92n ±1% | — |
+| JSONOneField | — | 116.7n ±2% | — |
+| JSONTenFields | — | 475.8n ±1% | — |
+| JSONContext | — | 292.4n ±1% | — |
+| PrettyNoFields | — | 46.44n ±3% | — |
+| PrettyTenFields | — | 468.1n ±4% | — |
+| Disabled | — | 33.38n ±1% | — |
+| ParallelJSON | — | 176.3n ±1% | — |
+| ParallelPretty | — | 170.2n ±3% | — |
+| **geomean** | 220.3n | 152.7n | **-18.97%** |
+
+## Current Results
+
+| Benchmark | ns/op | B/op | allocs/op |
+|:----------|------:|-----:|----------:|
+| BenchmarkJSON | 199.6 | 0 | 0 |
+| BenchmarkBare | 132.4 | 0 | 0 |
+| BenchmarkOptimized | 161.3 | 0 | 0 |
+| BenchmarkPretty | 172.9 | 0 | 0 |
+| BenchmarkPrettySorted | 175.6 | 0 | 0 |
+| BenchmarkPrettySortedContext | 258.4 | 0 | 0 |
+| BenchmarkJSONNoFields | 50.3 | 0 | 0 |
+| BenchmarkJSONOneField | 117.8 | 0 | 0 |
+| BenchmarkJSONTenFields | 476.2 | 616 | 3 |
+| BenchmarkJSONContext | 295.7 | 0 | 0 |
+| BenchmarkPrettyNoFields | 45.9 | 0 | 0 |
+| BenchmarkPrettyTenFields | 466.4 | 616 | 3 |
+| BenchmarkDisabled | 33.4 | 0 | 0 |
+| BenchmarkParallelJSON | 176.6 | 0 | 0 |
+| BenchmarkParallelPretty | 170.5 | 0 | 0 |

blip_test.go

@@ -215,3 +215,214 @@ func BenchmarkPrettySortedContext(b *testing.B) {
 		})
 	}
 }
+
+//
+// Extended benchmarks: field count variations
+//
+
+func BenchmarkJSONNoFields(b *testing.B) {
+	log.Setup(blip.Config{
+		Level:           blip.LevelDebug,
+		Output:          io.Discard,
+		StackTraceLevel: blip.LevelError,
+		Encoder:         blip.NewJSONEncoder(),
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	for range b.N {
+		log.Info(ctx, "Starting task")
+	}
+}
+
+func BenchmarkJSONOneField(b *testing.B) {
+	log.Setup(blip.Config{
+		Level:           blip.LevelDebug,
+		Output:          io.Discard,
+		StackTraceLevel: blip.LevelError,
+		Encoder:         blip.NewJSONEncoder(),
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	for range b.N {
+		log.Info(ctx, "Starting task", log.F{
+			"task_id": 123456,
+		})
+	}
+}
+
+func BenchmarkJSONTenFields(b *testing.B) {
+	log.Setup(blip.Config{
+		Level:           blip.LevelDebug,
+		Output:          io.Discard,
+		StackTraceLevel: blip.LevelError,
+		Encoder:         blip.NewJSONEncoder(),
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	for range b.N {
+		log.Info(ctx, "Starting task", log.F{
+			"device_unique_id": "G4000E-1000-F",
+			"task_id":          123456,
+			"status":           "success",
+			"template_name":    "index.tpl",
+			"user_id":          "usr_abc123",
+			"request_id":       "req_xyz789",
+			"duration_ms":      42,
+			"retry_count":      3,
+			"region":           "us-east-1",
+			"version":          "v2.1.0",
+		})
+	}
+}
+
+func BenchmarkJSONContext(b *testing.B) {
+	log.Setup(blip.Config{
+		Level:           blip.LevelDebug,
+		Output:          io.Discard,
+		StackTraceLevel: blip.LevelError,
+		Encoder:         blip.NewJSONEncoder(),
+	})
+	ctx := context.Background()
+	ctx = blip.ContextWithFields(ctx, log.F{"request_id": "req_xyz789"})
+	ctx = blip.ContextWithFields(ctx, log.F{"user_id": "usr_abc123"})
+
+	b.ResetTimer()
+	for range b.N {
+		log.Info(ctx, "Starting task", log.F{
+			"device_unique_id": "G4000E-1000-F",
+			"task_id":          123456,
+			"status":           "success",
+			"template_name":    "index.tpl",
+		})
+	}
+}
+
+func BenchmarkPrettyNoFields(b *testing.B) {
+	log.Setup(blip.Config{
+		Level:  blip.LevelDebug,
+		Output: io.Discard,
+		Encoder: &blip.ConsoleEncoder{
+			TimeFormat:      "2006-01-02 15:04:05.000",
+			TimePrecision:   1 * time.Millisecond,
+			Color:           true,
+			MinMessageWidth: 40,
+			SortFields:      true,
+		},
+		StackTraceLevel: blip.LevelError,
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	for range b.N {
+		log.Info(ctx, "Starting task")
+	}
+}
+
+func BenchmarkPrettyTenFields(b *testing.B) {
+	log.Setup(blip.Config{
+		Level:  blip.LevelDebug,
+		Output: io.Discard,
+		Encoder: &blip.ConsoleEncoder{
+			TimeFormat:      "2006-01-02 15:04:05.000",
+			TimePrecision:   1 * time.Millisecond,
+			Color:           true,
+			MinMessageWidth: 40,
+			SortFields:      true,
+		},
+		StackTraceLevel: blip.LevelError,
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	for range b.N {
+		log.Info(ctx, "Starting task", log.F{
+			"device_unique_id": "G4000E-1000-F",
+			"task_id":          123456,
+			"status":           "success",
+			"template_name":    "index.tpl",
+			"user_id":          "usr_abc123",
+			"request_id":       "req_xyz789",
+			"duration_ms":      42,
+			"retry_count":      3,
+			"region":           "us-east-1",
+			"version":          "v2.1.0",
+		})
+	}
+}
+
+//
+// Extended benchmarks: special cases
+//
+
+func BenchmarkDisabled(b *testing.B) {
+	log.Setup(blip.Config{
+		Level:           blip.LevelError,
+		Output:          io.Discard,
+		StackTraceLevel: blip.LevelPanic,
+		Encoder:         blip.NewJSONEncoder(),
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	for range b.N {
+		log.Info(ctx, "Starting task", log.F{
+			"device_unique_id": "G4000E-1000-F",
+			"task_id":          123456,
+			"status":           "success",
+			"template_name":    "index.tpl",
+		})
+	}
+}
+
+func BenchmarkParallelJSON(b *testing.B) {
+	logger := blip.New(blip.Config{
+		Level:           blip.LevelDebug,
+		Output:          io.Discard,
+		StackTraceLevel: blip.LevelError,
+		Encoder:         blip.NewJSONEncoder(),
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			logger.Info(ctx, "Starting task", blip.F{
+				"device_unique_id": "G4000E-1000-F",
+				"task_id":          123456,
+				"status":           "success",
+				"template_name":    "index.tpl",
+			})
+		}
+	})
+}
+
+func BenchmarkParallelPretty(b *testing.B) {
+	logger := blip.New(blip.Config{
+		Level:  blip.LevelDebug,
+		Output: io.Discard,
+		Encoder: &blip.ConsoleEncoder{
+			TimeFormat:      "2006-01-02 15:04:05.000",
+			TimePrecision:   1 * time.Millisecond,
+			Color:           true,
+			MinMessageWidth: 40,
+			SortFields:      true,
+		},
+		StackTraceLevel: blip.LevelError,
+	})
+	ctx := context.Background()
+
+	b.ResetTimer()
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			logger.Info(ctx, "Starting task", blip.F{
+				"device_unique_id": "G4000E-1000-F",
+				"task_id":          123456,
+				"status":           "success",
+				"template_name":    "index.tpl",
+			})
+		}
+	})
+}

buffer.go

@@ -37,11 +37,6 @@ func (buf *Buffer) WriteString(str string) {
 	buf.b = append(buf.b, str...)
 }
 
-// WriteRune writes a rune to the buffer. It encodes the rune as UTF-8.
-func (buf *Buffer) WriteRune(r rune) {
-	buf.b = utf8.AppendRune(buf.b, r)
-}
-
 // WriteInt writes an int64 value to the buffer.
 func (buf *Buffer) WriteInt(i int64) {
 	buf.b = strconv.AppendInt(buf.b, i, 10)
@@ -72,34 +67,52 @@ func (buf *Buffer) WriteTime(t time.Time, format string) {
 	buf.b = t.AppendFormat(buf.b, format)
 }
 
+// needsEscape is a lookup table for ASCII bytes that need JSON escaping.
+// true for control characters (< 0x20), double quote, and backslash.
+var needsEscape [128]bool
+
+func init() {
+	for i := range 0x20 {
+		needsEscape[i] = true
+	}
+	needsEscape['"'] = true
+	needsEscape['\\'] = true
+}
+
 // WriteEscapedString writes a string to the buffer, escaping special characters
-// as needed. It handles both ASCII and Unicode characters. The string is
-// enclosed in double quotes.
+// as needed for JSON. Valid UTF-8 is passed through as-is. Invalid UTF-8
+// sequences are replaced with \ufffd. The string is enclosed in double quotes.
 func (buf *Buffer) WriteEscapedString(str string) {
 	buf.WriteBytes('"')
 	// last is the last index of the string that has been written to the buffer.
 	// cur is the current index of the string being processed.
 	//
 	// Read the string byte by byte and escape any characters that need it.
-	// Check for ASCII characters first and then for other characters outside of
-	// the ASCII printable range. Write to the buffer as we go.
+	// Valid multi-byte UTF-8 sequences are skipped over and included in the
+	// next batch flush. Write to the buffer as we go.
 	last := 0
 	for cur := 0; cur < len(str); {
 		b := str[cur]
-		if b < 0x20 || b == '"' || b == '\\' || b >= 0x80 {
-			// Write unescaped segment
+		switch {
+		case b >= 0x80:
+			_, size := utf8.DecodeRuneInString(str[cur:])
+			if size == 1 {
+				// \uFFFD is the replacement character for invalid UTF-8
+				// sequences (�).
+				buf.flushAndWrite(str, last, cur, `\ufffd`)
+				cur++
+				last = cur
+			} else {
+				cur += size
+			}
+		case needsEscape[b]:
 			if last < cur {
 				buf.WriteString(str[last:cur])
 			}
-			if b >= 0x80 {
-				size := buf.writeEscapedUTF8(str[cur:])
-				cur += size
-			} else {
-				buf.writeEscapedASCII(b)
-				cur++
-			}
+			buf.writeEscapedByte(b)
+			cur++
 			last = cur
-		} else {
+		default:
 			cur++
 		}
 	}
@@ -110,14 +123,14 @@ func (buf *Buffer) WriteEscapedString(str string) {
 	buf.WriteBytes('"')
 }
 
-// WriteBase64 writes a byte slice to the buffer as a base64-encoded string.
-func (buf *Buffer) WriteBase64(b64enc *base64.Encoding, data []byte) {
-	buf.WriteBytes('"')
-	buf.b = b64enc.AppendEncode(buf.b, data)
-	buf.WriteBytes('"')
+func (buf *Buffer) flushAndWrite(str string, last, cur int, replacement string) {
+	if last < cur {
+		buf.WriteString(str[last:cur])
+	}
+	buf.WriteString(replacement)
 }
 
-func (buf *Buffer) writeEscapedASCII(b byte) {
+func (buf *Buffer) writeEscapedByte(b byte) {
 	switch b {
 	case '"', '\\':
 		buf.WriteBytes('\\', b)
@@ -131,21 +144,14 @@ func (buf *Buffer) writeEscapedASCII(b byte) {
 		buf.WriteBytes('\\', 'r')
 	case '\t':
 		buf.WriteBytes('\\', 't')
-	default:
-		// Ignore other control characters
 	}
 }
 
-func (buf *Buffer) writeEscapedUTF8(str string) int {
-	r, size := utf8.DecodeRuneInString(str)
-	if r == utf8.RuneError && size == 1 {
-		// \uFFFD is the replacement character for invalid UTF-8 sequences (�).
-		// It looks like a diamond with a question mark inside.
-		buf.WriteBytes('\\', 'u', 'f', 'f', 'f', 'd')
-		return 1
-	}
-	buf.WriteRune(r)
-	return size
+// WriteBase64 writes a byte slice to the buffer as a base64-encoded string.
+func (buf *Buffer) WriteBase64(b64enc *base64.Encoding, data []byte) {
+	buf.WriteBytes('"')
+	buf.b = b64enc.AppendEncode(buf.b, data)
+	buf.WriteBytes('"')
 }
 
 //