...
| Table of Contents | ||
|---|---|---|
|
Overview
This is a report for a series of Check-in-check-out test runs against the Honeysuckle release.
| Jira Legacy | ||||||
|---|---|---|---|---|---|---|
|
...
- 61 back-end modules deployed in 110 ECS services
- 3 okapi ECS services
- 8 m5.large EC2 instances
- 2 db.r5.xlarge AWS RDS instance
- INFO logging level
High Level Summary
- Check-out: Honeysuckle is slower by 9%-28% than Goldenrod
- Check-in: 4%-22% slower than Goldenrod
- APIs turned slower in Honeysuckle: GET /automated-patron-blocks/{id} (150% slower) and GET /circulation/loans (60%). These are covered by MODPATBLK-70 and CIRC-1014, respectively
- Okapi v4.3.3 seem to be using 2x-3x CPU cycles than in v1.3.2 (Goldenrod). Potential issue found with the logging methods OKAPI-964
- mod-pubsub has a memory leak that would drag down performance under high loads (see section on longevity test): MODPUBSUB-136
- Caching Okapi tokens in Okapi reduced mod-authtoken's CPU usage by over 90%
- Database's memory usage improved dramatically from Goldenrod's - little memory consumptions observed.
Test Runs
Test | Virtual Users | Duration | OKAPI log level |
1. | 1 | 30 mins | INFO |
2. | 5 | 30 mins | INFO |
3. | 8 | 30 mins | INFO |
4. | 20 | 30 mins | INFO |
5. | 20 | 24 Hours | INFO |
Results
Response Times
| 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 | 0.967 | 1.989 | 0.889 | 1.832 | 0.984 | 2.201 | 1.254 | 2.815 |
| 5 users | 1.053 | 2.171 | 0.981 | 1.969 | 1.114 | 2.253 | 1.528 | 3.370 |
| 8 users | 1.193 | 2.244 | 1.076 | 2.022 | 1.339 | 2.372 | 1.895 | 3.544 |
| 20 users | 2.391 | 3.901 | 1.639 | 3.073 | 2.263 | 4.12 | 4.811 | 8.784 |
...
- Services Modules Memory utilizations
- No modules exhibited memory leaks except for mod-pubsub
- Although there were two instances of mod-pubsub running on two different ec2 instances, mod-pubsub's traffic seemed to have been stickied to one instance. Here are graphs showing mod-pubsub's on one instance using up memory and CPU resources, and on another instance not showing much activities:
- mod-pubsub and Okapi on another node - Okapi's CPU utilization dwindles while mod-pubsub does not seem to be busy at all
CPUs and Memories
Okapi was profiled because of the apparent 3x CPU utilization compared to the Goldenrod runs.
...
- mod-authtoken uses much less CPU in Honeysuckle, over 90% reduction across all tests! This is because of the token caching functionality that was added to Okapi 4.x
- mod-circulation's CPU utilization in Honeysuckle averages over 20% lower than in Goldenrod.
- mod-circulation's CPU utilization in Honeysuckle is about 10-30% higher than in Goldenrod
- mod-inventory's CPU utilization in Honeysuckle averages 30% more than in Goldenrod
- mod-inventory-storage's CPU utilization in Honeysuckle averages 20% more than in Goldenrod
- mod-pubsub's CPU utilization in Honeysuckle is about 15% less than in Goldenrod
- mod-patron-blocks CPU utilization in Honeysuckle is at least 30% less than in Goldenrod
JVM Profiling
Because Okapi's CPU utilization in Honeysuckle seemed to have averaged 2x to 3x higher than in Goldenrod, it was profiled to get more insights of what happened inside it.
...
Note that the AbstractLogger.Info method in Okapi 4.3.3 total CPU time is about 3x higher than in Goldenrod. This is confirmed by Okapi 4.3.3's metrics showing ProxyContext.logRequest and ProxyContext.logResponse methods' response times degrade over time. These two methods need to be investigated.
Database
The database CPU utilizations are about the same between the Honeysuckle and Goldenrod
...
Goldenrod's memory profile shows quick claims of memory over 30 minutes tests runs.
Missing Indexes
Honeysuckle tests revealed the following missing indexes:
...
| Code Block |
|---|
WARNING: Doing LIKE search without index for accounts.jsonb->>'userId', CQL >>> SQL: userId == e96618a9-04ee-4fea-aa60-306a8f4dd89b >>> lower(f_unaccent(accounts.jsonb->>'userId')) LIKE lower(f_unaccent('e96618a9-04ee-4fea-aa60-306a8f4dd89b'))
WARNING: Doing LIKE search without index for accounts.jsonb->'status'>>'name', CQL >>> SQL: status.name <> Closed >>> lower(f_unaccent(accounts.jsonb>'status'->>'name')) NOT LIKE lower(f_unaccent('Closed'))
WARNING: Doing LIKE search without index for manualblocks.jsonb->>'userId', CQL >>> SQL: userId == a79b533d-8f29-4be1-9415-5f5cd936623b >>> lower(f_unaccent(manualblocks.jsonb->>'userId')) LIKE lower(f_unaccent('a79b533d-8f29-4be1-9415-5f5cd936623b')) |
Results for okapi-4.5.2
Results for okapi-4.5.2 for 1,5,8,20 users for 30 minute run. From the response times below, the average Check-out for 20 users is slower. On average 60% slower than okapi-4.3.3.
...
| 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 | 0.971 | 2.072 | 0.92 | 1.906 | 1.013 | 2.093 | 1.326 | 2.905 |
| 5 users | 1.003 | 2.114 | 0.925 | 1.947 | 1.055 | 2.235 | 1.458 | 3.149 |
| 8 users | 1.217 | 2.467 | 1.099 | 2.207 | 1.357 | 2.648 | 1.931 | 4.095 |
| 20 users | 2.409 | 5.213 | 2.141 | 4.478 | 2.763 | 5.682 | 4.233 | 8.484 |
CPUs and Memories
Service CPU Utilization:
CPU Utilization gradually increases as the number of users increase to 20 but this behavior is similar to okapi-4.3.3
...
Memory Utilization is a little high for mod-circulation 105% but for all other modules, it is relatively stable across all test runs for all users.
RDS CPU Utilization
RDS CPU Utilization is around 50% more compared to okapi-4.3.3
Results for okapi-4.6.1
Results for okapi-4.6.1 for 1,5,8,20 users for 30 minute run. From the response times below, comparing with okapi-4.3.3, the average Check-out/Check-in for okapi-4.6.1 is faster
Response Times Okapi-4.3.3
| 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 | |
| 8 users | 1.313 | 2.948 | 1.177 | 2.61 | 1.487 | 3.274 | 2.195 | 5.045 |
| 20 users | ||||||||
Response Times Okapi-4.6.1
| Average (seconds) | 50th %tile (seconds) | 75th %tile (seconds) | 95th %tile (seconds) | |||||||
| Check-in | Check-in performance with okapi-4.3.3 | Check-out | Check-out performance with okapi-4.3.3 | Check-in | Check-out | Check-in | Check-out | Check-in | Check-out | |
| 1 user | 1.041 | -7% | 2.332 | -17% | 0.957 | 2.139 | 1.06 | 2.369 | 1.378 | 3.394 |
| 5 users | 1.057 | -0.3% | 2.374 | -9% | 0.978 | 2.176 | 1.133 | 2.532 | 1.524 | 3.624 |
| 8 users | 1.277 | -7% | 2.814 | -25% | 1.144 | 2.512 | 1.44 | 3.074 | 2.112 | 4.718 |
| 20 users | 2.374 | +0.7% | 5.927 | -51.9% | 2.137 | 5.246 | 2.716 | 6.552 | 4.188 | 9.426 |
CPUs and Memories
Service CPU Utilization:
Compared to okapi-4.3.3, CPU Utilization for okapi-4.6.1 has almost doubled! Performance has degraded more than 50%
...
Service Memory Utilization:
RDS CPU Utilization
Comparison okapi-4.5.2 vs okapi-4.6.1
okapi-4.6.1 is slower than okapi-4.5.2. Checkin is 3.66% slower and Checkout is 9.48% slower. See below comparison for 8 Users 30-minute test run.
8 Hours Longevity test run for 20 Users
Service CPU Utilization:
Service Memory Utilization:
Comparison okapi-4.3.3 vs okapi-4.6.1 (okapi metrics enabled)
Below results are for 8 Users, 30 minutes against Checkin-Checkout workflow.
Grafana Performance Dashboard
Okapi-4.6.1 is around 71% faster than Okapi-4.3.3. Okapi-4.6.1 can process more requests and still perform better. In 30 minutes test run, okapi-4.6.1 was able to process 25% more requests with an average request per second(RPS) is 40.
...
Okapi-4.6.1 Grafana performance dashboard:
Checkin-Checkout API level comparison
For Okapi-4.6.1, Check-in is 71% faster and Checkout is around 65% faster.
Log request/response comparison
For Okapi-4.6.1, Log request has improved from 3.16 second to 0.243 seconds. Log request is faster by 1200% faster. Log response has improved from 3.25 seconds to 0.266 seconds which is 1100% faster.
...
Okapi-4.6.1 log request/response comparison:
Service CPU Utilization
Okapi-4.6.1 consumes less CPU and hence more efficient. Average CPU Utilization for okapi-4.6.1 is around 380% vs okapi-4.3.3 which is 600%.
...
Okapi-4.6.1 Service CPU Utilization:
Appendix
https://issues.folio.org/browse/MODPATBLK-70
...