WORK IN PROGRESS
PERF-39 - Getting issue details... STATUS
Overview
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-users-17.1.0
- mod-users-bl-6.0.0
- mod-authtoken-2.5.1
- mod-permissions-5.11.2
- mod-circulation-19.0.9
- mod-circulation-storage-12.0.1
- okapi-3.1.1
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
- On average POST_/circulation/renew-by-barcode API call takes average 671.12 seconds as we gradually increase the number of loans and users to 200 and 2 respectively.
- POST_/circulation/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 covered by this testing effort.
Test Runs
Test | Virtual Users | Duration | OKAPI log level | Profiled | Loans per User |
1. | 1 | 30 min | WARNING | No | 10, 50, 100, 200 |
2. | 2 | 30 min | WARNING | No | 10, 50, 100, 200 |
| 3. | 1 | 30 min | INFO | No | 10, 50, 100, 200 |
Results
Renew all loans by barcode
For 30 minutes Loans Renew all loans (Average) POST_/circulation/renew-by-barcode (Average) 1 user 10 6.52 seconds
585.11 ms
50 31.81 seconds
637.48 ms
100 1.06 minutes 650.15 ms
200 2.09 minutes 673.40 ms
2 users 10 7.42 seconds
683.76 ms
50 32.61 seconds
686.65 ms
100 1.10 minutes
705.37 ms
200 2.27 minutes
747.04 ms
Below is the dependency graph generated from Giraffe for POST_/circulation/renew-by-barcode API. It shows individual calls made by renew-by-barcode to gather prerequisite information from different APIs such as item-storage, location-units, loan-types, request-storage, notice-policy, locations and mod-authtoken.
JVM Profiling
- Overall slow methods (between the modules profiled: mod-rtac, 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=1592598484852&to=1592600441623&var-service_tag=mod-rtac&var-aggregation=10s
Database
The database CPU usage decreases slightly as the number of users increases 1, 5 users run. At maximum 28% CPU usage for 1 user. We are seeing a slight decrease in CPU utilization for 5 Users because RDS Postgresql is caching the most frequent query results.
Database Slow queries
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 |
API response time vs Postgresql query response time
This difference below between API and Postgresql query response time is the sum of network time to/back from calling database, deserialization of JSON string into JSON objects, processing time, and network time to/from API. Below are a single API request and SQL query triggered manually for comparison.
| Action | Type of Request | Actual request | Time, ms |
|---|---|---|---|
| get Instance | SQL query | select * from fs09000000_mod_inventory_storage.instance where id = '00009a0b-e973-443b-9796-c3373a352f86'; | 305 |
| API request | https:/{okapi-url}/inventory/instances/00009a0b-e973-443b-9796-c3373a352f86 | 368 | |
| get holdings | SQL query | select * from fs09000000_mod_inventory_storage.holdings_record hr1 where hr1.instanceid = '121063ba-43cc-48f4-a49f-aaf5488127e0'; | 350 |
| API request | https:/{okapi-url}/holdings-storage/holdings?limit=2147483647&query=instanceId==121063ba-43cc-48f4-a49f-aaf5488127e | 503 | |
| get Item | SQL query | select * from fs09000000_mod_inventory_storage.item where holdingsrecordid='95a897e5-2505-4803-a7f1-7da39c9f67cb'; | 353 |
| API request | https://{okapi-url}/inventory/items?limit=2147483647&query=holdingsRecordId%3D%3D95a897e5-2505-4803-a7f1-7da39c9f67cb | 662 | |
| get Open loan | SQL query | select * from fs09000000_mod_circulation_storage.loan where jsonb->>'itemId'='3faad467-fca1-41c8-ad7d-af1dcd3fdc3c' AND jsonb->'status'->>'name'='Open'; | 372 |
| API request | https://{okapi-url}/circulation/loans?limit=2147483647&query=(itemId==3faad467-fca1-41c8-ad7d-af1dcd3fdc3c and status.name==Open) | 400 |
CPU Utilization
CPU utilization is relatively on a lower side for most modules except for mod-inventory-storage
| 1 user | 5 users | |
|---|---|---|
| Average % | Average % | |
| mod-circulation | 3.14 | 3.95 |
| mod-circulation-storage | 4.84 | 6.38 |
| mod-inventory | 5.38 | 6.54 |
| mod-inventory-storage | 26 | 24 |
| mod-rtac | 2.45 | 3 |
Memory
Memory was stable throughout the runs, only a spike here or there, but in a 30 minutes run they were consistent.
| 1 user | 5 users | |
|---|---|---|
| Average % | Average % | |
| mod-circulation | 72.1 | 72.50 |
| mod-circulation-storage | 39.46 | 39.55 |
| mod-inventory | 44 | 46.5 |
| mod-inventory-storage | 44.30 | 45 |
| mod-rtac | 55.2 | 55 |
Recommended Improvements
- The following JIRA has been created for mod-authtoken optimization:
MODAT-80 - Getting issue details... STATUS
Appendix
See Attached rtac-test-report.xlsx for details