WORK IN PROGRESSWORK IN PROGRESS
| Jira Legacy | ||||||||
|---|---|---|---|---|---|---|---|---|
|
...
In this workflow, we are checking the performance of the renewal of loan items for the Goldenrod release.
We tested it with 1, 2 virtual users for 30 minutes.
Backend:
- mod-circulationusers-1817.1.0.9
- mod-circulationusers-storagebl-116.0.0
- mod-inventory-storage-19authtoken-2.5.1.2
- mod-inventorypermissions-145.111.32
- okapimod-circulation-219.380.09
- mod-authtokencirculation-storage-212.40.01mod
- okapi-permissions-53.91.01
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
...
- AWS RDS instance
- INFO logging level
High Level Summary
- On average renew-by-barcode API call takes average 671.12 seconds as we gradually increase number of loans and users to 200 and 2 respectively.
- renew-by-barcode API makes 26 different API requests to gather userBarcode and itemBarcode information. 34% of those are calls are to mod-authtoken.
see Recommended Improvements for the JIRAs that were created/covered by this testing effort.
...
Test | Virtual Users | Duration | OKAPI log level | Profiled | Holdings per instance | API call |
1. | 1 | 30 min | WARNING | No | greater than 300 | GET rtac/${instanceId} |
2. | 5 | 30 min | WARNING | No | greater than 300 | GET rtac/${instanceId} |
| 3. | 1 | 30 min | WARNING | Off | greater than 300 | Mimic above call: GET inventory/instances/${instanceId} → GET /holdings-storage/holdings → GET /inventory/items → GET /circulation/loans |
| 4. | 5 | 30 min | WARNING | Off | greater than 300 | Mimic above call: GET inventory/instances/${instanceId} → GET /holdings-storage/holdings → GET /inventory/items → GET /circulation/loans |
Results
- A rtac-level request to get all open loans for greater than 300 holdings per instance
GET rtac/${instanceId}
For 30 minutes Profiler Average 75th %tile 1 user ON 17.62 seconds 25.47 seconds 1 user OFF 15.44 seconds 20.99 seconds 5 users ON 47.53 seconds 55.01 seconds 5 users OFF 42.06 seconds 49.61 seconds Because there are no custom metrics inside mod-rtac to expose the wait time of each API call, we needed to mimic the rtac API logic by making subsequent calls to mod-inventory, mod-circulation to get open loans for greater than 300 holdings per instance in the JMeter script. One caveat is that these calls are synchronous and are end-to-end (over the internet from JMeter to FOLIO) so naturally these API calls will be slower compared to the actual /rtac API calls from mod-rtac which were implemented asynchronously. Therefore, the response times while are not likely what is seen by the code but should still give us a good idea of the cost of making n^3 API calls even if we take off some percentage for end-to-end over-the-wire latencies.
Calculations:
Total response time to get all holdings, items, open loans per instance(seconds) = time to get current instance + time to get all holdings
...
time to get all loans = get current_loan * total loans
Get an instance
GET inventory/instances/${instanceId}...
| Profiler | avg(get all holdings per instance) + avg(get all items) + avg(get all loans) = Total average | avg(get all holdings per instance) + avg(get all items) + avg(get all loans) = Total average 75th %tile | |
| 1 user | ON | 174 ms + 39 sec + 15.3 sec = 54.5 sec | 213 ms + 40.2 sec + 14.3 sec = 54.7 sec |
| 1 user | OFF | 73 ms + 34 sec + 14.3 sec = 48.4 sec | 86 ms + 40.2 sec + 12.3 sec = 52.6 sec |
| 5 users | ON | 179 ms + 49.3 sec + 17.7 sec = 67.2 sec | 223 ms + 51.6 sec + 18 sec = 70.1 sec |
| 5 users | OFF | 71 ms + 42.9 sec + 14.9 sec = 57.8 | 40 ms + 42.6 sec + 15.6 sec = 58.2 sec |
For each holding, get all items
GET /inventory/items?limit=2147483647&query=holdingsRecordId==${current_holding}| Profiler | avg(get current_item) * total items = Total average | avg(get current_item) * total items = Total average 75th %tile | |
| 1 user | ON | 119 ms * 333 = 39 sec | 121 ms * 333 = 40.2 sec |
| 1 user | OFF | 104 ms * 333 = 34 sec | 106 ms * 333 = 35.2 sec |
| 5 users | ON | 148 ms * 333 = 49.3 sec | 155 ms * 333 = 51.6 sec |
| 5 users | OFF | 129 ms * 333 = 42.9 sec | 128 ms * 333 = 42.6 sec |
For each item, get all open loans
GET /circulation/loans?limit=2147483647&query=(itemId==${current_item} and status.name==Open)...
The slowest query which took the most of execution time was initiated by the mod_inventory_storage service presented in the following table:
Percent of total time | Average Time, ms | Calls | Module | Query |
|---|---|---|---|---|
| 77% | 14,632 ms | 21 | mod_inventory_storage | SELECT COUNT(*) FROM fs09000000_mod_inventory_storage.holdings_record |
...
Recommended Improvements
| Anchor | ||||
|---|---|---|---|---|
|
- The following JIRA has been created for mod-rtac:
Jira Legacy server System Jira columns key,summary,type,created,updated,due,assignee,reporter,priority,status,resolution serverId 01505d01-b853-3c2e-90f1-ee9b165564fc key MODRTAC-38
- Consider taking advantage of CQL "OR" operator to chain IDs together at each level of getting items, holdings, loans, instead of making API calls. This approach could be faster, although need to be proven.
- Consider doing SQL joins between instance/holdings/items where possible to reduce making API and database calls.
- In mod-circulation, mod-circulation-storage, mod-inventory-storage, consider using a more efficient JSON package or call using the existing Jackson serialization calls in a different way to address the item: JVM profiling shows JSON de/serialization operations one of the slowest operations.
...