The org_folio_okapi_code_executionTime metrics show that the code blocks ProxyContext.logRequest and ProxyContext.logResponse's performance degraded over time during the check-in-check-out tests, especially with 8 concurrent users. In the screenshots
These two methods' response times started out at 200ms and increased to 4 seconds on average. What's worse is that between the test runs when the background tasks were running, not sure of what the pattern of call was, the response times for these two methods spiked up dramatically, with multiple spikes as there were more loans to process (created by the previous test runs).
These metrics results corroborate with the results of profiling Okapi v4.3.3. When comparing profiled results of Okapi 4.3.3 with Okapi v3.1.2, Okapi 4.3.3 seemed to be spending more CPU time logging. Consider the output of the profiler that profiled Okapi 3.1.2 when running the same test. , the logInfo method accounted for 91.3 seconds in total. With Okapi 4.3.3, , the total time of logInfo was 297.8 seconds, over 3x increased. Clearly it took longer to log and therefore it used up more CPU time.
Additionally, the memory profile of Okapi during the test run matched up with the response time of the logger methods: This is a screenshot of one of the 3 Okapi nodes. The memory seemed to have increased from 50% to 62% during the test run.
Steps to Reproduce:
- Run the PTF's JMeter check-in-check-out test with 8 users over an hour
No change in response times
Changes in response time, see Overview