Merge pull request #285 from Consensys/284-support-logging-of-memory-…

…and-execution-time

feat: Support Performance Stats

go.mod

@@ -17,6 +17,7 @@ require (
 	github.com/kr/text v0.2.0 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/rogpeppe/go-internal v1.12.0 // indirect
+	github.com/sirupsen/logrus v1.9.3 // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

go.sum

@@ -26,17 +26,21 @@ github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZN
 github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8=
 github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4=
 github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
+github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
+github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/spf13/cobra v1.8.0 h1:7aJaZx1B85qltLMc546zn58BxxfZdR/W22ej9CFoEf0=
 github.com/spf13/cobra v1.8.0/go.mod h1:WXLWApfZ71AjXPya3WOlMsY9yMs7YeiHhFVlvLyhcho=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
 github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo=
+github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/stretchr/testify v1.8.2 h1:+h33VjcLVPDHtOdpUCuF+7gSuG3yGIftsP1YvFihtJ8=
 github.com/stretchr/testify v1.8.2/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
+golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.9.0 h1:KS/R3tvhPqvJvwcKfnBHJwwthS11LRhmM5D59eEXa0s=
 golang.org/x/sys v0.9.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=

pkg/cmd/check.go

@@ -8,6 +8,7 @@ import (
 	sc "github.com/consensys/go-corset/pkg/schema"
 	"github.com/consensys/go-corset/pkg/trace"
 	"github.com/consensys/go-corset/pkg/util"
+	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 )
 
@@ -26,6 +27,11 @@ var checkCmd = &cobra.Command{
 			fmt.Println(cmd.UsageString())
 			os.Exit(1)
 		}
+		// Configure log level
+		if getFlag(cmd, "debug") {
+			log.SetLevel(log.DebugLevel)
+		}
+		//
 		cfg.air = getFlag(cmd, "air")
 		cfg.mir = getFlag(cmd, "mir")
 		cfg.hir = getFlag(cmd, "hir")
@@ -36,12 +42,16 @@ var checkCmd = &cobra.Command{
 		cfg.quiet = getFlag(cmd, "quiet")
 		cfg.padding.Right = getUint(cmd, "padding")
 		cfg.parallelExpansion = !getFlag(cmd, "sequential")
+		//
+		stats := NewPerfStats()
 		// TODO: support true ranges
 		cfg.padding.Left = cfg.padding.Right
 		// Parse constraints
 		hirSchema = readSchemaFile(args[1])
 		// Parse trace file
 		columns := readTraceFile(args[0])
+		//
+		stats.Log("Reading trace files")
 		// Go!
 		checkTraceWithLowering(columns, hirSchema, cfg)
 	},
@@ -105,7 +115,7 @@ func checkTraceWithLoweringHir(cols []trace.RawColumn, hirSchema *hir.Schema, cf
 	trHIR, errsHIR := checkTrace("HIR", cols, hirSchema, cfg)
 	//
 	if errsHIR != nil {
-		reportErrors("ERROR", "HIR", trHIR, errsHIR, cfg)
+		reportErrors(true, "HIR", trHIR, errsHIR, cfg)
 		os.Exit(1)
 	}
 }
@@ -117,7 +127,7 @@ func checkTraceWithLoweringMir(cols []trace.RawColumn, hirSchema *hir.Schema, cf
 	trMIR, errsMIR := checkTrace("MIR", cols, mirSchema, cfg)
 	//
 	if errsMIR != nil {
-		reportErrors("ERROR", "MIR", trMIR, errsMIR, cfg)
+		reportErrors(true, "MIR", trMIR, errsMIR, cfg)
 		os.Exit(1)
 	}
 }
@@ -130,7 +140,7 @@ func checkTraceWithLoweringAir(cols []trace.RawColumn, hirSchema *hir.Schema, cf
 	trAIR, errsAIR := checkTrace("AIR", cols, airSchema, cfg)
 	//
 	if errsAIR != nil {
-		reportErrors("ERROR", "AIR", trAIR, errsAIR, cfg)
+		reportErrors(true, "AIR", trAIR, errsAIR, cfg)
 		os.Exit(1)
 	}
 }
@@ -148,9 +158,9 @@ func checkTraceWithLoweringDefault(cols []trace.RawColumn, hirSchema *hir.Schema
 	trAIR, errsAIR := checkTrace("AIR", cols, airSchema, cfg)
 	//
 	if errsHIR != nil || errsMIR != nil || errsAIR != nil {
-		reportErrors("ERROR", "HIR", trHIR, errsHIR, cfg)
-		reportErrors("ERROR", "MIR", trMIR, errsMIR, cfg)
-		reportErrors("ERROR", "AIR", trAIR, errsAIR, cfg)
+		reportErrors(true, "HIR", trHIR, errsHIR, cfg)
+		reportErrors(true, "MIR", trMIR, errsMIR, cfg)
+		reportErrors(true, "AIR", trAIR, errsAIR, cfg)
 		os.Exit(1)
 	}
 }
@@ -159,21 +169,31 @@ func checkTrace(ir string, cols []trace.RawColumn, schema sc.Schema, cfg checkCo
 	builder := sc.NewTraceBuilder(schema).Expand(cfg.expand).Parallel(cfg.parallelExpansion)
 	//
 	for n := cfg.padding.Left; n <= cfg.padding.Right; n++ {
+		stats := NewPerfStats()
 		tr, errs := builder.Padding(n).Build(cols)
+
+		stats.Log("Expanding trace columns")
 		// Check for errors
 		if tr == nil || (cfg.strict && len(errs) > 0) {
 			return tr, errs
 		} else if len(errs) > 0 {
-			reportErrors("WARNING", ir, tr, errs, cfg)
+			reportErrors(false, ir, tr, errs, cfg)
 		}
-		// Validate trace.  Observe that this is only done for
+		// Validate trace.
+		stats = NewPerfStats()
+		//
 		if err := validationCheck(tr, schema); err != nil {
 			return tr, []error{err}
 		}
-		// Check whether accepted or not.
+		// Check trace.
+		stats.Log("Validating trace")
+		stats = NewPerfStats()
+		//
 		if err := sc.Accepts(schema, tr); err != nil {
 			return tr, []error{err}
 		}
+
+		stats.Log("Checking constraints")
 	}
 	// Done
 	return nil, nil
@@ -206,20 +226,24 @@ func validationCheck(tr trace.Trace, schema sc.Schema) error {
 	return nil
 }
 
-func reportErrors(level string, ir string, tr trace.Trace, errs []error, cfg checkConfig) {
+func reportErrors(error bool, ir string, tr trace.Trace, errs []error, cfg checkConfig) {
 	if cfg.report && tr != nil {
 		trace.PrintTrace(tr)
 	}
 	// Construct set to ensure deduplicate errors
 	set := make(map[string]bool, len(errs))
 	//
 	for _, err := range errs {
-		key := fmt.Sprintf("[%s] %s (%s)", level, err, ir)
+		key := fmt.Sprintf("%s (%s)", err, ir)
 		set[key] = true
 	}
-	// Print each one
+	// Report each one
 	for e := range set {
-		fmt.Println(e)
+		if error {
+			log.Errorln(e)
+		} else {
+			log.Warnln(e)
+		}
 	}
 }
 
@@ -232,6 +256,7 @@ func init() {
 	checkCmd.Flags().Bool("air", false, "check at AIR level")
 	checkCmd.Flags().BoolP("warn", "w", false, "report warnings instead of failing for certain errors"+
 		"(e.g. unknown columns in the trace)")
+	checkCmd.Flags().BoolP("debug", "d", false, "report debug logs")
 	checkCmd.Flags().BoolP("quiet", "q", false, "suppress output (e.g. warnings)")
 	checkCmd.Flags().Bool("sequential", false, "perform sequential trace expansion")
 	checkCmd.Flags().Uint("padding", 0, "specify amount of (front) padding to apply")

pkg/cmd/util.go

@@ -4,14 +4,17 @@ import (
 	"fmt"
 	"os"
 	"path"
+	"runtime"
 	"strings"
+	"time"
 
 	"github.com/consensys/go-corset/pkg/binfile"
 	"github.com/consensys/go-corset/pkg/hir"
 	"github.com/consensys/go-corset/pkg/sexp"
 	"github.com/consensys/go-corset/pkg/trace"
 	"github.com/consensys/go-corset/pkg/trace/json"
 	"github.com/consensys/go-corset/pkg/trace/lt"
+	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 )
 
@@ -192,3 +195,36 @@ func maxHeightColumns(cols []trace.RawColumn) uint {
 	// Done
 	return h
 }
+
+// PerfStats provides a snapshot of memory allocation at a given point in time.
+type PerfStats struct {
+	// Starting time
+	startTime time.Time
+	// Starting total memory allocation
+	startMem uint64
+	// Starting number of gc events
+	startGc uint32
+}
+
+// NewPerfStats creates a new snapshot of the current amount of memory allocated.
+func NewPerfStats() *PerfStats {
+	var m runtime.MemStats
+
+	startTime := time.Now()
+
+	runtime.ReadMemStats(&m)
+
+	return &PerfStats{startTime, m.TotalAlloc, m.NumGC}
+}
+
+// Log logs the difference between the state now and as it was when the PerfStats object was created.
+func (p *PerfStats) Log(prefix string) {
+	var m runtime.MemStats
+
+	runtime.ReadMemStats(&m)
+	alloc := (m.TotalAlloc - p.startMem) / 1024 / 1024 / 1024
+	gcs := m.NumGC - p.startGc
+	exectime := time.Since(p.startTime).Seconds()
+
+	log.Debugf("%s took %0.2fs using %v Gb (%v GC events)", prefix, exectime, alloc, gcs)
+}

pkg/util/field_array.go

@@ -48,8 +48,8 @@ func NewFrArray(height uint, bitWidth uint) FrArray {
 		var pool FrIndexPool[uint16] = NewFrIndexPool[uint16]()
 		return NewFrPoolArray[uint16](height, bitWidth, pool)
 	default:
-		// var pool FrMapPool = NewFrMapPool(bitWidth)
-		// return NewFrPoolArray[uint32](height, bitWidth, pool)
+		//var pool FrMapPool = NewFrMapPool(bitWidth)
+		//return NewFrPoolArray[uint32](height, bitWidth, pool)
 		// return NewFrPtrElementArray(height, bitWidth)
 		return NewFrElementArray(height, bitWidth)
 	}