Capture time taken creating and signing attestations in AttestationPr…

…oductionDuty (Consensys#7630)

* Capture time taken creating and signing attestations in AttestationProductionDuty

* Update signing timer

* Validate before recording metric

validator/client/src/main/java/tech/pegasys/teku/validator/client/duties/attestations/AttestationDutyFactory.java

@@ -51,7 +51,8 @@ public AttestationProductionDuty createProductionDuty(
         slot,
         forkProvider,
         validatorApiChannel,
-        new BatchAttestationSendingStrategy<>(validatorApiChannel::sendSignedAttestations));
+        new BatchAttestationSendingStrategy<>(validatorApiChannel::sendSignedAttestations),
+        validatorDutyMetrics);
   }
 
   @Override

validator/client/src/main/java/tech/pegasys/teku/validator/client/duties/attestations/AttestationProductionDuty.java

@@ -38,6 +38,8 @@
 import tech.pegasys.teku.validator.client.duties.DutyResult;
 import tech.pegasys.teku.validator.client.duties.DutyType;
 import tech.pegasys.teku.validator.client.duties.ProductionResult;
+import tech.pegasys.teku.validator.client.duties.ValidatorDutyMetrics;
+import tech.pegasys.teku.validator.client.duties.ValidatorDutyMetrics.Step;
 
 public class AttestationProductionDuty implements Duty {
   private static final Logger LOG = LogManager.getLogger();
@@ -48,18 +50,21 @@ public class AttestationProductionDuty implements Duty {
   private final ForkProvider forkProvider;
   private final ValidatorApiChannel validatorApiChannel;
   private final SendingStrategy<Attestation> sendingStrategy;
+  private final ValidatorDutyMetrics validatorDutyMetrics;
 
   public AttestationProductionDuty(
       final Spec spec,
       final UInt64 slot,
       final ForkProvider forkProvider,
       final ValidatorApiChannel validatorApiChannel,
-      final SendingStrategy<Attestation> sendingStrategy) {
+      final SendingStrategy<Attestation> sendingStrategy,
+      final ValidatorDutyMetrics validatorDutyMetrics) {
     this.spec = spec;
     this.slot = slot;
     this.forkProvider = forkProvider;
     this.validatorApiChannel = validatorApiChannel;
     this.sendingStrategy = sendingStrategy;
+    this.validatorDutyMetrics = validatorDutyMetrics;
   }
 
   @Override
@@ -121,7 +126,10 @@ private List<SafeFuture<ProductionResult<Attestation>>> produceAttestationsForCo
       final int committeeIndex,
       final ScheduledCommittee committee) {
     final SafeFuture<Optional<AttestationData>> unsignedAttestationFuture =
-        validatorApiChannel.createAttestationData(slot, committeeIndex);
+        validatorDutyMetrics.record(
+            () -> validatorApiChannel.createAttestationData(slot, committeeIndex),
+            this,
+            ValidatorDutyMetrics.Step.CREATE);
     unsignedAttestationFuture.propagateTo(committee.getAttestationDataFuture());
 
     return committee.getValidators().stream()
@@ -143,8 +151,14 @@ private SafeFuture<ProductionResult<Attestation>> signAttestationForValidatorInC
             maybeUnsignedAttestation ->
                 maybeUnsignedAttestation
                     .map(
-                        attestationData ->
-                            signAttestationForValidator(slot, forkInfo, attestationData, validator))
+                        attestationData -> {
+                          validateAttestationData(slot, attestationData);
+                          return validatorDutyMetrics.record(
+                              () ->
+                                  signAttestationForValidator(forkInfo, attestationData, validator),
+                              this,
+                              Step.SIGN);
+                        })
                     .orElseGet(
                         () ->
                             SafeFuture.completedFuture(
@@ -159,16 +173,19 @@ private SafeFuture<ProductionResult<Attestation>> signAttestationForValidatorInC
         .exceptionally(error -> ProductionResult.failure(validator.getPublicKey(), error));
   }
 
-  private SafeFuture<ProductionResult<Attestation>> signAttestationForValidator(
-      final UInt64 slot,
-      final ForkInfo forkInfo,
-      final AttestationData attestationData,
-      final ValidatorWithCommitteePositionAndIndex validator) {
+  private static void validateAttestationData(
+      final UInt64 slot, final AttestationData attestationData) {
     checkArgument(
         attestationData.getSlot().equals(slot),
         "Unsigned attestation slot (%s) does not match expected slot %s",
         attestationData.getSlot(),
         slot);
+  }
+
+  private SafeFuture<ProductionResult<Attestation>> signAttestationForValidator(
+      final ForkInfo forkInfo,
+      final AttestationData attestationData,
+      final ValidatorWithCommitteePositionAndIndex validator) {
     return validator
         .getSigner()
         .signAttestationData(attestationData, forkInfo)

validator/client/src/test/java/tech/pegasys/teku/validator/client/duties/AttestationProductionDutyTest.java

@@ -20,6 +20,7 @@
 import static org.mockito.ArgumentMatchers.argThat;
 import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.spy;
 import static org.mockito.Mockito.times;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.verifyNoInteractions;
@@ -39,6 +40,7 @@
 import tech.pegasys.teku.bls.BLSSignature;
 import tech.pegasys.teku.infrastructure.async.SafeFuture;
 import tech.pegasys.teku.infrastructure.logging.ValidatorLogger;
+import tech.pegasys.teku.infrastructure.metrics.StubMetricsSystem;
 import tech.pegasys.teku.infrastructure.ssz.collections.SszBitlist;
 import tech.pegasys.teku.infrastructure.unsigned.UInt64;
 import tech.pegasys.teku.spec.Spec;
@@ -54,6 +56,7 @@
 import tech.pegasys.teku.validator.api.ValidatorApiChannel;
 import tech.pegasys.teku.validator.client.ForkProvider;
 import tech.pegasys.teku.validator.client.Validator;
+import tech.pegasys.teku.validator.client.duties.ValidatorDutyMetrics.Step;
 import tech.pegasys.teku.validator.client.duties.attestations.AttestationProductionDuty;
 import tech.pegasys.teku.validator.client.duties.attestations.BatchAttestationSendingStrategy;
 
@@ -68,14 +71,17 @@ class AttestationProductionDutyTest {
   private final ForkProvider forkProvider = mock(ForkProvider.class);
   private final ValidatorApiChannel validatorApiChannel = mock(ValidatorApiChannel.class);
   private final ValidatorLogger validatorLogger = mock(ValidatorLogger.class);
+  private final ValidatorDutyMetrics validatorDutyMetrics =
+      spy(ValidatorDutyMetrics.create(new StubMetricsSystem()));
 
   private final AttestationProductionDuty duty =
       new AttestationProductionDuty(
           spec,
           SLOT,
           forkProvider,
           validatorApiChannel,
-          new BatchAttestationSendingStrategy<>(validatorApiChannel::sendSignedAttestations));
+          new BatchAttestationSendingStrategy<>(validatorApiChannel::sendSignedAttestations),
+          validatorDutyMetrics);
 
   @BeforeEach
   public void setUp() {
@@ -88,7 +94,7 @@ public void setUp() {
   public void shouldNotProduceAnyAttestationsWhenNoValidatorsAdded() {
     performAndReportDuty();
 
-    verifyNoInteractions(validatorApiChannel, validatorLogger);
+    verifyNoInteractions(validatorApiChannel, validatorLogger, validatorDutyMetrics);
   }
 
   @Test
@@ -109,6 +115,9 @@ public void shouldFailWhenUnsignedAttestationCanNotBeCreated() {
             eq(Set.of(validator.getPublicKey().toAbbreviatedString())),
             any(IllegalStateException.class));
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics)
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
   }
 
   @Test
@@ -154,6 +163,10 @@ public void shouldPublishProducedAttestationsWhenSomeUnsignedAttestationsCanNotB
             eq(Set.of(validator1.getPublicKey().toAbbreviatedString())),
             any(IllegalStateException.class));
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics, times(2))
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
+    verify(validatorDutyMetrics).record(any(), any(AttestationProductionDuty.class), eq(Step.SIGN));
   }
 
   @Test
@@ -198,6 +211,10 @@ public void shouldPublishProducedAttestationsWhenSomeUnsignedAttestationsFail()
     verify(validatorLogger)
         .dutyFailed(TYPE, SLOT, Set.of(validator1.getPublicKey().toAbbreviatedString()), failure);
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics, times(2))
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
+    verify(validatorDutyMetrics).record(any(), any(AttestationProductionDuty.class), eq(Step.SIGN));
   }
 
   @Test
