Overview

This document has been created to show performance of requisition initiate endpoint. The document contains:

• an example execution of the endpoint on UI,
• how long each method in the requisition service was executed,
• where the endpoint takes too much time,
• proposal solutions.

Test environment

The test was executed on the following machine:

Both OpenLMIS instance and PostgreSQL database are on the same machine. In the database there is about 99,096 requisitions in the RELEASE status. A user has only rights to create and authorize requisitions. In this test the user will try to create a new requisition for the given program and supervised facility. The following java options has been set for the requisition service to connect with the service by JMX: 

-Dlogging.config=/config/log/logback.xml -Dflyway.locations=classpath:db/migration -Dcom.sun.management.jmxremote.port=9010 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.rmi.port=9010 -Djava.rmi.server.hostname=IP_ADDRESS

Endpoint execution

The endpoint is executed each time when a user clicks on Proceed button on Create/Authorize view and the status of a requisition is equal to "Not yet started". To display the button the user has to select Create/Authorize option in the navigation bar (in the Requisition section). On this view he or she has ability to select if want to create a requisition for home facility or supervised facility. For both cases the user has ability to select a program. After that the user has to click the Search button. The table will be shown and user will have ability to initiate a requisition for the last free period. A period is free when there is no a requisition for the given facility, program and period.

The above image presents execution time of the initiate endpoint. It took 34.85 seconds to initiate a new requisition. The request response is not used on UI. After response the UI move to other view (product grid view) which retrieve the initiated requisition one more time.

Methods

The following image presents a list of methods that has been used while the user initiate requisition. The visualvm tool has been used to capture those methods. The tool was configured to capture only methods from org.openlmis package and sub-packages in the requisition service.

In the above example the initiate endpoint was executed in 34.85s. It takes about 21 seconds (another 21 seconds has been used by other endpoint) to retrieve single objects from the reference-data service. It's quite interesting that the service needed about 9 seconds to retrieve the last regular requisition. We create a single SQL query and execute it. The issue may be in fact that we join two tables and the join operation can be time consuming.

The following image presents only methods that has been executed with the initiate endpoint:

We can see that the check permission method was quite fast but still retrieving last regular requisition takes about 8 seconds.

Code

The code that is used to create a new requisition is long and split into few methods and classes:

Requisition Controller

public RequisitionDto initiate(@RequestParam(value = "program") UUID program,
                  @RequestParam(value = "facility") UUID facility,
                  @RequestParam(value = "suggestedPeriod", required = false) UUID suggestedPeriod,
                  @RequestParam(value = "emergency") boolean emergency) {
  if (null == facility || null == program) {
    throw new ValidationMessageException(
        new Message(MessageKeys.ERROR_INITIALIZE_MISSING_PARAMETERS));
  }

  permissionService.canInitRequisition(program, facility);
  facilitySupportsProgramHelper.checkIfFacilitySupportsProgram(facility, program);

  Requisition newRequisition = requisitionService
      .initiate(program, facility, suggestedPeriod, emergency);
  return requisitionDtoBuilder.build(newRequisition);
}

Most important things:

• Line 172: check whether a user has permission to initiate a requisition for the given program and facility. The service needs to call the reference-data service endpoint to check that,
• Line 173: check if the given facility supports program. The method retrieves facility data from the reference-data service (based on facility id from the request),
• Line 175/176: the most important part of this endpoint. Details below,
• Line 177: build DTO object based on business object. We don't use this object on UI. The created requisition is retrieved second time when the view is changed.

Requisition Service

public Requisition initiate(UUID programId, UUID facilityId, UUID suggestedPeriodId,
                            boolean emergency) {
  Requisition requisition = RequisitionBuilder.newRequisition(
      facilityId, programId, emergency);
  requisition.setStatus(RequisitionStatus.INITIATED);

  ProcessingPeriodDto period = periodService
      .findPeriod(programId, facilityId, suggestedPeriodId, emergency);

  requisition.setProcessingPeriodId(period.getId());
  requisition.setNumberOfMonthsInPeriod(period.getDurationInMonths());

  FacilityDto facility = facilityReferenceDataService.findOne(facilityId);
  ProgramDto program = programReferenceDataService.findOne(programId);

  Collection<ApprovedProductDto> approvedProducts =
      approvedProductReferenceDataService.getApprovedProducts(
          facility.getId(), program.getId(), true);

  RequisitionTemplate requisitionTemplate = findRequisitionTemplate(programId);

  int numberOfPreviousPeriodsToAverage;
  List<Requisition> previousRequisitions;
  // numberOfPeriodsToAverage is always >= 2 or null
  if (requisitionTemplate.getNumberOfPeriodsToAverage() == null) {
    numberOfPreviousPeriodsToAverage = 0;
    previousRequisitions = getRecentRequisitions(requisition, 1);
  } else {
    numberOfPreviousPeriodsToAverage = requisitionTemplate.getNumberOfPeriodsToAverage() - 1;
    previousRequisitions =
        getRecentRequisitions(requisition, numberOfPreviousPeriodsToAverage);
  }

  if (numberOfPreviousPeriodsToAverage > previousRequisitions.size()) {
    numberOfPreviousPeriodsToAverage = previousRequisitions.size();
  }

  ProofOfDeliveryDto pod = getProofOfDeliveryDto(emergency, requisition);

  requisition.initiate(requisitionTemplate, approvedProducts, previousRequisitions,
      numberOfPreviousPeriodsToAverage, pod, authenticationHelper.getCurrentUser().getId());

  requisition.setAvailableNonFullSupplyProducts(approvedProductReferenceDataService
      .getApprovedProducts(facility.getId(), program.getId(), false)
      .stream()
      .map(ap -> ap.getOrderable().getId())
      .collect(Collectors.toSet()));

  requisitionRepository.save(requisition);
  return requisition;
}

