Loading items on instance record (in holdings accordion) Test Report (Fameflower)
https://folio-org.atlassian.net/browse/PERF-40
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. https://folio-org.atlassian.net/browse/PERF-40 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
Slow APIs taking more than 100ms to run:
GET source-storage/formattedRecords/{id}
GET inventory/instances keyword all "aba"
POST checkout-by-barcode
GET inventory/items
GET inventory/instances/{id}
GET circulation/loans
GET locations
GET circulation/requests
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
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%.
JVM profiling shows the slowest operations, totaling more CPU time than other calls:
Get module for request
JSON de/serialization
logging with INFO level
Test Runs
Test | Virtual Users | Duration | OKAPI log level | Profiled | Ramp up (total time in seconds) |
1. | 1 | 30 min | INFO | No | 1 |
2. | 5 | 30 min | INFO | No | 50 |
3. | 8 | 30 min | INFO | No | 80 |
4. | 20 | 30 min | INFO | No | 200 |
5. | 1 | 30 min | INFO | Yes | 1 |
6. | 5 | 30 min | INFO | Yes | 50 |
7. | 8 | 30 min | INFO | Yes | 80 |
8. | 20 | 30 min | INFO | Yes | 200 |
Results
Overall load items workflow time in seconds
Slow APIs taking more than 100 ms to return
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:
Percent of total time | Average Time,ms | Calls | Module | Query |
52% | 20,855 ms | 1,325 | mod_source_record_storage | select get_record_by_external_id($1, $2) Examples: EXPLAIN ANALYZE select get_record_by_external_id('89a7ec1c-608f-4d24-90b6-57da21557874', 'instanceId') EXPLAIN ANALYZE select get_record_by_external_id('1abdfd67-a4c3-46ba-a66b-82619f633e9a', 'instanceId') EXPLAIN ANALYZE select get_record_by_external_id('ff2f06c1-caf7-427a-9544-d8716eda90a6', 'instanceId') |
0.8% | 669 ms | 658 | mod_inventory_storage | WITH headrecords AS ( SELECT jsonb, lower(f_unaccent(jsonb->>$1)) AS title FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector($2, f_unaccent(concat_space_sql(instance.jsonb->>$3 , concat_array_object_values(instance.jsonb->$4,$5) , concat_array_object_values(instance.jsonb->$6,$7)))) @@ (to_tsquery($8, f_unaccent($9)))) AND left(lower(f_unaccent(jsonb->>$10)),$11) < ( SELECT left(lower(f_unaccent(jsonb->>$12)),$13) FROM fs09000000_mod_inventory_storage.instance ORDER BY left(lower(f_unaccent(jsonb->>'title')),600) OFFSET $14 LIMIT $15 ) ORDER BY left(lower(f_unaccent(jsonb->>$16)),$17) LIMIT $18 OFFSET $19 ), allrecords AS ( SELECT jsonb, lower(f_unaccent(jsonb->>$20)) AS title FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector($21, f_unaccent(concat_space_sql(instance.jsonb->>$22 , concat_array_object_values(instance.jsonb->$23,$24) , concat_array_object_values(instance.jsonb->$25,$26)))) @@ (to_tsquery($27, f_unaccent($28)))) AND (SELECT COUNT(*) FROM headrecords) < $29 ) SELECT jsonb, title, $30 AS count FROM headrecords WHERE (SELECT COUNT(*) FROM headrecords) >= $31 UNION (SELECT jsonb, title, (SELECT COUNT(*) FROM allrecords) AS count FROM allrecords ORDER BY title LIMIT $32 OFFSET $33 ) ORDER BY title
E.x. WITH headrecords AS ( SELECT jsonb, lower(f_unaccent(jsonb->>'title')) AS title FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector('simple', f_unaccent(concat_space_sql(instance.jsonb->>'title' , concat_array_object_values(instance.jsonb->'contributors','name') , concat_array_object_values(instance.jsonb->'identifiers','value')))) @@ (to_tsquery('simple', f_unaccent('''aba''')))) AND left(lower(f_unaccent(jsonb->>'title')),600) < ( SELECT left(lower(f_unaccent(jsonb->>'title')),600) FROM fs09000000_mod_inventory_storage.instance ORDER BY left(lower(f_unaccent(jsonb->>'title')),600) OFFSET 10000 LIMIT 1 ) ORDER BY left(lower(f_unaccent(jsonb->>'title')),600) LIMIT 100 OFFSET 0 ), allrecords AS ( SELECT jsonb, lower(f_unaccent(jsonb->>'title')) AS title FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector('simple', f_unaccent(concat_space_sql(instance.jsonb->>'title' , concat_array_object_values(instance.jsonb->'contributors','name') , concat_array_object_values(instance.jsonb->'identifiers','value')))) @@ (to_tsquery('simple', f_unaccent('''aba''')))) AND (SELECT COUNT(*) FROM headrecords) < 100 ) SELECT jsonb, title, 0 AS count FROM headrecords WHERE (SELECT COUNT(*) FROM headrecords) >= 100 UNION (SELECT jsonb, title, (SELECT COUNT(*) FROM allrecords) AS count FROM allrecords ORDER BY title LIMIT 100 OFFSET 0 ) ORDER BY title |
0.8% | 214 ms | 1,918 | mod_circulation_storage | SELECT COUNT(*) FROM (SELECT jsonb,id FROM fs09000000_mod_circulation_storage.request WHERE (to_tsvector($1, f_unaccent(request.jsonb->>$2)) @@ replace((to_tsquery($3, f_unaccent($4)))::text, $5, $6)::tsquery) AND (to_tsvector($7, f_unaccent(request.jsonb->>$8)) @@ replace((to_tsquery($9, f_unaccent($10)))::text, $11, $12)::tsquery) LIMIT $13) x E.x. SELECT COUNT(*) FROM (SELECT jsonb,id FROM fs09000000_mod_circulation_storage.request WHERE (to_tsvector('simple', f_unaccent(request.jsonb->>'requesterId')) @@ replace((to_tsquery('simple', f_unaccent('''c2d0fc7d-85a9-4527-945d-6e5e29e74efc''')))::text, '&', '<->')::tsquery) AND (to_tsvector('simple', f_unaccent(request.jsonb->>'status')) @@ replace((to_tsquery('simple', f_unaccent('''Open''')))::text, '&', '<->')::tsquery) LIMIT 100) x |
0.6% | 177 ms | 1,914 | mod_inventory_storage | SELECT COUNT(*) FROM (SELECT jsonb,id FROM fs09000000_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->>$1)) LIKE lower(f_unaccent($2)) LIMIT $3) x E.x. SELECT COUNT(*) FROM (SELECT jsonb,id FROM fs09000000_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->>'barcode')) LIKE lower(f_unaccent('19878861')) LIMIT 1) x |