Overview

This document has been created to show poor performance of requisition authorize endpoint. It contains:

an example execution of the endpoint on the UI,
how long it took for methods in the requisition service to execute,
where the endpoint takes 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 "Authorize" we can see the following requests being executed:

The ones worth noting are:

GET /api/requisitions/<id>, which takes 24.96s
Is this really needed? The requisition was already fetched when entering the product grid
POST /api/requisitions/<id>/authorize, 23.06s
This is the endpoint we are interested in. The response contains 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.59s
GET /api/requisitions/search, 1.3m
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 image presents a list of methods that have been used while authorizing the requisition. The request was 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.

The above example shows that endpoint was executed in 21.40s, most of which (17.70s) was consumed by RequisitionDtoBuilder to construct the response. Getting all orderables from reference data service took another 2,78s.

Code

RequisitionController

public RequisitionDto authorizeRequisition(@PathVariable("id") UUID requisitionId) {
  permissionService.canAuthorizeRequisition(requisitionId);

  if (configurationSettingService.getBoolValue("skipAuthorization")) {
    throw new ValidationMessageException(new Message(ERROR_AUTHORIZATION_TO_BE_SKIPPED));
  }

  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()) {
    throw new BindingResultException(getErrors(bindingResult));
  }
  facilitySupportsProgramHelper.checkIfFacilitySupportsProgram(requisition.getFacilityId(),
      requisition.getProgramId());

  UserDto user = authenticationHelper.getCurrentUser();
  requisition.authorize(orderableReferenceDataService.findAll(), user.getId());

  UUID supervisoryNode = supervisoryNodeReferenceDataService.findSupervisoryNode(
      requisition.getProgramId(), requisition.getFacilityId()).getId();
  requisition.setSupervisoryNodeId(supervisoryNode);

  saveStatusMessage(requisition);

  requisitionRepository.save(requisition);
  requisitionStatusProcessor.statusChange(requisition);
  LOGGER.debug("Requisition: " + requisitionId + " authorized.");

  return requisitionDtoBuilder.build(requisition);
}

Time consuming calls:

Line 537: Fetch all the orderables from reference data service.
Line 549: 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;
}