From dd7b8bd204c8efb8a30f248b62e83429fe0dda6c Mon Sep 17 00:00:00 2001 From: Will Lahti Date: Wed, 28 Nov 2018 15:04:25 -0500 Subject: [PATCH] CC launch failure/timeout and execute timeout metrics This CR adds metrics for chaincode launch failures, chaincode launch timeouts, and chaincode execute timeouts. FAB-13027 #done Change-Id: Id995c92c56e2c064e38ee42f907c92af32c101c8 Signed-off-by: Will Lahti --- core/chaincode/handler.go | 6 ++++- core/chaincode/handler_test.go | 20 +++++++++++++++++ core/chaincode/metrics.go | 27 ++++++++++++++++++++++ core/chaincode/runtime_launcher.go | 6 +++++ core/chaincode/runtime_launcher_test.go | 30 +++++++++++++++++++++++++ 5 files changed, 88 insertions(+), 1 deletion(-) diff --git a/core/chaincode/handler.go b/core/chaincode/handler.go index 28be8df0fe5..0e96f0554ba 100644 --- a/core/chaincode/handler.go +++ b/core/chaincode/handler.go @@ -163,7 +163,7 @@ type Handler struct { chatStream ccintf.ChaincodeStream // errChan is used to communicate errors from the async send to the receive loop errChan chan error - // Metrics holds chaincode metrics + // Metrics holds chaincode handler metrics Metrics *HandlerMetrics } @@ -1142,6 +1142,10 @@ func (h *Handler) Execute(txParams *ccprovider.TransactionParams, cccid *ccprovi // are typically treated as error case <-time.After(timeout): err = errors.New("timeout expired while executing transaction") + ccName := cccid.Name + ":" + cccid.Version + h.Metrics.ExecuteTimeouts.With( + "chaincode", ccName, + ).Add(1) } return ccresp, err diff --git a/core/chaincode/handler_test.go b/core/chaincode/handler_test.go index cdce247e077..c0c6c1e14ae 100644 --- a/core/chaincode/handler_test.go +++ b/core/chaincode/handler_test.go @@ -46,6 +46,7 @@ var _ = Describe("Handler", func() { fakeShimRequestsReceived *metricsfakes.Counter fakeShimRequestsCompleted *metricsfakes.Counter fakeShimRequestDuration *metricsfakes.Histogram + fakeExecuteTimeouts *metricsfakes.Counter responseNotifier chan *pb.ChaincodeMessage txContext *chaincode.TransactionContext @@ -94,11 +95,14 @@ var _ = Describe("Handler", func() { fakeShimRequestsCompleted.WithReturns(fakeShimRequestsCompleted) fakeShimRequestDuration = &metricsfakes.Histogram{} fakeShimRequestDuration.WithReturns(fakeShimRequestDuration) + fakeExecuteTimeouts = &metricsfakes.Counter{} + fakeExecuteTimeouts.WithReturns(fakeExecuteTimeouts) chaincodeMetrics := &chaincode.HandlerMetrics{ ShimRequestsReceived: fakeShimRequestsReceived, ShimRequestsCompleted: fakeShimRequestsCompleted, ShimRequestDuration: fakeShimRequestDuration, + ExecuteTimeouts: fakeExecuteTimeouts, } handler = &chaincode.Handler{ @@ -2322,6 +2326,22 @@ var _ = Describe("Handler", func() { Eventually(errCh).Should(Receive(MatchError("timeout expired while executing transaction"))) }) + It("records execute timeouts", func() { + errCh := make(chan error, 1) + go func() { + _, err := handler.Execute(txParams, cccid, incomingMessage, time.Millisecond) + errCh <- err + }() + Eventually(errCh).Should(Receive(MatchError("timeout expired while executing transaction"))) + Expect(fakeExecuteTimeouts.WithCallCount()).To(Equal(1)) + labelValues := fakeExecuteTimeouts.WithArgsForCall(0) + Expect(labelValues).To(Equal([]string{ + "chaincode", "chaincode-name:chaincode-version", + })) + Expect(fakeExecuteTimeouts.AddCallCount()).To(Equal(1)) + Expect(fakeExecuteTimeouts.AddArgsForCall(0)).To(BeNumerically("~", 1.0)) + }) + It("deletes the transaction context", func() { handler.Execute(txParams, cccid, incomingMessage, time.Millisecond) diff --git a/core/chaincode/metrics.go b/core/chaincode/metrics.go index 4c4986d97ec..bfc1439ae09 100644 --- a/core/chaincode/metrics.go +++ b/core/chaincode/metrics.go @@ -16,6 +16,20 @@ var ( LabelNames: []string{"chaincode", "success"}, StatsdFormat: "%{#fqname}.%{chaincode}.%{success}", } + launchFailures = metrics.CounterOpts{ + Namespace: "chaincode", + Name: "launch_failures", + Help: "The number of chaincode launches that have failed.", + LabelNames: []string{"chaincode"}, + StatsdFormat: "%{#fqname}.%{chaincode}", + } + launchTimeouts = metrics.CounterOpts{ + Namespace: "chaincode", + Name: "launch_timeouts", + Help: "The number of chaincode launches that have timed out.", + LabelNames: []string{"chaincode"}, + StatsdFormat: "%{#fqname}.%{chaincode}", + } shimRequestsReceived = metrics.CounterOpts{ Namespace: "chaincode", @@ -38,12 +52,20 @@ var ( LabelNames: []string{"type", "channel", "chaincode", "success"}, StatsdFormat: "%{#fqname}.%{type}.%{channel}.%{chaincode}.%{success}", } + executeTimeouts = metrics.CounterOpts{ + Namespace: "chaincode", + Name: "execute_timeouts", + Help: "The number of chaincode executions (Init or Invoke) that have timed out.", + LabelNames: []string{"chaincode"}, + StatsdFormat: "%{#fqname}.%{chaincode}", + } ) type HandlerMetrics struct { ShimRequestsReceived metrics.Counter ShimRequestsCompleted metrics.Counter ShimRequestDuration metrics.Histogram + ExecuteTimeouts metrics.Counter } func NewHandlerMetrics(p metrics.Provider) *HandlerMetrics { @@ -51,15 +73,20 @@ func NewHandlerMetrics(p metrics.Provider) *HandlerMetrics { ShimRequestsReceived: p.NewCounter(shimRequestsReceived), ShimRequestsCompleted: p.NewCounter(shimRequestsCompleted), ShimRequestDuration: p.NewHistogram(shimRequestDuration), + ExecuteTimeouts: p.NewCounter(executeTimeouts), } } type LaunchMetrics struct { LaunchDuration metrics.Histogram + LaunchFailures metrics.Counter + LaunchTimeouts metrics.Counter } func NewLaunchMetrics(p metrics.Provider) *LaunchMetrics { return &LaunchMetrics{ LaunchDuration: p.NewHistogram(launchDuration), + LaunchFailures: p.NewCounter(launchFailures), + LaunchTimeouts: p.NewCounter(launchTimeouts), } } diff --git a/core/chaincode/runtime_launcher.go b/core/chaincode/runtime_launcher.go index 02d31cea29f..a1e32a05641 100644 --- a/core/chaincode/runtime_launcher.go +++ b/core/chaincode/runtime_launcher.go @@ -64,9 +64,15 @@ func (r *RuntimeLauncher) Launch(ccci *ccprovider.ChaincodeContainerInfo) error err = errors.WithMessage(launchState.Err(), "chaincode registration failed") case err = <-startFailCh: launchState.Notify(err) + r.Metrics.LaunchFailures.With( + "chaincode", cname, + ).Add(1) case <-timeoutCh: err = errors.Errorf("timeout expired while starting chaincode %s for transaction", cname) launchState.Notify(err) + r.Metrics.LaunchTimeouts.With( + "chaincode", cname, + ).Add(1) } success := true diff --git a/core/chaincode/runtime_launcher_test.go b/core/chaincode/runtime_launcher_test.go index 763dd5f26f9..1fccb798056 100644 --- a/core/chaincode/runtime_launcher_test.go +++ b/core/chaincode/runtime_launcher_test.go @@ -26,6 +26,8 @@ var _ = Describe("RuntimeLauncher", func() { fakeRegistry *fake.LaunchRegistry launchState *chaincode.LaunchState fakeLaunchDuration *metricsfakes.Histogram + fakeLaunchFailures *metricsfakes.Counter + fakeLaunchTimeouts *metricsfakes.Counter ccci *ccprovider.ChaincodeContainerInfo @@ -48,9 +50,15 @@ var _ = Describe("RuntimeLauncher", func() { fakeLaunchDuration = &metricsfakes.Histogram{} fakeLaunchDuration.WithReturns(fakeLaunchDuration) + fakeLaunchFailures = &metricsfakes.Counter{} + fakeLaunchFailures.WithReturns(fakeLaunchFailures) + fakeLaunchTimeouts = &metricsfakes.Counter{} + fakeLaunchTimeouts.WithReturns(fakeLaunchTimeouts) launchMetrics := &chaincode.LaunchMetrics{ LaunchDuration: fakeLaunchDuration, + LaunchFailures: fakeLaunchFailures, + LaunchTimeouts: fakeLaunchTimeouts, } ccci = &ccprovider.ChaincodeContainerInfo{ Name: "chaincode-name", @@ -136,6 +144,17 @@ var _ = Describe("RuntimeLauncher", func() { Expect(launchState.Err()).To(MatchError("error starting container: banana")) }) + It("records chaincode launch failures", func() { + runtimeLauncher.Launch(ccci) + Expect(fakeLaunchFailures.WithCallCount()).To(Equal(1)) + labelValues := fakeLaunchFailures.WithArgsForCall(0) + Expect(labelValues).To(Equal([]string{ + "chaincode", "chaincode-name:chaincode-version", + })) + Expect(fakeLaunchFailures.AddCallCount()).To(Equal(1)) + Expect(fakeLaunchFailures.AddArgsForCall(0)).To(BeNumerically("~", 1.0)) + }) + It("stops the runtime", func() { runtimeLauncher.Launch(ccci) @@ -200,6 +219,17 @@ var _ = Describe("RuntimeLauncher", func() { Expect(launchState.Err()).To(MatchError("timeout expired while starting chaincode chaincode-name:chaincode-version for transaction")) }) + It("records chaincode launch timeouts", func() { + runtimeLauncher.Launch(ccci) + Expect(fakeLaunchTimeouts.WithCallCount()).To(Equal(1)) + labelValues := fakeLaunchTimeouts.WithArgsForCall(0) + Expect(labelValues).To(Equal([]string{ + "chaincode", "chaincode-name:chaincode-version", + })) + Expect(fakeLaunchTimeouts.AddCallCount()).To(Equal(1)) + Expect(fakeLaunchTimeouts.AddArgsForCall(0)).To(BeNumerically("~", 1.0)) + }) + It("stops the runtime", func() { runtimeLauncher.Launch(ccci)