[FOLIO-1815] SPIKE: "profile" checkin/out-by-barcode API response time Created: 20/Feb/19  Updated: 03/Jun/20  Resolved: 15/Mar/19

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

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

Attachments: PDF File checkout-call-graph-2.pdf     Text File okapi-checkout-2.log    
Issue links:
Relates
relates to MODINVSTOR-247 filtering /item-storage/items by 'que... Closed
relates to FOLIO-1771 clean up and isolate tests Closed
relates to MODINVSTOR-269 filtering /item-storage/items by 'que... Closed
relates to FOLIO-1868 Analyze module calls generated from c... Closed
relates to MODAT-43 Bump up token perm cache from 10s to 60s Closed
relates to CIRC-250 Remove unnecessary heavy count(*) que... Closed
relates to FOLIO-1811 SPIKE: verify and analyze checkin per... Closed
relates to FOLIO-1812 SPIKE: verify and analyze checkout pe... Closed
relates to FOLIO-1856 Generalize okapi call graph tool Closed
relates to FOLIO-1857 extract all unique CQL queries used f... Closed
Sprint: Core: Platform - Sprint 58, Core: Platform - Sprint 59
Story Points: 3
Development Team: Core: Platform

 Description   

As shown in FOLIO-1811 Closed and FOLIO-1812 Closed , when there are concurrent checkin/out-by-barcode requests, the response time for each checkin/out request is very long. This needs to be improved because checkin/out are likely to be used quite often in a library system.

Note: since checkin/out-by-barcode APIs fan-out to multiple other APIs to mod-inventory/inventory-storage/circulation-storage, it is inevitable slower due to many calls involved. Also it makes it harder to pin down which APIs or database calls are more time consuming. If FOLIO has a way to help troubleshooting performance across multiple modules/layers, that would be very helpful.

Acceptance criteria: ideally the response time should be under 2 seconds even when there are concurrent checkin/out requests. Upgrade to latest RMB, and do general performance analysis of check-in/out by barcode.

  • Timing of check-in/out by barcode
  • Timing of search for an instance by known instanceId, for comparison
  • Determine where time is spent


 Comments   
Comment by Jakub Skoczen [ 27/Feb/19 ]

Eric Valuk Hongwei Ji guys, can you confirm that the check-in/check-out tests (workflows) have been added to the isolated set under FOLIO-1771 Closed ?

Comment by Eric Valuk [ 27/Feb/19 ]

They have been added

Comment by Marc Johnson [ 28/Feb/19 ]

Which module (or modules) are intended to be upgraded to the latest RAML Module Builder to do this profiling?

I’m asking because mod-circulation is not using RAML Module Builder. It could be converted (it was intended to be a while ago). It is likely significant work to do so.

Comment by Nassib Nassar [ 04/Mar/19 ]

Running locally (folio/testing-backend VM) using the performance test data, initial timing for a single check out is ~24 seconds and for a single check in is ~24 seconds.

Comment by Jakub Skoczen [ 04/Mar/19 ]

Nassib Nassar Ok, cool. For comparison: how long does it take to search for an instance by known instanceId on the same machine with the same data set?

Comment by Nassib Nassar [ 06/Mar/19 ]

For check-in/out by barcode, a relevant timing is 18680979us for the call to mod-inventory-storage:/item-storage/items:

