...

In this workflow we are checking the performance of the check-in-check-out workflow running in the Fameflower release (

...

1. Overall check in, check out time in seconds

   1. Average check in time is 1.51 seconds for a typical use case of 8 users, 1.65 seconds for 20 users
   2. Average check out time is 1.75 seconds for a typical use case of 8 users, 1.90 seconds for 20 users
2. 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
3. Excess logging of mod-circulation-storage log warnings for missing indexes - 64K lines in  45 minutes run. Logging level could be reduced to WARNING or INFO, but at the cost of having less data to work with should there be a need to troubleshoot.
4. JVM profiling shows JSON de/serialization operations one of the slowest operations.

Test Runs

...

Test

...

Virtual Users

...

Duration

...

OKAPI log level

...

Profiled

...

1.

...

1

...

1. Adding the missing indexes could improve performance while stop logging these warnings 

   Jira Legacy
   server System JIRA serverId 01505d01-b853-3c2e-90f1-ee9b165564fc key CIRCSTORE-215

2. JVM profiling shows JSON de/serialization operations one of the slowest operations, totaling more CPU time than other calls.  Since FOLIO modules retrieve and stores JSON objects, making sure that serializing and deserializing JSON efficient is essential, see Recommended Improvements

Test Runs

Results

1. 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	1.015	1.234	0.96	1.277	1.071	1.409	1.322	1.653
   5 users	1.236	1.488	1.156	1.393	1.464	1.869	1.704	2.219
   8 users	1.512	1.751	1.403	1.852	1.741	2.031	2.02	2.274
   20 users	1.649	1.898	1.535	1.996	1.896	2.211	2.252	2.539

   
   

2. Slow APIs taking more than 100 ms to return

   API	1 user (75th %tile)	5 users (75th %tile)	8 users (75th %tile)	20 Users (75th %tile)
   POST checkout-by-barcode	615 ms	905 ms	906 ms	988 ms
   POST checkin-by-barcode	548 ms	830 ms	1053 ms	1137 ms
   Get circulation/loans	283 ms	346 ms	449 ms	479 ms
   Get inventory/items	217 ms	232 ms	237 ms	281 ms

   
   

JVM Profiling

• Overall slow methods (between the modules profiled: okapi, mod-circulation, mod-circulation-storage, mod-inventory, mod-inventory-storage)
  • 
  • To see more drill down these methods at: http://ec2-3-93-19-104.compute-1.amazonaws.com/grafana/d/b2iP-9hiz/java-profiling-folio?orgId=1&from=1589940345995&to=1589943180494&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

...

• • Can drill down these methods for more information at : http://ec2-3-93-19-104.compute-1.amazonaws.com/grafana/d/b2iP-9hiz/java-profiling-folio?orgId=1&from=1590418466176&to=1590420349447&var-service_tag=mod-inventory&var-aggregation=10s
    • Areas of code that serializes and deserializes JSON objects
      • org.folio.inventory.storage.external.ExternalStorageModuleCollection
      • org.forlio.inventory.resources.Items$$Lambdas...apply()
      • org.folio.okapi.util.LockedStringMap.lambda$getString()
      • org.folio.okapi.util.LockedTypedMap.lambda...handle()
      • org.folio.okapi.managers..proxy
      • org.folio.cql2pgjson.CQL2PgJSON.loadDbSchema
      • org.folio.rest.persist.PostgresClient.deserializeRow
    • Logging
      • org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled
      • org.apache.logging.slf4j.Log4jLogger.info
    • org.joda.time.DateTime.parse
      • org.folio.circulation.domain.Loan.getReturnDate
      • org.folio.circulation.domain.Loan.getDueDate

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.

...

...

WARNING: Doing SQL query without index for scheduled_notice.jsonb->>'nextRunTime', CQL >>> SQL: nextRunTime < >>> scheduled_notice.jsonb->>'nextRunTime' <'2020-05-20T03:07:08.090Z'
WARNING: Doing FT search without index for request.jsonb->>'pickupServicePointId', CQL >>> SQL: pickupServicePointId = 130d8bff-bdbd-4dc5-a4ac-6d970f4918ff >>> to_tsvector('simple', f_unaccent(request.jsonb->>'pickupServicePointId')) @@ replace((to_tsquery('simple', f_unaccent('''130d8bff-bdbd-4dc5-a4ac-6d970f4918ff''')))::text, '&', '<->')::tsquery
WARNING: Doing FT search without index for request.jsonb->>'requesterId', CQL >>> SQL: requesterId = 001164c0-5466-4822-86f2-dcd2393a7ef7 >>> to_tsvector('simple', f_unaccent(request.jsonb->>'requesterId')) @@ replace((to_tsquery('simple', f_unaccent('''001164c0-5466-4822-86f2-dcd2393a7ef7''')))::text, '&', '<->')::tsquery
WARNING: Doing FT search without index for request.jsonb->>'status', CQL >>> SQL: status = Open >>> to_tsvector('simple', f_unaccent(request.jsonb->>'status')) @@ replace((to_tsquery('simple', f_unaccent('''Open''')))::text, '&', '<->')::tsquery
WARNING: Doing LIKE search without index for jsonb->>'requestId', CQL >>> SQL: requestId == 01819cdb-de38-4562-9835-14071dcaf53d >>> lower(f_unaccent(jsonb->>'requestId')) LIKE lower(f_unaccent('01819cdb-de38-4562-9835-14071dcaf53d'))
WARNING: Doing LIKE search without index for request.jsonb->>'requesterId', CQL >>> SQL: requesterId == 005de89f-bfe1-4bf7-a1e3-f34a707ace21 >>> lower(f_unaccent(request.jsonb->>'requesterId')) LIKE lower(f_unaccent('005de89f-bfe1-4bf7-a1e3-f34a707ace21'))

Recommended Improvements 

Anchor
recommendedImprovements recommendedImprovements

• In mod-circulation and okapi consider using a more efficient JSON package or calling use the existing jackson serialization calls in a different way to address the item: JVM profiling shows JSON de/serialization operations one of the slowest operations.
• In mod-circulation consider using a more efficient date-time package instead of joda time because it's one of the slowest operations.
• Consider logging with ERROR level if not fixing the JIRA below to reduce the excess logging by mod-circulation-storage

• Have follow-up stories to study the performance of the four APIs that are still taking over 100ms to return to see where performance could improve.

Appendix

For more raw data of the test runs please see the attached check-in-check-out-FF-UChicago.xlsx.

...