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