PERF-40 - Getting issue details... STATUS

Overview

In this workflow we are checking the performance of the loading items on instance record (in holdings accordion) workflow running in the Fameflower release.  The series of steps can be found in the attached screencast.  PERF-40 - Getting issue details... STATUS We tested it with 1, 5, 8, and 20 virtual users for 30 minutes.  A longevity test will also be executed to see if there were memory issues.

Backend:

• mod-inventory-storage-19.1.2
• mod-inventory-14.1.3
• mod-circulation-18.0.9
• mod-circulation-storage-11.0.8
• okapi-2.38.0
• mod-authtoken-2.4.0
• mod-permissions-5.9.0
• mod-data-export-1.1.1
• mod-source-record-storage-3.1.4
• mod-source-record-manager-2.1.4

Frontend:

• folio_inventory-2.0.2
• 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

1. Slow APIs taking more than 100ms to run:
   1. GET source-storage/formattedRecords/{id}
   2. GET inventory/instances keyword all "aba"
   3. POST checkout-by-barcode
   4. GET inventory/items
   5. GET inventory/instances/{id}
   6. GET circulation/loans
   7. GET locations
   8. GET circulation/requests
2. Some mod_source_record_storage's, mod-inventory-storage's, mod-circulation-storage's SQL queries took more than 500 ms to run, see the Slow Queries section and Recommended Improvements for the JIRAs created to address these SQL queries
3. On average, the performance can be improved by 100%. if we remove redundant "EXPLAIN ANALYZE" query call on mod_source_record_storage module. EXPLAIN ANALYZE statements are debugging statements that added a second execution (along with the first one) therefore increasing the overall time by 100%. 
4. JVM profiling shows the slowest operations, totaling more CPU time than other calls:
   
   1. Get module for request
   2. JSON de/serialization
   3. logging with INFO level

Test Runs

Results

1. Overall load items workflow time in seconds

   	Average	50th %tile	75th %tile	95th %tile
   1 user	14.39 s	14.39 s	14.39 s	14.39 s
   5 users	46.30 s	45.75 s	46.57 s	46.59 s
   8 users	1.24 min	1.21 min	1.25 min	1.25 min
   20 users	3.10 min	3.05 min	3.12 min	3.12 min

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)
   Inventory
   GET source-storage/formattedRecords/{id}	5.32 s	19.92 s	34.83 s	1.46 min
   GET inventory/instances keyword all "aba"	355.60 ms	753.86 ms	909.02 ms	2.87 s
   GET locations	221.09 ms	142.89 ms	152.26 ms	205.71 ms
   GET inventory/items	164.45 ms	251.71 ms	286.87 ms	405.85 ms
   GET inventory/instances/{id}	119.93 ms	115.98 ms	123.88 ms	131.89 ms
   Check Out
   POST circulation/check-out-by-barcode	679.72 ms	1.04 s	1.11 s	1.45 s
   GET circulation/loans	221.95 ms	254.08 ms	251.45 ms	256.18 ms
   GET circulation/requests	81.77 ms	212.38 ms	257.80 ms	443.79 ms
   GET inventory/items	164.45 ms	251.71 ms	286.87 ms	405.85 ms

JVM Profiling

• Overall slow methods (between the modules profiled: okapi, mod-inventory, mod-inventory-storage, mod-circulation, mod-circulation-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&var-service_tag=okapi&var-service_tag=mod-inventory-storage&var-service_tag=mod-inventory&var-aggregation=10s&from=1590418466176&to=1590420349447

• Only slow Okapi methods:

When drilling down org.folio.okapi.managers.ProxyService.getModulesForRequest , 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.folio.okapi.managers.ProxyService&method=getModulesForRequest&from=1590418466176&to=1590420349447

• Slow mod-inventory methods:

• 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=1589940195166&to=1589943457693&var-service_tag=mod-circulation&var-aggregation=10s

Database

Database show much CPU usage for 5, 8 and 20 users runs.  100% CPU usage for 5, 8, 20 users. Some mod_source_record_storage's, mod-inventory-storage's, mod-circulation-storage's SQL queries took more than 500ms to run, see the Slow Queries section and Recommended Improvements for the JIRAs created to address these SQL queries.

There aren't any WARNING statements of missing indexes in mod-inventory-storage, mod-source-record-storage modules.

The following WARNING statements of missing indexes were generated during a test run and logged by mod-circulation-storage:

WARNING: Doing LIKE search without index for request.jsonb->>'requesterId', CQL >>> SQL: requesterId == a79b533d-8f29-4be1-9415-5f5cd936623b >>> lower(f_unaccent(request.jsonb->>'requesterId')) LIKE lower(f_unaccent('a79b533d-8f29-4be1-9415-5f5cd936623b'))
WARNING: Doing FT search without index for request.jsonb->>'pickupServicePointId', CQL >>> SQL: pickupServicePointId = 51787734-d899-41e6-b6b2-e531a315fd61 >>> to_tsvector('simple', f_unaccent(request.jsonb->>'pickupServicePointId')) @@ replace((to_tsquery('simple', f_unaccent('''51787734-d899-41e6-b6b2-e531a315fd61''')))::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 SQL query without index for scheduled_notice.jsonb->>'nextRunTime', CQL >>> SQL: nextRunTime < 2020-05-27T00:00:00.000Z >>> scheduled_notice.jsonb->>'nextRunTime' <'2020-05-27T00:00:00.000Z'
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 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 patron_action_session.jsonb->>'patronId', CQL >>> SQL: patronId == a79b533d-8f29-4be1-9415-5f5cd936623b >>> lower(f_unaccent(patron_action_session.jsonb->>'patronId')) LIKE lower(f_unaccent('a79b533d-8f29-4be1-9415-5f5cd936623b'))
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'))

Database Slow queries 

Slowest queries which took the most of execution time were initiated by the mod_source_record_storage, mod-inventory-storage and mod_circulation_storage services presented in the following table:

CPU Utilization

Memory

Memory was stable throughout the runs, only a spike here or there, but in a 30 minutes run they were consistent. 

Recommended Improvements 

• The following JIRAs have been created for mod_source_record_storage:

MODSOURCE-149 - Getting issue details... STATUS

MODSOURCE-150 - Getting issue details... STATUS

• On average, the performance can be improved by 100%. if we remove redundant "EXPLAIN ANALYZE" query call on mod_source_record_storage module. EXPLAIN ANALYZE statements are debugging statements that added a second execution (along with the first one) therefore increasing the overall time by 100%. 
• Missing Indexes Warnings are covered by the story CIRCSTORE-215 - Getting issue details... STATUS
• In mod-inventory-storage 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.

Appendix

See Attached FameFlower Performance Test Runs.xlsx for details