testing.B.Loop() standardization and StackAsync.Debug improvement (#156)

* testing.B.Loop() standardization and StackAsync.Debug heap debugging improvement

* apply @MDr164 fixes

* @MDr164 great suggestions to prevent panic and print correct mallocs

http/httpraw/header_test.go

@@ -124,7 +124,7 @@ func BenchmarkParseBytes(b *testing.B) {
 	var hdr Header
 	b.StartTimer()
 
-	for i := 0; i < b.N; i++ {
+	for b.Loop() {
 		err := hdr.ParseBytes(asRequest, data)
 		if err != nil {
 			b.Fatal(err)

internal/debug.go

@@ -2,16 +2,16 @@ package internal
 
 import (
 	"log/slog"
+	"os"
 	"runtime"
 	"strconv"
 	"sync"
-	"unsafe"
 )
 
 const (
 	LevelTrace slog.Level = slog.LevelDebug - 2
 
-	usePrintLogAllocs = true
+	usePrintLogAllocs = HeapAllocDebugging
 )
 
 var (
@@ -19,9 +19,13 @@ var (
 	lastAllocs  uint64
 	lastMallocs uint64
 	allocmu     sync.Mutex
-	allocbuf    [256]byte
+	allocbuf    [128]byte
 )
 
+func LogAttrsAndAllocs(allocmsg string, l *slog.Logger, level slog.Level, msg string, attrs ...slog.Attr) {
+	logAttrsAndAllocs(allocmsg, l, level, msg, attrs...)
+}
+
 func LogAllocs(msg string) {
 	allocmu.Lock()
 	runtime.ReadMemStats(&memstats)
@@ -29,23 +33,34 @@ func LogAllocs(msg string) {
 		allocmu.Unlock()
 		return
 	}
+	inc := int64(memstats.TotalAlloc) - int64(lastAllocs)
+	numAlloc := int64(memstats.Mallocs) - int64(lastMallocs)
+	free := memstats.HeapSys - memstats.HeapInuse
 	if usePrintLogAllocs {
+		// Branch used when debugheaplog enabled
 		print("[ALLOC] ", msg)
-		print(" inc=", int64(memstats.TotalAlloc)-int64(lastAllocs))
+		print(" inc=", inc)
-		print(" n=", int64(memstats.Mallocs)-int64(lastMallocs))
+		print(" n=", numAlloc)
 		print(" heap=", memstats.HeapAlloc)
-		print(" free=", memstats.HeapSys-memstats.HeapInuse)
+		print(" free=", free)
 		print(" tot=", memstats.TotalAlloc)
 		println()
 	} else {
-		n := copy(allocbuf[:], "[ALLOC] ")
+		buf := allocbuf[:len(allocbuf)-1] // keep one character for newline.
-		n += copy(allocbuf[n:], msg)
+		n := copy(buf[:], "[ALLOC] ")
-		n += copyValueInt(allocbuf[n:], "inc", int64(memstats.TotalAlloc)-int64(lastAllocs))
+		n += copy(buf[n:], msg)
-		n += copyValueInt(allocbuf[n:], "n", int64(memstats.Mallocs)-int64(lastMallocs))
+		n += copyValueInt(buf[n:], "inc", inc)
-		n += copyValueUint(allocbuf[n:], "heap", memstats.HeapAlloc)
+		n += copyValueInt(buf[n:], "n", numAlloc)
-		n += copyValueUint(allocbuf[n:], "free", memstats.HeapSys-memstats.HeapInuse)
+		n += copyValueUint(buf[n:], "heap", memstats.HeapAlloc)
-		n += copyValueUint(allocbuf[n:], "tot", memstats.TotalAlloc)
+		n += copyValueUint(buf[n:], "free", free)
-		println(unsafe.String(&allocbuf[0], n))
+		lastN := copyValueUint(buf[n:], "tot", memstats.TotalAlloc)
+		n += lastN
+		allocbuf[n] = '\n' // n will never be larger than len(allocbuf)-1
+		os.Stdout.Write(allocbuf[:n+1])
+		if lastN == 0 {
+			n2 := copy(allocbuf[:], "[WARN] ALLOC BUF OVERRUN\n")
+			os.Stdout.Write(allocbuf[:n2])
+		}
 	}
 	lastAllocs = memstats.TotalAlloc
 	lastMallocs = memstats.Mallocs

internal/debug_heaplog.go

@@ -4,7 +4,6 @@ package internal
 
 import (
 	"log/slog"
-	"runtime"
 	"time"
 	"unsafe"
 )
@@ -22,10 +21,13 @@ func LogEnabled(l *slog.Logger, lvl slog.Level) bool {
 	return true
 }
 
+func logAttrsAndAllocs(allocmsg string, l *slog.Logger, level slog.Level, msg string, attrs ...slog.Attr) {
+	LogAttrs(nil, level, msg, attrs...) // already logs attributes
+}
+
 func LogAttrs(_ *slog.Logger, level slog.Level, msg string, attrs ...slog.Attr) {
 	now := time.Now()
 	n := len(now.AppendFormat(timebuf[:0], timefmt))
-	LogAllocs(msg)
 	print("time=", unsafe.String(&timebuf[0], n), " ")
 	if level == LevelTrace {
 		print("TRACE ")
@@ -35,7 +37,6 @@ func LogAttrs(_ *slog.Logger, level slog.Level, msg string, attrs ...slog.Attr)
 		print(level.String(), " ")
 	}
 	print(msg)
-
 	for _, a := range attrs {
 		switch a.Value.Kind() {
 		case slog.KindString:
@@ -49,12 +50,5 @@ func LogAttrs(_ *slog.Logger, level slog.Level, msg string, attrs ...slog.Attr)
 		}
 	}
 	println()
-	allocmu.Lock()
+	LogAllocs(msg)
-	runtime.ReadMemStats(&memstats)
-	if lastAllocs != memstats.TotalAlloc {
-		print("alloc increase in heaplog")
-	}
-	lastAllocs = memstats.TotalAlloc
-	lastMallocs = memstats.Mallocs
-	allocmu.Unlock()
 }

internal/debug_noheaplog.go

@@ -21,3 +21,9 @@ func LogAttrs(l *slog.Logger, level slog.Level, msg string, attrs ...slog.Attr)
 		l.LogAttrs(context.Background(), level, msg, attrs...)
 	}
 }
+
+func logAttrsAndAllocs(allocmsg string, l *slog.Logger, level slog.Level, msg string, attrs ...slog.Attr) {
+	LogAllocs(allocmsg)
+	LogAttrs(l, level, msg, attrs...)
+	LogAllocs(msg) // Should not log again unless LogAttrs allocated.
+}

internet/pcap/capture_bench_test.go

@@ -132,7 +132,7 @@ func BenchmarkPcap(b *testing.B) {
 				var frames []Frame
 				b.ReportAllocs()
 				b.ResetTimer()
-				for i := 0; i < b.N; i++ {
+				for b.Loop() {
 					frames, _ = pb.CaptureEthernet(frames[:0], tc.pkt, 0)
 				}
 			})
@@ -148,7 +148,7 @@ func BenchmarkPcap(b *testing.B) {
 				var buf []byte
 				b.ReportAllocs()
 				b.ResetTimer()
-				for i := 0; i < b.N; i++ {
+				for b.Loop() {
 					buf, _ = f.FormatFrames(buf[:0], frames, tc.pkt)
 				}
 			})
@@ -161,7 +161,7 @@ func BenchmarkPcap(b *testing.B) {
 				var buf []byte
 				b.ReportAllocs()
 				b.ResetTimer()
-				for i := 0; i < b.N; i++ {
+				for b.Loop() {
 					frames, _ = pb.CaptureEthernet(frames[:0], tc.pkt, 0)
 					buf, _ = f.FormatFrames(buf[:0], frames, tc.pkt)
 				}
@@ -193,7 +193,7 @@ func BenchmarkPcapPhases(b *testing.B) {
 			var buf []byte
 			var decNs, fmtNs int64
 			b.ResetTimer()
-			for i := 0; i < b.N; i++ {
+			for b.Loop() {
 				t0 := time.Now()
 				frames, _ = pb.CaptureEthernet(frames[:0], tc.pkt, 0)
 				t1 := time.Now()

tcp/syncookie_test.go

@@ -227,7 +227,7 @@ func BenchmarkSYNCookie_Generate(b *testing.B) {
 	clientISN := Value(0x12345678)
 
 	b.ResetTimer()
-	for i := 0; i < b.N; i++ {
+	for b.Loop() {
 		sc.MakeSYNCookie(srcAddr, dstAddr, srcPort, dstPort, clientISN)
 	}
 }
@@ -247,7 +247,7 @@ func BenchmarkSYNCookie_Validate(b *testing.B) {
 	ackNum := cookie + 1
 
 	b.ResetTimer()
-	for i := 0; i < b.N; i++ {
+	for b.Loop() {
 		sc.ValidateSYNCookie(srcAddr, dstAddr, srcPort, dstPort, clientISN, ackNum)
 	}
 }

x/xnet/stack-async.go

@@ -842,24 +842,18 @@ func addr4(addr [4]byte, ok bool) netip.Addr {
 	return netip.AddrFrom4(addr)
 }
 
-// Debug prints debugging information. Very useful for users when coupled with
+// Debug prints debugging and heap information.
-// the debugheaplog build tag. See [internal.LogAttrs] debugheaplog version.
-//
-//	go build -tags=debugheaplog ./yourprogram
 func (s *StackAsync) Debug(msg string) {
-	internal.LogAttrs(slog.Default(), slog.LevelDebug, "stackasync",
+	internal.LogAttrsAndAllocs(msg, slog.Default(), slog.LevelDebug, "stackasync",
 		slog.String("umsg", msg),
 		slog.Uint64("sent", s.stats.TotalSent),
 		slog.Uint64("recv", s.stats.TotalReceived),
 	)
 }
 
-// DebugErr prints debugging and error info. Very useful for users when coupled with
+// DebugErr prints debugging and heap information.
-// the debugheaplog build tag. See [internal.LogAttrs] debugheaplog version.
-//
-//	go build -tags=debugheaplog ./yourprogram
 func (s *StackAsync) DebugErr(msg, err string) {
-	internal.LogAttrs(slog.Default(), slog.LevelError, "stackasync",
+	internal.LogAttrsAndAllocs(msg, slog.Default(), slog.LevelError, "stackasync",
 		slog.String("umsg", msg),
 		slog.String("err", err),
 		slog.Uint64("sent", s.stats.TotalSent),

x/xnet/xnet_bench_test.go

@@ -41,7 +41,7 @@ func BenchmarkARPExchange(b *testing.B) {
 	var buf [frameSize]byte
 
 	b.ResetTimer()
-	for i := 0; i < b.N; i++ {
+	for b.Loop() {
 		err = c1.StartResolveHardwareAddress6(queryAddr)
 		if err != nil {
 			b.Fatal(err)
@@ -130,7 +130,7 @@ func BenchmarkTCPHandshake(b *testing.B) {
 	var pktbuf [frameSize]byte
 
 	b.ResetTimer()
-	for i := 0; i < b.N; i++ {
+	for b.Loop() {
 		// Setup connections.
 		err = sv.ListenTCP4(svconn, svPort)
 		if err != nil {

x/xnet/xnet_debug_pcap.go

@@ -2,7 +2,11 @@
 
 package xnet
 
-import "os"
+import (
+	"os"
+
+	"github.com/soypat/lneto/internal"
+)
 
 var _pcap CapturePrinter
 
@@ -14,4 +18,7 @@ func init() {
 
 func debugPacket(msg string, b []byte) {
 	_pcap.PrintEthernet(msg, b)
+	if internal.HeapAllocDebugging {
+		internal.LogAllocs(msg)
+	}
 }

x/xnet/xnet_untinygo_test.go

@@ -13,6 +13,9 @@ import (
 )
 
 func TestTinyGoTest(t *testing.T) {
+	if testing.Short() {
+		t.Skip("`tinygo test` skipped on short test")
+	}
 	if exec.Command("tinygo", "version").Run() != nil {
 		t.Skip("tinygo not installed")
 	}