Overview

The test's target is to investigate the behaviour of the Check-In/Check-Out activities during fixed load tests.

PERF-470 - Getting issue details... STATUS

Summary

The essential difference (even without absolute comparing): ~20% of degradation for average response time between current test results and:
- Investigation of variability of test results
- Check-in-check-out Test Report (Nolana)
8 Container instances for ncp5 instead 9 for ncp3 could have a negative impact but not critical
No memory leaks were found during the series of tests
Based on the longevity test results, the response time for 30 virtual users during the long period of time was degraded by ~ 75% in comparison with the fixed load test for 8 virtual users of the same configuration. Moreover, 'mod-users' CPU Utilization was more than 100% during all test execution. After ~16 hours of the longevity test run, significant degradation of CPU Utilization took place by services involved in Check-in/Check-out operations.
Unexpected behaviour of 'mod-search' CPU utilization during fixed load retests with 20 virtual users
ERROR LOG Messages have not been found, but there were a lot of WARN LOG Messages (see Additional) connected to the queries usage without an index

Recommendations

Discuss & analyze the situation with WARN LOG Messages (see Additional):
- Potentially create indexes based on WARN LOG messages
- Clarify action items for 'The configuration' WARN LOG Messages
Discuss & analyze the worst API calls and potential root causes with a development team
Decrease the number of virtual users for longevity testing Orchid release candidate (down to 20 or even 8)
Discuss & analyze the involvement of 'mod-search' in Check-in/Check-out operations, and pay attention to 'mod-search' CPU utilization during future tests

Test Runs

The following table contains information about a test model and related Grafana snapshots:

Test #	Test Conditions	vUsers	Ramp-up, sec	Duration, sec	Grafana
1.	circulation_checkInCheckOut_orchid	8	80	2'780	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&from=1679388600000&to=1679391720000&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All
2.	circulation_checkInCheckOut_orchid	20	200	2'900	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&from=1679392500000&to=1679395560000&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All
3.	circulation_checkInCheckOut_orchid	30	300	3'000	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&from=1679396220000&to=1679399400000&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All
4.	circulation_checkInCheckOut_orchid	75	750	3'450	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&from=1679400360000&to=1679404020000&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All
5.	circulation_checkInCheckOut_orchid	30	300	86'700	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&from=1679070600000&to=1679157300000&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All

Based on previous results, the decision of additional execution was made:

Test #	Test Conditions	vUsers	Ramp-up, sec	Duration, sec	Grafana
1*	circulation_checkInCheckOut_orchid	8	80	2'780	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All&from=1679932800000&to=1679935800000
2*	circulation_checkInCheckOut_orchid	8	80	2'780	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All&from=1679940840000&to=1679943720000
3*	circulation_checkInCheckOut_orchid	20	200	2'900	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All&from=1679944440000&to=1679947500000
4*	circulation_checkInCheckOut_orchid	20	200	2'900	http://carrier-io.int.folio.ebsco.com/grafana/d/elIt9zCnz/jmeter-performance-test-copy?orgId=1&var-percentile=95&var-test_type=fix_load&var-test=circulation_checkInCheckOut_orchid&var-env=int&var-grouping=1s&var-low_limit=250&var-high_limit=750&var-db_name=jmeter&var-sampler_type=All&var-Request=All&from=1679947980000&to=1679951220000

Results

The following table contains information about test results and their comparison with the baseline (circulation_checkInCheckOut_orchid 8 VU).

Response Times

Test #

Test Conditions

vUsers

Action

Request count

MIN, ms

AVG, ms

Median, ms

95pct, ms

MAX, ms

Std.Dev

MoE

Confidence 95%

CoV

1.

circulation_checkInCheckOut_orchid

Baseline

8

Check-in

1'435

379

534

456

1'041

2'770

231

11.95

43.26%

Check-out

1'845

605

909

797

1'462

3'390

286

13.05

31.46%

2.

