Versions Compared

Version Old Version 17 New Version 18
Changes made by

Svitlana Zmiivska (Deactivated)

Svitlana Zmiivska (Deactivated)

Saved on

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.

FameFlower Test Results

Table of Contents

Overview

Jira LegacyserverSystem Jiracolumnskey,summary,type,created,updated,due,assignee,reporter,priority,status,resolutionFameFlower Test Results

Table of Contents

Overview

Jira Legacy
serverSystem Jira
columnskey,summary,type,created,updated,due,assignee,reporter,priority,status,resolution
serverId01505d01-b853-3c2e-90f1-ee9b165564fc
keyPERF-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.

Backend:
- mod-inventory-storage-19.1.2
- mod-inventory-14.1.3
- mod-authtoken-2.4.0
- mod-permissions-5.9.0
- okapi-2.38.0

- mod-circulation-18.0.9

- mod-circulation-storage-11.0.8


Frontend:
- folio_inventory-2.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. 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
    serverSystem Jira
    serverId01505d01-b853-3c2e-90f1-ee9b165564fc
    key

...

  1. CIRCSTORE-

...

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.

Backend:
- mod-inventory-storage-19.1.2
- mod-inventory-14.1.3
- mod-authtoken-2.4.0
- mod-permissions-5.9.0
- okapi-2.38.0

- mod-circulation-18.0.9

- mod-circulation-storage-11.0.8

Frontend:
- folio_inventory-2.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 
    215
  2. 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

  1. Overall load items workflow time in seconds


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





    1 user1.0150.9614.67 s1.322
    5 users1.2361.1561.4641.704
    8 users1.5121.4031.7412.02
    20 users1.6491.5351.8962.252


  2. 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)
    GET source-storage/formattedRecords/{id}5.32 s19.92 s34.83 s1.46 min

    GET inventory/instances keyword all "aba"

    		355.60 ms
  3. POST checkout-by-barcode
    4. GET inventory/items
    753.86 ms909.02 ms2.87 s
    POST circulation/check-out-by-barcode679.72 ms1.04 s1.11 s1.45 s
    GET inventory/items164.45 ms251.71 ms286.87 ms405.85 ms
    GET inventory/instances/{id}119.93 ms115.98 ms123.88 ms131.89 ms
    GET circulation/loans221.95 ms254.08 ms251.45 ms256.18 ms
    GET locations221.09 ms142.89 ms152.26 ms205.71 ms
    GET circulation/requests
    mod-inventory-storage log warnings for
    81.77 ms212.38 ms257.80 ms443.79 ms


  4. 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. Adding the missing indexes could improve performance while stop logging these warnings 
    Jira Legacy
    serverSystem Jira
    serverId01505d01-b853-3c2e-90f1-ee9b165564fc
    keyCIRCSTORE-215
    data to work with should there be a need to troubleshoot.


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

...

Slow APIs taking more than 100 ms to return

...

GET inventory/instances keyword all "aba"

...

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)

Image Removed

  • Only slow Okapi methods:

Image Removed

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

Image Removed

  • Slow mod-inventory methods:

Image Removed

Database

Database show much CPU usage for 5, 8 and 20 users runs.  100% CPU usage for 5, 8, 20 users.

Image Removed

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:

...

languagesql
linenumberstrue

...

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)


Image Added

  • Only slow Okapi methods:

Image Added

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

Image Added

  • Slow mod-inventory methods:


Image Added

Database

Database show much CPU usage for 5, 8 and 20 users runs.  100% CPU usage for 5, 8, 20 users.

