From e5585bb84d2e593cdcf4812500727de51be86522 Mon Sep 17 00:00:00 2001 From: DavePearce Date: Wed, 4 Sep 2024 11:26:46 +0100 Subject: [PATCH] Support Performance Stats This enables logging of some reasonably primitive performance stats. Particular, execution time and memory usage. --- go.mod | 1 + go.sum | 4 ++++ pkg/cmd/check.go | 51 ++++++++++++++++++++++++++++++----------- pkg/cmd/util.go | 36 +++++++++++++++++++++++++++++ pkg/util/field_array.go | 4 ++-- 5 files changed, 81 insertions(+), 15 deletions(-) diff --git a/go.mod b/go.mod index d4276ce3..2b27ffa0 100644 --- a/go.mod +++ b/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 ) diff --git a/go.sum b/go.sum index 4d057212..5560808f 100644 --- a/go.sum +++ b/go.sum @@ -26,6 +26,8 @@ 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= @@ -33,10 +35,12 @@ github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An 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= diff --git a/pkg/cmd/check.go b/pkg/cmd/check.go index 80430993..c35999d4 100644 --- a/pkg/cmd/check.go +++ b/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,7 +226,7 @@ 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) } @@ -214,12 +234,16 @@ func reportErrors(level string, ir string, tr trace.Trace, errs []error, cfg che 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") diff --git a/pkg/cmd/util.go b/pkg/cmd/util.go index 149636d4..cf49d11a 100644 --- a/pkg/cmd/util.go +++ b/pkg/cmd/util.go @@ -4,7 +4,9 @@ import ( "fmt" "os" "path" + "runtime" "strings" + "time" "github.com/consensys/go-corset/pkg/binfile" "github.com/consensys/go-corset/pkg/hir" @@ -12,6 +14,7 @@ import ( "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) +} diff --git a/pkg/util/field_array.go b/pkg/util/field_array.go index 4ee758a9..ac2e0ba9 100644 --- a/pkg/util/field_array.go +++ b/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) }