Placing Holds Test Report (Fameflower)
- PERF-27Getting issue details... STATUS
Overview
In this api, we are checking the performance of placing a holding on a discovery service interface (EDS) running in the Fameflower release -
We tested it with 1, 5, 8, and 20 virtual users for 30 minutes.
Backend:
- mod-patron-4.1.0
- mod-circulation-18.0.9
- mod-circulation-storage-11.0.0
- mod-inventory-storage-19.1.2
- mod-inventory-14.1.3
- mod-feesfines-15.7.2
- okapi-2.38.0
- mod-authtoken-2.4.0
- mod-permissions-5.9.0
Environment:
- 55 back-end modules deployed in 110 ECS services
- 3 okapi ECS services
- 8 m5.large EC2 instances
- 1 db.r5.xlarge AWS RDS instance
- INFO logging level
High Level Summary
- The placing a hold request takes about 1 seconds: POST /patron/account/{id}/instance/{instanceId}/hold.
- POST /patron/account/{id}/instance/{instanceId}/hold and POST /circulation/requests/instances show almost the same response time. In addition, mod-circulation's native item-level request code is 24.5% faster than mod-circulation's instance-level request code. Seems like the main issue is the mod-circulation instance-level request API, POST /circulation/requests/instances which is called by mod-patron subsequently.
- JVM profiling shows the slowest operations, totalling more CPU time than other calls:
- logging with INFO level - Logging level could be reduced to WARNING or ERROR, but at the cost of having less data to work with should there be a need to troubleshoot. The most CPU consuming methods are org.folio.circulation.support.Result.next and org.folio.circulation.support.Result.after from org.folio.circulation.support.SingleRecordFetcher, and org.folio.circulation.support.SingleRecordFetcher.fetch method
- JSON de/serialization - fasterxml.jackson.databind.ObjectMapper.readValue method of mod-circulation-storage and mod-inventory-storage consumed high CPU resources as there were a lot of JSON decoding, this implementation could be reviewed for optimisation possibilities. The most CPU consuming methods are org.folio.rest.persist.PgUtil.streamGet from org.folio.rest.impl.InstanceStorageAPI.getInstanceStorageInstancesByInstanceId (mod-inventory-storage), org.folio.rest.impl.HoldingsStorageAPI.getHoldingsStorageHoldings(mod-inventory-storage) and org.folio.rest.persist.PostgresClient.doGet from org.folio.rest.impl.LoansAPI.getLoanStorageLoans and org.folio.rest.impl.RequestsAPI.getRequestStorageRequests(mod-circulation-storage)
- request's validation - need to consider using a more efficient request's validation instead of org.hibernate.validator.internal.engine.ValidatorImpl.validate method because it's one of the slowest operations. The slowest method is org.folio.rest.RestVerticle.route and org.folio.rest.RestVerticle.parseParams
- mod-circulation-storage and mod-feesfines generated missing indexes warnings, see Recommended Improvements for the JIRAs that were created/covered by this testing effort.
Test Runs
Test | Virtual Users | Duration | OKAPI log level | Profiled | Ramp up (total time in seconds) | API call |
1. | 1 | 30 min | WARNING | No | 1 | POST /patron/account/{id}/instance/{instanceId}/hold |
2. | 5 | 30 min | WARNING | No | 50 | POST /patron/account/{id}/instance/{instanceId}/hold |
3. | 8 | 30 min | WARNING | No | 80 | POST /patron/account/{id}/instance/{instanceId}/hold |
4. | 20 | 30 min | WARNING | No | 200 | POST /patron/account/{id}/instance/{instanceId}/hold |
5. | 20 | 30 min | WARNING | Yes | 200 | POST /patron/account/{id}/instance/{instanceId}/hold |
6. | 1 | 30 min | WARNING | No | 1 | POST /circulation/requests/instances |
7. | 5 | 30 min | WARNING | No | 50 | POST /circulation/requests/instances |
8. | 8 | 30 min | WARNING | No | 80 | POST /circulation/requests/instances |
9. | 20 | 30 min | WARNING | No | 200 | POST /circulation/requests/instances |
10. | 20 | 30 min | WARNING | Yes | 200 | POST /circulation/requests/instances |
11. | 1 | 30 min | WARNING | Yes | 1 | POST /circulation/requests |
12. | 8 | 30 min | WARNING | Yes | 200 | POST /circulation/requests |
Results
- An instance-level request to mod-patron
POST /patron/account/{id}/instance/{instanceId}/hold
{ "item": { "instanceId": "c2063f7c-245a-4c24-b643-67fea831ebcc" }, "requestDate": "2020-06-01T18:51:24.000+0000", "pickupLocationId": "7068e104-aa14-4f30-a8bf-71f71cc15e07" }
Overall time for the placing holds api in seconds
Average 75th %tile 1 user 933.01 ms 1.10 s 5 users 1.01 s 1.12 s 8 users 1.03 s 1.18 s 20 users 1.33 s 1.47 s mod-patron subsequently calls mod-circulation to place instance-level requests
POST /circulation/requests/instances
{ "requestDate": "2017-07-29T22:25:37Z", "requesterId": "21932a85-bd00-446b-9565-46e0c1a5490b", "instanceId": "195efae1-588f-47bd-a181-13a2eb437701", "requestExpirationDate": "2017-07-25T22:25:37Z", "pickupServicePointId": "8359f2bc-b83e-48e1-8a5b-ca1a74e840de" }
Overall time in seconds
Average 75th %tile 1 user 864.35 ms 1.01 s 5 users 1.09 s 1.14 s 8 users 1.15 s 1.18 s 20 users 1.58 s 1.53 s An Item-level request
POST /circulation/requests
{ "requestDate": "2020-06-18T09:23:11.957Z", "requesterId": "e96618a9-04ee-4fea-aa60-306a8f4dd89b", "requestType": "Hold", "fulfilmentPreference": "Hold Shelf", "itemId": "0000023d-a95f-4396-8d37-42dda48cdf3d", "requestExpirationDate": "2020-06-18T09:23:11.957Z", "pickupServicePointId": "d80a641e-50b9-4bd2-99a2-a4a12c8515cb" }
Overall time in seconds
Average 75th %tile 1 user 807.90 ms 819.00 ms 8 users 855.92 ms 855.00 ms
The comparison table between an instance-level request and an Item-level request to mod-circulation (done 23.07.2020). The item-level request is 24.5% faster than an instance-level request
An instance-level request to mod-circulation POST /circulation/requests/instances | An Item-level request to mod-circulation POST /circulation/requests | |||
Average | 75th %tile | Average | 75th %tile | |
1 user | 1.07 s | 1.09 s | 807.90 ms | 819.00 ms |
8 users | 1.09 s | 1.09 s | 855.92 ms | 855.00 ms |
JVM Profiling
- Overall slow methods (between the modules profiled: mod-patron, mod-circulation, mod-circulation-storage, mod-inventory, mod-inventory-storage)
To see more drill down these methods at: http://ec2-54-165-58-65.compute-1.amazonaws.com/grafana/d/b3iP-8hiz/java-profiling-folio-new?orgId=1&from=1591958944552&to=1591961253729&var-service_tag=mod-patron&var-service_tag=mod-inventory-storage&var-service_tag=mod-inventory&var-service_tag=mod-circulation-storage&var-service_tag=mod-circulation&var-aggregation=10s
- Only slow mod-circulation methods:
When drilling down org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled, we get the following tree. To see more click here: