WIP adding in timers for student orchestrator.

Author: SoLetsDev

api/src/main/java/ca/bc/gov/educ/penreg/api/orchestrator/PenReqBatchStudentOrchestrator.java

@@ -29,12 +29,14 @@
 import ca.bc.gov.educ.penreg.api.struct.PenRequestBatchStudentSagaData;
 import ca.bc.gov.educ.penreg.api.struct.PenRequestValidationIssue;
 import ca.bc.gov.educ.penreg.api.util.JsonUtil;
+import ca.bc.gov.educ.penreg.api.util.Stopwatch;
 import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.core.type.TypeReference;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import java.io.IOException;
 import java.util.List;
 import java.util.Optional;
+import java.util.UUID;
 import java.util.concurrent.TimeoutException;
 import java.util.stream.Collectors;
 import lombok.Getter;
@@ -111,12 +113,18 @@ public void populateStepsToExecuteMap() {
    * @throws JsonProcessingException the json processing exception
    */
   protected void validateStudentDemographics(final Event event, final Saga saga, final PenRequestBatchStudentSagaData penRequestBatchStudentSagaData) throws IOException, InterruptedException, TimeoutException {
+    UUID sagaId = saga.getSagaId();
+    Stopwatch validateStudentDemographics = new Stopwatch("validateStudentDemographics", sagaId);
+    Stopwatch updateAttachedSagaWithEvents = new Stopwatch("updateAttachedSagaWithEvents", sagaId);
+    validateStudentDemographics.start();
     final var scrubbedSagaData = this.getPenRequestBatchStudentOrchestratorService()
         .scrubPayload(penRequestBatchStudentSagaData);
     final SagaEvent eventStates = this.createEventState(saga, event.getEventType(), event.getEventOutcome(), event.getEventPayload());
     saga.setSagaState(VALIDATE_STUDENT_DEMOGRAPHICS.toString());
     saga.setPayload(JsonUtil.getJsonStringFromObject(scrubbedSagaData)); // update the payload with scrubbed values to use it in the saga process...
+    updateAttachedSagaWithEvents.start();
     this.getSagaService().updateAttachedSagaWithEvents(saga, eventStates);
+    updateAttachedSagaWithEvents.stop();
     final var validationPayload = validationMapper.toStudentDemogValidationPayload(scrubbedSagaData);
 
     validationPayload.setTransactionID(saga.getSagaId().toString());
@@ -133,6 +141,8 @@ protected void validateStudentDemographics(final Event event, final Saga saga, f
       log.error("event payload is not present this should not have happened. :: {}", saga.getSagaId());
     }
 
+    validateStudentDemographics.stop();
+
   }
 
   /**
@@ -148,6 +158,12 @@ protected void validateStudentDemographics(final Event event, final Saga saga, f
    * @throws TimeoutException     the timeout exception
    */
   protected void processPenMatchResults(final Event event, final Saga saga, final PenRequestBatchStudentSagaData penRequestBatchStudentSagaData) throws IOException, InterruptedException, TimeoutException {
+    UUID sagaId = saga.getSagaId();
+    Stopwatch processPenMatchResults = new Stopwatch("processPenMatchResults", sagaId);
+    Stopwatch updateAttachedSaga = new Stopwatch("updateAttachedSagaWithEvents", sagaId);
+    Stopwatch updateAttachedEntityDuringSaga = new Stopwatch("updateAttachedEntityDuringSagaProcess", sagaId);
+    processPenMatchResults.start();
+
     final Optional<Event> eventOptional;
     if (penRequestBatchStudentSagaData.getIsPENMatchResultsProcessed() == null || !penRequestBatchStudentSagaData.getIsPENMatchResultsProcessed()) {
       // this is necessary to check, to avoid duplicate execution during replay process.
@@ -156,13 +172,19 @@ protected void processPenMatchResults(final Event event, final Saga saga, final
       final var penMatchResult = JsonUtil.getJsonObjectFromString(PenMatchResult.class, event.getEventPayload());
       penRequestBatchStudentSagaData.setPenMatchResult(penMatchResult); // update the original payload with response from PEN_MATCH_API
       saga.setPayload(JsonUtil.getJsonStringFromObject(penRequestBatchStudentSagaData)); // save the updated payload to DB...
+
+      updateAttachedSaga.start();
       this.getSagaService().updateAttachedSagaWithEvents(saga, eventStates);
+      updateAttachedSaga.stop();
 
       eventOptional = this.getPenRequestBatchStudentOrchestratorService().processPenMatchResult(saga, penRequestBatchStudentSagaData, penMatchResult);
 
       penRequestBatchStudentSagaData.setIsPENMatchResultsProcessed(true);
       saga.setPayload(JsonUtil.getJsonStringFromObject(penRequestBatchStudentSagaData)); // save the updated payload to DB...
+
+      updateAttachedEntityDuringSaga.start();
       this.getSagaService().updateAttachedEntityDuringSagaProcess(saga);
+      updateAttachedEntityDuringSaga.stop();
     } else {
       eventOptional = Optional.of(Event.builder().sagaId(saga.getSagaId())
           .eventType(PROCESS_PEN_MATCH_RESULTS).eventOutcome(PEN_MATCH_RESULTS_PROCESSED).eventPayload(penRequestBatchStudentSagaData.getPenMatchResult().getPenStatus())
@@ -177,6 +199,8 @@ protected void processPenMatchResults(final Event event, final Saga saga, final
           .build());
     }
 
+    processPenMatchResults.stop();
+
   }
 
 
@@ -188,11 +212,21 @@ protected void processPenMatchResults(final Event event, final Saga saga, final
    * @param penRequestBatchStudentSagaData the pen request batch student saga data
    */
   protected void processPenMatch(final Event event, final Saga saga, final PenRequestBatchStudentSagaData penRequestBatchStudentSagaData) {
+    UUID sagaId = saga.getSagaId();
+    Stopwatch processPenMatch = new Stopwatch("processPenMatch", sagaId);
+    Stopwatch updateAttachedSagaWithEvents = new Stopwatch("updateAttachedSagaWithEvents", sagaId);
+    Stopwatch saveDemogValidationResults = new Stopwatch("saveDemogValidationResults", sagaId);
+    processPenMatch.start();
+
     final SagaEvent eventStates = this.createEventState(saga, event.getEventType(), event.getEventOutcome(), event.getEventPayload());
     saga.setSagaState(PROCESS_PEN_MATCH.toString());
+    updateAttachedSagaWithEvents.start();
     this.getSagaService().updateAttachedSagaWithEvents(saga, eventStates);
+    updateAttachedSagaWithEvents.stop();
     // need to persist the validation warnings from response payload.
+    saveDemogValidationResults.start();
     this.saveDemogValidationResults(event, penRequestBatchStudentSagaData);
+    saveDemogValidationResults.stop();
     final var eventPayload = JsonUtil.getJsonString(penMatchSagaMapper.toPenMatchStudent(penRequestBatchStudentSagaData));
     if (eventPayload.isPresent()) {
       final Event nextEvent = Event.builder().sagaId(saga.getSagaId())
@@ -206,6 +240,8 @@ protected void processPenMatch(final Event event, final Saga saga, final PenRequ
       log.error("event payload is not present this should not have happened. :: {}", saga.getSagaId());
     }
 
+    processPenMatch.stop();
+
   }
 
   /**
@@ -226,6 +262,10 @@ private void completePenRequestBatchStudentSaga(final Event event, final Saga sa
    * @param sagaData the saga data
    */
   protected void saveDemogValidationResults(final Event event, final PenRequestBatchStudentSagaData sagaData) {
+    UUID sagaId = event.getSagaId();
+    Stopwatch saveDemogValidationResults = new Stopwatch("saveDemogValidationResults", sagaId);
+    Stopwatch saveDemogValidationResultsAndUpdateStudentStatus = new Stopwatch("saveDemogValidationResultsAndUpdateStudentStatus", sagaId);
+    saveDemogValidationResults.start();
     if (event.getEventType() == VALIDATE_STUDENT_DEMOGRAPHICS
         && StringUtils.isNotBlank(event.getEventPayload())
         && !StringUtils.equalsIgnoreCase(VALIDATION_SUCCESS_NO_ERROR_WARNING.toString(), event.getEventPayload())) {
@@ -241,11 +281,15 @@ protected void saveDemogValidationResults(final Event event, final PenRequestBat
         final var validationResults = new ObjectMapper().readValue(event.getEventPayload(), responseType);
         if (!validationResults.isEmpty()) {
           final var mappedEntities = validationResults.stream().map(issueMapper::toModel).collect(Collectors.toList());
+          saveDemogValidationResultsAndUpdateStudentStatus.start();
           this.getPenRequestBatchStudentOrchestratorService().saveDemogValidationResultsAndUpdateStudentStatus(mappedEntities, statusCode, sagaData.getPenRequestBatchStudentID());
+          saveDemogValidationResultsAndUpdateStudentStatus.stop();
         }
       } catch (final JsonProcessingException ex) {
         log.error("json exception for :: {} {}", event.getSagaId().toString(), ex);
       }
+
+      saveDemogValidationResults.stop();
     }
   }
 }

api/src/main/java/ca/bc/gov/educ/penreg/api/util/Stopwatch.java

@@ -0,0 +1,25 @@
+package ca.bc.gov.educ.penreg.api.util;
+
+import java.util.UUID;
+import lombok.extern.slf4j.Slf4j;
+
+@Slf4j
+public class Stopwatch {
+    private long startTime;
+    private final String functionName;
+    private final UUID sagaId;
+
+  public Stopwatch(String functionName, UUID sagaId) {
+    this.functionName = functionName;
+    this.sagaId = sagaId;
+  }
+
+  public void start() {
+        startTime = System.nanoTime();
+    }
+
+    public void stop() {
+        long endTime = System.nanoTime();
+        log.info("function :: {} took {} milliseconds for sagaId {}", this.functionName, (endTime - this.startTime) / 10000000, this.sagaId);
+      }
+}