FameFlower Test Results
| Table of Contents |
|---|
Overview
Jira Legacy
| Table of Contents |
|---|
Overview
| Jira Legacy | ||||||||
|---|---|---|---|---|---|---|---|---|
|
...
Frontend:
- folio_inventory-2.0.2
Folio build was deployed with 50+ ECS services distributed randomly across four
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
- Most of failed requests were related to GET_/inventory/instances and GET_/instance-bulk/ids that use mod-inventory-storage service, even in a 1-user 30-min test run.
- mod-inventory-storage used 99% of container memory on a machine with 8GB RAM to return 50K to 100K records.
The workflow that retrieves more than 100K records became non-responsive even with 1 user
- The workflow with more than 5 users became non-responsive
- fasterxml.jackson.databind.ObjectMapper.readValue method of mod-inventory-storage service consumed high CPU resources as there were a lot of JSON decoding, this implementation could be reviewed for optimization possibilities.
- FOLIO performs better without being profiled when the tests are running
Test Runs
30-min Runs for export instance UUIDs workflow:
...
Test
...
Virtual Users
...
Duration
...
OKAPI log level
...
Profiled
...
Ramp up (total time
in seconds)
...
Size of response (how many instances
were returned)
...
1. FameFlower
...
1
...
30 min
...
INFO
...
No
...
5
...
10K~50K instances
...
2. FameFlower
...
1
...
30 min
...
INFO
...
No
...
1
...
50K~100K instances
...
3. FameFlower
...
1
...
30 min
...
INFO
...
Yes
...
10
...
10K~50K instances
...
4. FameFlower
...
1
...
30 min
...
INFO
...
Yes
...
10
...
50K~100K instances
...
5. FameFlower
...
5
...
30 min
...
INFO
...
No
...
50
...
10K~50K instances
...
6. FameFlower
...
5
...
30 min
...
INFO
...
No
...
10
...
50K~100K instances
...
7. FameFlower
...
5
...
30 min
...
INFO
...
Yes
...
50
...
10K~50K instances
...
8. FameFlower
...
5
...
30 min
...
INFO
...
Yes
...
50
...
50K~100K instances
Results
...
Overall check in, check out time in seconds
Average (seconds) 50th %tile (seconds) 75th %tile (seconds) 95th %tile (seconds) Check-in Check-out Check-in Check-out Check-in Check-out Check-in Check-out 1 user 1.015 1.234 0.96 1.277 1.071 1.409 1.322 1.653 5 users 1.236 1.488 1.156 1.393 1.464 1.869 1.704 2.219 8 users 1.512 1.751 1.403 1.852 1.741 2.031 2.02 2.274 20 users 1.649 1.898 1.535 1.996 1.896 2.211 2.252 2.539 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) POST checkout-by-barcode 615 ms 905 ms 906 ms 988 ms POST checkin-by-barcode
548 ms 830 ms 1053 ms 1137 ms Get circulation/loans 283 ms 346 ms 449 ms 479 ms Get inventory/items 217 ms 232 ms 237 ms 281 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
30-min Runs for export instance UUIDs workflow:
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
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
1. High level FameFlower results data
...
Fig 3.1: mod-inventory-storage service consumed 99% of allocated RAM memory in the 5 users and 10K-50K instances retrieved test run.
Fig 3.1: mod-inventory-storage service consumed 99% of allocated RAM memory in the 5 users and 50K-100K instances retrieved test run.
...
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 | Query |
32% | 10,796 | 15 | SELECT jsonb,id FROM fs09000000_mod_inventory_storage.instance WHERE to_tsvector($1, f_unaccent(concat_space_sql(instance.jsonb->>$2 , concat_array_object_values(instance.jsonb->$3,$4) , concat_array_object_values(instance.jsonb->$5,$6)))) @@ (to_tsquery($7, f_unaccent($8))) ORDER BY left(lower(f_unaccent(instance.jsonb->>$9)),$10), lower(f_unaccent(instance.jsonb->>$11)) |
23% | 22,250 | 5 | SELECT jsonb,id FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector($1, f_unaccent(concat_space_sql(instance.jsonb->>$2 , concat_array_object_values(instance.jsonb->$3,$4) , concat_array_object_values(instance.jsonb->$5,$6)))) @@ (to_tsquery($7, f_unaccent($8)))) AND (to_tsvector($9, f_unaccent(instance.jsonb->>$10)) @@ replace((to_tsquery($11, f_unaccent($12)))::text, $13, $14)::tsquery) ORDER BY left(lower(f_unaccent(instance.jsonb->>$15)),$16), lower(f_unaccent(instance.jsonb->>$17)) |
13% | 1,709 | 37 | SELECT COUNT(*) FROM (SELECT jsonb,id FROM fs09000000_mod_inventory_storage.instance WHERE to_tsvector($1, f_unaccent(concat_space_sql(instance.jsonb->>$2 , concat_array_object_values(instance.jsonb->$3,$4) , concat_array_object_values(instance.jsonb->$5,$6)))) @@ (to_tsquery($7, f_unaccent($8))) ORDER BY left(lower(f_unaccent(instance.jsonb->>$9)),$10), lower(f_unaccent(instance.jsonb->>$11)) LIMIT $12) x |
12% | 1,818 | 34 | 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 |
4% | 2,804 | 7 | SELECT COUNT(*) FROM (SELECT jsonb,id FROM fs09000000_mod_inventory_storage.instance WHERE (to_tsvector($1, f_unaccent(concat_space_sql(instance.jsonb->>$2 , concat_array_object_values(instance.jsonb->$3,$4) , concat_array_object_values(instance.jsonb->$5,$6)))) @@ (to_tsquery($7, f_unaccent($8)))) AND (to_tsvector($9, f_unaccent(instance.jsonb->>$10)) @@ replace((to_tsquery($11, f_unaccent($12)))::text, $13, $14)::tsquery) ORDER BY left(lower(f_unaccent(instance.jsonb->>$15)),$16), lower(f_unaccent(instance.jsonb->>$17)) LIMIT $18) x |
3% | 1,865 | 9 | 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('''english''')))) 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('''english''')))) 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 |
...
JVM profiling of the most resources consuming okapi, mod-inventory, mod-inventory-storage service showed 6 3 methods which had a high CPU usage and impact on the overall service performance.
fasterxmlorg.folio.jacksonokapi.databindmanagers.ObjectMapperProxyService.readValuegetModulesForRequest method uses most of CPU capacity which leads to performance degradation
org.apache.logging.log4j.spi.AbstractLogger.info method has high CPU usage with default INFO logging level
Appendix
See Attached FameFlower Performance Test Runs.xlsx for details