Versions Compared

Old Version 59

changes.mady.by.user Svitlana Zmiivska (Deactivated)

Saved on

compared with

New Version Current

changes.mady.by.user Svitlana Zmiivska (Deactivated)

Saved on

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.

Jira LegacyserverSystem Jiracolumns

Jira Legacy
serverSystem JIRA
columnskey,summary,type,created,updated,due,assignee,reporter,priority,status,resolution
serverId01505d01-b853-3c2e-90f1-ee9b165564fc
keyPERF-27

...

In this api, we are checking the performance of placing a holding on a discovery service interface (EDS) running in the Fameflower release - 

...

  1. The placing a hold request takes about 1 seconds: POST /patron/account/{id}/instance/{instanceId}/hold. 
  2. POST /patron/account/{id}/instance/{instanceId}/hold and POST /circulation/requests/instances show almost the same response time. In addition, mod-circulation's native item-level request code is 24.5% faster than mod-circulation's instance-level request code. Seems like the main issue is the mod-circulation instance-level request API, POST /circulation/requests/instances which is called by mod-patron subsequently.
  3. JVM profiling shows the slowest operations, totalling more CPU time than other calls: 
    1. logging with INFO level - Logging level could be reduced to WARNING or ERROR, but at the cost of having less data to work with should there be a need to troubleshoot. The most CPU consuming methods are org.folio.circulation.support.Result.next and  org.folio.circulation.support.Result.after from org.folio.circulation.support.SingleRecordFetcher, and org.folio.circulation.support.SingleRecordFetcher.fetch method
    2. JSON de/serialization - fasterxml.jackson.databind.ObjectMapper.readValue method of mod-circulation-storage and mod-inventory-storage consumed high CPU resources as there were a lot of JSON decoding, this implementation could be reviewed for optimisation possibilities. The most CPU consuming methods are org.folio.rest.persist.PgUtil.streamGet from org.folio.rest.impl.InstanceStorageAPI.getInstanceStorageInstancesByInstanceId (mod-inventory-storage), org.folio.rest.impl.HoldingsStorageAPI.getHoldingsStorageHoldings(mod-inventory-storage) and org.folio.rest.persist.PostgresClient.doGet from  org.folio.rest.impl.LoansAPI.getLoanStorageLoans  and org.folio.rest.impl.RequestsAPI.getRequestStorageRequests(mod-circulation-storage)
    3. request's validation - need to consider using a more efficient request's validation instead of org.hibernate.validator.internal.engine.ValidatorImpl.validate method because it's one of the slowest operations. The slowest method is org.folio.rest.RestVerticle.route and org.folio.rest.RestVerticle.parseParams
  4. mod-circulation-storage and mod-feesfines generated missing indexes warnings, see Recommended Improvements for the JIRAs that were created/covered by this testing effort.

...

Test

Virtual Users

Duration

OKAPI log level

Profiled

Ramp up (total time

in seconds)

API call

1. 

1

30 min

WARNING

No

1

POST /patron/account/{id}/instance/{instanceId}/hold

2. 

5

30 min

WARNING

No

50

POST /patron/account/{id}/instance/{instanceId}/hold

3. 

8

30 min

WARNING

No

80

POST /patron/account/{id}/instance/{instanceId}/hold

4. 

20

30 min

WARNING

No

200

POST /patron/account/{id}/instance/{instanceId}/hold

5. 

20

30 min

WARNING

Yes

200

POST /patron/account/{id}/instance/{instanceId}/hold
6.130 minWARNINGNo1POST /circulation/requests/instances
7.530 minWARNINGNo50POST /circulation/requests/instances
8.830 minWARNINGNo80POST /circulation/requests/instances
9.2030 minWARNINGNo200POST /circulation/requests/instances
10.2030 minWARNINGYes200POST /circulation/requests/instances
11.130 minWARNINGYes1POST /circulation/requests
12.830 minWARNINGYes200POST /circulation/requests


