1 Overview
2 High Level Summary
3 Test Runs
4 Results
- 4.1 JVM Profiling
- 4.2 Database
- 4.3 CPU and Memory Utilization
- 4.4 400-users Run Data
5 Appendix

Overview

In this workflow we are checking the performance of the check-in-check-out workflow running in the Fameflower release with Okapi v2.40.0. We will test it with 1, 5, 8, and 20 virtual users for 30 minutes. This is a comparative study between the Fameflower release (with Okapi v.2.38.0) and FameFlower release with Okapi v2.40.0.

Backend:

mod-circulation-18.0.9
mod-circulation-storage-11.0.8
mod-inventory-storage-19.1.2
mod-inventory-14.1.3
okapi-2.40.0

Frontend:

folio_circulation-2.0.0
Item Check-in (folio_checkin-2.0.1)
Item Check-out (folio_checkout-3.0.2)

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

Overall check in, check out time in seconds
1. Average check in time is 1.00 seconds for a typical use case of 8 users, 1.13 seconds for 20 users
2. Average check out time is 1.14 seconds for a typical use case of 8 users, 1.32 seconds for 20 users
3. With Okapi v2.40.0 the response times for check-in/check-out are generally about 30% - 35% faster than when running with Okapi v2.38
Slow APIs taking more than 100ms to run
1. POST checkout-by-barcode
2. POST checkin-by-barcode
3. Get circulation/loans
4. Get inventory/items
JVM profiling shows JSON de/serialization operations one of the slowest operations.
When tested with 400 users, mod-auth-token CPU usage is pegged at 100%.

Test Runs

Test	Virtual Users	Duration	OKAPI log level	OKAPI Version	Profiled
1.	1	30 min	INFO	2.40.0	No
2.	5	30 min	INFO	2.40.0	No
3.	8	30 min	INFO	2.40.0	No
4.	20	20 min	INFO	2.40.0	No
5.	8	42 min	INFO	2.40.0	Yes
6.	400	60 min	INFO	2.40.0	No

Results

Response Times

	Average (seconds)		50th %tile (seconds)		75th %tile (seconds)		95th %tile (seconds)
	Check-in	Check-out	Check-in	Check-out	Check-in	Check-out	Check-in	Check-out
1 user	0.881	1.09	0.839	1.136	0.943	1.257	1.152	1.442
5 users	0.932	1.091	0.879	1.13	0.992	1.23	1.254	1.475
8 users	1.005	1.141	0.932	1.176	1.141	1.32	1.385	1.571
20 users	1.13	1.322	1.061	1.332	1.291	1.566	1.661	1.965

With Okapi v2.40.0 the response times for check-in/check-out are generally about 30% - 35% faster

	Average				50th Percentile				75th percentile				95th pecentile
	Check-in v2.38	Check-in v2.40	Check-out v2.38	Check-in v2.40	Check-in v2.38	Check-in v2.40	Check-out v2.38	Check-out v2.40	Check-in v2.38	Check-in v2.40	Check-out v2.38	Check-out v2.40	Check-in v2.38	Check-in v2.10	Check-out v2.38	Check-out v2.40
1 user	1.015	0.881	1.234	1.09	0.96	0.839	1.277	1.136	1.071	0.943	1.409	1.257	1.322	1.152	1.653	1.442
5 users	1.236	0.932	1.488	1.091	1.156	0.879	1.393	1.13	1.464	0.992	1.869	1.26	1.704	1.254	2.219	1.475
8 users	1.512	1.005	1.751	1.141	1.403	0.932	1.852	1.176	1.741	1.141	2.031	1.32	2.02	1.385	2.274	1.571
20 users	1.649	1.13	1.898	1.322	1.535	1.061	1.996	1.332	1.896	1.291	2.211	1.566	2.252	1.661	2.539	1.965

JVM Profiling

Overall slow methods (between the modules profiled: okapi, mod-circulation, mod-circulation-storage, mod-inventory, mod-inventory-storage) and also slowest Okapi methods
- http://ec2-3-93-19-104.compute-1.amazonaws.com/grafana/d/b2iP-9hiz/java-profiling-folio?orgId=1&from=1589951090422&to=1589954307983&var-service_tag=okapi&var-service_tag=mod-inventory-storage&var-service_tag=mod-inventory&var-service_tag=mod-circulation-storage&var-service_tag=mod-circulation&var-aggregation=10s

When drilling down org.apache.logging.log4j.spi.AbstractLogger.info, we get the following tree. To see more click here: http://ec2-3-93-19-104.compute-1.amazonaws.com/grafana/d/U9JtDPLWz/stacktrace?orgId=1&class=org.apache.logging.log4j.spi.AbstractLogger&method=info&from=1589951256523&to=1589954346642