@@ -237,6 +254,11 @@ public void shouldPublishProducedAttestationsWhenSignerFailsForSomeAttestations(
         .dutyFailed(
             TYPE, SLOT, Set.of(validator1.getPublicKey().toAbbreviatedString()), signingFailure);
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics)
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
+    verify(validatorDutyMetrics, times(2))
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.SIGN));
   }
 
   @Test
@@ -260,6 +282,10 @@ public void shouldCreateAttestationForSingleValidator() {
         .dutyCompleted(
             TYPE, SLOT, 1, Set.of(attestationData.getBeaconBlockRoot()), Optional.empty());
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics)
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
+    verify(validatorDutyMetrics).record(any(), any(AttestationProductionDuty.class), eq(Step.SIGN));
   }
 
   @Test
@@ -294,6 +320,10 @@ void shouldReportFailureWhenAttestationIsInvalid() {
                     error instanceof RestApiReportedException
                         && error.getMessage().equals("Naughty attestation")));
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics)
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
+    verify(validatorDutyMetrics).record(any(), any(AttestationProductionDuty.class), eq(Step.SIGN));
   }
 
   @SuppressWarnings("unchecked")
@@ -345,6 +375,11 @@ public void shouldCreateAttestationForMultipleValidatorsInSameCommittee() {
         .dutyCompleted(
             TYPE, SLOT, 3, Set.of(attestationData.getBeaconBlockRoot()), Optional.empty());
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics)
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
+    verify(validatorDutyMetrics, times(3))
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.SIGN));
   }
 
   @SuppressWarnings("unchecked")
@@ -406,6 +441,11 @@ public void shouldCreateAttestationForMultipleValidatorsInDifferentCommittees()
                 unsignedAttestation2.getBeaconBlockRoot()),
             Optional.empty());
     verifyNoMoreInteractions(validatorLogger);
+
+    verify(validatorDutyMetrics, times(2))
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.CREATE));
+    verify(validatorDutyMetrics, times(3))
+        .record(any(), any(AttestationProductionDuty.class), eq(Step.SIGN));
   }
 
   public Validator createValidator() {