Skip to content

Commit

Permalink
Merge pull request #2394 from onflow/dan/1536-add-cadence-execution-t…
Browse files Browse the repository at this point in the history
…ime-metrics

Dan/1536 add cadence execution time metrics
  • Loading branch information
danielholmes839 authored May 24, 2022
2 parents 0e5704c + 2c45c8d commit 74635a0
Show file tree
Hide file tree
Showing 8 changed files with 123 additions and 1 deletion.
1 change: 1 addition & 0 deletions engine/access/rpc/backend/backend.go
Original file line number Diff line number Diff line change
Expand Up @@ -106,6 +106,7 @@ func New(
connFactory: connFactory,
state: state,
log: log,
metrics: transactionMetrics,
seenScripts: &scriptMap{
scripts: make(map[[md5.Size]byte]time.Time),
lock: sync.RWMutex{},
Expand Down
16 changes: 15 additions & 1 deletion engine/access/rpc/backend/backend_scripts.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ import (
"google.golang.org/grpc/status"

"github.com/onflow/flow-go/model/flow"
"github.com/onflow/flow-go/module"
"github.com/onflow/flow-go/state/protocol"
"github.com/onflow/flow-go/storage"
)
Expand All @@ -26,6 +27,7 @@ type backendScripts struct {
state protocol.State
connFactory ConnectionFactory
log zerolog.Logger
metrics module.BackendScriptsMetrics
seenScripts *scriptMap
}

Expand All @@ -52,7 +54,6 @@ func (b *backendScripts) ExecuteScriptAtLatestBlock(
script []byte,
arguments [][]byte,
) ([]byte, error) {

// get the latest sealed header
latestHeader, err := b.state.Sealed().Head()
if err != nil {
Expand Down Expand Up @@ -120,13 +121,17 @@ func (b *backendScripts) executeScriptOnExecutionNode(

// try each of the execution nodes found
var errors *multierror.Error

// try to execute the script on one of the execution nodes
for _, execNode := range execNodes {
execStartTime := time.Now() // record start time
result, err := b.tryExecuteScript(ctx, execNode, execReq)

if err == nil {
if b.log.GetLevel() == zerolog.DebugLevel {
executionTime := time.Now()
timestamp, seen := b.seenScripts.getLastSeen(encodedScript)

// log if the script is unique in the time window
if !seen || executionTime.Sub(timestamp) >= uniqueScriptLoggingTimeWindow {
b.log.Debug().
Expand All @@ -138,8 +143,16 @@ func (b *backendScripts) executeScriptOnExecutionNode(
b.seenScripts.setLastSeenToTime(encodedScript, executionTime)
}
}

// log execution time
b.metrics.ScriptExecuted(
time.Since(execStartTime),
len(script),
)

return result, nil
}

// return if it's just a script failure as opposed to an EN failure and skip trying other ENs
if status.Code(err) == codes.InvalidArgument {
b.log.Debug().Err(err).
Expand All @@ -152,6 +165,7 @@ func (b *backendScripts) executeScriptOnExecutionNode(
}
errors = multierror.Append(errors, err)
}

errToReturn := errors.ErrorOrNil()
if errToReturn != nil {
b.log.Error().Err(err).Msg("script execution failed for execution node internal reasons")
Expand Down
5 changes: 5 additions & 0 deletions engine/access/rpc/backend/backend_transactions.go
Original file line number Diff line number Diff line change
Expand Up @@ -184,6 +184,7 @@ func (b *backendTransactions) GetTransaction(ctx context.Context, txID flow.Iden
// look up transaction from storage
tx, err := b.transactions.ByID(txID)
txErr := convertStorageError(err)

if txErr != nil {
if status.Code(txErr) == codes.NotFound {
return b.getHistoricalTransaction(ctx, txID)
Expand Down Expand Up @@ -230,7 +231,9 @@ func (b *backendTransactions) GetTransactionResult(
txID flow.Identifier,
) (*access.TransactionResult, error) {
// look up transaction from storage
start := time.Now()
tx, err := b.transactions.ByID(txID)

txErr := convertStorageError(err)
if txErr != nil {
if status.Code(txErr) == codes.NotFound {
Expand Down Expand Up @@ -276,6 +279,8 @@ func (b *backendTransactions) GetTransactionResult(
return nil, convertStorageError(err)
}

b.transactionMetrics.TransactionResultFetched(time.Since(start), len(tx.Script))

return &access.TransactionResult{
Status: txStatus,
StatusCode: uint(statusCode),
Expand Down
10 changes: 10 additions & 0 deletions module/metrics.go
Original file line number Diff line number Diff line change
Expand Up @@ -400,7 +400,17 @@ type ExecutionMetrics interface {
ExecutionBlockDataUploadFinished(dur time.Duration)
}

type BackendScriptsMetrics interface {
// Record the round trip time while executing a script
ScriptExecuted(dur time.Duration, size int)
}

type TransactionMetrics interface {
BackendScriptsMetrics

// Record the round trip time while getting a transaction result
TransactionResultFetched(dur time.Duration, size int)

// TransactionReceived starts tracking of transaction execution/finalization/sealing
TransactionReceived(txID flow.Identifier, when time.Time)

Expand Down
2 changes: 2 additions & 0 deletions module/metrics/noop.go
Original file line number Diff line number Diff line change
Expand Up @@ -142,6 +142,8 @@ func (nc *NoopCollector) RuntimeTransactionParsed(dur time.Duration)
func (nc *NoopCollector) RuntimeTransactionChecked(dur time.Duration) {}
func (nc *NoopCollector) RuntimeTransactionInterpreted(dur time.Duration) {}
func (nc *NoopCollector) RuntimeSetNumberOfAccounts(count uint64) {}
func (nc *NoopCollector) ScriptExecuted(dur time.Duration, size int) {}
func (nc *NoopCollector) TransactionResultFetched(dur time.Duration, size int) {}
func (nc *NoopCollector) TransactionReceived(txID flow.Identifier, when time.Time) {}
func (nc *NoopCollector) TransactionFinalized(txID flow.Identifier, when time.Time) {}
func (nc *NoopCollector) TransactionExecuted(txID flow.Identifier, when time.Time) {}
Expand Down
61 changes: 61 additions & 0 deletions module/metrics/transaction.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,10 @@ type TransactionCollector struct {
timeToExecuted prometheus.Summary
timeToFinalizedExecuted prometheus.Summary
transactionSubmission *prometheus.CounterVec
scriptExecutedDuration *prometheus.HistogramVec
transactionResultDuration *prometheus.HistogramVec
scriptSize prometheus.Histogram
transactionSize prometheus.Histogram
}

func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log zerolog.Logger,
Expand Down Expand Up @@ -81,11 +85,68 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log
Subsystem: subsystemTransactionSubmission,
Help: "counter for the success/failure of transaction submissions",
}, []string{"result"}),
scriptExecutedDuration: promauto.NewHistogramVec(prometheus.HistogramOpts{
Name: "script_executed_duration",
Namespace: namespaceAccess,
Subsystem: subsystemTransactionSubmission,
Help: "histogram for the duration in ms of the round trip time for executing a script",
Buckets: []float64{1, 100, 500, 1000, 2000, 5000},
}, []string{"script_size"}),
transactionResultDuration: promauto.NewHistogramVec(prometheus.HistogramOpts{
Name: "transaction_result_fetched_duration",
Namespace: namespaceAccess,
Subsystem: subsystemTransactionSubmission,
Help: "histogram for the duration in ms of the round trip time for getting a transaction result",
Buckets: []float64{1, 100, 500, 1000, 2000, 5000},
}, []string{"payload_size"}),
scriptSize: promauto.NewHistogram(prometheus.HistogramOpts{
Name: "script_size",
Namespace: namespaceAccess,
Subsystem: subsystemTransactionSubmission,
Help: "histogram for the script size in kb of scripts used in ExecuteScript",
}),
transactionSize: promauto.NewHistogram(prometheus.HistogramOpts{
Name: "transaction_size",
Namespace: namespaceAccess,
Subsystem: subsystemTransactionSubmission,
Help: "histogram for the transaction size in kb of scripts used in GetTransactionResult",
}),
}

return tc
}

func (tc *TransactionCollector) ScriptExecuted(dur time.Duration, size int) {
// record the execute script duration and script size
tc.scriptSize.Observe(float64(size / 1024))
tc.scriptExecutedDuration.With(prometheus.Labels{
"script_size": tc.sizeLabel(size),
}).Observe(float64(dur.Milliseconds()))
}

func (tc *TransactionCollector) TransactionResultFetched(dur time.Duration, size int) {
// record the transaction result duration and transaction script/payload size
tc.transactionSize.Observe(float64(size / 1024))
tc.transactionResultDuration.With(prometheus.Labels{
"payload_size": tc.sizeLabel(size),
}).Observe(float64(dur.Milliseconds()))
}

func (tc *TransactionCollector) sizeLabel(size int) string {
// determine the script size label using the size in bytes
sizeKb := size / 1024
sizeLabel := "100+kb" //"1kb,10kb,100kb, 100+kb" -> [0,1] [2,10] [11,100] [100, +inf]

if sizeKb <= 1 {
sizeLabel = "1kb"
} else if sizeKb <= 10 {
sizeLabel = "10kb"
} else if sizeKb <= 100 {
sizeLabel = "100kb"
}
return sizeLabel
}

func (tc *TransactionCollector) TransactionReceived(txID flow.Identifier, when time.Time) {
// we don't need to check whether the transaction timing already exists, it will not be overwritten by the mempool
added := tc.transactionTimings.Add(&flow.TransactionTiming{TransactionID: txID, Received: when})
Expand Down
19 changes: 19 additions & 0 deletions module/mock/backend_scripts_metrics.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

10 changes: 10 additions & 0 deletions module/mock/transaction_metrics.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

0 comments on commit 74635a0

Please sign in to comment.