From 2600bf5dda9f6a09e5ec4385a542ec909fc69bca Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 15 Aug 2023 13:41:34 -0700 Subject: [PATCH 1/4] udpate makefile and .gitignore --- Makefile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Makefile b/Makefile index e84f9b9..ba9318e 100644 --- a/Makefile +++ b/Makefile @@ -4,7 +4,7 @@ ARGS:=-n 10 -e 4 -r 3 -manual-check: manual-check-fortio manual-check-zap +manual-check: manual-check-fortio manual-check-zap manual-check-slog manual-check-fortio: $(MAKE) manual-check-param PARAM=fortio From ae17398a22f6934f025da726f212dfc27e567255 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 15 Aug 2023 14:30:44 -0700 Subject: [PATCH 2/4] adding memory stats and optional -profile --- main.go | 53 +++++++++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 49 insertions(+), 4 deletions(-) diff --git a/main.go b/main.go index 40fc2f0..bbec316 100644 --- a/main.go +++ b/main.go @@ -3,7 +3,9 @@ package main import ( "flag" "fmt" + "os" "runtime" + "runtime/pprof" "sync" "fortio.org/cli" @@ -23,6 +25,7 @@ func main() { numCallsFlag := flag.Int64("n", 100, "Number of calls logged (info level), per goroutine `r`") numExtraFlag := flag.Int("e", 9, "Number of extra debug calls (not logged for each `n` iteration), total call will be n*(e+1)") numGoroutineFlag := flag.Int("r", 10, "Number of go routines to use (multiplies the other numbers)") + profileFlag := flag.String("profile", "", "Write a cpu and memory profile to using the given file `prefix`") // Force JSON output even on console and disable expensive debug file/line logging // as well as goroutine id logging which most other loggers don't have. cli.BeforeFlagParseHook = func() { @@ -47,31 +50,57 @@ func main() { numCalls := *numCallsFlag numExtra := *numExtraFlag numThrds := *numGoroutineFlag + log.SetOutput(os.Stdout) log.S(log.Info, "Testing", log.Str("logger", cli.Command), log.Attr("num-calls", numCalls), log.Attr("num-extra", numExtra), log.Attr("num-goroutines", numThrds), log.Attr("gomaxprocs", runtime.GOMAXPROCS(0)), + log.Attr("profile", *profileFlag), ) switch cli.Command { case "fortio": - Drive(FortioLog1, numThrds, numCalls, numExtra) + log.SetOutput(os.Stderr) + Drive(*profileFlag, FortioLog1, numThrds, numCalls, numExtra) case "zap": SetupZapLogger() - Drive(ZapLog1, numThrds, numCalls, numExtra) + Drive(*profileFlag, ZapLog1, numThrds, numCalls, numExtra) _ = zlog.Sync() case "slog": SetupSlogLogger() - Drive(SlogLog1, numThrds, numCalls, numExtra) + Drive(*profileFlag, SlogLog1, numThrds, numCalls, numExtra) } } +func PrintMemoryStats(start, end *runtime.MemStats) { + log.S(log.Info, "Memory stats", + log.Attr("alloc", end.Alloc-start.Alloc), + log.Attr("total-alloc", end.TotalAlloc-start.TotalAlloc), + log.Attr("num-gc", end.NumGC-start.NumGC), + ) +} + // Drive the given (iteration logging) function from multiple goroutines. -func Drive(fn func(string, int64, int), numGoroutines int, numLogged int64, numExtraNotLogged int) { +func Drive(profile string, fn func(string, int64, int), numGoroutines int, numLogged int64, numExtraNotLogged int) { // wait group wg := sync.WaitGroup{} wg.Add(numGoroutines) + var mStart runtime.MemStats + var mEnd runtime.MemStats + runtime.GC() + runtime.ReadMemStats(&mStart) + var fc *os.File + if profile != "" { + var err error + fc, err = os.Create(profile + ".cpu") + if err != nil { + log.Fatalf("Unable to create .cpu profile: %v", err) + } + if err = pprof.StartCPUProfile(fc); err != nil { + log.Critf("Unable to start cpu profile: %v", err) + } + } for i := 1; i <= numGoroutines; i++ { go func(c int) { fn(fmt.Sprintf("R%d", c), numLogged, numExtraNotLogged) @@ -79,4 +108,20 @@ func Drive(fn func(string, int64, int), numGoroutines int, numLogged int64, numE }(i) } wg.Wait() + runtime.ReadMemStats(&mEnd) + log.SetOutput(os.Stdout) + if profile != "" { + pprof.StopCPUProfile() + fm, err := os.Create(profile + ".mem") + if err != nil { + log.Fatalf("Unable to create .mem profile: %v", err) + } + runtime.GC() // get up-to-date statistics + if err = pprof.WriteHeapProfile(fm); err != nil { + log.Critf("Unable to write heap profile: %v", err) + } + fm.Close() + log.Infof("Wrote profile data to %s.{cpu|mem}", profile) + } + PrintMemoryStats(&mStart, &mEnd) } From 1552f75366c240c29bb0882710d137aab6752fe4 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 15 Aug 2023 14:57:55 -0700 Subject: [PATCH 3/4] zap has sampling on by default for the prod config, turn it off --- main.go | 3 ++- zap.go | 2 ++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/main.go b/main.go index bbec316..b309495 100644 --- a/main.go +++ b/main.go @@ -42,6 +42,7 @@ func main() { valid := []string{"fortio", "zap", "slog"} cli.CommandBeforeFlags = true cli.CommandHelp = "{" + cli.ColorJoin(log.Colors.Purple, valid...) + "}" + log.SetOutput(os.Stdout) // we use stderr for the logger tests, and so stdout for this scli.ServerMain() vSet := sets.FromSlice(valid) if !vSet.Has(cli.Command) { @@ -61,7 +62,6 @@ func main() { ) switch cli.Command { case "fortio": - log.SetOutput(os.Stderr) Drive(*profileFlag, FortioLog1, numThrds, numCalls, numExtra) case "zap": SetupZapLogger() @@ -101,6 +101,7 @@ func Drive(profile string, fn func(string, int64, int), numGoroutines int, numLo log.Critf("Unable to start cpu profile: %v", err) } } + log.SetOutput(os.Stderr) for i := 1; i <= numGoroutines; i++ { go func(c int) { fn(fmt.Sprintf("R%d", c), numLogged, numExtraNotLogged) diff --git a/zap.go b/zap.go index b0383d5..33895c6 100644 --- a/zap.go +++ b/zap.go @@ -9,6 +9,8 @@ var zlog *zap.Logger func SetupZapLogger() { cfg := zap.NewProductionConfig() + // Important: turn off sampling! + cfg.Sampling = nil if log.GetLogLevel() == log.Debug { cfg.Level.SetLevel(zap.DebugLevel) } From 31a2fdcc7aaeba10d3171e7272947d0da6a651a8 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Tue, 15 Aug 2023 15:18:31 -0700 Subject: [PATCH 4/4] suffix the logger to profile so only need to say it once --- main.go | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/main.go b/main.go index b309495..87f1680 100644 --- a/main.go +++ b/main.go @@ -25,7 +25,8 @@ func main() { numCallsFlag := flag.Int64("n", 100, "Number of calls logged (info level), per goroutine `r`") numExtraFlag := flag.Int("e", 9, "Number of extra debug calls (not logged for each `n` iteration), total call will be n*(e+1)") numGoroutineFlag := flag.Int("r", 10, "Number of go routines to use (multiplies the other numbers)") - profileFlag := flag.String("profile", "", "Write a cpu and memory profile to using the given file `prefix`") + profileFlag := flag.String("profile", "", + "Write a cpu and memory profile to using the given file `prefix` (will add logger name .cpu and .mem)") // Force JSON output even on console and disable expensive debug file/line logging // as well as goroutine id logging which most other loggers don't have. cli.BeforeFlagParseHook = func() { @@ -51,25 +52,28 @@ func main() { numCalls := *numCallsFlag numExtra := *numExtraFlag numThrds := *numGoroutineFlag - log.SetOutput(os.Stdout) + profile := "" + if *profileFlag != "" { + profile = *profileFlag + "-" + cli.Command + } log.S(log.Info, "Testing", log.Str("logger", cli.Command), log.Attr("num-calls", numCalls), log.Attr("num-extra", numExtra), log.Attr("num-goroutines", numThrds), log.Attr("gomaxprocs", runtime.GOMAXPROCS(0)), - log.Attr("profile", *profileFlag), + log.Attr("profile", profile), ) switch cli.Command { case "fortio": - Drive(*profileFlag, FortioLog1, numThrds, numCalls, numExtra) + Drive(profile, FortioLog1, numThrds, numCalls, numExtra) case "zap": SetupZapLogger() - Drive(*profileFlag, ZapLog1, numThrds, numCalls, numExtra) + Drive(profile, ZapLog1, numThrds, numCalls, numExtra) _ = zlog.Sync() case "slog": SetupSlogLogger() - Drive(*profileFlag, SlogLog1, numThrds, numCalls, numExtra) + Drive(profile, SlogLog1, numThrds, numCalls, numExtra) } } @@ -122,7 +126,7 @@ func Drive(profile string, fn func(string, int64, int), numGoroutines int, numLo log.Critf("Unable to write heap profile: %v", err) } fm.Close() - log.Infof("Wrote profile data to %s.{cpu|mem}", profile) + log.S(log.Info, "Wrote profile data", log.Str("cpu", profile+".cpu"), log.Str("mem", profile+".mem")) } PrintMemoryStats(&mStart, &mEnd) }