circulation_checkInCheckOut_orchid

20

Check-in

3'513

318

600

+12.36%

482

+5.70%

1'196

+14.89%

2'580

291

9.62

48.50%

Check-out

4'682

599

1'110

+22.11%

1'010

+26.73%

1'807

+23.60%

3'670

396

11.34

35.68%

3.

circulation_checkInCheckOut_orchid

30

Check-in

5'109

341

834

+56.18%

662

+45.18%

1'708

+64.07%

4'810

469

12.86

56.24%

Check-out

6'783

609

1'590

+12.36%

1'511

+89.59%

2'777

+89.95%

6'470

635

15.11

39.94%

4.

circulation_checkInCheckOut_orchid

75

Check-in

13'378

337

825

+54.49%

688

+50.88%

1'566

+50.43%

4'230

411

6.96

49.82%

Check-out

17'744

644

1'960

+115.62%

1'904

+138.90%

3'142

+114.91%

6'370

667

9.81

34.03%

5.

circulation_checkInCheckOut_orchid

30

Check-in

208'809

311

550

+3.00%

455

-0.22%

1'061

+1.92%

16'108

257

1.10

46.73%

Check-out

277'292

111

1'597

+75.69%

1'306

+63.86%

3'233

+121.14%

133'698

852

3.17

53.35%

Comparisons

The following table contains information about additional test executions, their results and a comparison with Nolana's results:

Test #	Test Conditions	vUsers	Action	AVG, ms	Median, ms	95pct, ms	Std.Dev
B	circulation_checkInCheckOut_nolana	8	Check-in	456	441	534
B	circulation_checkInCheckOut_nolana	8	Check-out	698	672	839
1-Retest	circulation_checkInCheckOut_orchid	8	Check-in	534 +17.11%	474 +7.48%	1,027 +92.32%	239
1-Retest	circulation_checkInCheckOut_orchid	8	Check-out	811 +16.19%	749 +11.46%	1,201 +43.15%	252
2-Retest	circulation_checkInCheckOut_orchid	8	Check-in	538 +17.98%	475 +7.71%	1,428 +167.42%	241
2-Retest	circulation_checkInCheckOut_orchid	8	Check-out	799 +14.47%	747 +11.16%	1,008 +20.14%	214
B	circulation_checkInCheckOut_nolana	20	Check-in	425	414	489
B	circulation_checkInCheckOut_nolana	20	Check-out	658	638	758
3-Retest	circulation_checkInCheckOut_orchid	20	Check-in	513 +20.71%	460 +11.11%	812 +66.05%	229
3-Retest	circulation_checkInCheckOut_orchid	20	Check-out	798 +21.28%	737 +15.52%	1,130 +49.08%	220
4-Retest	circulation_checkInCheckOut_orchid	20	Check-in	507 +19.29%	453 +9.42%	939 +92.02%	236
4-Retest	circulation_checkInCheckOut_orchid	20	Check-out	777 +18.09%	721 +13.01%	994 +31.13%	212

API Comparisons

The following table contains information about the response time of the most important requests for CI/CO activities and their comparison with Nolana's results:

API

8 users Nolana

75pct, ms

8 users Orchid

75pct, ms

8 users Orchid

75pct, ms

20 users Nolana

75pct, ms

20 users Orchid

75pct, ms

20 users Orchid

75pct, ms

POST checkout-by-barcode

237

282

+18.99%

276

+16.46%

226

270

+19.47%

264

+16.81%

POST checkin-by-barcode

228

259

+13.6%

258

+13.16%

214

247

+15.42%

245

+14.49%

GET circulation/loans

122

139

+13.93%

140

+14.75%

120

138

+15.00%

136

+13.33%

Resources Utilization

Test	VU	Memory Utilization	CPU Utilization	RDS CPU Utilization	RDS Performance
1	8
2	20
3	30
4	75
5	30

Additional execution:

