Versions Compared

Old Version 43

changes.mady.by.user Svitlana Zmiivska (Deactivated)

Saved on

compared with

New Version Current

changes.mady.by.user Svitlana Zmiivska (Deactivated)

Saved on

Key

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

Jira Legacy
serverSystem JiraJIRA
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.  The series of steps can be found in the attached screencast. 

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

...

  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 500ms 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

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

...

  1. Overall load items workflow time in seconds


    		Average 50th %tile 75th %tile95th %tile 
    1 user14.39 s14.39 s14.39 s14.39 s
    5 users46.30 s45.75 s46.57 s46.59 s
    8 users1.24 min1.21 min1.25 min1.25 min
    20 users3.10 min3.05 min3.12 min3.12 min


  2. Slow APIs taking more than 100 ms to return

    1.45 s
    API1 user (75th %tile)5 users (75th %tile)8 users (75th %tile)20 Users (75th %tile)
    Loading items on instance record (in holdings accordion)
    GET source-storage/formattedRecords/{id}5.32 s19.92 s34.83 s1.46 min

    GET inventory/instances keyword all "aba"

    		355.60 ms753.86 ms909.02 ms2.87 sPOST circulation/check-out-by-barcode679.72 ms1.04 s1.11 s
    GET locations221.09 ms142.89 ms152.26 ms205.71 ms
    GET inventory/items164.45 ms251.71 ms286.87 ms405.85 ms
    GET inventory/instances/{id}119.93 ms115.98 ms123.88 ms131.89 ms
    Check Out
    POST circulation/check-out-by-barcode679.72 ms1.04 s1.11 s1.45 s
    GET circulation/loans221.95 ms254.08 ms251.45 ms256.18 ms
    GET locationscirculation/requests22181.09 77 ms142212.89 38 ms152257.26 80 ms205443.71 79 ms
    GET circulationinventory/requestsitems81164.77 45 ms212251.38 71 ms257286.80 87 ms443405.79 85 ms


JVM Profiling

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

...

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:

...

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,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->>$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.

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 ms1,918mod_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 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.item WHERE lower(f_unaccent(item.jsonb->>'barcode')) LIKE lower(f_unaccent('19878861')) LIMIT 1) x

0.6%165 ms1,914mod_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 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

...

  • The following JIRAs have been created for mod_source_record_storage:

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

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

  • 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
    Jira Legacy
    serverSystem JiraJIRA
    serverId01505d01-b853-3c2e-90f1-ee9b165564fc
    keyCIRCSTORE-215
  • 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 Runsload-item-records-FF.xlsx for details