[FOLIO-1868] Analyze module calls generated from check-out-by-barcode request Created: 14/Mar/19  Updated: 11/Aug/20  Resolved: 16/Sep/19

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

Type: Task Priority: P3
Reporter: Nassib Nassar Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: platform-backlog
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original estimate: Not Specified

Attachments: PDF File checkout-call-graph-2.pdf     PDF File checkout-call-graph-3.pdf     Text File okapi-checkout-2.log    
Issue links:
Duplicate
duplicates CIRC-448 investigate and verify backend API pe... Closed
Relates
relates to CIRC-250 Remove unnecessary heavy count(*) que... Closed
relates to CIRCSTORE-115 Improve loan related query performance Closed
relates to MODAT-43 Bump up token perm cache from 10s to 60s Closed
relates to FOLIO-1815 SPIKE: "profile" checkin/out-by-barco... Closed
Sprint: CP: ready for planning
Story Points: 5
Development Team: Core: Platform

 Description   

A single check-out-by-barcode request is made to mod-circulation, and this appears to result in approximately 30 sub-requests being made by mod-circulation in the course of handling the initial request.

Acceptance criteria: Analysis of the pattern of sub-requests to determine if they are in fact needed and if they are being used correctly and efficiently. The purpose is to explore opportunities to further reduce running time of handling the check-out-by-barcode request. (See FOLIO-1815 Closed )



 Comments   
Comment by Nassib Nassar [ 14/Mar/19 ]

Call graph attached as: "checkout-call-graph-2.pdf"

Okapi log attached as: "okapi-checkout-2.log"

Comment by Nassib Nassar [ 14/Mar/19 ]

The largest timings are:

2019-03-12 19:55:29,181 INFO ProxyContext 995617/circulation RES 201 1390417us mod-circulation-15.0.0-SNAPSHOT.232 http://10.0.2.15:9137/circulation/check-out-by-barcode
2019-03-12 19:55:27,790 INFO ProxyContext 995617/circulation RES 202 329478us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation/check-out-by-barcode
2019-03-12 19:55:27,788 INFO ProxyContext 935975/perms RES 200 297369us mod-permissions-5.5.0-SNAPSHOT.38 http://10.0.2.15:9152/perms/users/be69019d-fdb4-421d-ab14-9ad4c2c7ec56/permissions..
2019-03-12 19:55:28,485 INFO ProxyContext 995617/circulation;245145/item-storage RES 200 287072us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-12 19:55:28,775 INFO ProxyContext 995617/circulation;792786/holdings-storage RES 200 282249us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/holdings-storage/holdings..
2019-03-12 19:55:29,050 INFO ProxyContext 995617/circulation;577812/instance-storage RES 200 267921us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/instance-storage/instances..
2019-03-12 19:55:28,168 INFO ProxyContext 995617/circulation;665136/loan-storage RES 200 251227us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/loan-storage/loans..
2019-03-12 19:55:27,452 INFO ProxyContext 166966/authn RES 201 63548us mod-login-5.0.0-SNAPSHOT.46 http://10.0.2.15:9135/authn/login
Comment by Marc Johnson [ 14/Mar/19 ]

Are the timings for login included in the performance test timing (e.g. the /authn/login call above)?

As I imagine that is part of the setup of the test and isn't something that is invoked by mod-circulation

Comment by Nassib Nassar [ 14/Mar/19 ]

Yes, it is included in the log and timings above, but not in the call graph. Measured from the client side, the login completes in less than ~ 125 ms.

Comment by Nassib Nassar [ 15/Mar/19 ]

Updated call graph attached as: "checkout-call-graph-3.pdf"

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