[FOLIO-1812] SPIKE: verify and analyze checkout performance Created: 18/Feb/19  Updated: 03/Jun/20  Resolved: 20/Feb/19

Status: Closed
Project: FOLIO
Components: None
Affects versions: None
Fix versions: None

Type: Task Priority: P3
Reporter: Hongwei Ji Assignee: Hongwei Ji
Resolution: Done Votes: 0
Labels: platform-backlog, q1-performance
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original estimate: Not Specified

Attachments: Text File checkout.txt     Text File checkout_60_60.log     PNG File checkout_60_60.png     PNG File ebsco_checkinout_perf_result.png     Text File mod-circulation-storage.log     Text File mod-circulation.log     Text File mod-inventory-storage.log    
Issue links:
Relates
relates to CIRC-225 mod-circulation hangs when checkout-b... Closed
relates to FOLIO-1815 SPIKE: "profile" checkin/out-by-barco... Closed
relates to FOLIO-1811 SPIKE: verify and analyze checkin per... Closed
Sprint: Core: Platform - Sprint 57
Story Points: 1
Development Team: Core: Platform

 Description   

EBSCO did checkin/checkout workflow performance testing on q3 and q4 environment. One of the slowest API call was checkout by barcode /circulation/check-out-by-barcode. See attached JMeter result file for 5 concurrent users on a small tenant for 5 minutes:

We should verify the result using isolated test on nightly perf environment to see if the issue still exists and what are the possible causes.

Acceptance criteria: if performance issue is confirmed, create new JIRA ticket to address it.



 Comments   
Comment by Hongwei Ji [ 18/Feb/19 ]

To verify the result, I used the same JMeter checkin/out script but disabled all API calls in the workflow except the checkout-by-barcode one. The test was done on a standard perf env with the code from folio stable site on 2018-02-15. The test sends 60 requests in 60 seconds ramp-up window. Each request looks like checkout.txt and the barcode is selected from a pool and is different for each request. The JMeter log is in checkout_60_60.log and the result is in

In summary: checkout-bar-code has similar performance pattern to checkin-by-barcode, even though a single call on an idle system is not slow (under 2 seconds). When there are multiple concurrent checkout API calls (60 requests in 60s ramp-up window), each individual API call suffer some latency but better than checkin (average is 20 seconds, between min 3s to max 36s). Also the throughput is still good (49 requests per minute). Behind the scene, checkout-by-code API also makes multiple other API calls, see attached log files for mod-circulation.log, mod-circulation-storage.log, and mod-inventory-storage.log. Furthermore, I noticed that mod-circulation module will stop working if sending too many requests too fast. For example, initially I was using the same 100 requests in 60 seconds (as in checkin test case), mod-circulation stopped working and could not recover by itself after waiting long time. I had to restart it. It is possible that some resources (socket for example) were not released quickly/properly in in mod-circulation.

Comment by Hongwei Ji [ 20/Feb/19 ]

Created FOLIO-1815 Closed to address checkout-by-barcode performance issue.
Created CIRC-225 Closed to address the mod-circulation hangs.

Comment by Eric Valuk [ 27/Feb/19 ]

In my tests last night I saw the following error in 2/10 calls to circulation/loans. This may be related.

Failed to fetch loans from storage (500:ErrorMessage(fields=Map(Line -> 784, File -> postinit.c, SQLSTATE -> 53300, Routine -> InitPostgres, V -> FATAL, Message -> remaining connection slots are reserved for non-replication superuser connections, Severity -> FATAL)))

Comment by Hongwei Ji [ 05/Mar/19 ]

Update: above db error is not related. As discovered in CIRC-225 Closed , it is due to mod-circulation makes http connection to itself through Okapi, so the default http connection pool of 5 is exhausted. To make reproducing the problem easier, I also added a separate JMeter test for it.

Generated at Thu Feb 08 23:16:05 UTC 2024 using Jira 1001.0.0-SNAPSHOT#100246-sha1:7a5c50119eb0633d306e14180817ddef5e80c75d.