Overview

This document has been created to show poor performance of requisition submit/save endpoints. It contains:

an example execution of the endpoints on the UI,
how long it took for methods in the requisition service to execute,
where the endpoints take too much time,
proposal solutions.

Test environment

The tests were executed on EC2 m4.large instance (except for visualvm samples which were captured locally). The selected requisition contains over 230 products, most of which were skipped.

Endpoint execution

After clicking "Submit" we can see the following requests being executed:

The ones worth noting are:

PUT /api/requisitions/<id>, which took 22.86s
POST /api/requisitions/<id>/submit, 20.54s
These are the endpoints we are interested in. Their responses contain over 1000 non full supply products and over 230 requisition line items. We will look into what took so long in the next paragraph.
GET /api/requisitions/periodsForInitiate, 1.94s
GET /api/requisitions/search, 1.9m
These endpoints are executed when the UI goes back to the previous state (Create/authorize list).

Scalyr also shows a spike in CPU, Network and Disk bandwidth usage:

Methods

The following images present a list of methods that have been used while saving and submitting the requisition. The requests were sent through Swagger UI and no other endpoints were called during that time. 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.

Save

Submit

The above examples show that most of the time was consumed by RequisitionDtoBuilder to construct the response.

Code

RequisitionController

public RequisitionDto updateRequisition(@RequestBody RequisitionDto requisitionDto,
                                        @PathVariable("id") UUID requisitionId) {
  permissionService.canUpdateRequisition(requisitionId);

  if (isNotTrue(isNull(requisitionDto.getId()))
      && isNotTrue(requisitionId.equals(requisitionDto.getId()))) {
    throw new ValidationMessageException(new Message(ERROR_ID_MISMATCH));
  }

  Requisition requisitionToUpdate = requisitionRepository.findOne(requisitionId);

  if (isNull(requisitionToUpdate)) {
    throw new ContentNotFoundMessageException(new Message(
        ERROR_REQUISITION_NOT_FOUND, requisitionId));
  }

  Requisition requisition = RequisitionBuilder.newRequisition(requisitionDto,
      requisitionToUpdate.getTemplate(), requisitionToUpdate.getProgramId(),
      requisitionToUpdate.getStatus());
  requisition.setId(requisitionId);

  requisitionVersionValidator.validateRequisitionTimestamps(
      requisition, requisitionToUpdate
  );

  RequisitionStatus status = requisitionToUpdate.getStatus();
  if (status != RequisitionStatus.APPROVED
      && status != RequisitionStatus.SKIPPED
      && status != RequisitionStatus.RELEASED) {
    LOGGER.debug("Updating requisition with id: {}", requisitionId);

    BindingResult bindingResult = new BeanPropertyBindingResult(requisition, REQUISITION);
    draftValidator.validate(requisition, bindingResult);

    if (bindingResult.hasErrors()) {
      LOGGER.warn("Validation for requisition failed: {}", getErrors(bindingResult));
      throw new BindingResultException(getErrors(bindingResult));
    }

    requisitionToUpdate.updateFrom(requisition,
        stockAdjustmentReasonReferenceDataService.getStockAdjustmentReasonsByProgram(
            requisitionToUpdate.getProgramId()), orderableReferenceDataService.findAll());

    requisitionToUpdate = requisitionRepository.save(requisitionToUpdate);

    LOGGER.debug("Saved requisition with id: " + requisitionToUpdate.getId());
    return requisitionDtoBuilder.build(requisitionToUpdate);
  } else {
    throw new ValidationMessageException(new Message(ERROR_CANNOT_UPDATE_WITH_STATUS,
        requisitionToUpdate.getStatus()));
  }
}

Time consuming calls:

Line 313: Build the response dto.

public RequisitionDto submitRequisition(@PathVariable("id") UUID requisitionId) {
  permissionService.canSubmitRequisition(requisitionId);
  Requisition requisition = requisitionRepository.findOne(requisitionId);
  if (requisition == null) {
    throw new ContentNotFoundMessageException(
        new Message(MessageKeys.ERROR_REQUISITION_NOT_FOUND, requisitionId));
  }

  BindingResult bindingResult = new BeanPropertyBindingResult(requisition, REQUISITION);
  validator.validate(requisition, bindingResult);

  if (bindingResult.hasErrors()) {
    LOGGER.warn("Validation for requisition failed: {}", getErrors(bindingResult));
    throw new BindingResultException(getErrors(bindingResult));
  }

  facilitySupportsProgramHelper.checkIfFacilitySupportsProgram(requisition.getFacilityId(),
      requisition.getProgramId());

  LOGGER.debug("Submitting a requisition with id " + requisition.getId());

  UserDto user = authenticationHelper.getCurrentUser();
  requisition.submit(orderableReferenceDataService.findAll(), user.getId());
  saveStatusMessage(requisition);
  
  requisitionRepository.save(requisition);
  requisitionStatusProcessor.statusChange(requisition);
  LOGGER.debug("Requisition with id " + requisition.getId() + " submitted");

  return requisitionDtoBuilder.build(requisition);
}

Time consuming calls:

Line 237: Fetch all the orderables from reference data service.
Line 244: Build the response dto.

RequisitionDtoBuilder

public RequisitionDto build(Requisition requisition) {
  if (null == requisition) {
    return null;
  }

  RequisitionDto requisitionDto = new RequisitionDto();

  requisition.export(requisitionDto);
  List<RequisitionLineItemDto> requisitionLineItemDtoList =
      requisitionExportHelper.exportToDtos(requisition.getRequisitionLineItems());

  requisitionDto.setTemplate(requisition.getTemplate());
  requisitionDto.setFacility(facilityReferenceDataService.findOne(requisition.getFacilityId()));
  requisitionDto.setProgram(programReferenceDataService.findOne(requisition.getProgramId()));
  requisitionDto.setProcessingPeriod(periodService.getPeriod(
      requisition.getProcessingPeriodId()));
  requisitionDto.setRequisitionLineItems(requisitionLineItemDtoList);

  if (null != requisition.getAvailableNonFullSupplyProducts()) {
    requisitionDto.setAvailableNonFullSupplyProducts(
        requisition.getAvailableNonFullSupplyProducts()
            .stream()
            .filter(Objects::nonNull)
            .map(orderableReferenceDataService::findOne)
            .collect(Collectors.toSet())
    );
  }

  return requisitionDto;
}

Time consuming calls:

Lines 87-95: Fetch each of requisition's non full supply products from reference data service one by one.

Solutions

Both save and submit:

Return only relevant information about a requisition to the client: Do we really need to return non full supply products in the response of those endpoints? Perhaps we could keep this as a set of UUIDs instead of calling orderableReferenceDataService.findOne for each one of them, or, if really needed, create a batch endpoint that returns all of them at once

Submit:

We could reuse products that were previously retrieved in RequisitionController.
Try not to fetch all the orderables, search them by facility/program instead.