In Progress

PERF-100: Study * token to see if it has good impact on performanceClosed

Success criteria:

Scripts to generate the data be checked in

A report showing all the queries and times.

Analysis of why a query with the * token is slow or fast, if possible.

1 In Progress
2 Overview:
3 Version:
4 Test Runs:
5 Results
6 Resource usage:
7 Conclusions:

Overview:

In PERF-83 it was observed that a CQL query with the * token at the end resulted in a faster response time, despite a much higher database usage.

There are many entities of different statuses in FOLIO. It'd be interesting to see if this pattern holds true for other statuses and CQL queries.

There is 15 K records in DB with Closed status, and 5 K records in DB for Open status.

In this user story, run the following tests:

GET /circulation/loans?limit=2147483647&query=(itemId==${current_item} and status.name=="Closed*")

GET /circulation/requests?(itemId==${item_id} and (status=="Open - Awaiting pickup*" or status=="Open - Awaiting delivery*"))

GET /circulation/requests?(requesterId==${userID} and pickupServicePointId=${servicePoints_Id} and status=="Open - Awaiting pickup*")

Version:

OKAPI - Version 3.1.1

OKAPI modules

Okapi (okapi-3.1.1)
Circulation Module (mod-circulation-19.0.13)
Circulation Storage Module (mod-circulation-storage-12.0.1)

circulation 9.3

feesfines (mod-feesfines-15.8.2)
feesfines 15.2
feesfines 15.0

Test Runs:

Test	Virtual Users	Query	Duration (sec)	Ramp Up (sec)

Test	Virtual Users	Query	Duration (sec)	Ramp Up (sec)
1	8	/circulation/loans?limit=2147483647&query=(itemId==${current_item} and status.name=="Closed")	1800	80
2	20	/circulation/loans?limit=2147483647&query=(itemId==${current_item} and status.name=="Closed")		200
3	8	/circulation/loans?limit=2147483647&query=(itemId==${current_item} and status.name=="Closed*")		80
4	20	/circulation/loans?limit=2147483647&query=(itemId==${current_item} and status.name=="Closed*")		200
5	8	/circulation/requests?(itemId==[current_item] and (status=="Open - Not yet filled" or status=="Open - Awaiting delivery"))		80
6	20	/circulation/requests?(itemId==[current_item] and (status=="Open - Not yet filled" or status=="Open - Awaiting delivery"))		200
7	8	/circulation/requests?(itemId==[item_id] and (status=="Open - Not yet filled" or status=="Open - Awaiting delivery"))		80
8	20	/circulation/requests?(itemId==[item_id] and (status=="Open - Not yet filled" or status=="Open - Awaiting delivery"))		200
9	8	/circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled")		80
10	20	/circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled")		200
11	8	/circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled*")		80
12	20	/circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled*")		200

Results

Summary:

During test set we've defined that there is no major difference between queries includes "*" and without it for the same amount of data being retrieved.

For instance for "Closed" status query (GET /circulation/loans?limit=2147483647&query=(itemId==[current_item] and status.name=="Closed")) (test 1, 8 users)75 response time percentile without "*" token is 1.085 seconds and response time 75 percentile for same query with "*" token is 1,074 seconds so in this particular case delta is 11 ms. Same behavior can be seeing in next test for 20 users with same query: without "*" token 75 percentile of response time is 3.815 seconds and with "*" token it's 3.799, delta is 15 ms.

Test	Virtual Users	Request		Total	OK	75th pct	95th pct	99th pct	Max

