PTF -RTAC Workflow Test Report (Honeysuckle)
- Varun Javalkar
PERF-117 - Getting issue details... STATUS
WIP
Work in progress...
Overview
PERF-117 - Getting issue details... STATUS was created to re-run RTAC performance test in the Honeysuckle environment which will verify performance issues reported by MODRTAC-38 - Getting issue details... STATUS
We tested mod-rtac, edge-rtac with 1, 15, 20 virtual users for 15, 30 minutes with different combinations of instance size.
Backend:
- mod-circulation-19.2.3
- mod-circulation-storage-12.1.2
- mod-inventory-storage-19.4.3
- mod-inventory-16.1.0
- okapi-4.2.2
- mod-authtoken-2.6.0
- mod-permissions-5.12.2
Environment:
- 63 back-end modules deployed in 110 ECS services
- 3 okapi ECS services
- 10 m5.large EC2 instances
- 2 db.r5.xlarge AWS RDS instance (1 reader, 1 writer)
High Level Summary
- On average edge-rtac GET_/rtac?instanceIds=id1,id2,id3,idn API call takes 721.40 ms for 1 instance with 300+ holdings. This is an improvement from 17.5 seconds in Fameflower.
- On average mod-rtac POST_/rtac-batch API call takes 529 ms for 1 instance with 300+ holdings. This is an improvement from 17 seconds in Fameflower.
- On running mod-rtac POST_/rtac-batch API for more than 5 users for 15 minutes test run, mapping errors were seen. Please see MODRTAC-53 in recommended improvements below.
- See Recommended Improvements for the JIRAs that were created/covered by this testing effort.
Test Runs
Test | Virtual Users | Duration | OKAPI metrics | Holdings per instance | API call |
1. | 1 | 30 min | DISABLE | greater than 300 | edge-rtac GET https://edge-honeysuckle-cap1.int.aws.folio.org/rtac?instanceIds=id1,id2,id3,id4,id5,id6,id7,id8,id9,id10&apikey={API_KEY}&fullPeriodicals=true |
2. | 1 | 30 min | DISABLE | greater than 300 | mod-rtac POST https://okapi-honeysuckle-cap1.int.aws.folio.org/rtac-batch |
| 3. | 1 | 30 min | DISABLE | 50 instances with a mix of 3,4,5,6,7 holdings per instance | edge-rtac GET https://edge-honeysuckle-cap1.int.aws.folio.org/rtac?instanceIds=id1,id2,id3,id4,id5,id6,id7,id8,id9,id10&apikey={API_KEY}&fullPeriodicals=true |
| 4. | 1 | 30 min | DISABLE | 50 instances with a mix of 3,4,5,6,7 holdings per instance | mod-rtac GET https://okapi-honeysuckle-cap1.int.aws.folio.org/rtac-batch |
| 5. | 20 | 15 min | ENABLE | 50 instances with a mix of 3,4,5,6,7 holdings per instance | mod-rtac POST https://okapi-honeysuckle-cap1.int.aws.folio.org/rtac-batch |
| 6. | 15 | 15 min | ENABLE | 50 instances with a mix of 3,4,5,6,7 holdings per instance | mod-inventory-storage POST https://okapi-honeysuckle-cap1.int.aws.folio.org/inventory-hierarchy/items-and-holdings |
| 7. | 20 | 15 min | ENABLE | 50 instances with a mix of 3,4,5,6,7 holdings per instance | mod-inventory-storage POST https://okapi-honeysuckle-cap1.int.aws.folio.org/inventory-hierarchy/items-and-holdings |
Results
mod-rtac and inventory-hierarchy
A mod-rtac level request to get all open loans for greater than 300 holdings per instance
| POST /rtac-batch for 30 minutes | Total Instances | Total Holdings | Average | 75th %tile |
| 1 user | 1 | 333 | 529 ms | 456 ms |
| 1 user | 50 | mix of 3,4,5,6,7 | 2.57 seconds | 2.37 seconds |
This test was run to exaggerate with 20 users to recreate an error from mod-rtac. Out of 50 instance lookups, 3 lookups failed with facade error mapping.
| POST /rtac-batch for 15 minutes | Total Instances | Total Holdings | Average | 75th %tile |
| 2 user | 50 | mix of 3,4,5,6,7 | 2.97 seconds | 2.70 seconds |
| 20 user | 50 | mix of 3,4,5,6,7 | 21.75 seconds | 31.37 seconds |
Following errors were found in CloudWatch logs:
mod-rtac
2020-11-18T16:13:54.706-05:00 21:13:54 INFO FolioToRtacMapper Rtac handling periodicals: false 2020-11-18T16:13:54.706-05:00 21:13:54 INFO FolioToRtacMapper Rtac handling periodicals: false 2020-11-18T16:13:54.707-05:00 21:13:54 INFO FolioFacade Mapping inventory instances: 47 2020-11-18T16:13:54.707-05:00 21:13:54 INFO FolioFacade Mapping errors: 3 2020-11-18T16:13:54.707-05:00 21:13:54 INFO LogUtil org.folio.rest.RestVerticle start invoking postRtacBatch 2020-11-18T16:13:54.716-05:00 21:13:54 INFO LogUtil 127.0.0.1:44234 POST /rtac-batch null HTTP_1_1 200 338787 15258 tid=fs09000000 OK
10.23.10.246 - - [18/Nov/2020:21:20:10 +0000] "POST /mod-rtac/rtac-batch HTTP/1.1" 504 183 rt=599.997 uct="0.000" uht="600.001" urt="600.001" "Apache-HttpClient/4.5.6 (Java/1.8.0_232)" "fs09000000" "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJmb2xpbyIsInVzZXJfaWQiOiI5ZWI2NzMwMS02ZjZlLTQ2OGYtOWIxYS02MTM0ZGMzOWE2ODQiLCJtb2R1bGUiOiJtb2QtcnRhYy0yLjAuMSIsImV4dHJhX3Blcm1pc3Npb25zIjpbIlNZUyNtb2QtcnRhYy0yLjAuMSNcL3J0YWMtYmF0Y2gjW1BPU1RdIl0sInRlbmFudCI6ImZzMDkwMDAwMDAifQ.ifkt2jQFQauIXc2megNEB88qFYTCZmqZXcjGu2NE7yw" "{\x0D\x0A \x22instanceIds\x22: [\x0D\x0A \x2200009a0b-e973-443b-9796-c3373a352f86\x22,\x2200013259-9863-4259-910f-0d7ce90ff338\x22,\x2200017996-3315-4c35-a190-9ba05d845295\x22,\x2200020880-4d98-4875-94ef-bf2004ab67d8\x22,\x220002288a-59aa-4204-866e-7ffdd00fb96a\x22,\x2200042c9f-1019-4d65-9a75-d3a894507386\x22,\x22000516be-39ce-4fd8-8ac6-a45a4c3f702e\x22,\x2200052ca9-14f5-40bd-9a30-bb867a3436c2\x22,\x220005e0e3-5ecd-480b-96db-bab8ab8acff3\x22,\x2200062383-9abf-49c1-8b91-d6b989687ac4\x22,\x220012a59f-a16b-4a91-8c9c-a3d6b9fce816\x22,\x22001ac7b2-a57f-413d-bc30-64de99bac69c\x22,\x220020c571-e6e6-4dbc-a42f-fb8ba8728828\x22,\x220024a79a-bf95-47e9-8295-97ce9759c9c7\x22,\x2200278ebb-0cc3-4c8b-8373-7047096cc4a8\x22,\x2200280262-ac01-4159-b124-17e81cf4dd5e\x22,\x22002ae2e3-59b6-45f7-9b04-873fe03b7909\x22,\x22002b99a6-a75e-4444-ac43-574ea2207b84\x22,\x22003048f4-d47d-4206-a60c-b9b07526cf3a\x22,\x22003162f6-327b-41d2-8983-3fd32da1fb9a\x22,\x22000314cc-85a0-466b-83bc-e87abd73886a\x22,\x22000b35bf-9844-4c2e-bf27-e5aa62a911a4\x22,\x220010c364-fed3-467b-8145-19b48562dc68\x22,\x22001184f6-651d-4265-af5d-690194c31e45\x22,\x220042782b-8dca-4b0c-9dc5-5bde61d03095\x22,\x2200475cd9-d21a-427d-8f56-f3a53f1738b4\x22,\x220049dfb5-3947-405e-9491-c8cf5ae200ff\x22,\x22004e1405-ccda-4525-8e0e-1fd962696d8d\x22,\x2200541e48-6a59-407d-8d94-91fd6a78095e\x22,\x220061fce1-7973-4786-9251-a34944c6cdf9\x22,\x220011a8f1-efe4-44f0-9974-f94f2d6d204d\x22,\x220015fdae-66b1-4d7c-b896-1717b4339132\x22,\x22003d93a2-b27d-4fa4-9be1-50b8a0a80792\x22,\x220040a038-9ce4-451e-a608-cb98dd9edb35\x22,\x22006314ca-17b7-4c72-b760-b6186ad2ec1a\x22,\x22007f943c-6c20-45b8-8a81-d9b9e069f6db\x22,\x22009589d6-2644-4824-b343-5461aaea2d2e\x22,\x2200ae50af-33f7-4d7f-8632-4e6980ac8197\x22,\x2200b3bf8f-24d7-4178-8ceb-ec27c3ee039f\x22,\x2200b8ed0b-f265-499c-98fe-891ad8da4023\x22,\x22005a5bbb-8b80-4f3b-8be0-77021ff3ff56\x22,\x2200db8626-ece0-4b53-9120-b5220e27c491\x22,\x2200f8c674-6808-4d0b-a050-a385a5e345b5\x22,\x220121ebd1-351a-46ae-94c6-c7251bb1273c\x22,\x2201654b4f-a206-4153-af64-4afd2a357b6b\x22,\x2202038995-656d-4a87-8870-7dbf1fd5fe48\x22,\x2202235e2b-9a57-4175-9244-36bbe11beaf4\x22,\x22025e129b-1173-46f1-baa0-6f5ffca00b90\x22,\x220260fffd-3bbf-4664-8db1-e80405719601\x22,\x22030a018c-afe8-4f93-a883-581df5562194\x22\x0D\x0A ]\x0D\x0A}\x0D\x0A\x0D\x0A"
mod-rtac calls inventory-hierarchy. To investigate the error for mod-rtac for concurrent users(2 or more), POST inventory-hierarchy/items-and-holdings API tests were run for 15 users and 20 users. No errors were reported.
| POST inventory-hierarchy/items-and-holdings for 15 minutes | Total Instances | Total Holdings | Average | 75th %tile |
| 15 users | 50 | mix of 3,4,5,6,7 | 7.11 seconds | 7.23 seconds |
| 20 users | 50 | mix of 3,4,5,6,7 | 9.34 seconds | 9.56 seconds |
This proves that the issue is with mod-rtac and hence MODRTAC-53 - Getting issue details... STATUS was created.
edge-rtac
An edge-rtac level request to get all open loans for greater than 300 holdings per instance
| GET /rtac for 30 minutes | Total Instances | Total Holdings | Average | 75th %tile |
| 1 user | 1 | 333 | 721 ms | 500 ms |
| 1 user | 50 | mix of 3,4,5,6,7 | 2.58 seconds | 2.52 seconds |
Slow Queries
1 instance with 333 holdings
Percent of total time | Average Time, ms | Module | Query |
|---|---|---|---|
| 60% | 188 ms | mod_inventory_storage | select * from get_items_and_holdings_view($1,$2) |
50 instances with a mix of 3,4,5,6,7 holdings per instance
Percent of total time | Average Time, ms | Module | Query |
|---|---|---|---|
| 58% | 977 ms | mod_inventory_storage | select * from get_items_and_holdings_view($1,$2) |
RDS CPU Utilization
1 user 1 instance with 333 holdings. CPU is around 24% which is normal.
1 user 50 instances with a mix of 3,4,5,6,7 holdings per instance. CPU is around 27% which is normal.
15 users, 20 users 50 instances with a mix of 3,4,5,6,7 holdings per instance. CPU is close to 100% which is high because DB was fired with 15, 20 different users. This run involved 504 errors from mod-rtac. These many numbers of concurrent users are rare and will not happen in production.
Service Memory Utilization
1 user - 1 instance 333 holdings | 1 user - 50 instances with a mix of 3 to 7 holdings | |
|---|---|---|
| Average Range(high-low) % | Average Range(high-low) % | |
| mod-rtac | 91 -91 | 90 - 90 |
| edge-rtac | 32 -32 | 31 - 35 |
| mod-inventory | 50 -50 | 71.5 -72 |
| mod-inventory-storage | 57 - 57 | 68 - 68 |
| mod-circulation | 73 - 73 | 93 - 100 |
| mod-circulation-storage | 47 - 47 | 48 - 49 |
| okapi | 90 -91.5 | 91 - 92 |
15 users and 20 users for 50 instances with a mix of 3,4,5,6,7 holdings per instance. Service memory Utilization is relatively high for mod-rtac compared to other modules in the graph but this is rare. This use case was run to recreate the issue reported in MODRTAC-53. 2 vertical lines represent the time range for the test run.
Service CPU Utilization
1 user - 1 instance 333 holdings | 1 user - 50 instances with a mix of 3 to 7 holdings | |
|---|---|---|
| Average Range(high-low) % | Average Range(high-low) % | |
| mod-rtac | 81 - 240 | 4 - 130 |
| edge-rtac | 5.2 - 30.7 | 1.5 - 10.45 |
| mod-inventory | 2.5 - 3 | 3 -5 |
| mod-inventory-storage | 9 - 15 | 3.45 - 20 |
| mod-circulation | 3 - 16 | 3 - 14.4 |
| mod-circulation-storage | 3 - 33 | 3.6 - 40 |
| okapi | 5 - 80 | 5 - 163 |
15 users and 20 users for 50 instances with a mix of 3,4,5,6,7 holdings per instance. CPU Utilization is relatively high but this is rare. This use case was run to recreate the issue reported in MODRTAC-53
Heap Dump
edge-rtac
This heap dump is for 5 Users 1 instance 300+ holdings 30 minutes each, heap dump size before the fix was 448MB. This heap dump is referenced in the JIRA tickets below.
mod-inventory-storage
Below heap dump were taken during the test run for 5 Users 1 instance 300+ holdings 30 minutes. They did not reclaim much heap memory so there were no memory leaks for mod-inventory-storage. These heap dumps are referenced in the JIRA tickets below.
inventory-storage-heap-dump-during-test-run.tar.gz
inventory-storage-heap-dump-just-after-test-run.tar.gz
Recommended Improvements
- The following JIRAs were created as part of the testing effort:
MODRTAC-48 - Getting issue details... STATUS
EDGRTAC-33 - Getting issue details... STATUS
MODINVSTOR-614 - Getting issue details... STATUS
EDGRTAC-34 - Getting issue details... STATUS
MODAUD-39 - Getting issue details... STATUS
MODRTAC-53 - Getting issue details... STATUS
References
RTAC - Real Time Availability Checking
Appendix
See Attached rtac-test-report.xlsx for details