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 <wtlahti@us.ibm.com>

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

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)
 

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,28 +52,41 @@ 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 {
  return &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),
  }
 }

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

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)