...

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
   (seconds)50th %tile (seconds)75th %tile (seconds)95th %tile  (seconds)Check-inCheck-outCheck-inCheck-outCheck-inCheck-outCheck-inCheck-out1 user1.0151.2340.961.2771.0711.4091.3221.6535 users1.2361.4881.1561.3931.4641.8691.7042.2198 users1.5121.7511.4031.8521.7412.0312.022.27420 users1.6491.8981.5351.9961.8962.2112.2522.539

   Slow APIs taking more than 100 ms to return

   API1 user (75th %tile)5 users (75th %tile)8 users (75th %tile)20 Users (75th %tile)POST checkout-by-barcode615 ms905 ms906 ms988 ms

   POST checkin-by-barcode 

   548 ms830 ms1053 ms1137 msGet circulation/loans283 ms346 ms449 ms479 msGet inventory/items217 ms232 ms237 ms281 msExcess logging of 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.
2. JVM profiling shows JSON de/serialization operations one of the slowest operations.

Test Runs

...

Test

...

Virtual Users

...

Duration

...

OKAPI log level

...

Profiled

...

1.

...

1

...

30 min

...

INFO

...

No

...

2.

...

5

...

30 min

...

INFO

...

No

...

3.

...

8

...

30 min

...

INFO

...

No

...

4.

...

20

...

20 min

...

INFO

...

No

...

5.

...

8

...

42 min

...

INFO

...

Yes

Results

JVM Profiling

...

1. 1. 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 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

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=15899401951661590418466176&to=15899434576931590420349447&var-service_tag=mod-circulationinventory&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'))
WARNING: Doing LIKE search without index for patron_action_session.jsonb->>'actionType', CQL >>> SQL: actionType == Check-out >>> lower(f_unaccent(patron_action_session.jsonb->>'actionType')) LIKE lower(f_unaccent('Check-out'))
WARNING: Doing LIKE search without index for scheduled_notice.jsonb->>'triggeringEvent', CQL >>> SQL: triggeringEvent == "Due date" >>> lower(f_unaccent(scheduled_notice.jsonb->>'triggeringEvent')) LIKE lower(f_unaccent('Due date'))
WARNING: Doing LIKE search without index for scheduled_notice.jsonb->'noticeConfig'->>'sendInRealTime', CQL >>> SQL: noticeConfig.sendInRealTime == false >>> lower(f_unaccent(scheduled_notice.jsonb->'noticeConfig'->>'sendInRealTime')) LIKE lower(f_unaccent('false'))
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 SQL query without index for scheduled_notice.jsonb->>'nextRunTime', CQL >>> SQL: nextRunTime < 2020-05-20T00:00:00.000Z >>> scheduled_notice.jsonb->>'nextRunTime' <'2020-05-20T00:00:00.000Z'

CPU Utilization

...

' <'2020-05-20T00:00:00.000Z'

CPU Utilization

...