2019-03-05 21:03:15,699 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 SLF4J: Failed to load class "org.slf4j.impl.StaticMDCBinder".
2019-03-05 21:03:15,700 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 SLF4J: Defaulting to no-operation MDCAdapter implementation.
2019-03-05 21:03:15,700 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 SLF4J: See http://www.slf4j.org/codes.html#no_static_mdc_binder for further details.
2019-03-05 21:03:15,878 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 05 Mar 2019 21:03:15:875 INFO  PostgresClient [4276578eqId] DB config read from environment variables
2019-03-05 21:03:15,878 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 05 Mar 2019 21:03:15:876 INFO  PostgresClient [4276579eqId] Using schema: diku
2019-03-05 21:03:15,913 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 05 Mar 2019 21:03:15:912 INFO  PostgresClient [4276615eqId] postgreSQLClientConfig = {"maxPoolSize":5,"database":"okapi_modules","password":"...","username":"diku_mod_inventory_storage","port":5432,"host":"10.0.2.15"}
2019-03-05 21:03:16,083 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 05 Mar 2019 21:03:16:082 INFO  BaseSQLClient [4276785eqId] Creating configuration for 10.0.2.15:5432
2019-03-05 21:03:16,408 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 Mar 05, 2019 9:03:16 PM org.z3950.zing.cql.cql2pgjson.CQL2PgJSON loadDbSchema
2019-03-05 21:03:16,409 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 INFO: loadDbSchema: Loaded 'templates/db_scripts/schema.json' OK
2019-03-05 21:03:16,421 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 Mar 05, 2019 9:03:16 PM org.z3950.zing.cql.cql2pgjson.CQL2PgJSON getDbTable
2019-03-05 21:03:16,422 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 SEVERE: loadDbSchema(): No primary table name, can not load
2019-03-05 21:03:16,430 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 05 Mar 2019 21:03:16:428 INFO  ItemStorageAPI [4277131eqId] SQL generated by CQL query (barcode==7159052667):  WHERE ((jsonb_typeof(items_mt_view.jsonb->'barcode')='number' AND items_mt_view.jsonb->'barcode'=to_jsonb(7159052667)) OR (jsonb_typeof(items_mt_view.jsonb->'barcode')<>'number' AND items_mt_view.jsonb->'barcode'='"7159052667"' AND lower(f_unaccent(items_mt_view.jsonb->>'barcode'))='7159052667')) LIMIT 1 OFFSET 0
2019-03-05 21:03:24,715 INFO  DockerModuleHandle   mod-users-15.3.1-SNAPSHOT.60 21:03:24 INFO  ExpirationTool       Calling doExpiration()
2019-03-05 21:03:24,719 INFO  DockerModuleHandle   mod-users-15.3.1-SNAPSHOT.60 21:03:24 INFO  ExpirationTool       Calling doExpirationForTenant for tenant diku
2019-03-05 21:03:24,721 INFO  DockerModuleHandle   mod-users-15.3.1-SNAPSHOT.60 21:03:24 INFO  PostgresClient       Skipping query due to no results expected! SELECT * FROM diku_mod_users.users  WHERE (lower(f_unaccent(users.jsonb->>'active')) LIKE lower(f_unaccent('true'))) AND (users.jsonb->>'expirationDate' <'2019-03-05T21:03:24.707Z')
2019-03-05 21:03:24,721 INFO  DockerModuleHandle   mod-users-15.3.1-SNAPSHOT.60 21:03:24 INFO  ExpirationTool       No results found for query active == true AND expirationDate < 2019-03-05T21:03:24.707Z
2019-03-05 21:03:34,048 INFO  DockerModuleHandle   mod-inventory-storage-14.1.0-SNAPSHOT.215 05 Mar 2019 21:03:34:047 INFO  LogUtil [4294750eqId] org.folio.rest.RestVerticle start  invoking getItemStorageItems
2019-03-05 21:03:34,114 INFO  ProxyContext         132020/circulation;919154/item-storage RES 200 18680979us mod-inventory-storage-14.1.0-SNAPSHOT.215 http://10.0.2.15:9136/item-storage/items..

Current activity is to locate relevant code in mod-inventory-storage or CQL2PgJSON.

Comment by Nassib Nassar [ 06/Mar/19 ]

Running the above query on items_mt_view in the database completes instantly.

The large timing may be related to:

SEVERE: loadDbSchema(): No primary table name, can not load

The behavior appears superficially similar to a bug discussed by Wayne on Slack on Oct. 31, 2018, but the cause seems to be different.

While deploying debugging code, deployment instances were accidentally deleted and the "search for an instance by known instanceId" timing could not be completed today.

Comment by Jakub Skoczen [ 06/Mar/19 ]

Nassib Nassar Do I read this right that the large portion of time seem to be spent in a call to /items-storage/items/?query=barcode=xxx?

Comment by Jakub Skoczen [ 06/Mar/19 ]

Nassib Nassar the below logfile shows that the item "view" is use for filtering items by barcode.

Kurt Nordstrom We have identified this "view" as a source of performance issues and it was supposedly removed in a fix you applied MODINVSTOR-247 Closed . What is going on here?

Comment by Jakub Skoczen [ 06/Mar/19 ]

Kurt Nordstrom Nassib Nassar Adam Dickmeiss Hongwei Ji Ok, looking at the log it looks like Nassib is using an old version of mod-inventory-storage (14.1.0-SNAPSHOT) and MODINVSTOR-247 Closed is fixed from 15.0.0. However, looking at the performance result from Jenkins: https://jenkins-aws.indexdata.com/job/Automation/job/folio-perf-platform/14/performance/ I still see issues with both checkin/checkout and searching items by barcode (27s and 8s with 50users). The version of mod-inventory-storage used by the Jenkins job is 15.2.0-SNAPSHOT.

Comment by Nassib Nassar [ 06/Mar/19 ]

VM environment was rebuilt based on folio/snapshot-backend-core. Overall timings (running hot) are on the order of what was originally reported:

