investigate and verify backend API performance issues for UICHKIN-111

Description

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 giraffe

sub-task 1:

  • GET /inventory/items?query=barcode==123456 – this look up looks slow, almost 1s in some case, let's analyze this with giraffe

sub-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

Environment

None

Potential Workaround

None

Attachments

8
100% Done
Loading...

Checklist

hide

TestRail: Results

Activity

Show:

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 PM
Edited

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 PM
Edited

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.

Done

Details

Assignee

Reporter

Priority

Story Points

Sprint

Development Team

Core: Platform

TestRail: Cases

Open TestRail: Cases

TestRail: Runs

Open TestRail: Runs

Created September 10, 2019 at 2:07 PM
Updated October 15, 2019 at 10:03 AM
Resolved September 30, 2019 at 1:47 PM
TestRail: Cases
TestRail: Runs