From 24b38ebccf3d1280d9a3db3ad909ad8383d3957b Mon Sep 17 00:00:00 2001 From: Daniel Holmes Date: Fri, 6 May 2022 14:46:22 -0400 Subject: [PATCH 01/18] first commit --- engine/access/rpc/backend/backend_scripts.go | 20 +++++++++++++++++++- 1 file changed, 19 insertions(+), 1 deletion(-) diff --git a/engine/access/rpc/backend/backend_scripts.go b/engine/access/rpc/backend/backend_scripts.go index df34e5538a5..8af337a8206 100644 --- a/engine/access/rpc/backend/backend_scripts.go +++ b/engine/access/rpc/backend/backend_scripts.go @@ -3,6 +3,7 @@ package backend import ( "context" "crypto/md5" //nolint:gosec + "fmt" "time" "github.com/hashicorp/go-multierror" @@ -33,7 +34,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 { @@ -99,8 +99,12 @@ func (b *backendScripts) executeScriptOnExecutionNode( // encode to MD5 as low compute/memory lookup key encodedScript := md5.Sum(script) //nolint:gosec + // record start time + execStartTime := time.Now() + // 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 { result, err := b.tryExecuteScript(ctx, execNode, execReq) @@ -108,6 +112,7 @@ func (b *backendScripts) executeScriptOnExecutionNode( if b.log.GetLevel() == zerolog.DebugLevel { executionTime := time.Now() timestamp, seen := b.seenScripts[encodedScript] + // log if the script is unique in the time window if !seen || executionTime.Sub(timestamp) >= uniqueScriptLoggingTimeWindow { b.log.Debug(). @@ -119,8 +124,20 @@ func (b *backendScripts) executeScriptOnExecutionNode( b.seenScripts[encodedScript] = executionTime } } + + fmt.Println("HELLO HELLO HELLO") + fmt.Println("HELLO HELLO HELLO") + fmt.Println("HELLO HELLO HELLO") + fmt.Println("HELLO HELLO HELLO") + + // log execution time + b.log.Debug(). + Dur("exec_time", time.Since(execStartTime)). + Int("script_size", 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). @@ -133,6 +150,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") From 60da3b87aa17ffc444b4115116c1d88078b09410 Mon Sep 17 00:00:00 2001 From: Daniel Holmes Date: Tue, 10 May 2022 11:06:50 -0400 Subject: [PATCH 02/18] added BackendSCciptsMetrics interface and update noop/collector --- module/metrics.go | 7 +++++++ module/metrics/noop.go | 1 + module/metrics/transaction.go | 19 +++++++++++++++++++ module/mock/backend_scripts_metrics.go | 19 +++++++++++++++++++ module/mock/transaction_metrics.go | 5 +++++ 5 files changed, 51 insertions(+) create mode 100644 module/mock/backend_scripts_metrics.go diff --git a/module/metrics.go b/module/metrics.go index 41363eaabca..5ba3929d2ff 100644 --- a/module/metrics.go +++ b/module/metrics.go @@ -400,7 +400,14 @@ type ExecutionMetrics interface { ExecutionBlockDataUploadFinished(dur time.Duration) } +type BackendScriptsMetrics interface { + // Record the round trip time while executing a script + ExecuteScriptRTT(dur time.Duration, size int) +} + type TransactionMetrics interface { + BackendScriptsMetrics + // TransactionReceived starts tracking of transaction execution/finalization/sealing TransactionReceived(txID flow.Identifier, when time.Time) diff --git a/module/metrics/noop.go b/module/metrics/noop.go index c401ba970b7..2ad1ae8142b 100644 --- a/module/metrics/noop.go +++ b/module/metrics/noop.go @@ -142,6 +142,7 @@ 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) ExecuteScriptRTT(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) {} diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index cd84a9b0b3e..b20a1cca508 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -21,6 +21,8 @@ type TransactionCollector struct { timeToExecuted prometheus.Summary timeToFinalizedExecuted prometheus.Summary transactionSubmission *prometheus.CounterVec + executeScriptRTT prometheus.Counter + executeScriptSize prometheus.Histogram } func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log zerolog.Logger, @@ -81,11 +83,28 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log Subsystem: subsystemTransactionSubmission, Help: "counter for the success/failure of transaction submissions", }, []string{"result"}), + executeScriptRTT: promauto.NewCounter(prometheus.CounterOpts{ + Name: "execute_script_rtt", + Namespace: namespaceAccess, + Subsystem: "TEMP", + Help: "counter for the round trip time for executing a script", + }), + executeScriptSize: promauto.NewHistogram(prometheus.HistogramOpts{ + Name: "execute_script_size", + Namespace: namespaceAccess, + Subsystem: "TEMP", + Help: "histogram for the size in bytes of scripts being executed", + }), } return tc } +func (tc *TransactionCollector) ExecuteScriptRTT(dur time.Duration, size int) { + tc.executeScriptRTT.Add(float64(dur) / float64(time.Millisecond)) + tc.executeScriptSize.Observe(float64(size)) +} + 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}) diff --git a/module/mock/backend_scripts_metrics.go b/module/mock/backend_scripts_metrics.go new file mode 100644 index 00000000000..0d9799a6811 --- /dev/null +++ b/module/mock/backend_scripts_metrics.go @@ -0,0 +1,19 @@ +// Code generated by mockery v1.0.0. DO NOT EDIT. + +package mock + +import ( + mock "github.com/stretchr/testify/mock" + + time "time" +) + +// BackendScriptsMetrics is an autogenerated mock type for the BackendScriptsMetrics type +type BackendScriptsMetrics struct { + mock.Mock +} + +// ExecuteScriptRTT provides a mock function with given fields: dur, size +func (_m *BackendScriptsMetrics) ExecuteScriptRTT(dur time.Duration, size int) { + _m.Called(dur, size) +} diff --git a/module/mock/transaction_metrics.go b/module/mock/transaction_metrics.go index f480462cb2c..fd4ad2abe82 100644 --- a/module/mock/transaction_metrics.go +++ b/module/mock/transaction_metrics.go @@ -14,6 +14,11 @@ type TransactionMetrics struct { mock.Mock } +// ExecuteScriptRTT provides a mock function with given fields: dur, size +func (_m *TransactionMetrics) ExecuteScriptRTT(dur time.Duration, size int) { + _m.Called(dur, size) +} + // TransactionExecuted provides a mock function with given fields: txID, when func (_m *TransactionMetrics) TransactionExecuted(txID flow.Identifier, when time.Time) { _m.Called(txID, when) From afdc7797a3f1d73371409e72c68a08a61d6b5605 Mon Sep 17 00:00:00 2001 From: Daniel Holmes Date: Tue, 10 May 2022 11:08:35 -0400 Subject: [PATCH 03/18] call the metrics --- engine/access/rpc/backend/backend.go | 1 + engine/access/rpc/backend/backend_scripts.go | 15 ++++++--------- 2 files changed, 7 insertions(+), 9 deletions(-) diff --git a/engine/access/rpc/backend/backend.go b/engine/access/rpc/backend/backend.go index c83d21387ba..0c16eb8d99b 100644 --- a/engine/access/rpc/backend/backend.go +++ b/engine/access/rpc/backend/backend.go @@ -106,6 +106,7 @@ func New( state: state, log: log, seenScripts: make(map[[md5.Size]byte]time.Time), + metrics: transactionMetrics, }, backendTransactions: backendTransactions{ staticCollectionRPC: collectionRPC, diff --git a/engine/access/rpc/backend/backend_scripts.go b/engine/access/rpc/backend/backend_scripts.go index 8af337a8206..d95a939316a 100644 --- a/engine/access/rpc/backend/backend_scripts.go +++ b/engine/access/rpc/backend/backend_scripts.go @@ -3,7 +3,6 @@ package backend import ( "context" "crypto/md5" //nolint:gosec - "fmt" "time" "github.com/hashicorp/go-multierror" @@ -13,6 +12,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" ) @@ -27,6 +27,7 @@ type backendScripts struct { connFactory ConnectionFactory log zerolog.Logger seenScripts map[[md5.Size]byte]time.Time // to keep track of unique scripts sent by clients. bounded to 1MB (2^16*2*8) due to fixed key size + metrics module.BackendScriptsMetrics } func (b *backendScripts) ExecuteScriptAtLatestBlock( @@ -125,15 +126,11 @@ func (b *backendScripts) executeScriptOnExecutionNode( } } - fmt.Println("HELLO HELLO HELLO") - fmt.Println("HELLO HELLO HELLO") - fmt.Println("HELLO HELLO HELLO") - fmt.Println("HELLO HELLO HELLO") - // log execution time - b.log.Debug(). - Dur("exec_time", time.Since(execStartTime)). - Int("script_size", len(script)) + b.metrics.ExecuteScriptRTT( + time.Since(execStartTime), + len(script), + ) return result, nil } From f604ab27355a737778bba8cca9d59b7730d0d702 Mon Sep 17 00:00:00 2001 From: Daniel Holmes Date: Tue, 10 May 2022 15:03:15 -0400 Subject: [PATCH 04/18] switched to counter --- module/metrics/transaction.go | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index b20a1cca508..32e321a4ade 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -21,8 +21,8 @@ type TransactionCollector struct { timeToExecuted prometheus.Summary timeToFinalizedExecuted prometheus.Summary transactionSubmission *prometheus.CounterVec - executeScriptRTT prometheus.Counter - executeScriptSize prometheus.Histogram + executeScriptDuration prometheus.Counter + executeScriptSize prometheus.Counter } func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log zerolog.Logger, @@ -83,17 +83,17 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log Subsystem: subsystemTransactionSubmission, Help: "counter for the success/failure of transaction submissions", }, []string{"result"}), - executeScriptRTT: promauto.NewCounter(prometheus.CounterOpts{ - Name: "execute_script_rtt", + executeScriptDuration: promauto.NewCounter(prometheus.CounterOpts{ + Name: "execute_script_rtt_duration", Namespace: namespaceAccess, - Subsystem: "TEMP", + Subsystem: subsystemTransactionSubmission, Help: "counter for the round trip time for executing a script", }), - executeScriptSize: promauto.NewHistogram(prometheus.HistogramOpts{ - Name: "execute_script_size", + executeScriptSize: promauto.NewCounter(prometheus.CounterOpts{ + Name: "execute_script_rtt_size", Namespace: namespaceAccess, - Subsystem: "TEMP", - Help: "histogram for the size in bytes of scripts being executed", + Subsystem: subsystemTransactionSubmission, + Help: "counter for the size in bytes of scripts being executed", }), } @@ -101,8 +101,8 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log } func (tc *TransactionCollector) ExecuteScriptRTT(dur time.Duration, size int) { - tc.executeScriptRTT.Add(float64(dur) / float64(time.Millisecond)) - tc.executeScriptSize.Observe(float64(size)) + tc.executeScriptDuration.Add(float64(dur) / float64(time.Millisecond)) + tc.executeScriptSize.Add(float64(size)) } func (tc *TransactionCollector) TransactionReceived(txID flow.Identifier, when time.Time) { From 14fd008f29efefb94100b8bf05b4c19df78afd16 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Wed, 11 May 2022 12:42:14 -0400 Subject: [PATCH 05/18] added buckets for script size --- module/metrics/transaction.go | 30 ++++++++++++++++++------------ 1 file changed, 18 insertions(+), 12 deletions(-) diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index 32e321a4ade..dc99565aa36 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -21,8 +21,7 @@ type TransactionCollector struct { timeToExecuted prometheus.Summary timeToFinalizedExecuted prometheus.Summary transactionSubmission *prometheus.CounterVec - executeScriptDuration prometheus.Counter - executeScriptSize prometheus.Counter + executeScriptDuration *prometheus.CounterVec } func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log zerolog.Logger, @@ -83,26 +82,33 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log Subsystem: subsystemTransactionSubmission, Help: "counter for the success/failure of transaction submissions", }, []string{"result"}), - executeScriptDuration: promauto.NewCounter(prometheus.CounterOpts{ + executeScriptDuration: promauto.NewCounterVec(prometheus.CounterOpts{ Name: "execute_script_rtt_duration", Namespace: namespaceAccess, Subsystem: subsystemTransactionSubmission, Help: "counter for the round trip time for executing a script", - }), - executeScriptSize: promauto.NewCounter(prometheus.CounterOpts{ - Name: "execute_script_rtt_size", - Namespace: namespaceAccess, - Subsystem: subsystemTransactionSubmission, - Help: "counter for the size in bytes of scripts being executed", - }), + }, []string{"script_size"}), } return tc } func (tc *TransactionCollector) ExecuteScriptRTT(dur time.Duration, size int) { - tc.executeScriptDuration.Add(float64(dur) / float64(time.Millisecond)) - tc.executeScriptSize.Add(float64(size)) + 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" + } + + // record the script + tc.executeScriptDuration.With(prometheus.Labels{ + "script_size": sizeLabel, + }).Add(float64(dur.Milliseconds())) } func (tc *TransactionCollector) TransactionReceived(txID flow.Identifier, when time.Time) { From b6c248e816fc19620f8709804be7277285cfa523 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Wed, 11 May 2022 12:57:59 -0400 Subject: [PATCH 06/18] go fmt --- module/metrics/noop.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/module/metrics/noop.go b/module/metrics/noop.go index 2ad1ae8142b..b1f69abe4af 100644 --- a/module/metrics/noop.go +++ b/module/metrics/noop.go @@ -142,7 +142,7 @@ 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) ExecuteScriptRTT(dur time.Duration, size int) {} +func (nc *NoopCollector) ExecuteScriptRTT(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) {} From afcd92ccc79f269b0efc6fe69501cf9e56217b68 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Wed, 11 May 2022 15:49:44 -0400 Subject: [PATCH 07/18] added GetTransactionResultRTT metric --- module/metrics.go | 3 +++ module/metrics/noop.go | 1 + module/metrics/transaction.go | 42 ++++++++++++++++++++++++++---- module/mock/transaction_metrics.go | 5 ++++ 4 files changed, 46 insertions(+), 5 deletions(-) diff --git a/module/metrics.go b/module/metrics.go index 5ba3929d2ff..11958adc9cd 100644 --- a/module/metrics.go +++ b/module/metrics.go @@ -408,6 +408,9 @@ type BackendScriptsMetrics interface { type TransactionMetrics interface { BackendScriptsMetrics + // Record the round trip time while getting a transaction result + GetTransactionResultRTT(dur time.Duration, size int) + // TransactionReceived starts tracking of transaction execution/finalization/sealing TransactionReceived(txID flow.Identifier, when time.Time) diff --git a/module/metrics/noop.go b/module/metrics/noop.go index b1f69abe4af..55c2394cc71 100644 --- a/module/metrics/noop.go +++ b/module/metrics/noop.go @@ -143,6 +143,7 @@ func (nc *NoopCollector) RuntimeTransactionChecked(dur time.Duration) func (nc *NoopCollector) RuntimeTransactionInterpreted(dur time.Duration) {} func (nc *NoopCollector) RuntimeSetNumberOfAccounts(count uint64) {} func (nc *NoopCollector) ExecuteScriptRTT(dur time.Duration, size int) {} +func (nc *NoopCollector) GetTransactionResultRTT(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) {} diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index dc99565aa36..5be677f5753 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -22,6 +22,8 @@ type TransactionCollector struct { timeToFinalizedExecuted prometheus.Summary transactionSubmission *prometheus.CounterVec executeScriptDuration *prometheus.CounterVec + transactionResultDuration *prometheus.CounterVec + scriptSize *prometheus.HistogramVec } func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log zerolog.Logger, @@ -86,14 +88,41 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log Name: "execute_script_rtt_duration", Namespace: namespaceAccess, Subsystem: subsystemTransactionSubmission, - Help: "counter for the round trip time for executing a script", + Help: "counter for the duration in ms of the round trip time for executing a script", }, []string{"script_size"}), + transactionResultDuration: promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "transaction_result_rtt_duration", + Namespace: namespaceAccess, + Subsystem: subsystemTransactionSubmission, + Help: "counter for the duration in ms of the round trip time for getting a transaction result", + }, []string{"script_size"}), + scriptSize: promauto.NewHistogramVec(prometheus.HistogramOpts{ + Name: "script_size", + Namespace: namespaceAccess, + Subsystem: subsystemTransactionSubmission, + Help: "histogram for the script size in kb histogram in GetTransactionResult and ExecuteScript", + }, []string{"method"}), } return tc } func (tc *TransactionCollector) ExecuteScriptRTT(dur time.Duration, size int) { + tc.scriptSizeHist(size, "ExecuteScript") + tc.executeScriptDuration.With(prometheus.Labels{ + "script_size": tc.scriptSizeLabel(size), + }).Add(float64(dur.Milliseconds())) +} + +func (tc *TransactionCollector) GetTransactionResultRTT(dur time.Duration, size int) { + tc.scriptSizeHist(size, "GetTransactionResult") + tc.transactionResultDuration.With(prometheus.Labels{ + "script_size": tc.scriptSizeLabel(size), + }).Add(float64(dur.Milliseconds())) +} + +func (tc *TransactionCollector) scriptSizeLabel(size int) string { + // determine the script size label sizeKb := size / 1024 sizeLabel := "100+kb" //"1kb,10kb,100kb, 100+kb" -> [0,1] [2,10] [11,100] [100, +inf] @@ -104,11 +133,14 @@ func (tc *TransactionCollector) ExecuteScriptRTT(dur time.Duration, size int) { } else if sizeKb <= 100 { sizeLabel = "100kb" } + return sizeLabel +} - // record the script - tc.executeScriptDuration.With(prometheus.Labels{ - "script_size": sizeLabel, - }).Add(float64(dur.Milliseconds())) +func (tc *TransactionCollector) scriptSizeHist(size int, method string) { + // add the script size in kb to the histogram and the method used as a label + tc.scriptSize.With(prometheus.Labels{ + "method": method, + }).Observe(float64(size / 1024)) } func (tc *TransactionCollector) TransactionReceived(txID flow.Identifier, when time.Time) { diff --git a/module/mock/transaction_metrics.go b/module/mock/transaction_metrics.go index fd4ad2abe82..0343c09b734 100644 --- a/module/mock/transaction_metrics.go +++ b/module/mock/transaction_metrics.go @@ -19,6 +19,11 @@ func (_m *TransactionMetrics) ExecuteScriptRTT(dur time.Duration, size int) { _m.Called(dur, size) } +// GetTransactionResultRTT provides a mock function with given fields: dur, size +func (_m *TransactionMetrics) GetTransactionResultRTT(dur time.Duration, size int) { + _m.Called(dur, size) +} + // TransactionExecuted provides a mock function with given fields: txID, when func (_m *TransactionMetrics) TransactionExecuted(txID flow.Identifier, when time.Time) { _m.Called(txID, when) From a2b0c228036c41c0f709555e7c08af722b5cb065 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Wed, 11 May 2022 15:49:59 -0400 Subject: [PATCH 08/18] record GetTransactionResultRTT metric --- engine/access/rpc/backend/backend_transactions.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/engine/access/rpc/backend/backend_transactions.go b/engine/access/rpc/backend/backend_transactions.go index a597568ce48..686654d9167 100644 --- a/engine/access/rpc/backend/backend_transactions.go +++ b/engine/access/rpc/backend/backend_transactions.go @@ -182,9 +182,11 @@ func (b *backendTransactions) SendRawTransaction( func (b *backendTransactions) GetTransaction(ctx context.Context, txID flow.Identifier) (*flow.TransactionBody, error) { // look up transaction from storage + start := time.Now() tx, err := b.transactions.ByID(txID) - txErr := convertStorageError(err) - if txErr != nil { + b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) + + if txErr := convertStorageError(err); txErr != nil { if status.Code(txErr) == codes.NotFound { return b.getHistoricalTransaction(ctx, txID) } From 47cc8e7a1585e11b5e66655f140720ed420c7a56 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Wed, 11 May 2022 15:54:52 -0400 Subject: [PATCH 09/18] record GetTransactionResultRTT metric --- engine/access/rpc/backend/backend_transactions.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/engine/access/rpc/backend/backend_transactions.go b/engine/access/rpc/backend/backend_transactions.go index 686654d9167..6e7b54a8f68 100644 --- a/engine/access/rpc/backend/backend_transactions.go +++ b/engine/access/rpc/backend/backend_transactions.go @@ -182,11 +182,10 @@ func (b *backendTransactions) SendRawTransaction( func (b *backendTransactions) GetTransaction(ctx context.Context, txID flow.Identifier) (*flow.TransactionBody, error) { // look up transaction from storage - start := time.Now() tx, err := b.transactions.ByID(txID) - b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) + txErr := convertStorageError(err) - if txErr := convertStorageError(err); txErr != nil { + if txErr != nil { if status.Code(txErr) == codes.NotFound { return b.getHistoricalTransaction(ctx, txID) } @@ -232,7 +231,10 @@ func (b *backendTransactions) GetTransactionResult( txID flow.Identifier, ) (*access.TransactionResult, error) { // look up transaction from storage + start := time.Now() tx, err := b.transactions.ByID(txID) + b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) + txErr := convertStorageError(err) if txErr != nil { if status.Code(txErr) == codes.NotFound { From 42c2e2906a64d957aabc49d93f33089a9ba8b24b Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Wed, 11 May 2022 17:40:24 -0400 Subject: [PATCH 10/18] check unit tests --- engine/access/rpc/backend/backend_transactions.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/engine/access/rpc/backend/backend_transactions.go b/engine/access/rpc/backend/backend_transactions.go index 6e7b54a8f68..6712d94f3d3 100644 --- a/engine/access/rpc/backend/backend_transactions.go +++ b/engine/access/rpc/backend/backend_transactions.go @@ -231,9 +231,9 @@ func (b *backendTransactions) GetTransactionResult( txID flow.Identifier, ) (*access.TransactionResult, error) { // look up transaction from storage - start := time.Now() + // start := time.Now() tx, err := b.transactions.ByID(txID) - b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) + // b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) txErr := convertStorageError(err) if txErr != nil { From 4310670212b18139d72d4573a1085eb159841290 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Thu, 12 May 2022 12:01:00 -0400 Subject: [PATCH 11/18] fix unit tests --- engine/access/rpc/backend/backend_transactions.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/engine/access/rpc/backend/backend_transactions.go b/engine/access/rpc/backend/backend_transactions.go index 6712d94f3d3..9c5c53d26b4 100644 --- a/engine/access/rpc/backend/backend_transactions.go +++ b/engine/access/rpc/backend/backend_transactions.go @@ -231,9 +231,8 @@ func (b *backendTransactions) GetTransactionResult( txID flow.Identifier, ) (*access.TransactionResult, error) { // look up transaction from storage - // start := time.Now() + start := time.Now() tx, err := b.transactions.ByID(txID) - // b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) txErr := convertStorageError(err) if txErr != nil { @@ -280,6 +279,8 @@ func (b *backendTransactions) GetTransactionResult( return nil, convertStorageError(err) } + b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) + return &access.TransactionResult{ Status: txStatus, StatusCode: uint(statusCode), From b22167c60a670dbca76ce8062bdce5981de55c4b Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Thu, 12 May 2022 15:58:51 -0400 Subject: [PATCH 12/18] typo --- module/metrics/transaction.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index 5be677f5753..c26afd1b90d 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -100,7 +100,7 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log Name: "script_size", Namespace: namespaceAccess, Subsystem: subsystemTransactionSubmission, - Help: "histogram for the script size in kb histogram in GetTransactionResult and ExecuteScript", + Help: "histogram for the script size in kb of scripts used in GetTransactionResult and ExecuteScript", }, []string{"method"}), } From a627f320c2ed31308dd8d2d614d355d7ee7a9fd3 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Thu, 12 May 2022 16:19:20 -0400 Subject: [PATCH 13/18] moved start time into loop --- engine/access/rpc/backend/backend_scripts.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/engine/access/rpc/backend/backend_scripts.go b/engine/access/rpc/backend/backend_scripts.go index d95a939316a..713679c04fb 100644 --- a/engine/access/rpc/backend/backend_scripts.go +++ b/engine/access/rpc/backend/backend_scripts.go @@ -100,15 +100,14 @@ func (b *backendScripts) executeScriptOnExecutionNode( // encode to MD5 as low compute/memory lookup key encodedScript := md5.Sum(script) //nolint:gosec - // record start time - execStartTime := time.Now() - // 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() From 330c1b7bc860592e603b20af39691f4cd75f2169 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Thu, 12 May 2022 16:52:05 -0400 Subject: [PATCH 14/18] go fmt --- engine/access/rpc/backend/backend_scripts.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/engine/access/rpc/backend/backend_scripts.go b/engine/access/rpc/backend/backend_scripts.go index 713679c04fb..74b1ee0a6ef 100644 --- a/engine/access/rpc/backend/backend_scripts.go +++ b/engine/access/rpc/backend/backend_scripts.go @@ -107,7 +107,7 @@ func (b *backendScripts) executeScriptOnExecutionNode( 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() From b14ffa135ea500764e103e39803feeed4347ff76 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Mon, 16 May 2022 16:52:36 -0400 Subject: [PATCH 15/18] renamed methods and switched to histograms --- engine/access/rpc/backend/backend_scripts.go | 2 +- .../rpc/backend/backend_transactions.go | 2 +- module/metrics.go | 4 +-- module/metrics/noop.go | 4 +-- module/metrics/transaction.go | 28 ++++++++++--------- module/mock/backend_scripts_metrics.go | 4 +-- module/mock/transaction_metrics.go | 8 +++--- 7 files changed, 27 insertions(+), 25 deletions(-) diff --git a/engine/access/rpc/backend/backend_scripts.go b/engine/access/rpc/backend/backend_scripts.go index 74b1ee0a6ef..5965f718f3d 100644 --- a/engine/access/rpc/backend/backend_scripts.go +++ b/engine/access/rpc/backend/backend_scripts.go @@ -126,7 +126,7 @@ func (b *backendScripts) executeScriptOnExecutionNode( } // log execution time - b.metrics.ExecuteScriptRTT( + b.metrics.ScriptExecuted( time.Since(execStartTime), len(script), ) diff --git a/engine/access/rpc/backend/backend_transactions.go b/engine/access/rpc/backend/backend_transactions.go index 9c5c53d26b4..d952ebd1f59 100644 --- a/engine/access/rpc/backend/backend_transactions.go +++ b/engine/access/rpc/backend/backend_transactions.go @@ -279,7 +279,7 @@ func (b *backendTransactions) GetTransactionResult( return nil, convertStorageError(err) } - b.transactionMetrics.GetTransactionResultRTT(time.Since(start), len(tx.Script)) + b.transactionMetrics.TransactionResultFetched(time.Since(start), len(tx.Script)) return &access.TransactionResult{ Status: txStatus, diff --git a/module/metrics.go b/module/metrics.go index 11958adc9cd..f8d7b11a96d 100644 --- a/module/metrics.go +++ b/module/metrics.go @@ -402,14 +402,14 @@ type ExecutionMetrics interface { type BackendScriptsMetrics interface { // Record the round trip time while executing a script - ExecuteScriptRTT(dur time.Duration, size int) + ScriptExecuted(dur time.Duration, size int) } type TransactionMetrics interface { BackendScriptsMetrics // Record the round trip time while getting a transaction result - GetTransactionResultRTT(dur time.Duration, size int) + TransactionResultFetched(dur time.Duration, size int) // TransactionReceived starts tracking of transaction execution/finalization/sealing TransactionReceived(txID flow.Identifier, when time.Time) diff --git a/module/metrics/noop.go b/module/metrics/noop.go index 55c2394cc71..e82bb5302e5 100644 --- a/module/metrics/noop.go +++ b/module/metrics/noop.go @@ -142,8 +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) ExecuteScriptRTT(dur time.Duration, size int) {} -func (nc *NoopCollector) GetTransactionResultRTT(dur time.Duration, size int) {} +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) {} diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index c26afd1b90d..3279bf20c7d 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -21,8 +21,8 @@ type TransactionCollector struct { timeToExecuted prometheus.Summary timeToFinalizedExecuted prometheus.Summary transactionSubmission *prometheus.CounterVec - executeScriptDuration *prometheus.CounterVec - transactionResultDuration *prometheus.CounterVec + scriptExecutedDuration *prometheus.HistogramVec + transactionResultDuration *prometheus.HistogramVec scriptSize *prometheus.HistogramVec } @@ -84,17 +84,19 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log Subsystem: subsystemTransactionSubmission, Help: "counter for the success/failure of transaction submissions", }, []string{"result"}), - executeScriptDuration: promauto.NewCounterVec(prometheus.CounterOpts{ - Name: "execute_script_rtt_duration", + scriptExecutedDuration: promauto.NewHistogramVec(prometheus.HistogramOpts{ + Name: "script_executed_duration", Namespace: namespaceAccess, Subsystem: subsystemTransactionSubmission, - Help: "counter for the duration in ms of the round trip time for executing a script", + 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.NewCounterVec(prometheus.CounterOpts{ - Name: "transaction_result_rtt_duration", + transactionResultDuration: promauto.NewHistogramVec(prometheus.HistogramOpts{ + Name: "transaction_result_fetched_duration", Namespace: namespaceAccess, Subsystem: subsystemTransactionSubmission, - Help: "counter for the duration in ms of the round trip time for getting a transaction result", + 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{"script_size"}), scriptSize: promauto.NewHistogramVec(prometheus.HistogramOpts{ Name: "script_size", @@ -107,18 +109,18 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log return tc } -func (tc *TransactionCollector) ExecuteScriptRTT(dur time.Duration, size int) { +func (tc *TransactionCollector) ScriptExecuted(dur time.Duration, size int) { tc.scriptSizeHist(size, "ExecuteScript") - tc.executeScriptDuration.With(prometheus.Labels{ + tc.scriptExecutedDuration.With(prometheus.Labels{ "script_size": tc.scriptSizeLabel(size), - }).Add(float64(dur.Milliseconds())) + }).Observe(float64(dur.Milliseconds())) } -func (tc *TransactionCollector) GetTransactionResultRTT(dur time.Duration, size int) { +func (tc *TransactionCollector) TransactionResultFetched(dur time.Duration, size int) { tc.scriptSizeHist(size, "GetTransactionResult") tc.transactionResultDuration.With(prometheus.Labels{ "script_size": tc.scriptSizeLabel(size), - }).Add(float64(dur.Milliseconds())) + }).Observe(float64(dur.Milliseconds())) } func (tc *TransactionCollector) scriptSizeLabel(size int) string { diff --git a/module/mock/backend_scripts_metrics.go b/module/mock/backend_scripts_metrics.go index 0d9799a6811..fae23c8a38f 100644 --- a/module/mock/backend_scripts_metrics.go +++ b/module/mock/backend_scripts_metrics.go @@ -13,7 +13,7 @@ type BackendScriptsMetrics struct { mock.Mock } -// ExecuteScriptRTT provides a mock function with given fields: dur, size -func (_m *BackendScriptsMetrics) ExecuteScriptRTT(dur time.Duration, size int) { +// ScriptExecuted provides a mock function with given fields: dur, size +func (_m *BackendScriptsMetrics) ScriptExecuted(dur time.Duration, size int) { _m.Called(dur, size) } diff --git a/module/mock/transaction_metrics.go b/module/mock/transaction_metrics.go index 0343c09b734..6aa832c67aa 100644 --- a/module/mock/transaction_metrics.go +++ b/module/mock/transaction_metrics.go @@ -14,13 +14,13 @@ type TransactionMetrics struct { mock.Mock } -// ExecuteScriptRTT provides a mock function with given fields: dur, size -func (_m *TransactionMetrics) ExecuteScriptRTT(dur time.Duration, size int) { +// ScriptExecuted provides a mock function with given fields: dur, size +func (_m *TransactionMetrics) ScriptExecuted(dur time.Duration, size int) { _m.Called(dur, size) } -// GetTransactionResultRTT provides a mock function with given fields: dur, size -func (_m *TransactionMetrics) GetTransactionResultRTT(dur time.Duration, size int) { +// TransactionResultFetched provides a mock function with given fields: dur, size +func (_m *TransactionMetrics) TransactionResultFetched(dur time.Duration, size int) { _m.Called(dur, size) } From 8ef9aaea40cfe1569388cbcabcd589b8da892f29 Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Wed, 18 May 2022 10:58:20 -0400 Subject: [PATCH 16/18] fixed imports --- engine/access/rpc/backend/backend_scripts.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/engine/access/rpc/backend/backend_scripts.go b/engine/access/rpc/backend/backend_scripts.go index 4bb718f1ada..8bef55ed5e8 100644 --- a/engine/access/rpc/backend/backend_scripts.go +++ b/engine/access/rpc/backend/backend_scripts.go @@ -131,7 +131,7 @@ func (b *backendScripts) executeScriptOnExecutionNode( 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(). From 628a0cc230259e9111b757b2cca1962b8b19586d Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Thu, 19 May 2022 17:22:29 -0400 Subject: [PATCH 17/18] separated script size into two metrics --- module/metrics/transaction.go | 38 ++++++++++++++++++----------------- 1 file changed, 20 insertions(+), 18 deletions(-) diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index 3279bf20c7d..d7212fc9d5c 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -23,7 +23,8 @@ type TransactionCollector struct { transactionSubmission *prometheus.CounterVec scriptExecutedDuration *prometheus.HistogramVec transactionResultDuration *prometheus.HistogramVec - scriptSize *prometheus.HistogramVec + scriptSize prometheus.Histogram + transactionSize prometheus.Histogram } func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log zerolog.Logger, @@ -97,34 +98,42 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log 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{"script_size"}), - scriptSize: promauto.NewHistogramVec(prometheus.HistogramOpts{ + }, []string{"transaction_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 GetTransactionResult and ExecuteScript", - }, []string{"method"}), + 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) { - tc.scriptSizeHist(size, "ExecuteScript") + // record the execute script duration and script size + tc.scriptSize.Observe(float64(size / 1024)) tc.scriptExecutedDuration.With(prometheus.Labels{ - "script_size": tc.scriptSizeLabel(size), + "script_size": tc.sizeLabel(size), }).Observe(float64(dur.Milliseconds())) } func (tc *TransactionCollector) TransactionResultFetched(dur time.Duration, size int) { - tc.scriptSizeHist(size, "GetTransactionResult") + // record the transaction result duration and transaction script/payload size + tc.transactionSize.Observe(float64(size / 1024)) tc.transactionResultDuration.With(prometheus.Labels{ - "script_size": tc.scriptSizeLabel(size), + "transaction_size": tc.sizeLabel(size), }).Observe(float64(dur.Milliseconds())) } -func (tc *TransactionCollector) scriptSizeLabel(size int) string { - // determine the script size label +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] @@ -138,13 +147,6 @@ func (tc *TransactionCollector) scriptSizeLabel(size int) string { return sizeLabel } -func (tc *TransactionCollector) scriptSizeHist(size int, method string) { - // add the script size in kb to the histogram and the method used as a label - tc.scriptSize.With(prometheus.Labels{ - "method": method, - }).Observe(float64(size / 1024)) -} - 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}) From 9391bbb33d1ff1c8c2d575ee567f76604da3327c Mon Sep 17 00:00:00 2001 From: danielholmes839 Date: Thu, 19 May 2022 17:24:34 -0400 Subject: [PATCH 18/18] payload_size label --- module/metrics/transaction.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/module/metrics/transaction.go b/module/metrics/transaction.go index d7212fc9d5c..8488df7b909 100644 --- a/module/metrics/transaction.go +++ b/module/metrics/transaction.go @@ -98,7 +98,7 @@ func NewTransactionCollector(transactionTimings mempool.TransactionTimings, log 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{"transaction_size"}), + }, []string{"payload_size"}), scriptSize: promauto.NewHistogram(prometheus.HistogramOpts{ Name: "script_size", Namespace: namespaceAccess, @@ -128,7 +128,7 @@ func (tc *TransactionCollector) TransactionResultFetched(dur time.Duration, size // record the transaction result duration and transaction script/payload size tc.transactionSize.Observe(float64(size / 1024)) tc.transactionResultDuration.With(prometheus.Labels{ - "transaction_size": tc.sizeLabel(size), + "payload_size": tc.sizeLabel(size), }).Observe(float64(dur.Milliseconds())) }