Add transaction ms per computation metrics #4615

janezpodhostnik · 2023-08-10T17:44:00Z

This adds a new histogram for the ratio of time spent on a transaction vs computation used.

The metric is normalised by the original normalisation factor used when the computation weights were decided, which is 9999 computation per 200 milliseconds. Which means the histogram should be a bell curve around 1 (in reality its not, its closer to 3, but that is why we need to recalibrate the weights at some point).

This histogram will tell us how well our mathematical model for computation is performing.

We already have enough info in the logs to observe this information, but its really resource intensive trying to draw graphs from data from logs.

codecov-commenter · 2023-08-10T17:50:51Z

Codecov Report

Merging #4615 (6955c43) into master (2528190) will increase coverage by 3.98%.
Report is 493 commits behind head on master.
The diff coverage is n/a.

@@            Coverage Diff             @@
##           master    #4615      +/-   ##
==========================================
+ Coverage   56.25%   60.23%   +3.98%     
==========================================
  Files         653       51     -602     
  Lines       64699     6579   -58120     
==========================================
- Hits        36396     3963   -32433     
+ Misses      25362     2125   -23237     
+ Partials     2941      491    -2450

Flag	Coverage Δ
unittests	`60.23% <ø> (+3.98%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

see 600 files with indirect coverage changes

zhangchiqing · 2023-08-16T17:26:50Z

model/flow/constants.go

@@ -28,6 +28,10 @@ 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


Is this estimated as MaxTransactionGasLimit / AverageDurationForTransactionWithMaxGas?

If the accuracy is not that important, why not 10000 / 200 ?

Is this estimated as MaxTransactionGasLimit / AverageDurationForTransactionWithMaxGas?

yes. The AverageDurationForTransactionWithMaxGas is an old measurement (the one done during the calibration of the execution weights)

If the accuracy is not that important, why not 10000 / 200 ?

Its not that important, but I do't know if we benefit from rounding here.

zhangchiqing · 2023-08-16T17:32:16Z

module/metrics/execution.go

@@ -405,6 +406,14 @@ func NewExecutionCollector(tracer module.Tracer) *ExecutionCollector {
 		Buckets:   []float64{50, 100, 500, 1000, 5000, 10000},
 	})

+	transactionNormalizedTimePerComputation := promauto.NewHistogram(prometheus.HistogramOpts{


can you add comments about how to read this metrics?

Say the EstimatedComputationPerMillisecond is 50, then a transaction_computation_per_ms more than 1 means the EN took less time to finish executing this tx?

I added a comment

module/metrics/execution.go

zhangchiqing · 2023-08-17T00:04:52Z

module/metrics/execution.go

+	if compUsed > 0 {
+		// normalize so the value should be around 1
+		ec.transactionNormalizedTimePerComputation.Observe(
+			(float64(dur.Milliseconds()) / float64(compUsed)) * flow.EstimatedComputationPerMillisecond)


I still don't quite get this math. According to this comment "Value below 1 means the transaction was executed faster than estimated (is using less resources then estimated)"

So if EstimatedComputationPerMillisecond is 50, it means normally, running for 10ms should use 500 gas. For the metrics to be less than 1, the actual compUsed should be higher than 500, but in that case, isn't it uses more resource instead of less resource?

During the Variable execution effort flip the execution effort weights were set so that a transaction with max computation (9999 c) would run for 200 ms. and that is the EstimatedComputationPerMillisecond (=9999 c/ 200 ms).

If a transaction runs for 10 ms and uses 500 computation that means NormalizedTimePerComputation = (10 ms / 500 c) * ( 9999 c / 200 ms) = 0.9999 which means its was run as fast as we would expect it to run. A transaction using 500 c but running 20 ms would have a NormalizedTimePerComputation of about 2 which means it took twice as long as expected. But if it ran wit 5 ms it would have a value of 0.5 which would mean it ran twice as fast as expected.

For the metrics to be less than 1, the actual compUsed should be higher than 500, but in that case, isn't it uses more resource instead of less resource?

the amount of time spent on the transaction is the resource here. So if a transaction ran for 10 ms that is the resources it used. Computation used is an estimate for time spent. We estimate transactions that run 10 ms to be worth about 500 computation. If instead the transaction was worth 1000 computation than we ran it faster then expected (it was estimated to run for 20ms). If the transaction was worth 250 computation than it ran slower than expected (it was estimated to run 5ms).

Co-authored-by: Leo Zhang <zhangchiqing@gmail.com>

sideninja · 2023-10-02T17:06:29Z

module/metrics/execution.go

@@ -739,6 +749,11 @@ 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(


I wonder if the EstimatedComputationPerMillisecond will be recalibrated will the historic data be invalid compared to the new data? Will there be a new histogram created at that point? What I'm trying to get across is that if that value is changed and then we track historic data we might think we improved the computation but in fact we just changed the weights. Not sure if that's relevant tho since I don't have context.

Yes EstimatedComputationPerMillisecond does depend on how we do the calibration. When it changes we have to keep that in mind when comparing old transactions and new transactions.

when comparing transaction performance we should Ideally compare actually transaction execution time over comparing computation, because computation is just a model for execution time.

sideninja

Nice

janezpodhostnik added Improvement Execution Cadence Execution Team labels Aug 10, 2023

janezpodhostnik requested review from zhangchiqing, ramtinms, koko1123 and fxamacker August 10, 2023 17:44

janezpodhostnik self-assigned this Aug 10, 2023

janezpodhostnik force-pushed the janez/ms-per-computation-metrics branch from a2b2127 to 6955c43 Compare August 10, 2023 18:00

zhangchiqing reviewed Aug 16, 2023

View reviewed changes

Add transaction ms per computation metrics

8bfccfc

janezpodhostnik force-pushed the janez/ms-per-computation-metrics branch from 6955c43 to 8bfccfc Compare August 16, 2023 19:17

zhangchiqing reviewed Aug 17, 2023

View reviewed changes

Update module/metrics/execution.go

e172aab

Co-authored-by: Leo Zhang <zhangchiqing@gmail.com>

zhangchiqing approved these changes Sep 29, 2023

View reviewed changes

janezpodhostnik requested a review from sideninja October 2, 2023 16:52

sideninja reviewed Oct 2, 2023

View reviewed changes

sideninja approved these changes Oct 2, 2023

View reviewed changes

janezpodhostnik enabled auto-merge October 2, 2023 18:50

Merge branch 'master' into janez/ms-per-computation-metrics

08c2790

janezpodhostnik disabled auto-merge November 15, 2023 15:15

Merge branch 'master' into janez/ms-per-computation-metrics

3b01d42

janezpodhostnik enabled auto-merge November 15, 2023 15:34

janezpodhostnik added this pull request to the merge queue Nov 15, 2023

github-merge-queue bot removed this pull request from the merge queue due to no response for status checks Nov 15, 2023

janezpodhostnik added this pull request to the merge queue Nov 16, 2023

Merged via the queue into master with commit fa477d9 Nov 16, 2023
83 checks passed

janezpodhostnik deleted the janez/ms-per-computation-metrics branch November 16, 2023 13:35

janezpodhostnik mentioned this pull request Nov 17, 2023

Add transaction ms per computation metrics - port #5034

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add transaction ms per computation metrics #4615

Add transaction ms per computation metrics #4615

janezpodhostnik commented Aug 10, 2023

codecov-commenter commented Aug 10, 2023 •

edited

Loading

zhangchiqing Aug 16, 2023

janezpodhostnik Aug 16, 2023

zhangchiqing Aug 16, 2023

janezpodhostnik Aug 16, 2023

zhangchiqing Aug 17, 2023

janezpodhostnik Aug 17, 2023

sideninja Oct 2, 2023 •

edited

Loading

janezpodhostnik Oct 2, 2023

sideninja left a comment

Add transaction ms per computation metrics #4615

Add transaction ms per computation metrics #4615

Conversation

janezpodhostnik commented Aug 10, 2023

codecov-commenter commented Aug 10, 2023 • edited Loading

Codecov Report

zhangchiqing Aug 16, 2023

Choose a reason for hiding this comment

janezpodhostnik Aug 16, 2023

Choose a reason for hiding this comment

zhangchiqing Aug 16, 2023

Choose a reason for hiding this comment

janezpodhostnik Aug 16, 2023

Choose a reason for hiding this comment

zhangchiqing Aug 17, 2023

Choose a reason for hiding this comment

janezpodhostnik Aug 17, 2023

Choose a reason for hiding this comment

sideninja Oct 2, 2023 • edited Loading

Choose a reason for hiding this comment

janezpodhostnik Oct 2, 2023

Choose a reason for hiding this comment

sideninja left a comment

Choose a reason for hiding this comment

codecov-commenter commented Aug 10, 2023 •

edited

Loading

sideninja Oct 2, 2023 •

edited

Loading