Add MicroBenchmarking Logs

Author: ndegwamartin

Diff for: plugins/src/main/java/com/google/fhir/gateway/plugin/BenchmarkingHelper.java

@@ -0,0 +1,53 @@
+/*
+ * Copyright 2021-2023 Google LLC
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *       http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package com.google.fhir.gateway.plugin;
+
+import org.slf4j.Logger;
+
+public class BenchmarkingHelper {
+  public static void printCompletedInDuration(long startTime, String methodDetails, Logger logger) {
+    long nanoSecondsTaken = System.nanoTime() - startTime;
+    long millSecondsTaken = nanoSecondsTaken / 1000000;
+    logger.error(
+        String.format(
+            "########## %s completed in %s : Metric in seconds - %d : Metric in nanoseconds - %d",
+            methodDetails,
+            getHumanDuration(millSecondsTaken),
+            millSecondsTaken / 1000,
+            nanoSecondsTaken));
+  }
+
+  public static String getHumanDuration(long milliseconds) {
+
+    long minutes = (milliseconds / 1000) / 60;
+    long seconds = (milliseconds / 1000) % 60;
+    String secondsStr = Long.toString(seconds);
+    String secs;
+    if (secondsStr.length() >= 2) {
+      secs = secondsStr.substring(0, 2);
+    } else {
+      secs = "0" + secondsStr;
+    }
+
+    return minutes == 0 && seconds == 0
+        ? "less than a second"
+        : minutes + " mins " + secs + " secs";
+  }
+
+  public static long startBenchmarking() {
+    return System.nanoTime();
+  }
+}

Diff for: plugins/src/main/java/com/google/fhir/gateway/plugin/OpenSRPHelper.java

@@ -1,3 +1,18 @@
+/*
+ * Copyright 2021-2023 Google LLC
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *       http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
 package com.google.fhir.gateway.plugin;
 
 import static org.smartregister.utils.Constants.EMPTY_STRING;
@@ -66,6 +81,9 @@ public PractitionerDetails getPractitionerDetailsByKeycloakId(String keycloakUUI
   }
 
   public Bundle getSupervisorPractitionerDetailsByKeycloakId(String keycloakUUID) {
+
+    long start = BenchmarkingHelper.startBenchmarking();
+
     Bundle bundle = new Bundle();
 
     logger.info("Searching for practitioner with identifier: " + keycloakUUID);
@@ -79,10 +97,18 @@ public Bundle getSupervisorPractitionerDetailsByKeycloakId(String keycloakUUID)
       logger.error("Practitioner with KC identifier: " + keycloakUUID + " not found");
     }
 
+    BenchmarkingHelper.printCompletedInDuration(
+        start,
+        "getSupervisorPractitionerDetailsByKeycloakId : params --> keycloakUUID=" + keycloakUUID,
+        logger);
+
     return bundle;
   }
 
   private Bundle getAttributedPractitionerDetailsByPractitioner(Practitioner practitioner) {
+
+    long start = BenchmarkingHelper.startBenchmarking();
+
     Bundle responseBundle = new Bundle();
     List<Practitioner> attributedPractitioners = new ArrayList<>();
     PractitionerDetails practitionerDetails = getPractitionerDetailsByPractitioner(practitioner);
@@ -112,6 +138,10 @@ private Bundle getAttributedPractitionerDetailsByPractitioner(Practitioner pract
 
     careTeamList.addAll(attributedCareTeams);
 
+    logger.error(
+        "##### OpenSRPHelper.getAttributedPractitionerDetailsByPractitioner() -> CareTeam List"
+            + attributedCareTeams);
+
     for (CareTeam careTeam : careTeamList) {
       // Add current supervisor practitioners
       attributedPractitioners.addAll(
@@ -139,11 +169,18 @@ private Bundle getAttributedPractitionerDetailsByPractitioner(Practitioner pract
 
     responseBundle.setEntry(bundleEntryComponentList);
     responseBundle.setTotal(bundleEntryComponentList.size());
+
+    BenchmarkingHelper.printCompletedInDuration(
+        start, "getAttributedPractitionerDetailsByPractitioner: params " + practitioner, logger);
+
     return responseBundle;
   }
 
   @NotNull
   public static List<String> getAttributedLocations(List<LocationHierarchy> locationHierarchies) {
+
+    long start = BenchmarkingHelper.startBenchmarking();
+
     List<ParentChildrenMap> parentChildrenList =
         locationHierarchies.stream()
             .flatMap(
@@ -159,6 +196,10 @@ public static List<String> getAttributedLocations(List<LocationHierarchy> locati
             .flatMap(parentChildren -> parentChildren.getChildIdentifiers().stream())
             .map(it -> getReferenceIDPart(it.toString()))
             .collect(Collectors.toList());
+
+    BenchmarkingHelper.printCompletedInDuration(
+        start, "getAttributedLocations " + locationHierarchies, logger);
+
     return attributedLocationsList;
   }
 
@@ -167,6 +208,8 @@ private List<String> getOrganizationIdsByLocationIds(List<String> attributedLoca
       return new ArrayList<>();
     }
 
+    long start = BenchmarkingHelper.startBenchmarking();
+
     Bundle organizationAffiliationsBundle =
         getFhirClientForR4()
             .search()
@@ -175,15 +218,21 @@ private List<String> getOrganizationIdsByLocationIds(List<String> attributedLoca
             .returnBundle(Bundle.class)
             .execute();
 
-    return organizationAffiliationsBundle.getEntry().stream()
-        .map(
-            bundleEntryComponent ->
-                getReferenceIDPart(
-                    ((OrganizationAffiliation) bundleEntryComponent.getResource())
-                        .getOrganization()
-                        .getReference()))
-        .distinct()
-        .collect(Collectors.toList());
+    List<String> organizationIDs =
+        organizationAffiliationsBundle.getEntry().stream()
+            .map(
+                bundleEntryComponent ->
+                    getReferenceIDPart(
+                        ((OrganizationAffiliation) bundleEntryComponent.getResource())
+                            .getOrganization()
+                            .getReference()))
+            .distinct()
+            .collect(Collectors.toList());
+
+    BenchmarkingHelper.printCompletedInDuration(
+        start, "getOrganizationIdsByLocationIds : params " + attributedLocationsList, logger);
+
+    return organizationIDs;
   }
 
   private String getPractitionerIdentifier(Practitioner practitioner) {
@@ -196,31 +245,33 @@ private String getPractitionerIdentifier(Practitioner practitioner) {
 
   private PractitionerDetails getPractitionerDetailsByPractitioner(Practitioner practitioner) {
 
+    long start = BenchmarkingHelper.startBenchmarking();
+
     PractitionerDetails practitionerDetails = new PractitionerDetails();
     FhirPractitionerDetails fhirPractitionerDetails = new FhirPractitionerDetails();
     String practitionerId = getPractitionerIdentifier(practitioner);
 
-    logger.info("Searching for care teams for practitioner with id: " + practitioner);
+    logger.error("Searching for care teams for practitioner with id: " + practitioner);
     Bundle careTeams = getCareTeams(practitionerId);
     List<CareTeam> careTeamsList = mapBundleToCareTeams(careTeams);
     fhirPractitionerDetails.setCareTeams(careTeamsList);
     fhirPractitionerDetails.setPractitioners(Arrays.asList(practitioner));
 
-    logger.info("Searching for Organizations tied with CareTeams: ");
+    logger.error("Searching for Organizations tied with CareTeams: ");
     List<String> careTeamManagingOrganizationIds =
         getManagingOrganizationsOfCareTeamIds(careTeamsList);
 
     Bundle careTeamManagingOrganizations = getOrganizationsById(careTeamManagingOrganizationIds);
-    logger.info("Managing Organization are fetched");
+    logger.error("Managing Organization are fetched");
 
     List<Organization> managingOrganizationTeams =
         mapBundleToOrganizations(careTeamManagingOrganizations);
 
-    logger.info("Searching for organizations of practitioner with id: " + practitioner);
+    logger.error("Searching for organizations of practitioner with id: " + practitioner);
 
     List<PractitionerRole> practitionerRoleList =
         getPractitionerRolesByPractitionerId(practitionerId);
-    logger.info("Practitioner Roles are fetched");
+    logger.error("Practitioner Roles are fetched");
 
     List<String> practitionerOrganizationIds =
         getOrganizationIdsByPractitionerRoles(practitionerRoleList);
@@ -237,13 +288,13 @@ private PractitionerDetails getPractitionerDetailsByPractitioner(Practitioner pr
     fhirPractitionerDetails.setPractitionerRoles(practitionerRoleList);
 
     Bundle groupsBundle = getGroupsAssignedToPractitioner(practitionerId);
-    logger.info("Groups are fetched");
+    logger.error("Groups are fetched");
 
     List<Group> groupsList = mapBundleToGroups(groupsBundle);
     fhirPractitionerDetails.setGroups(groupsList);
     fhirPractitionerDetails.setId(practitionerId);
 
-    logger.info("Searching for locations by organizations");
+    logger.error("Searching for locations by organizations");
 
     Bundle organizationAffiliationsBundle =
         getOrganizationAffiliationsByOrganizationIdsBundle(
@@ -259,17 +310,20 @@ private PractitionerDetails getPractitionerDetailsByPractitioner(Practitioner pr
 
     List<String> locationIds = getLocationIdsByOrganizationAffiliations(organizationAffiliations);
 
-    logger.info("Searching for location hierarchy list by locations identifiers");
+    logger.error("Searching for location hierarchy list by locations identifiers");
     List<LocationHierarchy> locationHierarchyList = getLocationsHierarchyByLocationIds(locationIds);
     fhirPractitionerDetails.setLocationHierarchyList(locationHierarchyList);
 
-    logger.info("Searching for locations by ids");
+    logger.error("Searching for locations by ids");
     List<Location> locationsList = getLocationsByIds(locationIds);
     fhirPractitionerDetails.setLocations(locationsList);
 
     practitionerDetails.setId(practitionerId);
     practitionerDetails.setFhirPractitionerDetails(fhirPractitionerDetails);
 
+    BenchmarkingHelper.printCompletedInDuration(
+        start, "getPractitionerDetailsByPractitioner : params " + practitioner, logger);
+
     return practitionerDetails;
   }
 
@@ -476,6 +530,8 @@ private List<OrganizationAffiliation> mapBundleToOrganizationAffiliation(
   private List<LocationHierarchy> getLocationsHierarchyByLocationIds(List<String> locationIds) {
     if (locationIds.isEmpty()) return new ArrayList<>();
 
+    long start = BenchmarkingHelper.startBenchmarking();
+
     Bundle bundle =
         getFhirClientForR4()
             .search()
@@ -484,9 +540,15 @@ private List<LocationHierarchy> getLocationsHierarchyByLocationIds(List<String>
             .returnBundle(Bundle.class)
             .execute();
 
-    return bundle.getEntry().stream()
-        .map(it -> ((LocationHierarchy) it.getResource()))
-        .collect(Collectors.toList());
+    List<LocationHierarchy> locationHierarchies =
+        bundle.getEntry().stream()
+            .map(it -> ((LocationHierarchy) it.getResource()))
+            .collect(Collectors.toList());
+
+    BenchmarkingHelper.printCompletedInDuration(
+        start, "getLocationsHierarchyByLocationIds : params " + locationIds, logger);
+
+    return locationHierarchies;
   }
 
   public static String createSearchTagValues(Map.Entry<String, String[]> entry) {

Diff for: plugins/src/main/java/com/google/fhir/gateway/plugin/OpenSRPSyncAccessDecision.java

@@ -108,6 +108,8 @@ public boolean canAccess() {
   @Override
   public RequestMutation getRequestMutation(RequestDetailsReader requestDetailsReader) {
 
+    long start = BenchmarkingHelper.startBenchmarking();
+
     RequestMutation requestMutation = null;
     if (isSyncUrl(requestDetailsReader)) {
       if (locationIds.isEmpty() && careTeamIds.isEmpty() && organizationIds.isEmpty()) {
@@ -137,6 +139,14 @@ public RequestMutation getRequestMutation(RequestDetailsReader requestDetailsRea
       }
     }
 
+    BenchmarkingHelper.printCompletedInDuration(
+        start,
+        "getRequestMutation: params by RequestDetailReader "
+            + requestDetailsReader.getRequestType()
+            + " /"
+            + requestDetailsReader.getRequestPath(),
+        logger);
+
     return requestMutation;
   }
 
@@ -162,6 +172,8 @@ private List<String> addSyncFilters(Map<String, String[]> syncTags) {
   public String postProcess(RequestDetailsReader request, HttpResponse response)
       throws IOException {
 
+    long start = BenchmarkingHelper.startBenchmarking();
+
     String resultContent = null;
     Resource resultContentBundle;
     String gatewayMode = request.getHeader(Constants.FHIR_GATEWAY_MODE);
@@ -197,6 +209,12 @@ public String postProcess(RequestDetailsReader request, HttpResponse response)
           fhirR4Context.newJsonParser().encodeResourceToString(practitionerDetailsBundle);
     }
 
+    BenchmarkingHelper.printCompletedInDuration(
+        start,
+        "postProcess : params include Gateway mode "
+            + (gatewayMode != null ? gatewayMode : "Default"),
+        logger);
+
     return resultContent;
   }