Image Added

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
languagesql
linenumberstrue
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: requesterIdnextRunTime ==< a79b533d2020-8f29-4be1-9415-5f5cd936623b05-27T00:00:00.000Z >>> lower(f_unaccent(requestscheduled_notice.jsonb->>'requesterIdnextRunTime')) LIKE lower(f_unaccent('a79b533d-8f29-4be1-9415-5f5cd936623b')) <'2020-05-27T00:00:00.000Z'
WARNING: Doing FTLIKE search without index for requestscheduled_notice.jsonb->'noticeConfig'->>'pickupServicePointIdsendInRealTime', CQL >>> SQL: pickupServicePointIdnoticeConfig.sendInRealTime == 51787734-d899-41e6-b6b2-e531a315fd61false >>> to_tsvector('simple', lower(f_unaccent(requestscheduled_notice.jsonb->'noticeConfig'->>'pickupServicePointIdsendInRealTime')) @@LIKE replace((to_tsquery('simple', lower(f_unaccent('''51787734-d899-41e6-b6b2-e531a315fd61''')))::text, '&', '<->')::tsquery
false'))
WARNING: Doing FTLIKE search without index for requestscheduled_notice.jsonb->>'statustriggeringEvent', CQL >>> SQL: statustriggeringEvent == Open"Due date" >>> to_tsvector('simple', lower(f_unaccent(requestscheduled_notice.jsonb->>'status')) @@ replace((to_tsquery('simple', 'triggeringEvent')) LIKE lower(f_unaccent('''Open''')))::text, '&', '<->')::tsqueryDue date'))
WARNING: Doing SQLLIKE querysearch without index for scheduledpatron_action_noticesession.jsonb->>'nextRunTimepatronId', CQL >>> SQL: nextRunTimepatronId < 2020-05-27T00:00:00.000Z >>> scheduled_notice== a79b533d-8f29-4be1-9415-5f5cd936623b >>> lower(f_unaccent(patron_action_session.jsonb->>'nextRunTimepatronId' <'2020-05-27T00:00:00.000Z')) LIKE lower(f_unaccent('a79b533d-8f29-4be1-9415-5f5cd936623b'))
WARNING: Doing LIKE search without index for scheduledpatron_action_noticesession.jsonb->'noticeConfig'->>'sendInRealTimeactionType', CQL >>> SQL: noticeConfig.sendInRealTimeactionType == falseCheck-out >>> lower(f_unaccent(scheduledpatron_action_noticesession.jsonb->'noticeConfig'->>'sendInRealTimeactionType')) 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

...

Query

...

select get_record_by_external_id($1, $2)

Examples:

...

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

...

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:


SELECTCOUNT(*) FROM (SELECT jsonb,idFROM fs09000000_mod_inventory_storage.item WHERElower(f_unaccent(item.jsonb->>$1)) LIKElower(f_unaccent($2)) LIMIT $3) xSELECT jsonb,idFROM fs09000000_mod_inventory_storage.item WHERElower(f_unaccent(item.jsonb->>$1)) LIKElower(f_unaccent($2)) LIMIT $3OFFSET $4

Percent of total time

Average Time,ms

Calls

Module

Query

52%20,855 ms 1,325mod_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 ms658mod_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->>$

1

20)) AS title FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector($

2

21, f_unaccent(concat_space_sql(instance.jsonb->>$

3

22 , concat_array_object_values(instance.jsonb->$

4

23,$

5

24) , concat_array_object_values(instance.jsonb->$

6

25,$

7

26)))) @@ (to_tsquery($

8

27, f_unaccent($

9

28)))) AND

left

(

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

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-

>>$2021

>>'title')) AS title FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector(

$

'simple', f_unaccent(concat_space_sql(instance.jsonb-

>>$22

>>'title' , concat_array_object_values(instance.jsonb-

>$23,$24

>'contributors','name') , concat_array_object_values(instance.jsonb-

>$25,$2627

>'identifiers','value')))) @@ (to_tsquery(

$		0.6%177 ms1,914mod_inventory_storage0.6%165 ms1,914mod_inventory_storage0.4%1,299 ms159mod_inventory_storageEXPLAINANALYZEWITH 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''')))) ANDleft(lower(f_unaccent(jsonb->>'title')),600) < ( SELECTleft(lower(f_unaccent(jsonb->>'title')),600)

'simple', 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
0.8%214 ms1,918mod_circulation_storageSELECT 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

'''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 ms1,918mod_circulation_storageSELECT 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 ms1,914mod_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.

instance ORDERBYleft(

item WHERE lower(f_unaccent(item.jsonb->>'

title

barcode'))

,600) OFFSET10000LIMIT1 ) ORDERBYleft(

LIKE lower(f_unaccent(

jsonb->>

'

title

19878861'))

,600) LIMIT100OFFSET0 ), allrecords AS ( SELECT jsonb, lower(f_unaccent(jsonb->>'title')) AS title

LIMIT 1) x

0.6%165 ms1,914mod_inventory_storage

SELECT jsonb,idFROM 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 (SELECTCOUNT(*) FROM headrecords) < 100 ) SELECT jsonb, title, 0AScountFROM headrecords WHERE (SELECTCOUNT(*) FROM headrecords) >= 100UNION (SELECT jsonb, title, (SELECTCOUNT(*) FROM allrecords) AScountFROM allrecords ORDERBY title LIMIT100OFFSET0 ) ORDERBY title

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 user5 users8 users20 users

Average %Range %Average %Range %Average %Range %Average %Range %
Okapi2.120.29-8.942.871.56-13.652.780.31-16.822.850.32-11.65
mod-inventory0.840.31-14.820.680.30-4.010.670.26-7.790.650.27-3.72
mod-inventory-storage1.590.33-8.171.870.56-9.251.810.24-9.151.780.25-23.28
mod-circulation0.670.24-4.120.820.48-4.440.960.26-4.040.820.28-4.12
mod-circulation-storage0.710.25-6.600.740.31-2.790.860.29-3.270.710.27-2.50
mod-source-record-storage0.340.23-1.430.500.26-1.860.530.31-2.410.430.29-1.92

...

Jira Legacy
serverSystem Jira
serverId01505d01-b853-3c2e-90f1-ee9b165564fc
keyMODSOURCE-150

Appendix

See Attached FameFlower Performance Test Runs.xlsx for details