Most important things:

• Line 162/163: use period service to find appropriate processing period for the new requisition. Details below,
• Line 168: the method retrieves facility data from the reference-data service (the same data as in the controller layer),
• Lines 177-191: the method try to find previous requisitions (based on setting from template). Full requisitions objects are retrieved from database. Details below,
• Line 193: retrieve Proof of Delivery object from the fulfillment service,
• Lines 198-202: retrieve all non full supply products for the given program and facility.

private List<Requisition> getRecentRequisitions(Requisition requisition, int amount) {
  List<ProcessingPeriodDto> previousPeriods =
      periodService.findPreviousPeriods(requisition.getProcessingPeriodId(), amount);

  List<Requisition> recentRequisitions = new ArrayList<>();
  for (ProcessingPeriodDto period : previousPeriods) {
    List<Requisition> requisitionsByPeriod = getRequisitionsByPeriod(requisition, period);
    if (!requisitionsByPeriod.isEmpty()) {
      Requisition requisitionByPeriod = requisitionsByPeriod.get(0);
      recentRequisitions.add(requisitionByPeriod);
    }
  }
  return recentRequisitions;
}

Most important things:

• Line 582/583: use period service to find previous periods. Amount parameter depends on property from the requisition template. Details below,
• Lines 585-592: find requisitions with the given facility, program and period (full object is retrieved here!).

Period service

public ProcessingPeriodDto findPeriod(UUID programId, UUID facilityId, UUID suggestedPeriodId,
                                      Boolean emergency) {
  ProcessingPeriodDto period;

  if (emergency) {
    List<ProcessingPeriodDto> periods = getCurrentPeriods(programId, facilityId);

    if (periods.isEmpty()) {
      throw new ValidationMessageException(new Message(ERROR_INCORRECT_SUGGESTED_PERIOD));
    }

    period = periods.get(0);
  } else {
    period = findTheOldestPeriod(programId, facilityId);
  }

  if (period == null
      || (null != suggestedPeriodId && !suggestedPeriodId.equals(period.getId()))) {
    throw new ValidationMessageException(new Message(
        ERROR_PERIOD_SHOULD_BE_OLDEST_AND_NOT_ASSOCIATED));
  }

  Collection<ProcessingScheduleDto> schedules =
      scheduleReferenceDataService.searchByProgramAndFacility(programId, facilityId);

  if (schedules == null || schedules.isEmpty()) {
    throw new ContentNotFoundMessageException(new Message(
        ERROR_REQUISITION_GROUP_PROGRAM_SCHEDULE_WITH_PROGRAM_AND_FACILITY_NOT_FOUND));
  }

  ProcessingScheduleDto scheduleDto = schedules.iterator().next();

  if (!scheduleDto.getId().equals(period.getProcessingSchedule().getId())) {
    throw new ValidationMessageException(new Message(
        ERROR_PERIOD_MUST_BELONG_TO_THE_SAME_SCHEDULE));
  }

  return period;
}

Most important things:

• Line 195: retrieve current periods for emergency requisition. The method retrieves all periods based on program and facility. It filters retrieved list by finding only periods that are in the current date. For example if currently we have 10th November 2016 then only periods that have start date before (or equal to) current date and end date after (or equal to) current date will be accepted.
• Line 203: find the oldest period for regular requisition. Retrieve last regular requisition (full object!), retrieve all periods based on program and facility, for each period try to find requisition (full object!). Select period that has no requisition (so retrieved requisitions are basically not used).
• Line 212/213: find processing schedule based on program and facility, only to check if it exists.

public List<ProcessingPeriodDto> findPreviousPeriods(UUID periodId, int amount) {
  // retrieve data from reference-data
  ProcessingPeriodDto period = getPeriod(periodId);

  if (null == period) {
    return Collections.emptyList();
  }

  Collection<ProcessingPeriodDto> collection = search(
      period.getProcessingSchedule().getId(), period.getStartDate()
  );

  if (null == collection || collection.isEmpty()) {
    return Collections.emptyList();
  }

  // create a list...
  List<ProcessingPeriodDto> list = new ArrayList<>(collection);
  // ...remove the latest period from the list...
  list.removeIf(p -> p.getId().equals(periodId));
  // .. and sort elements by startDate property DESC.
  list.sort((one, two) -> ObjectUtils.compare(two.getStartDate(), one.getStartDate()));

  if (amount > list.size()) {
    return list;
  }
  return list.subList(0, amount);
}

Most important things:

• Line 150: retrieve single processing period based on ID,
• Line 156/157/158: find all periods based on processing schedule and start date,
• Line 169: the list has been sorted by start date.

Scalyr

Additional I checked the system usage when the requisition initiate endpoint is executed. This time I used our training server where there are more than 90,000 requisitions in RELEASED status. After 15 minutes a user gets 504 error message from backend. It seems like there is no big problem with CPU, disk, memory or network usage. There are two spikes in the CPU usage but they are quickly end. The disk and memory usage is on the same level during the initiation process. The network bandwidth shows that a lot of data have been received by the system while the OpenLMIS tried to create a new requisition for the given facility and program.

Solutions

• Modify domain object that they will not retrieve related data automatically for example a requisition should not retrieve related line items,
• Try to retrieve the given object only one time, for example currently facility object is retrieved two times,
• Return only main information about a requisition to the client,
• Avoid retrieving data from database only to check if those data exists,