Check out by barcode:  ~4 s
Check in by barcode:   ~4 s
Get instance by id:    ~1 s
Comment by Nassib Nassar [ 06/Mar/19 ]

Timings for a single "check out" (cold)

Timings greater than one second:

2019-03-06 22:39:17,128 INFO  ProxyContext         200303/circulation;874098/item-storage RES 200 1631583us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-06 22:39:18,943 INFO  ProxyContext         200303/circulation RES 201 3493067us mod-circulation-15.0.0-SNAPSHOT.232 http://10.0.2.15:9137/circulation/check-out-by-barcode

All timings:

2019-03-06 22:39:14,677 INFO  ProxyContext         164024/authn RES 202 3902us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/authn/login
2019-03-06 22:39:14,694 INFO  ProxyContext         346005/users RES 202 2516us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/users..
2019-03-06 22:39:14,723 INFO  ProxyContext         346005/users RES 200 28120us mod-users-15.3.1-SNAPSHOT.69 http://10.0.2.15:9143/users..
2019-03-06 22:39:14,762 INFO  ProxyContext         483809/token RES 202 9116us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/token
2019-03-06 22:39:14,768 INFO  ProxyContext         483809/token RES 201 4804us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/token
2019-03-06 22:39:14,770 INFO  ProxyContext         901797/refreshtoken RES 202 12079us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/refreshtoken
2019-03-06 22:39:14,787 INFO  ProxyContext         901797/refreshtoken RES 201 17268us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/refreshtoken
2019-03-06 22:39:14,788 INFO  ProxyContext         039001/audit-data RES 202 3967us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-06 22:39:14,825 INFO  ProxyContext         996866/audit-data RES 202 9833us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-06 22:39:14,825 INFO  ProxyContext         164024/authn RES 201 147647us mod-login-5.0.0-SNAPSHOT.46 http://10.0.2.15:9135/authn/login
2019-03-06 22:39:14,833 INFO  ProxyContext         039001/audit-data RES 201 44982us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-06 22:39:14,834 INFO  ProxyContext         064253/configurations RES 202 12560us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/configurations/entries..
2019-03-06 22:39:14,893 INFO  ProxyContext         064253/configurations RES 200 58640us mod-configuration-5.0.2-SNAPSHOT.50 http://10.0.2.15:9131/configurations/entries..
2019-03-06 22:39:14,894 INFO  ProxyContext         090248/audit-data RES 202 37815us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-06 22:39:14,894 INFO  ProxyContext         807779/perms RES 202 30475us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/perms/users..
2019-03-06 22:39:14,918 INFO  ProxyContext         807779/perms RES 200 24016us mod-permissions-5.5.0-SNAPSHOT.38 http://10.0.2.15:9152/perms/users..
2019-03-06 22:39:14,939 INFO  ProxyContext         996866/audit-data RES 201 113447us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-06 22:39:14,945 INFO  ProxyContext         067433/perms RES 202 11151us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/perms/users/be69019d-fdb4-421d-ab14-9ad4c2c7ec56/permissions..
2019-03-06 22:39:14,969 INFO  ProxyContext         090248/audit-data RES 201 74820us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-06 22:39:15,440 INFO  ProxyContext         067433/perms RES 200 494069us mod-permissions-5.5.0-SNAPSHOT.38 http://10.0.2.15:9152/perms/users/be69019d-fdb4-421d-ab14-9ad4c2c7ec56/permissions..2019-03-06 22:39:15,449 INFO  ProxyContext         200303/circulation RES 202 600285us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation/check-out-by-barcode
2019-03-06 22:39:15,476 INFO  ProxyContext         200303/circulation;872787/users RES 202 16230us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/users..
2019-03-06 22:39:15,496 INFO  ProxyContext         200303/circulation;874098/item-storage RES 202 33143us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/item-storage/items..
2019-03-06 22:39:15,513 INFO  ProxyContext         200303/circulation;872787/users RES 200 35838us mod-users-15.3.1-SNAPSHOT.69 http://10.0.2.15:9143/users..
2019-03-06 22:39:15,522 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:15 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:17,128 INFO  ProxyContext         200303/circulation;874098/item-storage RES 200 1631583us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-06 22:39:17,136 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:17,146 INFO  ProxyContext         200303/circulation;610446/holdings-storage RES 202 3860us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/holdings-storage/holdings/7698149a-702e-449f-8545-12678d2c6f29
2019-03-06 22:39:17,161 INFO  ProxyContext         200303/circulation;610446/holdings-storage RES 200 14222us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/holdings-storage/holdings/7698149a-702e-449f-8545-12678d2c6f29
2019-03-06 22:39:17,167 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-06 22:39:17,175 INFO  ProxyContext         200303/circulation;151038/instance-storage RES 202 3344us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/instance-storage/instances/52760ff3-2736-4ecb-a9fc-fe0b4b313e51
2019-03-06 22:39:17,192 INFO  ProxyContext         200303/circulation;151038/instance-storage RES 200 16823us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/instance-storage/instances/52760ff3-2736-4ecb-a9fc-fe0b4b313e51
2019-03-06 22:39:17,202 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-06 22:39:17,214 INFO  ProxyContext         200303/circulation;709908/locations RES 202 3734us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/locations/53cf956f-c1df-410b-8bea-27f712cca7c0
2019-03-06 22:39:17,231 INFO  ProxyContext         200303/circulation;709908/locations RES 200 16857us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/locations/53cf956f-c1df-410b-8bea-27f712cca7c0
2019-03-06 22:39:17,241 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-06 22:39:17,261 INFO  ProxyContext         200303/circulation;193879/service-points RES 202 4599us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/service-points/3a40852d-49fd-4df2-a1f9-6e2641a6e91f
2019-03-06 22:39:17,282 INFO  ProxyContext         200303/circulation;193879/service-points RES 200 20602us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/service-points/3a40852d-49fd-4df2-a1f9-6e2641a6e91f
2019-03-06 22:39:17,287 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-06 22:39:17,302 INFO  ProxyContext         200303/circulation;540439/material-types RES 202 3378us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/material-types/1a54b431-2e4f-452d-9cae-9cee66c9a892
2019-03-06 22:39:17,311 INFO  ProxyContext         200303/circulation;540439/material-types RES 200 8403us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/material-types/1a54b431-2e4f-452d-9cae-9cee66c9a892
2019-03-06 22:39:17,318 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-06 22:39:17,329 INFO  ProxyContext         200303/circulation;544283/loan-storage RES 202 4265us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/loan-storage/loans..
2019-03-06 22:39:17,595 INFO  ProxyContext         200303/circulation;544283/loan-storage RES 200 265843us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/loan-storage/loans..
2019-03-06 22:39:17,600 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:17,616 INFO  ProxyContext         200303/circulation;503455/request-storage RES 202 3936us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/request-storage/requests..
2019-03-06 22:39:17,633 INFO  ProxyContext         200303/circulation;503455/request-storage RES 200 16686us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/request-storage/requests..
2019-03-06 22:39:17,640 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:17 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:17,653 INFO  ProxyContext         200303/circulation;528468/item-storage RES 202 2789us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/item-storage/items..
2019-03-06 22:39:18,002 INFO  ProxyContext         200303/circulation;528468/item-storage RES 200 349280us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-06 22:39:18,008 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:18 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:18,023 INFO  ProxyContext         200303/circulation;008354/holdings-storage RES 202 10658us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/holdings-storage/holdings..
2019-03-06 22:39:18,351 INFO  ProxyContext         200303/circulation;008354/holdings-storage RES 200 328235us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/holdings-storage/holdings..
2019-03-06 22:39:18,356 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:18 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:18,366 INFO  ProxyContext         200303/circulation;268832/instance-storage RES 202 4178us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/instance-storage/instances..
2019-03-06 22:39:18,690 INFO  ProxyContext         200303/circulation;268832/instance-storage RES 200 323737us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/instance-storage/instances..
2019-03-06 22:39:18,698 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:18 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:18,708 INFO  ProxyContext         200303/circulation;661008/locations RES 202 4814us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/locations..
2019-03-06 22:39:18,725 INFO  ProxyContext         200303/circulation;661008/locations RES 200 16202us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/locations..
2019-03-06 22:39:18,728 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:18 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-06 22:39:18,749 INFO  ProxyContext         200303/circulation;413447/circulation RES 202 4375us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation/rules/loan-policy..
2019-03-06 22:39:18,760 INFO  ProxyContext         200303/circulation;413447/circulation;560339/circulation-rules-storage RES 202 2385us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation-rules-storage
2019-03-06 22:39:18,770 INFO  ProxyContext         200303/circulation;413447/circulation;560339/circulation-rules-storage RES 200 9887us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/circulation-rules-storage
2019-03-06 22:39:18,778 INFO  ProxyContext         200303/circulation;413447/circulation RES 200 28885us mod-circulation-15.0.0-SNAPSHOT.232 http://10.0.2.15:9137/circulation/rules/loan-policy..
2019-03-06 22:39:18,788 INFO  ProxyContext         200303/circulation;973556/loan-policy-storage RES 202 2865us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/loan-policy-storage/loan-policies/d9cd0bed-1b49-4b5e-a7bd-064b8d177231
2019-03-06 22:39:18,802 INFO  ProxyContext         200303/circulation;973556/loan-policy-storage RES 200 13124us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/loan-policy-storage/loan-policies/d9cd0bed-1b49-4b5e-a7bd-064b8d177231
2019-03-06 22:39:18,807 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:18 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-06 22:39:18,824 INFO  ProxyContext         200303/circulation;827287/calendar RES 202 3923us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/calendar/periods/3a40852d-49fd-4df2-a1f9-6e2641a6e91f/calculateopening..
2019-03-06 22:39:18,845 INFO  ProxyContext         200303/circulation;827287/calendar RES 200 20867us mod-calendar-1.3.0-SNAPSHOT.74 http://10.0.2.15:9148/calendar/periods/3a40852d-49fd-4df2-a1f9-6e2641a6e91f/calculateopening..
2019-03-06 22:39:18,852 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 22:39:18 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-06 22:39:18,868 INFO  ProxyContext         200303/circulation;708676/item-storage RES 202 5929us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/item-storage/items/17ebed7b-7a6d-457e-b936-b5a0e44ba526
2019-03-06 22:39:18,883 INFO  ProxyContext         200303/circulation;708676/item-storage RES 204 14527us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items/17ebed7b-7a6d-457e-b936-b5a0e44ba526
2019-03-06 22:39:18,911 INFO  ProxyContext         905589/audit-data RES 202 7835us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-06 22:39:18,916 INFO  ProxyContext         200303/circulation;295786/loan-storage RES 202 5396us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/loan-storage/loans
2019-03-06 22:39:18,933 INFO  ProxyContext         200303/circulation;295786/loan-storage RES 201 17518us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/loan-storage/loans
2019-03-06 22:39:18,943 INFO  ProxyContext         200303/circulation RES 201 3493067us mod-circulation-15.0.0-SNAPSHOT.232 http://10.0.2.15:9137/circulation/check-out-by-barcode
2019-03-06 22:39:18,955 INFO  ProxyContext         905589/audit-data RES 201 44385us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-06 22:39:19,001 INFO  ProxyContext         085766/audit-data RES 202 25751us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-06 22:39:19,014 INFO  ProxyContext         444078/audit-data RES 202 25100us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-06 22:39:19,063 INFO  ProxyContext         085766/audit-data RES 201 61520us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-06 22:39:19,071 INFO  ProxyContext         444078/audit-data RES 201 56000us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data

