FameFlower Test Results

Table of Contents

Overview

Jira Legacy

server	System Jira
columns	key,summary,type,created,updated,due,assignee,reporter,priority,status,resolution
serverId	01505d01-b853-3c2e-90f1-ee9b165564fc
key	PERF-40

...

In this workflow we are checking the performance of the loading items on instance record (in holdings accordion) workflow running in the Fameflower release. We will test 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.

...

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
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
mod-inventory-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. 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
JVM profiling shows JSON de/serialization operations one of the slowest operations, totaling more CPU time than other calls. Since FOLIO modules retrieves and stores JSON objects, making sure that serialization and deserialization JSON efficient is essential, see Recommended Improvements

Test Runs

Overall load items workflow time in seconds

Average (seconds) 50th %tile (seconds) 75th %tile (seconds) 95th %tile (seconds)

1 user 1.015 0.96 14.67 s 1.322
5 users 1.236 1.156 1.464 1.704
8 users 1.512 1.403 1.741 2.02
20 users 1.649 1.535 1.896 2.252

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)
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
POST circulation/check-out-by-barcode	679.72 ms	1.04 s	1.11 s	1.45 s
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
GET circulation/loans	221.95 ms	254.08 ms	251.45 ms	256.18 ms
GET locations	221.09 ms	142.89 ms	152.26 ms	205.71 ms
GET circulation/requests	81.77 ms	212.38 ms	257.80 ms	443.79 ms

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.
JVM profiling shows JSON de/serialization operations one of the slowest operations.

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

formattedRecords

Results

JVM Profiling

Overall slow methods (between the modules profiled: okapi, mod-inventory, mod-inventory-storage, mod-circulation, mod-circulation-storage)

...

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.

...

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:

Code Block

language	sql
linenumbers	true

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'))

6. 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: EXPLAINANALYZEselect 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)))) ANDleft(lower(f_unaccent(jsonb->>$10)),$11) < ( SELECTleft(lower(f_unaccent(jsonb->>$12)),$13) FROM fs09000000_mod_inventory_storage.instance ORDERBYleft(lower(f_unaccent(jsonb->>'title')),600) OFFSET $14LIMIT $15 ) ORDERBYleft(lower(f_unaccent(jsonb->>$16)),$17) LIMIT $18OFFSET $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 (SELECTCOUNT() FROM headrecords) < $29 ) SELECT jsonb, title, $30AScountFROM headrecords WHERE (SELECTCOUNT() FROM headrecords) >= $31UNION (SELECT jsonb, title, (SELECTCOUNT() FROM allrecords) AScountFROM allrecords ORDERBY title LIMIT $32OFFSET $33 ) ORDERBY title E.x. EXPLAIN ANALYZE 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
0.6%	177 ms	1,914	mod_inventory_storage	SELECTCOUNT() FROM (SELECT jsonb,idFROM fs09000000_mod_inventory_storage.item WHERElower(f_unaccent(item.jsonb->>$1)) LIKElower(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
0.6%	165 ms	1,914	mod_inventory_storage	SELECT jsonb,idFROM fs09000000_mod_inventory_storage.item WHERElower(f_unaccent(item.jsonb->>$1)) LIKElower(f_unaccent($2)) LIMIT $3OFFSET $4 E.x. SELECT jsonb,idFROM fs09000000_mod_inventory_storage.item WHERE lower(f_unaccent(item.jsonb->>'barcode')) LIKE lower(f_unaccent('19878861')) LIMIT 1 OFFSET 0

CPU Utilization

	1 user		5 users		8 users		20 users
	Average %	Range %	Average %	Range %	Average %	Range %	Average %	Range %
Okapi	2.12	0.29-8.94	2.87	1.56-13.65	2.78	0.31-16.82	2.85	0.32-11.65
mod-inventory	0.84	0.31-14.82	0.68	0.30-4.01	0.67	0.26-7.79	0.65	0.27-3.72
mod-inventory-storage	1.59	0.33-8.17	1.87	0.56-9.25	1.81	0.24-9.15	1.78	0.25-23.28
mod-circulation	0.67	0.24-4.12	0.82	0.48-4.44	0.96	0.26-4.04	0.82	0.28-4.12
mod-circulation-storage	0.71	0.25-6.60	0.74	0.31-2.79	0.86	0.29-3.27	0.71	0.27-2.50
mod-source-record-storage	0.34	0.23-1.43	0.50	0.26-1.86	0.53	0.31-2.41	0.43	0.29-1.92

Memory

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

	1 user	5 users	8 users	20 users
	Average	Average	Average	Average
Okapi	40%	42%	40%	40%
mod-inventory	40%	43%	44%	43%
mod-inventory-storage	40%	40%	41%	41%
mod-circulation	72%	75%	72%	74%
mod-circulation-storage	32%	32%	32%	32%
mod-source-record-storage	53%	53%	53%	53%

Recommended Improvements

On average, we can improve performance by 50% if we remove redundant "EXPLAIN ANALYZE" query call on mod_source_record_storage.records table

...

Jira Legacy

server	System Jira
serverId	01505d01-b853-3c2e-90f1-ee9b165564fc
key	MODSOURCE-150

Appendix

See Attached FameFlower Performance Test Runs.xlsx for details

Version	Old Version 18	New Version 19
Changes made by	Svitlana Zmiivska (Deactivated)	Svitlana Zmiivska (Deactivated)
Saved on	May 31, 2020	May 31, 2020

Versions Compared

Key

Overview

High Level Summary

Test Runs

Test Runs

Results

JVM Profiling

Database

6. Database Slow queries

CPU Utilization

Memory

Recommended Improvements

Appendix

	Average (seconds)	50th %tile (seconds)	75th %tile (seconds)	95th %tile (seconds)

1 user	1.015	0.96	14.67 s	1.322
5 users	1.236	1.156	1.464	1.704
8 users	1.512	1.403	1.741	2.02
20 users	1.649	1.535	1.896	2.252

Page Comparison

Versions Compared

Key

Overview

High Level Summary

Test Runs

Test Runs

Results

JVM Profiling

Database

6. Database Slow queries

CPU Utilization

Memory

Recommended Improvements

Appendix