Test	VU	Memory Utilization	CPU Utilization	RDS CPU Utilization	RDS Performance
1-Retest	8
2-Retest	8
3-Retest	20
4-Retest	20

Appendix

Infrastructure

PTF -environment ncp3

PTF -environment ncp5

9 m6i.2xlarge EC2 instances located in US East (N. Virginia)us-east-1
2 instances of db.r6.xlarge database instances, one reader, and one writer
MSK ptf-kakfa-3
- 4 m5.2xlarge brokers in 2 zones
- Apache Kafka version 2.8.0
- EBS storage volume per broker 300 GiB
- auto.create.topics.enable=truec
- log.retention.minutes=480
- default.replication.factor=3

8 m6i.2xlarge EC2 instances located in US East (N. Virginia)us-east-1 [Number of ECS instances, instance type, location region]
2 instances of db.r6.xlarge database instances: Writer & reader instances
MSK ptf-kakfa-3 [ kafka configurations]
- 4 kafka.m5.2xlarge brokers in 2 zones
- Apache Kafka version 2.8.0
- EBS storage volume per broker 300 GiB
- auto.create.topics.enable=true
- log.retention.minutes=480
- default.replication.factor=3

Modules memory and CPU parameters

Modules	Version	Task Definition	Running Tasks	CPU	Memory	MemoryReservation	MaxMetaspaceSize	Xmx
mod-inventory	19.0.1 mod-inventory:20.0.0-SNAPSHOT.392	1 4	2	1024	2880	2592	512m	1814m
mod-inventory-storage	25.0.1 mod-inventory-storage:26.1.0-SNAPSHOT.644	1 4	2	1024	2208	1952	512m	1440m
okapi	4.14.7 okapi:5.1.0-SNAPSHOT.1352	1 3	3	1024	1684	1440	512m	922m
mod-feesfines	18.1.0 mod-feesfines:18.3.0-SNAPSHOT.141	1 3	2	128	1024	896	128	768
mod-patron-blocks	1.7.1 mod-patron-blocks:1.9.0-SNAPSHOT.90	1 5	2	1024	1024	896	128	768
mod-pubsub	2.7.0 mod-pubsub:2.10.0-SNAPSHOT.124	1 4	2	1024	1536	1440	512	922
mod-authtoken	2.12.0 mod-authtoken:2.14.0-SNAPSHOT.238	1 3	2	512	1440	1152	128	922
mod-circulation-storage	15.0.0 mod-circulation-storage:16.1.0-SNAPSHOT.305	1 3	2	1024	1536	1440	512	896
mod-circulation	23.3.0 mod-circulation:23.5.0-SNAPSHOT.556	1 3	2	1024	1024	896	128	768
mod-configuration	5.9.0 mod-configuration:5.9.2-SNAPSHOT.291	1 3	2	128	1024	896	128m	768m
mod-users	19.0.0 mod-users:19.2.0-SNAPSHOT.584	1 3	2	258 128	1024	896	128m	768m
mod-remote-storage	1.7.0 mod-remote-storage:2.0.0-SNAPSHOT.83	1 4	2	128 1024	1872 4920	1684 4472	512m	1178m 3960m

Methodology/Approach

Executed check-ins with up to 8, concurrent vUsers and the interval between vUsers is 1 min. (On carrier-io use the artefact "circulation_checkInCheckOut_orchid.zip")
Scripts used:
1. DB Refresh - check-in-checkout-db-restore.sql
2. DB Update - circ-data-load_item-level-requests.sh

Additional Screenshots of graphs or charts

LOG Analysis

ERROR Messages have not been found

WARN Messages:

@message
13:53:19 [314720/circulation;580034/patron-action-session-storage] [fs09000000] [] [mod_circulation_storage] WARN CQL2PgJSON 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'))
@timestamp
1679406799342

