Versions Compared

Version Old Version 7 New Version 8
Changes made by

Varun Javalkar

Varun Javalkar

Saved on

Key

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

WORK IN PROGRESS

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

...

In this workflow, we are checking the performance of the renewal of loan items for the Goldenrod release.

We tested it with 1, 2 virtual users for 30 minutes.  

Backend:

  • mod-users-17.1.0
  • mod-users-bl-6.0.0
  • mod-authtoken-2.5.1
  • mod-permissions-5.11.2
  • mod-circulation-19.0.9
  • mod-circulation-storage-12.0.1
  • okapi-3.1.1

Environment:

  • 55 back-end modules deployed in 110 ECS services
  • 3 okapi ECS services
  • 8 m5.large  EC2 instances
  • 1  db.r5.xlarge AWS RDS instance
  • INFO logging level

...

  1. On average POST_/circulation/renew-by-barcode API call takes average 671.12 seconds as we gradually increase the number of loans and users to 200 and 2 respectively.
  2. POST_/circulation/renew-by-barcode API makes 26 different API requests to gather userBarcode and itemBarcode information. 34% of those are calls are to mod-authtoken. S See Recommended Improvements for the JIRAs that were covered by this testing effort.
  3. No missing indexes or no suspicious slow queries found except a number of SELECT count_estimate() calls.

Test Runs

Test

Virtual Users

Duration

OKAPI log level

Profiled

Loans per User

1. 

1

30 min

WARNING

No

10, 50, 100, 200

2. 

2

30 min

WARNING

No

10, 50, 100, 200

3.130 minINFONo10, 50, 100, 200


Results

  1. Renew all loans by barcode

    For 30 minutesLoansRenew all loans (Average)POST_/circulation/renew-by-barcode (Average)
    1 user10

    6.52 seconds

    585.11 ms

    50

    31.81 seconds

    637.48 ms

    1001.06 minutes

    650.15 ms

    2002.09 minutes

    673.40 ms

    2 users10

    7.42 seconds

    683.76 ms

    50

    32.61 seconds

    686.65 ms

    100

    1.10 minutes

    705.37 ms

    200

    2.27 minutes

    747.04 ms



  2. Below is the dependency graph generated from Giraffe for single POST_/circulation/renew-by-barcode API. It shows individual calls made by renew-by-barcode to gather prerequisite information data from different APIs such as item-storage, location-units, loan-types, request-storage, notice-policy, locations, and mod-authtoken.

Image Removed

JVM Profiling

  • Overall slow methods (between the modules profiled: mod-rtac, mod-circulation, mod-circulation-storage, mod-inventory, mod-inventory-storage)

Image Removed

To see more drill down these methods at: http://ec2-54-165-58-65.compute-1.amazonaws.com/grafana/d/b3iP-8hiz/java-profiling-folio-new?orgId=1&from=1592598484852&to=1592600441623&var-service_tag=mod-rtac&var-aggregation=10s

  1. In all, this call took 990 ms, and 6% of that is consumed by mod-authtoken and the remaining 94% of the time is taken by other APIs to gather prerequisite data.

Image Added



Database

The database CPU usage decreases slightly as the number of users increases 1, 5  users run. At maximum 28% CPU usage for 1 user. We are seeing a slight decrease in CPU utilization for 5 Users because RDS Postgresql is caching the most frequent query results.


Database

...

queries 
Anchor
slowQueries
slowQueries

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

...

 For 30 minutes test, following queries were made

QueryTotal timeAverage Time
, ms77%14,632 ms21mod_inventory_storageSELECT COUNT(*)

Calls

Module

Query

Total calls made
SELECT count_estimate('SELECT jsonb,id FROM fs09000000_mod_inventory_storage.
holdings_record

API response time vs Postgresql query response time

This difference below between API and Postgresql query response time is the sum of network time to/back from calling database, deserialization of JSON string into JSON objects, processing time, and network time to/from API. Below are a single API request and SQL query triggered manually for comparison.

ActionType of RequestActual requestTime, msget InstanceSQL queryselect * from fs09000000_mod_inventory_storage.instance where id = '00009a0b-e973-443b-9796-c3373a352f86';305API requesthttps:/{okapi-url}/inventory/instances/00009a0b-e973-443b-9796-c3373a352f86368get holdingsSQL queryselect * from fs09000000_mod_inventory_storage.holdings_record hr1 where hr1.instanceid = '121063ba-43cc-48f4-a49f-aaf5488127e0';350API requesthttps:/{okapi-url}/holdings-storage/holdings?limit=2147483647&query=instanceId==121063ba-43cc-48f4-a49f-aaf5488127e503get ItemSQL queryselect * from fs09000000_mod_inventory_storage.item where holdingsrecordid='95a897e5-2505-4803-a7f1-7da39c9f67cb';353API requesthttps://{okapi-url}/inventory/items?limit=2147483647&query=holdingsRecordId%3D%3D95a897e5-2505-4803-a7f1-7da39c9f67cb662get Open loanSQL queryselect * from fs09000000_mod_circulation_storage.loan where jsonb->>'itemId'='3faad467-fca1-41c8-ad7d-af1dcd3fdc3c' AND jsonb->'status'->>'name'='Open'; 372API requesthttps://{okapi-url}/circulation/loans?limit=2147483647&query=(itemId==3faad467-fca1-41c8-ad7d-af1dcd3fdc3c and status.name==Open)400
item WHERE lower(f_unaccent(item.jsonb->>''barcode'')) LIKE lower(f_unaccent(''54357881''))')2 minutes or 71%14 ms9027
SELECT count_estimate('SELECT jsonb FROM fs09000000_mod_patron_blocks.user_summary WHERE (jsonb->>''userId'') = ''4deba809-4fb4-432a-b3df-c54b6ad51d22''')0 minutes or 10%2 ms8457


CPU Utilization

CPU utilization is relatively on a lower side for most modules except for mod-inventory-storage

...


Recommended Improvements 
Anchor
recommendedImprovements
recommendedImprovements

  • The following JIRA has been created for mod-authtoken optimization:

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

Appendix

See Attached rtac-test-report.xlsx for details