diff --git a/http/httpraw/header_test.go b/http/httpraw/header_test.go index 4325d96..4228225 100644 --- a/http/httpraw/header_test.go +++ b/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) diff --git a/internal/debug.go b/internal/debug.go index caff18f..d0991cb 100644 --- a/internal/debug.go +++ b/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(" n=", int64(memstats.Mallocs)-int64(lastMallocs)) + print(" inc=", inc) + 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] ") - n += copy(allocbuf[n:], msg) - n += copyValueInt(allocbuf[n:], "inc", int64(memstats.TotalAlloc)-int64(lastAllocs)) - n += copyValueInt(allocbuf[n:], "n", int64(memstats.Mallocs)-int64(lastMallocs)) - n += copyValueUint(allocbuf[n:], "heap", memstats.HeapAlloc) - n += copyValueUint(allocbuf[n:], "free", memstats.HeapSys-memstats.HeapInuse) - n += copyValueUint(allocbuf[n:], "tot", memstats.TotalAlloc) - println(unsafe.String(&allocbuf[0], n)) + buf := allocbuf[:len(allocbuf)-1] // keep one character for newline. + n := copy(buf[:], "[ALLOC] ") + n += copy(buf[n:], msg) + n += copyValueInt(buf[n:], "inc", inc) + n += copyValueInt(buf[n:], "n", numAlloc) + n += copyValueUint(buf[n:], "heap", memstats.HeapAlloc) + n += copyValueUint(buf[n:], "free", free) + 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 diff --git a/internal/debug_heaplog.go b/internal/debug_heaplog.go index bf4f561..5815c87 100644 --- a/internal/debug_heaplog.go +++ b/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() - runtime.ReadMemStats(&memstats) - if lastAllocs != memstats.TotalAlloc { - print("alloc increase in heaplog") - } - lastAllocs = memstats.TotalAlloc - lastMallocs = memstats.Mallocs - allocmu.Unlock() + LogAllocs(msg) } diff --git a/internal/debug_noheaplog.go b/internal/debug_noheaplog.go index a39a0be..7cade96 100644 --- a/internal/debug_noheaplog.go +++ b/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. +} diff --git a/internet/pcap/capture_bench_test.go b/internet/pcap/capture_bench_test.go index b108860..8f3aa4d 100644 --- a/internet/pcap/capture_bench_test.go +++ b/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() diff --git a/tcp/syncookie_test.go b/tcp/syncookie_test.go index e81fdac..451622a 100644 --- a/tcp/syncookie_test.go +++ b/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) } } diff --git a/x/xnet/stack-async.go b/x/xnet/stack-async.go index 170e212..8792bba 100644 --- a/x/xnet/stack-async.go +++ b/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 -// the debugheaplog build tag. See [internal.LogAttrs] debugheaplog version. -// -// go build -tags=debugheaplog ./yourprogram +// Debug prints debugging and heap information. 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 -// the debugheaplog build tag. See [internal.LogAttrs] debugheaplog version. -// -// go build -tags=debugheaplog ./yourprogram +// DebugErr prints debugging and heap information. 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), diff --git a/x/xnet/xnet_bench_test.go b/x/xnet/xnet_bench_test.go index 8bcfce5..35740b1 100644 --- a/x/xnet/xnet_bench_test.go +++ b/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 { diff --git a/x/xnet/xnet_debug_pcap.go b/x/xnet/xnet_debug_pcap.go index 48d5ac5..dfe7e34 100644 --- a/x/xnet/xnet_debug_pcap.go +++ b/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) + } } diff --git a/x/xnet/xnet_untinygo_test.go b/x/xnet/xnet_untinygo_test.go index 36665ed..a3fd910 100644 --- a/x/xnet/xnet_untinygo_test.go +++ b/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") }