@message
13:54:53 [113748/circulation;788610/actual-cost-record-storage] [fs07000002] [] [mod_circulation_storage] WARN CQL2PgJSON Doing LIKE search without index for actual_cost_record.jsonb->>'status', CQL >>> SQL: status == Open >>> lower(f_unaccent(actual_cost_record.jsonb->>'status')) LIKE lower(f_unaccent('Open'))
@timestamp
1679406893978

@message
13:54:53 [571164/circulation;683747/actual-cost-record-storage] [fs09000000] [] [mod_circulation_storage] WARN CQL2PgJSON Doing SQL query without index for actual_cost_record.jsonb->>'expirationDate', CQL >>> SQL: expirationDate < 2023-03-21T13:54:53.955Z >>> actual_cost_record.jsonb->>'expirationDate' <'2023-03-21T13:54:53.955Z'
@timestamp
1679406893978

@message
13:34:53 [355402/circulation;196278/loan-storage] [fs07000001] [] [mod_circulation_storage] WARN CQL2PgJSON Doing SQL query without index for loan.jsonb->'agedToLostDelayedBilling'->>'dateLostItemShouldBeBilled', CQL >>> SQL: agedToLostDelayedBilling.dateLostItemShouldBeBilled <= 2023-03-21T13:34:53.334Z >>> loan.jsonb->'agedToLostDelayedBilling'->>'dateLostItemShouldBeBilled' <='2023-03-21T13:34:53.334Z'
@timestamp
1679405693349

@message
13:34:51 [506887/circulation;226984/loan-storage] [fs07000002] [] [mod_circulation_storage] WARN CQL2PgJSON Doing FT search without index for loan.jsonb->>'userId', CQL >>> SQL: userId = "" >>> loan.jsonb->>'userId' ~ ''
@timestamp
1679405691613

@message
13:06:31 [351599/circulation;964992/request-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN CQL2PgJSON Doing LIKE search without index for request.jsonb->>'instanceId', CQL >>> SQL: instanceId == 5fe9addc-3492-4013-9346-b3ddd2bea42e >>> lower(f_unaccent(request.jsonb->>'instanceId')) LIKE lower(f_unaccent('5fe9addc-3492-4013-9346-b3ddd2bea42e'))
@timestamp
1679403991572

@message
13:06:30 [432564/circulation;469696/request-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN CQL2PgJSON Doing FT search without index for request.jsonb->>'pickupServicePointId', CQL >>> SQL: pickupServicePointId = 7068e104-aa14-4f30-a8bf-71f71cc15e07 >>> get_tsvector(f_unaccent(request.jsonb->>'pickupServicePointId')) @@ tsquery_phrase(f_unaccent('7068e104-aa14-4f30-a8bf-71f71cc15e07'))
@timestamp
1679403990723

@message
13:06:09 [258334/circulation;184404/scheduled-notice-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN CQL2PgJSON loadDbSchema loadDbSchema(): No configuration for table jsonb found, using defaults
@timestamp
1679403969594

@message
13:06:09 [258334/circulation;184404/scheduled-notice-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN CQL2PgJSON Doing LIKE search without index for jsonb->>'loanId', CQL >>> SQL: loanId == ef136e5f-4496-42f4-abc2-dfa9dbecce2e >>> lower(f_unaccent(jsonb->>'loanId')) LIKE lower(f_unaccent('ef136e5f-4496-42f4-abc2-dfa9dbecce2e'))
@timestamp
1679403969594

@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.protocol' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.endpoint.identification.algorithm' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.keystore.location' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.truststore.type' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.keystore.type' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.truststore.location' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.keystore.password' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.key.password' was supplied but isn't a known config.
@timestamp
1679403991672
@message
13:06:31 [351599/circulation;380795/loan-storage] [fs09000000] [9eb67301-6f6e-468f-9b1a-6134dc39a684] [mod_circulation_storage] WARN AbstractConfig The configuration 'ssl.truststore.password' was supplied but isn't a known config.
@timestamp
1679403991672

Browser not supported