add logging to perf tool (#1542)

Author: Tofel

book/src/SUMMARY.md

@@ -80,6 +80,7 @@
       - [Custom Prometheus metrics](./libs/wasp/benchspy/prometheus_custom.md)
       - [To Loki or not to Loki?](./libs/wasp/benchspy/loki_dillema.md)
       - [Real world example](./libs/wasp/benchspy/real_world.md)
+      - [Debugging](./libs/wasp/benchspy/debugging.md)
       - [Reports](./libs/wasp/benchspy/reports/overview.md)
         - [Standard Report](./libs/wasp/benchspy/reports/standard_report.md)
           - [Adding new QueryExecutor](./libs/wasp/benchspy/reports/new_executor.md)

book/src/libs/wasp/benchspy/debugging.md

@@ -0,0 +1,3 @@
+# BenchSpy - Debugging
+
+If you run into any issues with `BenchSpy` it might help to lower the default logging level to either `debug` or `trace`. It's controlled by environment variable called `BENCHSPY_LOG_LEVEL`.

book/src/libs/wasp/benchspy/getting_started.md

@@ -11,4 +11,7 @@ The following examples assume you have access to the following applications:
 
 Since BenchSpy is tightly coupled with WASP, we highly recommend that you [get familiar with it first](../overview.md) if you haven't already.
 
-Ready? [Let's get started!](./first_test.md)
+Ready? [Let's get started!](./first_test.md)
+
+> [!NOTE]
+> You can `BENCHSPY_LOG_LEVEL` environment variable to control the log level.

wasp/benchspy/TO_DO.md

@@ -1,5 +1,5 @@
 Known things to do:
-- [ ] add logger
+- [x] add logger
 - [x] add unit tests for prometheus
 - [x] add wasp test for prometheus only
 - [ ] add e2e OCRv2 test with CTFv2

wasp/benchspy/basic.go

@@ -34,9 +34,12 @@ func MustNewBasicData(commitOrTag string, generators ...*wasp.Generator) BasicDa
 }
 
 // NewBasicData creates a new BasicData instance using the provided commit or tag and a list of generators.
-// It ensures that at least one generator is provided and that it is associated with a testing.T instance. 
+// It ensures that at least one generator is provided and that it is associated with a testing.T instance.
 // This function is essential for initializing test data configurations in a structured manner.
 func NewBasicData(commitOrTag string, generators ...*wasp.Generator) (*BasicData, error) {
+	L.Debug().
+		Msg("Creating new basic data instance")
+
 	if len(generators) == 0 {
 		return nil, errors.New("at least one generator is required")
 	}
@@ -60,12 +63,18 @@ func NewBasicData(commitOrTag string, generators ...*wasp.Generator) (*BasicData
 		return nil, timeErr
 	}
 
+	L.Debug().
+		Msg("Basic data instance created successfully")
+
 	return b, nil
 }
 
 // FillStartEndTimes calculates the earliest start time and latest end time from generator schedules.
 // It updates the BasicData instance with these times, ensuring all segments have valid start and end times.
 func (b *BasicData) FillStartEndTimes() error {
+	L.Debug().
+		Msg("Filling test start and end times for basic data instance based on generator schedules")
+
 	earliestTime := time.Now()
 	var latestTime time.Time
 
@@ -92,13 +101,19 @@ func (b *BasicData) FillStartEndTimes() error {
 
 	b.TestStart = earliestTime
 	b.TestEnd = latestTime
+	L.Debug().
+		Str("Test start time", earliestTime.Format(time.RFC3339)).
+		Str("Test end time", latestTime.Format(time.RFC3339)).
+		Msg("Start and end times filled successfully")
 
 	return nil
 }
 
 // Validate checks the integrity of the BasicData fields, ensuring that the test start and end times are set,
 // and that at least one generator configuration is provided. It returns an error if any of these conditions are not met.
 func (b *BasicData) Validate() error {
+	L.Debug().
+		Msg("Validating basic data instance")
 	if b.TestStart.IsZero() {
 		return errors.New("test start time is missing. We cannot query Loki without a time range. Please set it and try again")
 	}
@@ -110,6 +125,9 @@ func (b *BasicData) Validate() error {
 		return errors.New("generator configs are missing. At least one is required. Please set them and try again")
 	}
 
+	L.Debug().
+		Msg("Basic data instance is valid")
+
 	return nil
 }
 
@@ -118,7 +136,9 @@ func (b *BasicData) Validate() error {
 // returning an error if any discrepancies are found. This function is useful for ensuring
 // consistency between data reports before processing or comparison.
 func (b *BasicData) IsComparable(otherData BasicData) error {
-	// are all configs present? do they have the same schedule type? do they have the same segments? is call timeout the same? is rate limit timeout the same?
+	L.Debug().
+		Msg("Checking if basic data instances are comparable")
+
 	if len(b.GeneratorConfigs) != len(otherData.GeneratorConfigs) {
 		return fmt.Errorf("generator configs count is different. Expected %d, got %d", len(b.GeneratorConfigs), len(otherData.GeneratorConfigs))
 	}
@@ -133,6 +153,9 @@ func (b *BasicData) IsComparable(otherData BasicData) error {
 		}
 	}
 
+	L.Debug().
+		Msg("Basic data instances are comparable")
+
 	return nil
 }
 

wasp/benchspy/direct.go

@@ -39,19 +39,27 @@ func NewStandardDirectQueryExecutor(generator *wasp.Generator) (*DirectQueryExec
 // NewDirectQueryExecutor creates a new DirectQueryExecutor with the specified generator and query functions.
 // It initializes the executor with a kind name and prepares a map for query results, enabling efficient query execution.
 func NewDirectQueryExecutor(generator *wasp.Generator, queries map[string]DirectQueryFn) (*DirectQueryExecutor, error) {
-	g := &DirectQueryExecutor{
+	ex := &DirectQueryExecutor{
 		KindName:     string(StandardQueryExecutor_Direct),
 		Generator:    generator,
 		Queries:      queries,
 		QueryResults: make(map[string]interface{}),
 	}
 
-	return g, nil
+	L.Debug().
+		Str("Generator", ex.GeneratorName()).
+		Int("Queries", len(queries)).
+		Msg("Creating new Direct query executor")
+
+	return ex, nil
 }
 
 // GeneratorName returns the name of the generator associated with the query executor.
 // It is useful for identifying and categorizing results based on their generator type.
 func (g *DirectQueryExecutor) GeneratorName() string {
+	if g.Generator == nil {
+		return ""
+	}
 	return g.Generator.Cfg.GenName
 }
 
@@ -70,6 +78,10 @@ func (l *DirectQueryExecutor) Kind() string {
 // IsComparable checks if the given QueryExecutor is of the same type and has comparable configurations.
 // It returns an error if the types do not match or if the configurations are not comparable.
 func (g *DirectQueryExecutor) IsComparable(otherQueryExecutor QueryExecutor) error {
+	L.Debug().
+		Str("Expected kind", g.KindName).
+		Msg("Checking if query executors are comparable")
+
 	otherType := reflect.TypeOf(otherQueryExecutor)
 
 	if otherType != reflect.TypeOf(g) {
@@ -82,7 +94,16 @@ func (g *DirectQueryExecutor) IsComparable(otherQueryExecutor QueryExecutor) err
 		return errors.New("generators are not comparable")
 	}
 
-	return g.compareQueries(otherGeneratorQueryExecutor.Queries)
+	queryErr := g.compareQueries(otherGeneratorQueryExecutor.Queries)
+	if queryErr != nil {
+		return queryErr
+	}
+
+	L.Debug().
+		Str("Kind", g.KindName).
+		Msg("Query executors are comparable")
+
+	return nil
 }
 
 func (l *DirectQueryExecutor) compareQueries(other map[string]DirectQueryFn) error {
@@ -104,6 +125,9 @@ func (l *DirectQueryExecutor) compareQueries(other map[string]DirectQueryFn) err
 // It ensures that a generator is set and at least one query is provided.
 // Returns an error if validation fails, helping to prevent execution issues.
 func (g *DirectQueryExecutor) Validate() error {
+	L.Debug().
+		Msg("Validating Direct query executor")
+
 	if g.Generator == nil {
 		return errors.New("generator is not set")
 	}
@@ -112,18 +136,31 @@ func (g *DirectQueryExecutor) Validate() error {
 		return errors.New("at least one query is needed")
 	}
 
+	L.Debug().
+		Msg("Direct query executor is valid")
+
 	return nil
 }
 
 // Execute runs the defined queries using the data from the generator.
 // It validates the generator's data and aggregates responses before executing each query.
 // This function is essential for processing and retrieving results from multiple queries concurrently.
 func (g *DirectQueryExecutor) Execute(_ context.Context) error {
+	L.Info().
+		Str("Generator", g.Generator.Cfg.GenName).
+		Int("Queries", len(g.Queries)).
+		Msg("Executing Direct queries")
+
 	if g.Generator == nil {
 		return errors.New("generator is not set")
 	}
 
 	for queryName, queryFunction := range g.Queries {
+		L.Debug().
+			Str("Generator", g.Generator.Cfg.GenName).
+			Str("Query", queryName).
+			Msg("Executing Direct query")
+
 		if g.Generator.GetData() == nil {
 			return fmt.Errorf("generator %s has no data", g.Generator.Cfg.GenName)
 		}
@@ -148,8 +185,18 @@ func (g *DirectQueryExecutor) Execute(_ context.Context) error {
 		}
 
 		g.QueryResults[queryName] = results
+
+		L.Debug().
+			Str("Query", queryName).
+			Float64("Result", results).
+			Msg("Direct query executed successfully")
 	}
 
+	L.Info().
+		Str("Generator", g.Generator.Cfg.GenName).
+		Int("Queries", len(g.Queries)).
+		Msg("Direct queries executed successfully")
+
 	return nil
 }
 
@@ -160,6 +207,9 @@ func (g *DirectQueryExecutor) TimeRange(_, _ time.Time) {
 }
 
 func (g *DirectQueryExecutor) generateStandardQueries() (map[string]DirectQueryFn, error) {
+	L.Debug().
+		Msg("Generating standard Direct queries")
+
 	standardQueries := make(map[string]DirectQueryFn)
 
 	for _, metric := range StandardLoadMetrics {
@@ -170,6 +220,10 @@ func (g *DirectQueryExecutor) generateStandardQueries() (map[string]DirectQueryF
 		standardQueries[string(metric)] = query
 	}
 
+	L.Debug().
+		Int("Queries", len(standardQueries)).
+		Msg("Standard queries Direct generated")
+
 	return standardQueries, nil
 }
 

wasp/benchspy/log.go

@@ -1,6 +1,7 @@
 package benchspy
 
 import (
+	"fmt"
 	"os"
 
 	"github.com/rs/zerolog"
@@ -28,5 +29,15 @@ func initDefaultLogging() {
 	if err != nil {
 		panic(err)
 	}
-	L = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}).Level(lvl)
+
+	output := zerolog.ConsoleWriter{Out: os.Stderr}
+	output.FormatMessage = func(i interface{}) string {
+		return fmt.Sprintf("\033[38;5;136m%v \033[0m", i) // Dark gold color for message
+	}
+
+	output.FormatFieldValue = func(i interface{}) string {
+		return fmt.Sprintf("\033[38;5;136m%v \033[0m", i) // Dark gold color for field value
+	}
+
+	L = log.Output(output).Level(lvl)
 }