[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: |
|
||||||||||||||||||||||||||||||||||||||||||||
| Issue links: |
|
||||||||||||||||||||||||||||||||||||||||||||
| Sprint: | Core: Platform - Sprint 58, Core: Platform - Sprint 59 | ||||||||||||||||||||||||||||||||||||||||||||
| Story Points: | 3 | ||||||||||||||||||||||||||||||||||||||||||||
| Development Team: | Core: Platform | ||||||||||||||||||||||||||||||||||||||||||||
| Description |
|
As shown in
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:
|
| 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
|
| 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
|
| 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
|
| 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:
|
| 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
|
| 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. |