Results

  1. An instance-level request to mod-patron 

    POST /patron/account/{id}/instance/{instanceId}/hold

    Code Block
    {
    "item": {
	    "instanceId": "c2063f7c-245a-4c24-b643-67fea831ebcc"
	},
    "requestDate": "2020-06-01T18:51:24.000+0000",
    "pickupLocationId": "7068e104-aa14-4f30-a8bf-71f71cc15e07"
}

    Overall time for the placing holds api in seconds 


    		Average 75th %tile
    1 user933.01 ms 1.10 s
    5 users1.01 s1.12 s
    8 users1.03 s1.18 s
    20 users1.33 s1.47 s


  2. mod-patron subsequently calls mod-circulation to place instance-level requests

     POST /circulation/requests/instances

    Code Block
    {
  "requestDate": "2017-07-29T22:25:37Z",
  "requesterId": "21932a85-bd00-446b-9565-46e0c1a5490b",
  "instanceId": "195efae1-588f-47bd-a181-13a2eb437701",
  "requestExpirationDate": "2017-07-25T22:25:37Z",
  "pickupServicePointId": "8359f2bc-b83e-48e1-8a5b-ca1a74e840de"
}

    Overall time in seconds 


    		Average 75th %tile
    1 user864.35 ms1.01 s
    5 users1.09 s1.14 s
    8 users1.15 s1.18 s
    20 users1.58 s1.53 s


  3.  An Item-level request 

    POST /circulation/requests

    Code Block
    {
  "requestDate": "2020-06-18T09:23:11.957Z",
  "requesterId": "e96618a9-04ee-4fea-aa60-306a8f4dd89b",
  "requestType": "Hold",
  "fulfilmentPreference": "Hold Shelf",
  "itemId": "0000023d-a95f-4396-8d37-42dda48cdf3d",
  "requestExpirationDate": "2020-06-18T09:23:11.957Z",
  "pickupServicePointId": "d80a641e-50b9-4bd2-99a2-a4a12c8515cb"
}

    Overall time in seconds 


    		Average 75th %tile
    1 user807.90 ms819.00 ms
    8 users855.92 ms855.00 ms


                    The comparison table between an instance-level request and an Item-level request to mod-circulation (done 23.07.2020). The item-level request is 24.5% faster than an instance-level request


An instance-level request to mod-circulation

POST /circulation/requests/instances

An Item-level request to mod-circulation

POST /circulation/requests 


Average 75th %tileAverage 75th %tile
1 user1.07 s1.09 s807.90 ms819.00 ms
8 users1.09 s1.09 s855.92 ms855.00 ms

...

There aren't any WARNING statements of missing indexes in mod-inventory-storage, mod-patron modules.

The following WARNING statements of missing indexes were generated during a test run and logged by mod-circulation-storage:

...

The slowest query which took the most of execution time was initiated by the mod_circulation_storage service presented in the following table:


Percent of total time

Average Time,ms

Calls

Module

Query

7%25 ms 426mod_circulation_storage

SELECT jsonb,idFROM fs09000000_mod_circulation_storage.loan WHERE (lower(f_unaccent(loan.jsonb->'status'->>'name')) LIKE lower(f_unaccent('ClosedOpen'))) AND (loan.jsonb->>'userId' ~ '') LIMIT 5000 OFFSET 0


CPU Utilization


1 user5 users8 users20 users

Average %Range %Average %Range %Average %Range %Average %Range %
mod-circulation1.230-31.9832-2030-1460-88
mod-circulation-storage0.610.25-6.601.730.23-26.7720-630-9
mod-patron10-2422-6610-1200-11
mod-feesfines100101-102100101-103100101-103100101-103

...

  • In mod-circulation, mod-circulation-storage, mod-inventory-storage consider using a more efficient JSON package or calling use the existing jackson serialization calls in a different way to address the item: JVM profiling shows JSON de/serialization operations one of the slowest operations.
  • In mod-circulation consider using a more efficient request's validation instead of org.hibernate.validator.internal.engine.ValidatorImpl.validate method because it's one of the slowest operations.
  • The following JIRAs have been created for mod-circulation-storage and mod-fees-fines:
  • Jira Legacy
    serverSystem JiraJIRA
    columnskey,summary,type,created,updated,due,assignee,reporter,priority,status,resolution
    serverId01505d01-b853-3c2e-90f1-ee9b165564fc
    keyCIRCSTORE-216
  • Jira Legacy
    serverSystem
    Jira
    JIRA
    serverId01505d01-b853-3c2e-90f1-ee9b165564fc
    keyMODFEE-67
  • Some missing indexes warnings are covered by the story
    Jira Legacy
    serverSystem JiraJIRA
    serverId01505d01-b853-3c2e-90f1-ee9b165564fc
    keyCIRCSTORE-215
  • Consider logging with ERROR level if not fixing the JIRA below to reduce the excess logging by mod-circulation-storage and mod-feesfines
  • It will great for the modules to have custom metrics, such as rates and response times of out-going API and database calls so that we can get more insight on how an API behaves.

Discussions

We could not get to the bottom of instance-level requests slowness. That why we needed to look into item-level request. mod-circulation's native item-level request code is 24.5% faster than mod-circulation's instance-level request code.

Appendix

See Attached place-holds-FF.xlsx for details 

...