Check-in-check-out Test Report (Fameflower with Okapi v2.40.0)
- Martin Tran
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