In Progress

PERF-100 - Getting issue details... STATUS

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.

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:

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.

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:

1. 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;
2. 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. 
3. 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'))