Check-in-check-out Test Report (Fameflower with Okapi v2.40.0)
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
- Average check in time is 1.00 seconds for a typical use case of 8 users, 1.13 seconds for 20 users
- Average check out time is 1.14 seconds for a typical use case of 8 users, 1.32 seconds for 20 users
- 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
- POST checkout-by-barcode
- POST checkin-by-barcode
- Get circulation/loans
- 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
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:
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 | |
|---|---|---|---|---|---|
| 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-FF-UChicago.xlsx.