It appears that ~ 3.5 s is reported for the entire request, and within that the largest time is spent in a call to mod-inventory-storage ( ~ 1.6 s ). Most of the time seems to be spent in the ~ 80 other calls in aggregate.

Comment by Nassib Nassar [ 07/Mar/19 ]

Timings for a single "check out" (hot)

Timings greater than one second:

2019-03-07 07:40:43,013 INFO  ProxyContext         457168/circulation;952144/item-storage RES 200 1427483us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-07 07:40:44,630 INFO  ProxyContext         457168/circulation RES 201 3080059us mod-circulation-15.0.0-SNAPSHOT.232 http://10.0.2.15:9137/circulation/check-out-by-barcode

All timings:

2019-03-07 07:40:40,960 INFO  ProxyContext         694493/authn RES 202 2962us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/authn/login
2019-03-07 07:40:40,973 INFO  ProxyContext         537677/users RES 202 1646us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/users..
2019-03-07 07:40:40,992 INFO  ProxyContext         537677/users RES 200 18666us mod-users-15.3.1-SNAPSHOT.69 http://10.0.2.15:9143/users..
2019-03-07 07:40:41,014 INFO  ProxyContext         304456/token RES 202 3446us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/token
2019-03-07 07:40:41,024 INFO  ProxyContext         872151/refreshtoken RES 202 10102us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/refreshtoken
2019-03-07 07:40:41,024 INFO  ProxyContext         304456/token RES 201 9636us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/token
2019-03-07 07:40:41,026 INFO  ProxyContext         872151/refreshtoken RES 201 2548us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/refreshtoken
2019-03-07 07:40:41,039 INFO  ProxyContext         305905/configurations RES 202 2194us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/configurations/entries..
2019-03-07 07:40:41,056 INFO  ProxyContext         811805/audit-data RES 202 1937us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-07 07:40:41,069 INFO  ProxyContext         811805/audit-data RES 201 12768us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-07 07:40:41,083 INFO  ProxyContext         694493/authn RES 201 122514us mod-login-5.0.0-SNAPSHOT.46 http://10.0.2.15:9135/authn/login
2019-03-07 07:40:41,086 INFO  ProxyContext         144100/audit-data RES 202 9844us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-07 07:40:41,086 INFO  ProxyContext         305905/configurations RES 200 47641us mod-configuration-5.0.2-SNAPSHOT.50 http://10.0.2.15:9131/configurations/entries..
2019-03-07 07:40:41,123 INFO  ProxyContext         059947/audit-data RES 202 15053us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-07 07:40:41,129 INFO  ProxyContext         024870/perms RES 202 10390us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/perms/users..
2019-03-07 07:40:41,136 INFO  ProxyContext         024870/perms RES 200 6946us mod-permissions-5.5.0-SNAPSHOT.38 http://10.0.2.15:9152/perms/users..
2019-03-07 07:40:41,155 INFO  ProxyContext         725030/perms RES 202 1953us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/perms/users/be69019d-fdb4-421d-ab14-9ad4c2c7ec56/permissions..
2019-03-07 07:40:41,162 INFO  ProxyContext         144100/audit-data RES 201 75624us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-07 07:40:41,185 INFO  ProxyContext         059947/audit-data RES 201 62534us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-07 07:40:41,534 INFO  ProxyContext         725030/perms RES 200 379630us mod-permissions-5.5.0-SNAPSHOT.38 http://10.0.2.15:9152/perms/users/be69019d-fdb4-421d-ab14-9ad4c2c7ec56/permissions..
2019-03-07 07:40:41,549 INFO  ProxyContext         457168/circulation RES 202 447338us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation/check-out-by-barcode
2019-03-07 07:40:41,583 INFO  ProxyContext         457168/circulation;422833/users RES 202 7906us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/users..
2019-03-07 07:40:41,585 INFO  ProxyContext         457168/circulation;952144/item-storage RES 202 4467us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/item-storage/items..
2019-03-07 07:40:41,628 INFO  ProxyContext         457168/circulation;422833/users RES 200 44807us mod-users-15.3.1-SNAPSHOT.69 http://10.0.2.15:9143/users..
2019-03-07 07:40:41,641 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:41 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:43,013 INFO  ProxyContext         457168/circulation;952144/item-storage RES 200 1427483us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-07 07:40:43,020 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:43,029 INFO  ProxyContext         457168/circulation;847834/holdings-storage RES 202 2962us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/holdings-storage/holdings/7698149a-702e-449f-8545-12678d2c6f29
2019-03-07 07:40:43,045 INFO  ProxyContext         457168/circulation;847834/holdings-storage RES 200 16361us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/holdings-storage/holdings/7698149a-702e-449f-8545-12678d2c6f29
2019-03-07 07:40:43,052 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-07 07:40:43,068 INFO  ProxyContext         457168/circulation;004876/instance-storage RES 202 2349us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/instance-storage/instances/52760ff3-2736-4ecb-a9fc-fe0b4b313e51
2019-03-07 07:40:43,080 INFO  ProxyContext         457168/circulation;004876/instance-storage RES 200 10883us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/instance-storage/instances/52760ff3-2736-4ecb-a9fc-fe0b4b313e51
2019-03-07 07:40:43,085 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-07 07:40:43,096 INFO  ProxyContext         457168/circulation;504447/locations RES 202 4521us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/locations/53cf956f-c1df-410b-8bea-27f712cca7c0
2019-03-07 07:40:43,109 INFO  ProxyContext         457168/circulation;504447/locations RES 200 12897us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/locations/53cf956f-c1df-410b-8bea-27f712cca7c0
2019-03-07 07:40:43,113 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-07 07:40:43,129 INFO  ProxyContext         457168/circulation;561254/service-points RES 202 5574us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/service-points/3a40852d-49fd-4df2-a1f9-6e2641a6e91f
2019-03-07 07:40:43,139 INFO  ProxyContext         457168/circulation;561254/service-points RES 200 9187us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/service-points/3a40852d-49fd-4df2-a1f9-6e2641a6e91f
2019-03-07 07:40:43,145 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-07 07:40:43,159 INFO  ProxyContext         457168/circulation;649120/material-types RES 202 2665us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/material-types/1a54b431-2e4f-452d-9cae-9cee66c9a892
2019-03-07 07:40:43,173 INFO  ProxyContext         457168/circulation;649120/material-types RES 200 14428us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/material-types/1a54b431-2e4f-452d-9cae-9cee66c9a892
2019-03-07 07:40:43,181 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-07 07:40:43,189 INFO  ProxyContext         457168/circulation;306446/loan-storage RES 202 3686us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/loan-storage/loans..
2019-03-07 07:40:43,410 INFO  ProxyContext         457168/circulation;306446/loan-storage RES 200 220664us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/loan-storage/loans..
2019-03-07 07:40:43,418 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:43,426 INFO  ProxyContext         457168/circulation;538039/request-storage RES 202 4631us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/request-storage/requests..
2019-03-07 07:40:43,450 INFO  ProxyContext         457168/circulation;538039/request-storage RES 200 23775us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/request-storage/requests..
2019-03-07 07:40:43,457 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:43,473 INFO  ProxyContext         457168/circulation;994166/item-storage RES 202 2568us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/item-storage/items..
2019-03-07 07:40:43,769 INFO  ProxyContext         457168/circulation;994166/item-storage RES 200 295773us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-07 07:40:43,774 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:43 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:43,783 INFO  ProxyContext         457168/circulation;754459/holdings-storage RES 202 2626us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/holdings-storage/holdings..
2019-03-07 07:40:44,077 INFO  ProxyContext         457168/circulation;754459/holdings-storage RES 200 294071us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/holdings-storage/holdings..
2019-03-07 07:40:44,082 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:44 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:44,096 INFO  ProxyContext         457168/circulation;838734/instance-storage RES 202 3507us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/instance-storage/instances..
2019-03-07 07:40:44,375 INFO  ProxyContext         457168/circulation;838734/instance-storage RES 200 279346us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/instance-storage/instances..
2019-03-07 07:40:44,389 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:44 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:44,391 INFO  ProxyContext         457168/circulation;173890/locations RES 202 5871us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/locations..
2019-03-07 07:40:44,398 INFO  ProxyContext         457168/circulation;173890/locations RES 200 7591us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/locations..
2019-03-07 07:40:44,403 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:44 INFO  MultipleRecords      Response received, status code: 200 body: {
2019-03-07 07:40:44,414 INFO  ProxyContext         457168/circulation;838742/circulation RES 202 7258us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation/rules/loan-policy..
2019-03-07 07:40:44,427 INFO  ProxyContext         457168/circulation;838742/circulation;156967/circulation-rules-storage RES 202 3232us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation-rules-storage
2019-03-07 07:40:44,436 INFO  ProxyContext         457168/circulation;838742/circulation;156967/circulation-rules-storage RES 200 7930us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/circulation-rules-storage
2019-03-07 07:40:44,441 INFO  ProxyContext         457168/circulation;838742/circulation RES 200 25934us mod-circulation-15.0.0-SNAPSHOT.232 http://10.0.2.15:9137/circulation/rules/loan-policy..
2019-03-07 07:40:44,471 INFO  ProxyContext         457168/circulation;595004/loan-policy-storage RES 202 2948us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/loan-policy-storage/loan-policies/d9cd0bed-1b49-4b5e-a7bd-064b8d177231
2019-03-07 07:40:44,481 INFO  ProxyContext         457168/circulation;595004/loan-policy-storage RES 200 9303us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/loan-policy-storage/loan-policies/d9cd0bed-1b49-4b5e-a7bd-064b8d177231
2019-03-07 07:40:44,485 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:44 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-07 07:40:44,493 INFO  ProxyContext         457168/circulation;741651/calendar RES 202 2762us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/calendar/periods/3a40852d-49fd-4df2-a1f9-6e2641a6e91f/calculateopening..
2019-03-07 07:40:44,508 INFO  ProxyContext         457168/circulation;741651/calendar RES 200 14423us mod-calendar-1.3.0-SNAPSHOT.74 http://10.0.2.15:9148/calendar/periods/3a40852d-49fd-4df2-a1f9-6e2641a6e91f/calculateopening..
2019-03-07 07:40:44,513 INFO  DockerModuleHandle   mod-circulation-15.0.0-SNAPSHOT.232 07:40:44 INFO  SingleRecordMapper   Response received, status code: 200 body: {
2019-03-07 07:40:44,530 INFO  ProxyContext         457168/circulation;709453/item-storage RES 202 2473us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/item-storage/items/17ebed7b-7a6d-457e-b936-b5a0e44ba526
2019-03-07 07:40:44,548 INFO  ProxyContext         457168/circulation;709453/item-storage RES 204 17397us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items/17ebed7b-7a6d-457e-b936-b5a0e44ba526
2019-03-07 07:40:44,568 INFO  ProxyContext         694985/audit-data RES 202 2829us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-07 07:40:44,583 INFO  ProxyContext         457168/circulation;627891/loan-storage RES 202 3106us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/loan-storage/loans
2019-03-07 07:40:44,616 INFO  ProxyContext         694985/audit-data RES 201 47927us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-07 07:40:44,530 INFO  ProxyContext         457168/circulation;709453/item-storage RES 202 2473us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/item-storage/items/17ebed7b-7a6d-457e-b936-b5a0e44ba526
2019-03-07 07:40:44,548 INFO  ProxyContext         457168/circulation;709453/item-storage RES 204 17397us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items/17ebed7b-7a6d-457e-b936-b5a0e44ba526
2019-03-07 07:40:44,568 INFO  ProxyContext         694985/audit-data RES 202 2829us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-07 07:40:44,583 INFO  ProxyContext         457168/circulation;627891/loan-storage RES 202 3106us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/loan-storage/loans
2019-03-07 07:40:44,616 INFO  ProxyContext         694985/audit-data RES 201 47927us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-07 07:40:44,622 INFO  ProxyContext         457168/circulation;627891/loan-storage RES 201 39377us mod-circulation-storage-7.0.0-SNAPSHOT.150 http://10.0.2.15:9144/loan-storage/loans
2019-03-07 07:40:44,630 INFO  ProxyContext         457168/circulation RES 201 3080059us mod-circulation-15.0.0-SNAPSHOT.232 http://10.0.2.15:9137/circulation/check-out-by-barcode
2019-03-07 07:40:44,666 INFO  ProxyContext         811711/audit-data RES 202 6267us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-07 07:40:44,666 INFO  ProxyContext         378499/audit-data RES 202 4346us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/audit-data
2019-03-07 07:40:44,705 INFO  ProxyContext         811711/audit-data RES 201 38457us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
2019-03-07 07:40:44,718 INFO  ProxyContext         378499/audit-data RES 201 51701us mod-audit-0.0.4-SNAPSHOT.23 http://10.0.2.15:9146/audit-data
Comment by Nassib Nassar [ 07/Mar/19 ]

Complete okapi log attached as: okapi-check-out-hot.log

Comment by Nassib Nassar [ 11/Mar/19 ]

After 1427483us the largest timings are:

2019-03-07 07:40:41,549 INFO ProxyContext 457168/circulation RES 202 447338us mod-authtoken-2.0.5-SNAPSHOT.42 http://10.0.2.15:9142/circulation/check-out-by-barcode
2019-03-07 07:40:41,534 INFO ProxyContext 725030/perms RES 200 379630us mod-permissions-5.5.0-SNAPSHOT.38 http://10.0.2.15:9152/perms/users/be69019d-fdb4-421d-ab14-9ad4c2c7ec56/permissions..
2019-03-07 07:40:43,769 INFO ProxyContext 457168/circulation;994166/item-storage RES 200 295773us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/item-storage/items..
2019-03-07 07:40:44,077 INFO ProxyContext 457168/circulation;754459/holdings-storage RES 200 294071us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/holdings-storage/holdings..
2019-03-07 07:40:44,375 INFO ProxyContext 457168/circulation;838734/instance-storage RES 200 279346us mod-inventory-storage-15.2.0-SNAPSHOT.252 http://10.0.2.15:9145/instance-storage/instances..
Comment by Jakub Skoczen [ 11/Mar/19 ]

Nassib Nassar on Friday we discussed that the following should be done before closing this issue:

  • rerun with the latest code that includes fixes for slowness in the query-item-by-barcode
  • attach the latest "call graph" (you've demoed one on Friday)
  • point at the next slowest API call within check-in/check-out (to create Jira issue for optimizing it)
  • create a new issue for "sharing" the script to generate "call graphs"
Comment by Nassib Nassar [ 11/Mar/19 ]

Jakub Skoczen can we clarify "latest code" to be used.

Comment by Jakub Skoczen [ 12/Mar/19 ]

Nassib Nassar Code that includes fixes from MODINVSTOR-269 Closed

Comment by Nassib Nassar [ 12/Mar/19 ]

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

These timings used the "latest code" provided by Hongwei.

Comment by Nassib Nassar [ 12/Mar/19 ]

Issue for call graph tool is: https://folio-org.atlassian.net/browse/FOLIO-1856

Comment by Nassib Nassar [ 12/Mar/19 ]

Client-side timings:

Check out by barcode:  1.8 s
Check in by barcode:   1.8 s
Get instance by id:    0.4 s

These have been confirmed using Postman (thanks to Hongwei for suggesting this).

A previous comment with timings has been deleted and these timings supersede it. Those timings were off by 0.7 s because of my own operator error.

Comment by Nassib Nassar [ 12/Mar/19 ]

Test code is: https://github.com/nassibnassar/folio-adhoc-tests

Note that this code has not been instrumented since our focus shifted to the okapi log. It provides only approximate timings.

Comment by Nassib Nassar [ 12/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 ]

New issue created at: https://folio-org.atlassian.net/browse/FOLIO-1868

Comment by Nassib Nassar [ 14/Mar/19 ]

This issue can be closed.

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