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 diff --git a/main.go b/main.go index 40fc2f0..87f1680 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,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` (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() { @@ -39,6 +43,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) { @@ -47,31 +52,60 @@ func main() { numCalls := *numCallsFlag numExtra := *numExtraFlag numThrds := *numGoroutineFlag + 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", profile), ) switch cli.Command { case "fortio": - Drive(FortioLog1, numThrds, numCalls, numExtra) + Drive(profile, FortioLog1, numThrds, numCalls, numExtra) case "zap": SetupZapLogger() - Drive(ZapLog1, numThrds, numCalls, numExtra) + Drive(profile, ZapLog1, numThrds, numCalls, numExtra) _ = zlog.Sync() case "slog": SetupSlogLogger() - Drive(SlogLog1, numThrds, numCalls, numExtra) + Drive(profile, 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) + } + } + log.SetOutput(os.Stderr) for i := 1; i <= numGoroutines; i++ { go func(c int) { fn(fmt.Sprintf("R%d", c), numLogged, numExtraNotLogged) @@ -79,4 +113,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.S(log.Info, "Wrote profile data", log.Str("cpu", profile+".cpu"), log.Str("mem", profile+".mem")) + } + PrintMemoryStats(&mStart, &mEnd) } 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) }