investigate and verify backend API performance issues for UICHKIN-111
Description
Environment
Potential Workaround
Attachments
blocks
is blocked by
Checklist
hideTestRail: Results
Activity

Hongwei Ji September 30, 2019 at 1:47 PM
Per standup, close this ticket since we have identified performance issues in mod-authtoken and mod-permission, and created related tickets to work on.

Hongwei Ji September 23, 2019 at 2:05 PMEdited
Over the weekend while no one (I think) was using the BugFest env, I did a checkout and checkin test and recorded Okapi log for both. See attached checkout/in logs.
BTW there were some unrelated lines due to timers. I also removed "us" part so I can sort the lines.

Hongwei Ji September 20, 2019 at 12:56 PM
I ran the checkin in Bugfest and sort the log by time. See below the top ones and the full list

Cate Boerema September 19, 2019 at 9:57 AM
Hi , et al. Jakub asked me to test this in BugFest to see if it reproed there and it does. I added some fresh details and a fresh screencast to UICHKIN-111
Also, Core Functional reviewed the frontend changes that were proposed by to improve Check in performance (UICHKIN-112). We don't think the proposal will work because certain operations (display of multipiece and check in notes, for example) have to happen before the item has been actually checked in (per user requirements). Other operations (status change, patron notice sent, staff slip created) need to happen after the item has actually been checked in. So we don't think there is potential in UICHKIN-112. If you have questions about this, please add them to that issue.

Hongwei Ji September 18, 2019 at 2:12 PMEdited
Created for mod-notify/send-patron-notice
slowness. Asked Theo to run a checkout/in test on Chalmers and noticed below in the Okapi log
About why the numbers do not add up in checkin3.log, I double checked the okapi logs and do not see any more entries related to that specific request id. So either something was not logged or the mod-circ spent some time not doing Okapi requests. Unfortunately, we did not keep the mod-circ log from that time period.
Details
Assignee
Hongwei JiHongwei JiReporter
Jakub SkoczenJakub SkoczenLabels
Priority
P2Story Points
2Sprint
NoneDevelopment Team
Core: PlatformTestRail: Cases
Open TestRail: CasesTestRail: Runs
Open TestRail: Runs
Details
Details
Assignee

Reporter

Task
Let's get the Okapi logs from the Chalmers environment that have timings for the operations from UICHKIN-111.
When debugging performance of particular API calls (especially the business logic ones) I'd recommend we use this tool:
https://github.com/folio-labs/giraffe
Which allows to generate call graphs, with timing information on individual calls, from the Okapi log. This is a profiling tool that allows to pinpoint the performance issue.
Environment and data
This might be dependent on data so let's try to gather some information about the data loaded in the Chalmers env:
How many records (instance/holdings/items and requests) are loaded into the system?
The individual response times of check-in (over 2s) in UICHKIN-111 look particularly high compared to what we see on performance test job:
https://jenkins-aws.indexdata.com/job/Automation/job/folio-perf-platform/254/performance/uriReport/jmeter_perf.jtl%3APerf+-+POST+circulation_check-in-by-barcode.endperformanceparameter/
We must understand where the discrepancy is coming from.
Particular API calls
Based on the screenshots from UICHKIN-111 the following API calls take the most time and should be investigated:
sub-task 0 (this ticket):
POST /circulation/checkin-by-barcode
– please analyze the call graph for this BL call using giraffesub-task 1:
GET /inventory/items?query=barcode==123456
– this look up looks slow, almost 1s in some case, let's analyze this with giraffesub-task 2:
GET /circulation/requests?query=itemId==123456 and status=="Open -- Awaiting Pickup"
– please create jMeter test(s) with similar query to "folio-perf-platform" and verify if DB indexing (schema.json) is properly set up (no warning from RMB)GET /circulation/requests?query=requesterId==f303e908-30dc-4139-9542-4a4e206c4b96 and pickupServicePointId=7c5abc9f-f3d7-4856-b8d7-6712462ca007 and(status=="Closed - Pickup expired" or status=="Open - Awaiting pickup")
GET /circulation/loans/?query=userId=XXXX and status.name<>Closed