When drilling down com.fasterxml.jackson.databind.Objectmapper.readValue, we get the following: http://ec2-3-93-19-104.compute-1.amazonaws.com/grafana/d/U9JtDPLWz/stacktrace?orgId=1&class=com.fasterxml.jackson.databind.ObjectMapper&method=readValue&from=1589951256523&to=1589954346642

When drilling into org.folio.okapi.bean.RoutingEntry.fastMatch, we get the following:

http://ec2-3-93-19-104.compute-1.amazonaws.com/grafana/d/U9JtDPLWz/stacktrace?orgId=1&class=org.folio.okapi.bean.RoutingEntry&method=fastMatch&from=1589951256523&to=1589954346642

Database

Database does not show much CPU usage for 1, 5, 8 and 20 users runs. At maximum only 25% CPU usage for the high case of 20 users.

With 400 users

The following queries took more than 100ms to execute under load

UPDATE fs09000000_mod_inventory_storage.item SET jsonb = $1::jsonb  WHERE id='aef3bbad-d2a8-4339-a782-2336bb873e34' 
     parameters: $1 = '{"id": "aef3bbad-d2a8-4339-a782-2336bb873e34", "hrid": "it2477827", "notes": [], "status": {"name": "Checked out"}, "barcode": "H92270805", "metadata":    {"createdDate": "2020-05-23T19:22:12.828+0000", "updatedDate": "2020-05-23T19:22:12.828+0000", "createdByUserId": "9eb67301-6f6e-468f-9b1a-6134dc39a684", "updatedByUserId": "9eb67301-6f6e-468f-9b1a-6134dc39a684"}, "formerIds": [], "yearCaption": [], "materialTypeId": "025ba2c5-5e96-4667-a677-8186463aee69", "circulationNotes": [], "electronicAccess": [], "holdingsRecordId": "f14f21ef-c59c-44f2-be50-be2be6af3f92", "statisticalCodeIds": ["c6de6928-bb6e-4458-97f4-9145b27abb24"], "permanentLoanTypeId": "23e4f1ec-cf31-4098-959e-de64ce4781ce", "effectiveCallNumberComponents": {"typeId": "47f04fa9-dcc4-4e2f-9bd5-29fe53873b68", "callNumber": "I-B 78-901475"}}'
SELECT COUNT(*) FROM fs09000000_mod_users.users 
SELECT count_estimate_default('SELECT * FROM fs09000000_mod_users.users WHERE (lower(f_unaccent(users.jsonb->>''active'')) LIKE lower(f_unaccent(''true''))) AND (CASE WHEN length(''2020-05-23T19:1:0037.377Z'') <= 600 THEN left(users.jsonb->>''expirationDate'',600) < ''2020-05-23T19:1:0037.377Z'' ELSE left(users.jsonb->>''expirationDate'',600) < left(''2020-05-23T19:1:0037.377Z'',600) AND users.jsonb->>''expirationDate'' <= ''2020-05-23T19:1:0037.377Z'' END)')
SELECT count_estimate_default('SELECT jsonb,id FROM fs09000000_mod_circulation_storage.request WHERE (to_tsvector(''simple'', f_unaccent(request.jsonb->>''requesterId'')) @@ replace((to_tsquery(''simple'', f_unaccent(''''''0964616a-8ad7-4f5c-b644-756e4924a52c'''''')))::text, ''&'', ''<->'')::tsquery) AND (to_tsvector(''simple'', f_unaccent(request.jsonb->>''status'')) @@ replace((to_tsquery(''simple'', f_unaccent(''''''Open'''''')))::text, ''&'', ''<->'')::tsquery)')
SELECT count_estimate_default('SELECT jsonb,id FROM fs09000000_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->>''barcode'')) LIKE lower(f_unaccent(''085291644''))')
SELECT jsonb ->> 'patronId' AS "patronId", jsonb ->> 'actionType' AS "actionType" FROM fs09000000_mod_circulation_storage.patron_action_session  GROUP BY jsonb ->> 'patronId', jsonb ->> 'actionType' HAVING max(jsonb #>> '{metadata,createdDate}') < '2020-05-23T19:20:0014.726Z' ORDER BY max(jsonb #>> '{metadata,createdDate}') ASC LIMIT '1'
SELECT jsonb,id FROM fs09000000_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->>'barcode')) LIKE lower(f_unaccent('085556727')) LIMIT 1 OFFSET 0

CPU and Memory Utilization

The following table showing average CPU and memory percentages.

	1 user	5 users	8 users	20 users	400 users

	1 user	5 users	8 users	20 users	400 users
Okapi CPU	1.87	6	10.17	22.77	30
Okapi Memory	42.34	41.7	40.93	40.16	46%

400-users Run Data

400 users run's response time

400 users run CPU and memory utilization

Interestingly mod-auth-token pegged at 100% CPU utilization! It is due to the fact that the 400 users constantly coming back to log in.

Appendix

For more raw data of the test runs please see the attached .

Check-in-check-out Test Report (Fameflower with Okapi v2.40.0)