From 91d94cb2c63bd1917115dfd92c21279912164538 Mon Sep 17 00:00:00 2001 From: Roger Leite Lucena Date: Fri, 16 Oct 2020 19:14:59 -0300 Subject: [PATCH 1/5] Support pprof profiling in BadWolf (activated through the CLI in "repl.go") --- tools/vcli/bw/repl/repl.go | 59 +++++++++++++++++++++++++++++++++++++- 1 file changed, 58 insertions(+), 1 deletion(-) diff --git a/tools/vcli/bw/repl/repl.go b/tools/vcli/bw/repl/repl.go index c997522f..18e56970 100644 --- a/tools/vcli/bw/repl/repl.go +++ b/tools/vcli/bw/repl/repl.go @@ -22,6 +22,7 @@ import ( "fmt" "io" "os" + "runtime/pprof" "strings" "time" @@ -88,10 +89,50 @@ func SimpleReadLine(done chan bool) <-chan string { return c } +// startProfilingIfEnabled starts profiling for the current call to runBQLFromFile if profilingEnabled is true, +// returning the two files to which the profiling metrics will be printed. +func startProfilingIfEnabled(profilingEnabled bool) (*os.File, *os.File) { + if !profilingEnabled { + return nil, nil + } + + cpuProfile, err := os.Create("cpuprofile") + if err != nil { + fmt.Println(err) + fmt.Println("Profiling for current BQL file was aborted.") + return nil, nil + } + memProfile, err := os.Create("memprofile") + if err != nil { + fmt.Println(err) + fmt.Println("Profiling for current BQL file was aborted.") + return nil, nil + } + pprof.StartCPUProfile(cpuProfile) + + return cpuProfile, memProfile +} + +// stopProfilingIfEnabled stops profiling for the current call to runBQLFromFile if profilingEnabled is true, +// writing the final profiling metrics to the correspondent files and closing them. +func stopProfilingIfEnabled(profilingEnabled bool, cpuProfile, memProfile *os.File) { + if !profilingEnabled { + return + } + if cpuProfile == nil || memProfile == nil { + return + } + + pprof.StopCPUProfile() + pprof.WriteHeapProfile(memProfile) + cpuProfile.Close() + memProfile.Close() +} + // REPL starts a read-evaluation-print-loop to run BQL commands. func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, builderSize int, done chan bool) int { var tracer io.Writer - ctx, isTracingToFile, sessionStart := context.Background(), false, time.Now() + ctx, isTracingToFile, profilingEnabled, sessionStart := context.Background(), false, false, time.Now() driverPlain := func() storage.Store { return od @@ -175,6 +216,18 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu done <- false continue } + if strings.HasPrefix(l, "start profiling") { + profilingEnabled = true + fmt.Println("Profiling with pprof is enabled.") + done <- false + continue + } + if strings.HasPrefix(l, "stop profiling") { + profilingEnabled = false + fmt.Println("Profiling with pprof is disabled.") + done <- false + continue + } if strings.HasPrefix(l, "export") { now := time.Now() args := strings.Split("bw "+strings.TrimSpace(l)[:len(l)-1], " ") @@ -208,7 +261,11 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu } if strings.HasPrefix(l, "run") { now := time.Now() + + cpuProfile, memProfile := startProfilingIfEnabled(profilingEnabled) path, cmds, err := runBQLFromFile(ctx, driver(), chanSize, bulkSize, strings.TrimSpace(l[:len(l)-1]), tracer) + stopProfilingIfEnabled(profilingEnabled, cpuProfile, memProfile) + if err != nil { fmt.Printf("[ERROR] %s\n\n", err) } else { From dc14f658d14a9258eddc010f13d940b8dad5a89a Mon Sep 17 00:00:00 2001 From: Roger Leite Lucena Date: Tue, 27 Oct 2020 17:08:07 -0300 Subject: [PATCH 2/5] Allow the user to customize the CPU profiling rate through the CLI --- tools/vcli/bw/repl/repl.go | 26 ++++++++++++++++++++++++-- 1 file changed, 24 insertions(+), 2 deletions(-) diff --git a/tools/vcli/bw/repl/repl.go b/tools/vcli/bw/repl/repl.go index 18e56970..0865b675 100644 --- a/tools/vcli/bw/repl/repl.go +++ b/tools/vcli/bw/repl/repl.go @@ -22,7 +22,9 @@ import ( "fmt" "io" "os" + "runtime" "runtime/pprof" + "strconv" "strings" "time" @@ -217,13 +219,33 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu continue } if strings.HasPrefix(l, "start profiling") { - profilingEnabled = true - fmt.Println("Profiling with pprof is enabled.") + args := strings.Split(strings.TrimSpace(l)[:len(l)-1], " ") + switch len(args) { + case 2: + profilingEnabled = true + fmt.Println("Profiling with pprof is enabled.") + case 4: + if args[2] != "-cpurate" { + fmt.Printf("Invalid syntax with %q.\n\tstart profiling -cpurate \n", args[2]) + break + } + cpuProfRate, err := strconv.ParseInt(args[3], 10, 32) + if err != nil { + fmt.Println(err) + break + } + runtime.SetCPUProfileRate(int(cpuProfRate)) + profilingEnabled = true + fmt.Printf("Profiling with pprof is enabled (CPU profiling rate: %d samples per second).\n", cpuProfRate) + default: + fmt.Println("Invalid syntax.\n\tstart profiling -cpurate ") + } done <- false continue } if strings.HasPrefix(l, "stop profiling") { profilingEnabled = false + runtime.SetCPUProfileRate(0) fmt.Println("Profiling with pprof is disabled.") done <- false continue From 6602cf5a92509f31a2add5eba8dd79362af144b2 Mon Sep 17 00:00:00 2001 From: Roger Leite Lucena Date: Mon, 26 Oct 2020 10:41:51 -0300 Subject: [PATCH 3/5] Profiles of successive calls to "runBQLFromFile" are now successfully appended to the same files --- tools/vcli/bw/repl/repl.go | 87 +++++++++++++++++++++++--------------- 1 file changed, 53 insertions(+), 34 deletions(-) diff --git a/tools/vcli/bw/repl/repl.go b/tools/vcli/bw/repl/repl.go index 0865b675..c5937f1f 100644 --- a/tools/vcli/bw/repl/repl.go +++ b/tools/vcli/bw/repl/repl.go @@ -91,42 +91,38 @@ func SimpleReadLine(done chan bool) <-chan string { return c } -// startProfilingIfEnabled starts profiling for the current call to runBQLFromFile if profilingEnabled is true, -// returning the two files to which the profiling metrics will be printed. -func startProfilingIfEnabled(profilingEnabled bool) (*os.File, *os.File) { - if !profilingEnabled { - return nil, nil - } - +// startProfiling tries to start pprof profiling, returning the two files to which the profiling metrics will be printed. +func startProfiling() (*os.File, *os.File, error) { cpuProfile, err := os.Create("cpuprofile") if err != nil { - fmt.Println(err) - fmt.Println("Profiling for current BQL file was aborted.") - return nil, nil + return nil, nil, err } memProfile, err := os.Create("memprofile") if err != nil { - fmt.Println(err) - fmt.Println("Profiling for current BQL file was aborted.") - return nil, nil + return nil, nil, err } - pprof.StartCPUProfile(cpuProfile) - return cpuProfile, memProfile + err = pprof.StartCPUProfile(cpuProfile) + if err != nil { + return nil, nil, err + } + + return cpuProfile, memProfile, nil } -// stopProfilingIfEnabled stops profiling for the current call to runBQLFromFile if profilingEnabled is true, -// writing the final profiling metrics to the correspondent files and closing them. -func stopProfilingIfEnabled(profilingEnabled bool, cpuProfile, memProfile *os.File) { - if !profilingEnabled { - return - } +// stopProfiling stops pprof profiling, writing the final profiling metrics to the correspondent files and closing them. +func stopProfiling(cpuProfile, memProfile *os.File) { if cpuProfile == nil || memProfile == nil { + fmt.Println("cpuProfile and memProfile must be both non-nil to stop profiling.") return } pprof.StopCPUProfile() - pprof.WriteHeapProfile(memProfile) + err := pprof.WriteHeapProfile(memProfile) + if err != nil { + fmt.Println(err) + } + cpuProfile.Close() memProfile.Close() } @@ -134,7 +130,8 @@ func stopProfilingIfEnabled(profilingEnabled bool, cpuProfile, memProfile *os.Fi // REPL starts a read-evaluation-print-loop to run BQL commands. func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, builderSize int, done chan bool) int { var tracer io.Writer - ctx, isTracingToFile, profilingEnabled, sessionStart := context.Background(), false, false, time.Now() + ctx, isTracingToFile, isProfiling, sessionStart := context.Background(), false, false, time.Now() + var cpuProfile, memProfile *os.File driverPlain := func() storage.Store { return od @@ -168,6 +165,11 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu for l := range rl(done) { if strings.HasPrefix(l, "quit") { + if isProfiling { + fmt.Println("Stopping profiling and closing correspondent files.") + stopProfiling(cpuProfile, memProfile) + isProfiling = false + } done <- true break } @@ -219,11 +221,22 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu continue } if strings.HasPrefix(l, "start profiling") { + if isProfiling { + fmt.Println("Profiling is already ongoing.") + done <- false + continue + } args := strings.Split(strings.TrimSpace(l)[:len(l)-1], " ") + var err error switch len(args) { case 2: - profilingEnabled = true - fmt.Println("Profiling with pprof is enabled.") + if cpuProfile, memProfile, err = startProfiling(); err == nil { + isProfiling = true + fmt.Println("Profiling with pprof is on.") + } else { + fmt.Println(err) + fmt.Println("Profiling failed to start.") + } case 4: if args[2] != "-cpurate" { fmt.Printf("Invalid syntax with %q.\n\tstart profiling -cpurate \n", args[2]) @@ -232,11 +245,17 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu cpuProfRate, err := strconv.ParseInt(args[3], 10, 32) if err != nil { fmt.Println(err) + fmt.Println("Profiling failed to start.") break } runtime.SetCPUProfileRate(int(cpuProfRate)) - profilingEnabled = true - fmt.Printf("Profiling with pprof is enabled (CPU profiling rate: %d samples per second).\n", cpuProfRate) + if cpuProfile, memProfile, err = startProfiling(); err == nil { + isProfiling = true + fmt.Printf("Profiling with pprof is on (CPU profiling rate: %d samples per second).\n", cpuProfRate) + } else { + fmt.Println(err) + fmt.Println("Profiling failed to start.") + } default: fmt.Println("Invalid syntax.\n\tstart profiling -cpurate ") } @@ -244,9 +263,13 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu continue } if strings.HasPrefix(l, "stop profiling") { - profilingEnabled = false - runtime.SetCPUProfileRate(0) - fmt.Println("Profiling with pprof is disabled.") + if isProfiling { + stopProfiling(cpuProfile, memProfile) + isProfiling = false + fmt.Println("Profiling with pprof is turned off.") + } else { + fmt.Println("Profiling with pprof is already off.") + } done <- false continue } @@ -283,11 +306,7 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu } if strings.HasPrefix(l, "run") { now := time.Now() - - cpuProfile, memProfile := startProfilingIfEnabled(profilingEnabled) path, cmds, err := runBQLFromFile(ctx, driver(), chanSize, bulkSize, strings.TrimSpace(l[:len(l)-1]), tracer) - stopProfilingIfEnabled(profilingEnabled, cpuProfile, memProfile) - if err != nil { fmt.Printf("[ERROR] %s\n\n", err) } else { From 4def5a7fe278332ac983b94ed9cbde3edae67e79 Mon Sep 17 00:00:00 2001 From: Roger Leite Lucena Date: Fri, 30 Oct 2020 12:50:12 -0300 Subject: [PATCH 4/5] Add CLI profiling commands to "help" --- tools/vcli/bw/repl/repl.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/tools/vcli/bw/repl/repl.go b/tools/vcli/bw/repl/repl.go index c5937f1f..c6cce951 100644 --- a/tools/vcli/bw/repl/repl.go +++ b/tools/vcli/bw/repl/repl.go @@ -353,6 +353,9 @@ func printHelp() { fmt.Println("run - runs all the BQL statements in the file.") fmt.Println("start tracing [trace_file] - starts tracing queries.") fmt.Println("stop tracing - stops tracing queries.") + fmt.Println("start profiling - starts pprof profiling for queries.") + fmt.Println("start profiling -cpurate - starts pprof profiling with customized CPU sampling rate.") + fmt.Println("stop profiling - stops pprof profiling for queries.") fmt.Println("quit - quits the console.") fmt.Println() } From a5d10f7e021b4896c64e39d5975ba3d2e19825d3 Mon Sep 17 00:00:00 2001 From: Roger Leite Lucena Date: Tue, 3 Nov 2020 15:57:25 -0300 Subject: [PATCH 5/5] Improve profiling flow in code by handling the errors first (more Go-like code) --- tools/vcli/bw/repl/repl.go | 18 ++++++++++-------- 1 file changed, 10 insertions(+), 8 deletions(-) diff --git a/tools/vcli/bw/repl/repl.go b/tools/vcli/bw/repl/repl.go index c6cce951..d3542f03 100644 --- a/tools/vcli/bw/repl/repl.go +++ b/tools/vcli/bw/repl/repl.go @@ -230,13 +230,14 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu var err error switch len(args) { case 2: - if cpuProfile, memProfile, err = startProfiling(); err == nil { - isProfiling = true - fmt.Println("Profiling with pprof is on.") - } else { + cpuProfile, memProfile, err = startProfiling() + if err != nil { fmt.Println(err) fmt.Println("Profiling failed to start.") + break } + isProfiling = true + fmt.Println("Profiling with pprof is on.") case 4: if args[2] != "-cpurate" { fmt.Printf("Invalid syntax with %q.\n\tstart profiling -cpurate \n", args[2]) @@ -249,13 +250,14 @@ func REPL(od storage.Store, input *os.File, rl ReadLiner, chanSize, bulkSize, bu break } runtime.SetCPUProfileRate(int(cpuProfRate)) - if cpuProfile, memProfile, err = startProfiling(); err == nil { - isProfiling = true - fmt.Printf("Profiling with pprof is on (CPU profiling rate: %d samples per second).\n", cpuProfRate) - } else { + cpuProfile, memProfile, err = startProfiling() + if err != nil { fmt.Println(err) fmt.Println("Profiling failed to start.") + break } + isProfiling = true + fmt.Printf("Profiling with pprof is on (CPU profiling rate: %d samples per second).\n", cpuProfRate) default: fmt.Println("Invalid syntax.\n\tstart profiling -cpurate ") }