Test	Virtual Users	Request		Total	OK	75th pct	95th pct	99th pct	Max
1	8	GET /circulation/loans?limit=2147483647&query=(itemId==[current_item] and status.name=="Closed")	link	13788	13788	1.085	1.235	3.028	5.706
2	20	GET /circulation/loans?limit=2147483647&query=(itemId==[current_item] and status.name=="Closed")	link	12225	12143	3.815	4.736	6.181	30.171
3	8	GET /circulation/loans?limit=2147483647&query=(itemId==[current_item] and status.name=="Closed*")	link	13691	13582	1.074	1.226	3.205	32.6
4	20	GET /circulation/loans?limit=2147483647&query=(itemId==[current_item] and status.name=="Closed*")	link	12548	12548	3.799	4.715	5.46	9.462
5	8	GET /circulation/requests?(itemId==[current_item] and (status==Open - Not yet filled or status==Open - Awaiting delivery))	link	69925	69925	0.204	0.24	0.309	4.328
6	20	GET /circulation/requests?(itemId==[current_item] and (status==Open - Not yet filled or status==Open - Awaiting delivery))	link	86602	86602	0.423	0.513	0.661	15.306
7	8	GET /circulation/requests?(itemId==[item_id] and (status=="Open - Awaiting pickup" or status=="Open - Awaiting delivery"))	link	67688	67688	0.214	0.26	0.385	23.776
8	20	GET /circulation/requests?(itemId==[item_id] and (status=="Open - Awaiting pickup" or status=="Open - Awaiting delivery"))	link	78697	78697	0.48	0.607	0.969	8.646
9	8	GET /circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled")	link	66713	66713	0.215	0.265	0.384	31.676
10	20	GET /circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled")	link	79364	79364	0.477	0.603	0.99	3.834
11	8	GET /circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled*")	link	66830	66830	0.217	0.269	0.401	2.991
12	20	GET /circulation/requests?(requesterId==[requesterID] and pickupServicePointId=[pickPoint] and status=="Open - Not yet filled*")	link	78824	78824	0.482	0.611	0.923	4.893

On chart below you can see differences between queries includes "*" token and without it. As you may see the difference between 75% response times fluctuates from +11 ms to -5 ms. Which is not a significant deviation.

Resource usage:

Taking into account the number of tests that have been performed, moreover tests for "open" status shows us pretty much similar response times, let's take closer look of several of them:

GET /circulation/loans?limit=2147483647&query=(itemId==[current_item] and status.name=="Closed") 8 Users test run Resources usage:

RDS CPU usage 8 users test run:

RDS Performance Insights:

As you can see on chart above - most of waiting is CPU time. Moreover longest waits was made by mod feesfines queries in both cases:

Note: No slow queries were found on PGHero during whole test set.

Services CPU utilization:

Note: There is a little different scale of charts (can't be updated due to AWS CloudWatch data aggregation), however the CPU usage level are the same for query included "*" token and without it.

GET /circulation/loans?limit=2147483647&query=(itemId==[current_item] and status.name=="Closed") 20 Users test run Resources usage:

RDS CPU usage 20 users test run:

RDS Performance Insights:

We can observe the same behavior as in 8 users test. High CPU DB usage and a lot of CPU waitings on DB side. Moreover longest waits was made by mod feesfines queries in both cases:

Services CPU utilization:

Note: There is a little different scale of charts (can't be updated due to AWS CloudWatch data aggregation), however the CPU usage level are the same for query included "*" token and without it.

GET /circulation/requests?(itemId==[current_item] and (status==Open - Not yet filled or status==Open - Awaiting delivery)) 8 users Resources usage:

RDS CPU usage :

As you see, in comparison to "Closed" status test set there is much less DB CPU usage. That may be explained by differences in data set.

RDS Performance Insights:

As you may see, differences in data amount has strongly influence on DB performance. (In comparison to "Closed status tests set");

We still can observe a lot of mod feesfines calls, but at this time, due to less data, it working faster.

Services CPU utilization:

While DB is no longer an issue with the high CPU usage we can see much higher services CPU usage.

Note: most loaded modules - mod autotoken, OKAPI:

GET /circulation/requests?(itemId==[current_item] and (status==Open - Not yet filled or status==Open - Awaiting delivery)) 20 users Resources usage:

RDS CPU usage :

Even during 20 users test RDS CPU usage wasn't higher than 20 % (except 27% spike at the end of second test).

RDS Performance Insights:

Services CPU utilization:

As in previous example, most used modules are Mod Autotoken and OKAPI

Conclusions:

As was proven - there is no big difference between queries used "*" token and without it. Difference between 75% response times fluctuates from +11 ms to -5 ms;
There is dependency between data volume in DB. For instance Closed status records quantity was 15 K and Open status records was 5K. and the difference between 75 % response times are 750%. so volume testing is recommended to define performance degradation depends on data volume.
The following WARNING statements of missing indexes were generated by mod-circulation during a test run:

WARNING: Doing LIKE search without index for accounts.jsonb->>'loanId', CQL >>> SQL: loanId == 5fb2c891-64eb-4b6c-b3a2-715ad91f593b >>> lower(f_unaccent(accounts.jsonb->>'loanId')) LIKE lower(f_unaccent('5fb2c891-64eb-4b6c-b3a2-715ad91f593b'))