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.

edge-rtac.hprof.zip

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

Browser not supported