increase logging for duplicates

Author: alexmcdermid

api/src/main/java/ca/bc/gov/educ/studentdatacollection/api/controller/v1/CollectionController.java

@@ -131,7 +131,11 @@ public MonitorIndySdcSchoolCollectionsResponse getMonitorIndySdcSchoolCollection
 
   @Override
   public List<String> findDuplicatesInCollection(UUID collectionID, List<String> matchedAssignedIDs) {
-    return this.collectionService.findDuplicatesInCollection(collectionID, matchedAssignedIDs);
+    long startTime = System.currentTimeMillis();
+    log.info("CollectionController::findDuplicatesInCollection: Received request for collectionID :: {} with {} assignedIDs", collectionID, matchedAssignedIDs.size());
+    List<String> result = this.collectionService.findDuplicatesInCollection(collectionID, matchedAssignedIDs);
+    log.info("CollectionController::findDuplicatesInCollection: Completed in {} ms for collectionID :: {}. Returned {} duplicates", System.currentTimeMillis() - startTime, collectionID, result.size());
+    return result;
   }
 
   private void validatePayload(Supplier<List<FieldError>> validator) {

api/src/main/java/ca/bc/gov/educ/studentdatacollection/api/controller/v1/SdcDistrictCollectionController.java

@@ -20,13 +20,15 @@
 import org.springframework.data.jpa.domain.Specification;
 import org.springframework.http.ResponseEntity;
 import org.springframework.web.bind.annotation.RestController;
+import lombok.extern.slf4j.Slf4j;
 
 import java.util.ArrayList;
 import java.util.List;
 import java.util.UUID;
 import java.util.concurrent.CompletableFuture;
 
 @RestController
+@Slf4j
 public class SdcDistrictCollectionController implements SdcDistrictCollectionEndpoint {
 
   private static final SdcDistrictCollectionMapper mapper = SdcDistrictCollectionMapper.mapper;
@@ -57,7 +59,11 @@ public List<SdcDuplicate> getDistrictCollectionDuplicates(UUID sdcDistrictCollec
 
   @Override
   public List<SdcDuplicate> getDistrictCollectionProvincialDuplicates(UUID sdcDistrictCollectionID) {
-    return this.sdcDuplicatesService.getAllProvincialDuplicatesBySdcDistrictCollectionID(sdcDistrictCollectionID).stream().map(duplicateMapper::toSdcDuplicate).toList();
+    long startTime = System.currentTimeMillis();
+    log.info("getDistrictCollectionProvincialDuplicates: Received request for sdcDistrictCollectionID :: {}", sdcDistrictCollectionID);
+    List<SdcDuplicate> result = this.sdcDuplicatesService.getAllProvincialDuplicatesBySdcDistrictCollectionID(sdcDistrictCollectionID).stream().map(duplicateMapper::toSdcDuplicate).toList();
+    log.info("getDistrictCollectionProvincialDuplicates: Completed in {} ms for sdcDistrictCollectionID :: {}. Returned {} duplicates", System.currentTimeMillis() - startTime, sdcDistrictCollectionID, result.size());
+    return result;
   }
 
   @Override

api/src/main/java/ca/bc/gov/educ/studentdatacollection/api/controller/v1/SdcDuplicateController.java

@@ -63,7 +63,11 @@ public ResponseEntity<Void> markPENForReview(SdcSchoolCollectionStudent sdcSchoo
 
   @Override
   public List<SdcDuplicate> getSchoolCollectionProvincialDuplicates(UUID sdcSchoolCollectionID) {
-    return this.sdcDuplicatesService.getAllProvincialDuplicatesBySdcSchoolCollectionID(sdcSchoolCollectionID).stream().map(duplicateMapper::toSdcDuplicate).toList();
+    long startTime = System.currentTimeMillis();
+    log.info("getSchoolCollectionProvincialDuplicates: Received request for sdcSchoolCollectionID :: {}", sdcSchoolCollectionID);
+    List<SdcDuplicate> result = this.sdcDuplicatesService.getAllProvincialDuplicatesBySdcSchoolCollectionID(sdcSchoolCollectionID).stream().map(duplicateMapper::toSdcDuplicate).toList();
+    log.info("getSchoolCollectionProvincialDuplicates: Completed in {} ms for sdcSchoolCollectionID :: {}. Returned {} duplicates", System.currentTimeMillis() - startTime, sdcSchoolCollectionID, result.size());
+    return result;
   }
 
   @Override

api/src/main/java/ca/bc/gov/educ/studentdatacollection/api/service/v1/CollectionService.java

@@ -18,6 +18,7 @@
 import ca.bc.gov.educ.studentdatacollection.api.util.TransformUtil;
 import lombok.AccessLevel;
 import lombok.Getter;
+import lombok.extern.slf4j.Slf4j;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.stereotype.Service;
 import org.springframework.transaction.annotation.Propagation;
@@ -26,6 +27,7 @@
 import java.util.*;
 
 @Service
+@Slf4j
 public class CollectionService {
 
   @Getter(AccessLevel.PRIVATE)
@@ -209,9 +211,14 @@ private boolean isStatusConfirmed(String statusCode, String... confirmedStatuses
   }
 
   public List<String> findDuplicatesInCollection(UUID collectionID, List<String> matchedAssignedIDs) {
+    long startTime = System.currentTimeMillis();
+    log.info("CollectionService::findDuplicatesInCollection: Starting for collectionID :: {} with {} assignedIDs", collectionID, matchedAssignedIDs.size());
     List<UUID> matchedAssignedUUIDs = matchedAssignedIDs.stream().map(UUID::fromString).toList();
     List<SdcSchoolCollectionStudentEntity> duplicateStudents = sdcSchoolCollectionStudentRepository.findAllDuplicateStudentsByCollectionID(collectionID, matchedAssignedUUIDs);
-    return duplicateStudents.stream().map(s -> s.getAssignedStudentId().toString()).toList();
+    log.info("CollectionService::findDuplicatesInCollection: DB query took {} ms, found {} duplicate students for collectionID :: {}", System.currentTimeMillis() - startTime, duplicateStudents.size(), collectionID);
+    List<String> result = duplicateStudents.stream().map(s -> s.getAssignedStudentId().toString()).toList();
+    log.info("CollectionService::findDuplicatesInCollection: Completed in {} ms for collectionID :: {}", System.currentTimeMillis() - startTime, collectionID);
+    return result;
   }
 
   public List<SdcSchoolCollectionEntity> getSchoolCollectionsInCollection(UUID collectionID){

api/src/main/java/ca/bc/gov/educ/studentdatacollection/api/service/v1/SdcDuplicatesService.java

@@ -77,14 +77,26 @@ public List<SdcSchoolCollectionStudentLightEntity> findAllInProvinceDuplicateStu
   }
 
   public List<SdcDuplicateEntity> getAllProvincialDuplicatesBySdcDistrictCollectionID(UUID sdcDistrictCollectionID) {
+    long startTime = System.currentTimeMillis();
+    log.info("getAllProvincialDuplicatesBySdcDistrictCollectionID: Starting provincial duplicates retrieval for sdcDistrictCollectionID :: {}", sdcDistrictCollectionID);
     var districtCollection = sdcDistrictCollectionRepository.findById(sdcDistrictCollectionID).orElseThrow(() -> new EntityNotFoundException(SdcDistrictCollectionEntity.class, "sdcDistrictCollectionEntity", sdcDistrictCollectionID.toString()));
+
+    long idQueryStart = System.currentTimeMillis();
     List<UUID> ids = sdcSchoolCollectionStudentRepository.findAllInProvinceDuplicateStudentIdsInSdcDistrictCollection(districtCollection.getCollectionEntity().getCollectionID(), sdcDistrictCollectionID);
+    log.info("getAllProvincialDuplicatesBySdcDistrictCollectionID: DB query findAllInProvinceDuplicateStudentIdsInSdcDistrictCollection took {} ms, found {} IDs for sdcDistrictCollectionID :: {}", System.currentTimeMillis() - idQueryStart, ids.size(), sdcDistrictCollectionID);
+
+    List<SdcSchoolCollectionStudentLightEntity> provinceDupes;
+    if (ids.isEmpty()) {
+      provinceDupes = List.of();
+    } else {
+      long entityQueryStart = System.currentTimeMillis();
+      provinceDupes = sdcSchoolCollectionStudentLightRepository.findAllById(ids);
+      log.info("getAllProvincialDuplicatesBySdcDistrictCollectionID: DB query findAllById took {} ms, fetched {} light entities for sdcDistrictCollectionID :: {}", System.currentTimeMillis() - entityQueryStart, provinceDupes.size(), sdcDistrictCollectionID);
+    }
 
-    List<SdcSchoolCollectionStudentLightEntity> provinceDupes = ids.isEmpty()
-            ? List.of()
-            : sdcSchoolCollectionStudentLightRepository.findAllById(ids);
-    
+    long generateStart = System.currentTimeMillis();
     var dupes = generateFinalDuplicatesSet(provinceDupes, DuplicateLevelCode.PROVINCIAL);
+    log.info("getAllProvincialDuplicatesBySdcDistrictCollectionID: generateFinalDuplicatesSet took {} ms, produced {} duplicates for sdcDistrictCollectionID :: {}", System.currentTimeMillis() - generateStart, dupes.size(), sdcDistrictCollectionID);
 
     var finalSet = new HashSet<SdcDuplicateEntity>();
     dupes.forEach(dupe -> {
@@ -95,14 +107,22 @@ public List<SdcDuplicateEntity> getAllProvincialDuplicatesBySdcDistrictCollectio
       });
     });
 
+    log.info("getAllProvincialDuplicatesBySdcDistrictCollectionID: Completed in {} ms for sdcDistrictCollectionID :: {}. Total duplicates found :: {}", System.currentTimeMillis() - startTime, sdcDistrictCollectionID, finalSet.size());
     return finalSet.stream().toList();
   }
 
   public List<SdcDuplicateEntity> getAllProvincialDuplicatesBySdcSchoolCollectionID(UUID sdcSchoolCollectionID) {
+    long startTime = System.currentTimeMillis();
+    log.info("getAllProvincialDuplicatesBySdcSchoolCollectionID: Starting provincial duplicates retrieval for sdcSchoolCollectionID :: {}", sdcSchoolCollectionID);
     var schoolCollection = sdcSchoolCollectionRepository.findById(sdcSchoolCollectionID).orElseThrow(() -> new EntityNotFoundException(SdcSchoolCollectionEntity.class, "sdcSchoolCollectionEntity", sdcSchoolCollectionID.toString()));
+
+    long dbQueryStart = System.currentTimeMillis();
     List<SdcSchoolCollectionStudentLightEntity> provinceDupes = sdcSchoolCollectionStudentRepository.findAllInProvinceDuplicateStudentsInSdcSchoolCollection(schoolCollection.getCollectionEntity().getCollectionID(), sdcSchoolCollectionID);
+    log.info("getAllProvincialDuplicatesBySdcSchoolCollectionID: DB query findAllInProvinceDuplicateStudentsInSdcSchoolCollection took {} ms, found {} students for sdcSchoolCollectionID :: {}", System.currentTimeMillis() - dbQueryStart, provinceDupes.size(), sdcSchoolCollectionID);
 
+    long generateStart = System.currentTimeMillis();
     var dupes = generateFinalDuplicatesSet(provinceDupes, DuplicateLevelCode.PROVINCIAL);
+    log.info("getAllProvincialDuplicatesBySdcSchoolCollectionID: generateFinalDuplicatesSet took {} ms, produced {} duplicates for sdcSchoolCollectionID :: {}", System.currentTimeMillis() - generateStart, dupes.size(), sdcSchoolCollectionID);
 
     var finalSet = new HashSet<SdcDuplicateEntity>();
     dupes.forEach(dupe -> {
@@ -113,6 +133,7 @@ public List<SdcDuplicateEntity> getAllProvincialDuplicatesBySdcSchoolCollectionI
       });
     });
 
+    log.info("getAllProvincialDuplicatesBySdcSchoolCollectionID: Completed in {} ms for sdcSchoolCollectionID :: {}. Total duplicates found :: {}", System.currentTimeMillis() - startTime, sdcSchoolCollectionID, finalSet.size());
     return finalSet.stream().toList();
   }
 
@@ -205,7 +226,7 @@ public void generateAllProvincialDuplicates(UUID collectionID){
 
     List<SdcSchoolCollectionStudentLightEntity> provinceDupes = findAllInProvinceDuplicateStudentsInCollection(collectionID);
 
-    List<SdcDuplicateEntity> finalDuplicatesSet =  generateFinalDuplicatesSet(provinceDupes, DuplicateLevelCode.PROVINCIAL);
+    List<SdcDuplicateEntity> finalDuplicatesSet = generateFinalDuplicatesSet(provinceDupes, DuplicateLevelCode.PROVINCIAL);
     sdcDuplicateRepository.saveAll(finalDuplicatesSet);
 
     this.collectionRepository.updateCollectionStatus(collectionID, String.valueOf(CollectionStatus.PROVDUPES));
@@ -244,12 +265,17 @@ public void generateAllProvincialDuplicates(UUID collectionID){
   }
 
   public List<SdcDuplicateEntity> generateFinalDuplicatesSet(List<SdcSchoolCollectionStudentLightEntity> duplicateStudentEntities, DuplicateLevelCode duplicateLevelCode) {
+    long startTime = System.currentTimeMillis();
+    log.info("generateFinalDuplicatesSet: Starting with {} students at level :: {}", duplicateStudentEntities.size(), duplicateLevelCode);
     HashMap<UUID, List<SdcSchoolCollectionStudentLightEntity>> groupedDups = new HashMap<>();
 
     for (SdcSchoolCollectionStudentLightEntity student : duplicateStudentEntities) {
       groupedDups.computeIfAbsent(student.getAssignedStudentId(), k -> new ArrayList<>()).add(student);
     }
+    log.info("generateFinalDuplicatesSet: Grouped into {} unique assigned student IDs in {} ms", groupedDups.size(), System.currentTimeMillis() - startTime);
+
     List<SdcDuplicateEntity> finalDuplicatesSet = new ArrayList<>();
+    int pairsChecked = 0;
 
     for (List<SdcSchoolCollectionStudentLightEntity> group : groupedDups.values()) {
       for (int i = 0; i < group.size(); i++) {
@@ -258,10 +284,12 @@ public List<SdcDuplicateEntity> generateFinalDuplicatesSet(List<SdcSchoolCollect
           SdcSchoolCollectionStudentLightEntity entity2 = group.get(j);
           List<SdcDuplicateEntity> duplicateRecords = runDuplicatesCheck(duplicateLevelCode, entity1, entity2);
           finalDuplicatesSet.addAll(duplicateRecords);
+          pairsChecked++;
         }
       }
     }
 
+    log.info("generateFinalDuplicatesSet: Completed in {} ms. Checked {} pairs, generated {} duplicate records at level :: {}", System.currentTimeMillis() - startTime, pairsChecked, finalDuplicatesSet.size(), duplicateLevelCode);
     return finalDuplicatesSet;
   }
 
@@ -346,6 +374,7 @@ public Set<String> pluckEmailAddressesFromDistrict(List<EdxUser> edxUsers){
   }
 
   public List<SdcDuplicateEntity> runDuplicatesCheck(DuplicateLevelCode level, SdcSchoolCollectionStudentLightEntity entity1, SdcSchoolCollectionStudentLightEntity entity2){
+    long startTime = System.currentTimeMillis();
     List<SdcDuplicateEntity> dups = new ArrayList<>();
     SchoolTombstone schoolTombstone1 = restUtils.getSchoolBySchoolID(entity1.getSdcSchoolCollectionEntitySchoolID().toString()).orElseThrow(() ->
             new StudentDataCollectionAPIRuntimeException("School provided by ID " + entity1.getSdcSchoolCollectionEntitySchoolID() + "was not found - this is not expected"));
@@ -427,10 +456,13 @@ public List<SdcDuplicateEntity> runDuplicatesCheck(DuplicateLevelCode level, Sdc
       }
     }
 
+    log.debug("runDuplicatesCheck: Completed in {} ms for assignedStudentId :: {}. Found {} duplicates at level :: {}", System.currentTimeMillis() - startTime, entity1.getAssignedStudentId(), dups.size(), level);
     return dups;
   }
 
   private List<SdcDuplicateEntity> generateProgramDuplicates(List<SdcDuplicateEntity> newDuplicates, SdcSchoolCollectionStudentLightEntity student1, SdcSchoolCollectionStudentLightEntity student2, DuplicateLevelCode level) {
+    long startTime = System.currentTimeMillis();
+    int initialSize = newDuplicates.size();
     List<String> student1Programs = validationRulesService.splitEnrolledProgramsString(student1.getEnrolledProgramCodes());
     List<String> student2Programs = validationRulesService.splitEnrolledProgramsString(student2.getEnrolledProgramCodes());
 
@@ -461,6 +493,7 @@ private List<SdcDuplicateEntity> generateProgramDuplicates(List<SdcDuplicateEnti
       newDuplicates.add(generateDuplicateEntity(level, student1, student2, DuplicateTypeCode.PROGRAM, DuplicateSeverityCode.NON_ALLOWABLE, ProgramDuplicateTypeCode.CAREER, null));
     }
 
+    log.debug("generateProgramDuplicates: Completed in {} ms for assignedStudentId :: {}. Added {} program duplicates at level :: {}", System.currentTimeMillis() - startTime, student1.getAssignedStudentId(), newDuplicates.size() - initialSize, level);
     return newDuplicates;
   }