...
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)
- 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.
The following WARNING statements of missing indexes were generated during a test run and logged by mod-source-record-storage:
...
FameFlower Test Results
| Table of Contents |
|---|
Overview
| Jira Legacy | ||||||||
|---|---|---|---|---|---|---|---|---|
|
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
Overall check in, check out time in seconds
- Average check in time is 1.51 seconds for a typical use case of 8 users, 1.65 seconds for 20 users
- Average check out time is 1.75 seconds for a typical use case of 8 users, 1.90 seconds for 20 users
- Slow APIs taking more than 100ms to run
- POST checkout-by-barcode
- POST checkin-by-barcode
- Get circulation/loans
- Get inventory/items
- 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
...
Slow APIs taking more than 100 ms to return
...
GET inventory/instances keyword all "aba"
...
FameFlower Test Results
| Table of Contents |
|---|
Overview
| Jira Legacy | ||||||||
|---|---|---|---|---|---|---|---|---|
|
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
Overall check in, check out time in seconds
- Average check in time is 1.51 seconds for a typical use case of 8 users, 1.65 seconds for 20 users
- Average check out time is 1.75 seconds for a typical use case of 8 users, 1.90 seconds for 20 users
- Slow APIs taking more than 100ms to run
- POST checkout-by-barcode
- POST checkin-by-barcode
- Get circulation/loans
- Get inventory/items
- 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)
- 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.
The following WARNING statements of missing indexes were generated during a test run and logged by mod-source-record-storage:
| Code Block | ||||
|---|---|---|---|---|
| ||||
6. Database Slow queries
Slowest queries which took the most of execution time were initiated by the mod-inventory-storage service 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 |
| 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 |
| 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 |
| 0.4% | 1,299 ms | 159 | mod_inventory_storage | EXPLAINANALYZEWITH 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) FROM fs09000000_mod_inventory_storage.instance ORDERBYleft(lower(f_unaccent(jsonb->>'title')),600) OFFSET10000LIMIT1 ) ORDERBYleft(lower(f_unaccent(jsonb->>'title')),600) LIMIT100OFFSET0 ), 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 (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 |
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 |
...
| 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% |
Appendix
See Attached FameFlower Performance Test Runs.xlsx for details