Log/unique pcs (#453)

* chore: add and rearrange how/what is logged

* log unique pc's

* inline comment improvements

* minor changes

* improve inline documentation

* improve rounding

* use setUint64

* fix error

---------

Co-authored-by: Anish Naik <[email protected]>

compilation/platforms/crytic_compile.go

@@ -11,6 +11,7 @@ import (
 	"strings"
 
 	"github.com/crytic/medusa/compilation/types"
+	"github.com/crytic/medusa/logging"
 	"github.com/crytic/medusa/utils"
 )
 
@@ -114,6 +115,7 @@ func (c *CryticCompilationConfig) Compile() ([]types.Compilation, string, error)
 
 	// Get main command and set working directory
 	cmd := exec.Command("crytic-compile", args...)
+	logging.GlobalLogger.Info("Running command:\n", cmd.String())
 
 	// Install a specific `solc` version if requested in the config
 	if c.SolcVersion != "" {

fuzzing/coverage/coverage_maps.go

@@ -2,12 +2,12 @@ package coverage
 
 import (
 	"golang.org/x/exp/slices"
-	"sync"
 
 	compilationTypes "github.com/crytic/medusa/compilation/types"
 	"github.com/crytic/medusa/utils"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/crypto"
+	"sync"
 )
 
 // CoverageMaps represents a data structure used to identify instruction execution coverage of various smart contracts
@@ -212,6 +212,7 @@ func (cm *CoverageMaps) UpdateAt(codeAddress common.Address, codeLookupHash comm
 
 	// Set our coverage in the map and return our change state
 	changedInMap, err = coverageMap.updateCoveredAt(codeSize, pc)
+
 	return addedNewMap || changedInMap, err
 }
 
@@ -243,6 +244,37 @@ func (cm *CoverageMaps) RevertAll() (bool, error) {
 	return revertedCoverageChanged, nil
 }
 
+// UniquePCs is a function that returns the total number of unique program counters (PCs)
+func (cm *CoverageMaps) UniquePCs() uint64 {
+	uniquePCs := uint64(0)
+	// Iterate across each contract deployment
+	for _, mapsByAddress := range cm.maps {
+		for _, contractCoverageMap := range mapsByAddress {
+			// TODO: Note we are not checking for nil dereference here because we are guaranteed that the successful
+			//  coverage and reverted coverage arrays have been instantiated if we are iterating over it
+
+			// Iterate across each PC in the successful coverage array
+			// We do not separately iterate over the reverted coverage array because if there is no data about a
+			// successful PC execution, then it is not possible for that PC to have ever reverted either
+			for i, hits := range contractCoverageMap.successfulCoverage.executedFlags {
+				// If we hit the PC at least once, we have a unique PC hit
+				if hits != 0 {
+					uniquePCs++
+
+					// Do not count both success and revert
+					continue
+				}
+
+				// This is only executed if the PC was not executed successfully
+				if contractCoverageMap.revertedCoverage.executedFlags != nil && contractCoverageMap.revertedCoverage.executedFlags[i] != 0 {
+					uniquePCs++
+				}
+			}
+		}
+	}
+	return uniquePCs
+}
+
 // ContractCoverageMap represents a data structure used to identify instruction execution coverage of a contract.
 type ContractCoverageMap struct {
 	// successfulCoverage represents coverage for the contract bytecode, which did not encounter a revert and was
@@ -268,7 +300,7 @@ func (cm *ContractCoverageMap) Equal(b *ContractCoverageMap) bool {
 	return cm.successfulCoverage.Equal(b.successfulCoverage) && cm.revertedCoverage.Equal(b.revertedCoverage)
 }
 
-// update creates updates the current ContractCoverageMap with the provided one.
+// update updates the current ContractCoverageMap with the provided one.
 // Returns two booleans indicating whether successful or reverted coverage changed, or an error if one was encountered.
 func (cm *ContractCoverageMap) update(coverageMap *ContractCoverageMap) (bool, bool, error) {
 	// Update our success coverage data

fuzzing/fuzzer.go

@@ -173,11 +173,13 @@ func NewFuzzer(config config.ProjectConfig) (*Fuzzer, error) {
 	if fuzzer.config.Compilation != nil {
 		// Compile the targets specified in the compilation config
 		fuzzer.logger.Info("Compiling targets with ", colors.Bold, fuzzer.config.Compilation.Platform, colors.Reset)
+		start := time.Now()
 		compilations, _, err := (*fuzzer.config.Compilation).Compile()
 		if err != nil {
 			fuzzer.logger.Error("Failed to compile target", err)
 			return nil, err
 		}
+		fuzzer.logger.Info("Finished compiling targets in ", time.Since(start).Round(time.Second))
 
 		// Add our compilation targets
 		fuzzer.AddCompilationTargets(compilations)
@@ -191,8 +193,6 @@ func NewFuzzer(config config.ProjectConfig) (*Fuzzer, error) {
 		attachAssertionTestCaseProvider(fuzzer)
 	}
 	if fuzzer.config.Fuzzing.Testing.OptimizationTesting.Enabled {
-		// TODO: Remove this warning when call sequence shrinking is improved
-		fuzzer.logger.Warn("Currently, optimization mode's call sequence shrinking is inefficient; this may lead to minor performance issues")
 		attachOptimizationTestCaseProvider(fuzzer)
 	}
 	return fuzzer, nil
@@ -744,7 +744,7 @@ func (f *Fuzzer) Start() error {
 	}
 
 	// Set it up with our deployment/setup strategy defined by the fuzzer.
-	f.logger.Info("Setting up base chain")
+	f.logger.Info("Setting up test chain")
 	trace, err := f.Hooks.ChainSetupFunc(f, baseTestChain)
 	if err != nil {
 		if trace != nil {
@@ -754,11 +754,18 @@ func (f *Fuzzer) Start() error {
 		}
 		return err
 	}
+	f.logger.Info("Finished setting up test chain")
 
 	// Initialize our coverage maps by measuring the coverage we get from the corpus.
 	var corpusActiveSequences, corpusTotalSequences int
-	f.logger.Info("Initializing and validating corpus call sequences")
+	if f.corpus.CallSequenceEntryCount(true, true, true) > 0 {
+		f.logger.Info("Running call sequences in the corpus...")
+	}
+	startTime := time.Now()
 	corpusActiveSequences, corpusTotalSequences, err = f.corpus.Initialize(baseTestChain, f.contractDefinitions)
+	if corpusTotalSequences > 0 {
+		f.logger.Info("Finished running call sequences in the corpus in ", time.Since(startTime).Round(time.Second))
+	}
 	if err != nil {
 		f.logger.Error("Failed to initialize the corpus", err)
 		return err
@@ -857,12 +864,14 @@ func (f *Fuzzer) printMetricsLoop() {
 	lastCallsTested := big.NewInt(0)
 	lastSequencesTested := big.NewInt(0)
 	lastWorkerStartupCount := big.NewInt(0)
+	lastGasUsed := big.NewInt(0)
 
 	lastPrintedTime := time.Time{}
 	for !utils.CheckContextDone(f.ctx) {
 		// Obtain our metrics
 		callsTested := f.metrics.CallsTested()
 		sequencesTested := f.metrics.SequencesTested()
+		gasUsed := f.metrics.GasUsed()
 		failedSequences := f.metrics.FailedSequences()
 		workerStartupCount := f.metrics.WorkerStartupCount()
 		workersShrinking := f.metrics.WorkersShrinkingCount()
@@ -882,10 +891,12 @@ func (f *Fuzzer) printMetricsLoop() {
 		logBuffer.Append("elapsed: ", colors.Bold, time.Since(startTime).Round(time.Second).String(), colors.Reset)
 		logBuffer.Append(", calls: ", colors.Bold, fmt.Sprintf("%d (%d/sec)", callsTested, uint64(float64(new(big.Int).Sub(callsTested, lastCallsTested).Uint64())/secondsSinceLastUpdate)), colors.Reset)
 		logBuffer.Append(", seq/s: ", colors.Bold, fmt.Sprintf("%d", uint64(float64(new(big.Int).Sub(sequencesTested, lastSequencesTested).Uint64())/secondsSinceLastUpdate)), colors.Reset)
-		logBuffer.Append(", coverage: ", colors.Bold, fmt.Sprintf("%d", f.corpus.ActiveMutableSequenceCount()), colors.Reset)
-		logBuffer.Append(", shrinking: ", colors.Bold, fmt.Sprintf("%v", workersShrinking), colors.Reset)
+		logBuffer.Append(", coverage: ", colors.Bold, fmt.Sprintf("%d", f.corpus.CoverageMaps().UniquePCs()), colors.Reset)
+		logBuffer.Append(", corpus: ", colors.Bold, fmt.Sprintf("%d", f.corpus.ActiveMutableSequenceCount()), colors.Reset)
 		logBuffer.Append(", failures: ", colors.Bold, fmt.Sprintf("%d/%d", failedSequences, sequencesTested), colors.Reset)
+		logBuffer.Append(", gas/s: ", colors.Bold, fmt.Sprintf("%d", uint64(float64(new(big.Int).Sub(gasUsed, lastGasUsed).Uint64())/secondsSinceLastUpdate)), colors.Reset)
 		if f.logger.Level() <= zerolog.DebugLevel {
+			logBuffer.Append(", shrinking: ", colors.Bold, fmt.Sprintf("%v", workersShrinking), colors.Reset)
 			logBuffer.Append(", mem: ", colors.Bold, fmt.Sprintf("%v/%v MB", memoryUsedMB, memoryTotalMB), colors.Reset)
 			logBuffer.Append(", resets/s: ", colors.Bold, fmt.Sprintf("%d", uint64(float64(new(big.Int).Sub(workerStartupCount, lastWorkerStartupCount).Uint64())/secondsSinceLastUpdate)), colors.Reset)
 		}
@@ -895,6 +906,7 @@ func (f *Fuzzer) printMetricsLoop() {
 		lastPrintedTime = time.Now()
 		lastCallsTested = callsTested
 		lastSequencesTested = sequencesTested
+		lastGasUsed = gasUsed
 		lastWorkerStartupCount = workerStartupCount
 
 		// If we reached our transaction threshold, halt

fuzzing/fuzzer_metrics.go

@@ -11,16 +11,19 @@ type FuzzerMetrics struct {
 
 // fuzzerWorkerMetrics represents metrics for a single FuzzerWorker instance.
 type fuzzerWorkerMetrics struct {
-	// sequencesTested describes the amount of sequences of transactions which tests were run against.
+	// sequencesTested is the amount of sequences of transactions which tests were run against.
 	sequencesTested *big.Int
 
-	// failedSequences describes the amount of sequences of transactions which tests failed.
+	// failedSequences is the amount of sequences of transactions which tests failed.
 	failedSequences *big.Int
 
-	// callsTested describes the amount of transactions/calls the fuzzer executed and ran tests against.
+	// callsTested is the amount of transactions/calls the fuzzer executed and ran tests against.
 	callsTested *big.Int
 
-	// workerStartupCount describes the amount of times the worker was generated, or re-generated for this index.
+	// gasUsed is the amount of gas the fuzzer executed and ran tests against.
+	gasUsed *big.Int
+
+	// workerStartupCount is the amount of times the worker was generated, or re-generated for this index.
 	workerStartupCount *big.Int
 
 	// shrinking indicates whether the fuzzer worker is currently shrinking.
@@ -39,6 +42,7 @@ func newFuzzerMetrics(workerCount int) *FuzzerMetrics {
 		metrics.workerMetrics[i].failedSequences = big.NewInt(0)
 		metrics.workerMetrics[i].callsTested = big.NewInt(0)
 		metrics.workerMetrics[i].workerStartupCount = big.NewInt(0)
+		metrics.workerMetrics[i].gasUsed = big.NewInt(0)
 	}
 	return &metrics
 }
@@ -70,6 +74,14 @@ func (m *FuzzerMetrics) CallsTested() *big.Int {
 	return transactionsTested
 }
 
+func (m *FuzzerMetrics) GasUsed() *big.Int {
+	gasUsed := big.NewInt(0)
+	for _, workerMetrics := range m.workerMetrics {
+		gasUsed.Add(gasUsed, workerMetrics.gasUsed)
+	}
+	return gasUsed
+}
+
 // WorkerStartupCount describes the amount of times the worker was spawned for this index. Workers are periodically
 // reset.
 func (m *FuzzerMetrics) WorkerStartupCount() *big.Int {

fuzzing/fuzzer_worker.go

@@ -301,6 +301,8 @@ func (fw *FuzzerWorker) testNextCallSequence() (calls.CallSequence, []ShrinkCall
 
 		// Update our metrics
 		fw.workerMetrics().callsTested.Add(fw.workerMetrics().callsTested, big.NewInt(1))
+		lastCallSequenceElement := currentlyExecutedSequence[len(currentlyExecutedSequence)-1]
+		fw.workerMetrics().gasUsed.Add(fw.workerMetrics().gasUsed, new(big.Int).SetUint64(lastCallSequenceElement.ChainReference.Block.MessageResults[lastCallSequenceElement.ChainReference.TransactionIndex].Receipt.GasUsed))
 
 		// If our fuzzer context is done, exit out immediately without results.
 		if utils.CheckContextDone(fw.fuzzer.ctx) {
@@ -425,6 +427,8 @@ func (fw *FuzzerWorker) shrinkCallSequence(callSequence calls.CallSequence, shri
 		// 2) Add block/time delay to previous call (retain original block/time, possibly exceed max delays)
 		// At worst, this costs `2 * len(callSequence)` shrink iterations.
 		fw.workerMetrics().shrinking = true
+		fw.fuzzer.logger.Info(fmt.Sprintf("[Worker %d] Shrinking call sequence with %d call(s)", fw.workerIndex, len(callSequence)))
+
 		for removalStrategy := 0; removalStrategy < 2 && !shrinkingEnded(); removalStrategy++ {
 			for i := len(optimizedSequence) - 1; i >= 0 && !shrinkingEnded(); i-- {
 				// Recreate our current optimized sequence without the item at this index