Merge pull request onflow#5385 from onflow/janez/time-per-computation…

…-estimation-logs

[FVM] Add normalised time per computation logs to transaction execution

engine/execution/computation/computer/result_collector.go

@@ -244,6 +244,7 @@ func (collector *resultCollector) processTransactionResult(
 		Uint64("computation_used", output.ComputationUsed).
 		Uint64("memory_used", output.MemoryEstimate).
 		Int64("time_spent_in_ms", timeSpent.Milliseconds()).
+		Float64("normalized_time_per_computation", flow.NormalizedExecutionTimePerComputationUnit(timeSpent, output.ComputationUsed)).
 		Logger()
 
 	if output.Err != nil {

model/flow/constants.go

@@ -28,10 +28,6 @@ const DefaultTransactionExpiryBuffer = 30
 // DefaultMaxTransactionGasLimit is the default maximum value for the transaction gas limit.
 const DefaultMaxTransactionGasLimit = 9999
 
-// EstimatedComputationPerMillisecond is the approximate number of computation units that can be performed in a millisecond.
-// this was calibrated during the Variable Transaction Fees: Execution Effort FLIP https://github.com/onflow/flow/pull/753
-const EstimatedComputationPerMillisecond = 9999.0 / 200.0
-
 // DefaultMaxTransactionByteSize is the default maximum transaction byte size. (~1.5MB)
 const DefaultMaxTransactionByteSize = 1_500_000
 
@@ -103,3 +99,19 @@ func paddedDomainTag(s string) [DomainTagLength]byte {
 
 	return tag
 }
+
+// EstimatedComputationPerMillisecond is the approximate number of computation units that can be performed in a millisecond.
+// this was calibrated during the Variable Transaction Fees: Execution Effort FLIP https://github.com/onflow/flow/pull/753
+const EstimatedComputationPerMillisecond = 9999.0 / 200.0
+
+// NormalizedExecutionTimePerComputationUnit returns the normalized time per computation unit
+// If the computation estimation is correct (as per the FLIP https://github.com/onflow/flow/pull/753) the value should be 1.
+// If the value is greater than 1, the computation estimation is too low; we are underestimating transaction complexity (and thus undercharging).
+// If the value is less than 1, the computation estimation is too high; we are overestimating transaction complexity (and thus overcharging).
+func NormalizedExecutionTimePerComputationUnit(execTime time.Duration, computationUsed uint64) float64 {
+	if computationUsed == 0 {
+		return 0
+	}
+
+	return (float64(execTime.Milliseconds()) / float64(computationUsed)) * EstimatedComputationPerMillisecond
+}

module/metrics/execution.go

@@ -755,7 +755,7 @@ func (ec *ExecutionCollector) ExecutionBlockCachedPrograms(programs int) {
 	ec.blockCachedPrograms.Set(float64(programs))
 }
 
-// TransactionExecuted reports stats for executing a transaction
+// ExecutionTransactionExecuted reports stats for executing a transaction
 func (ec *ExecutionCollector) ExecutionTransactionExecuted(
 	dur time.Duration,
 	numConflictRetries int,
@@ -769,11 +769,8 @@ func (ec *ExecutionCollector) ExecutionTransactionExecuted(
 	ec.transactionExecutionTime.Observe(float64(dur.Milliseconds()))
 	ec.transactionConflictRetries.Observe(float64(numConflictRetries))
 	ec.transactionComputationUsed.Observe(float64(compUsed))
-	if compUsed > 0 {
-		// normalize so the value should be around 1
-		ec.transactionNormalizedTimePerComputation.Observe(
-			(float64(dur.Milliseconds()) / float64(compUsed)) * flow.EstimatedComputationPerMillisecond)
-	}
+	ec.transactionNormalizedTimePerComputation.Observe(
+		flow.NormalizedExecutionTimePerComputationUnit(dur, compUsed))
 	ec.transactionMemoryEstimate.Observe(float64(memoryUsed))
 	ec.transactionEmittedEvents.Observe(float64(eventCounts))
 	ec.transactionEventSize.Observe(float64(eventSize))