API slowdown?

yuriy · May 28, 2021, 2:26pm

Greetings Backendless dev team.
Our app id is 4BAEABFC-6FEF-EB39-FFE3-162B0D48F300
We have quite an old app, about year ago we had to freeze all development due to financial difficulties. We ran on plan “cloud 99” back then, for sdk v5 I think. And it was before USA cluster. Now company decided to try revive app. We on plan “cloud 9” for now. And I see we are on USA cluster.
So, the problem - almost every custom api call is much much slower than it was year ago.
Does cloud 9 have so much less speed than cloud 99?
I thought it may be due to our app uses old sdk and I tried to update to latest version, but it didn’t helped speed up (but it broke a few things due to changes in API, sigh…)
you can test by running “myCustomEvent” custom event. It’s just one simple row save and three related fields assignment and it took about 3 seconds!

mark-piller · May 28, 2021, 2:32pm

Hello @yuriy,

Could you add logging in your code to see how much time is spent for each step? Please share your findings with us.

Regards,
Mark

yuriy · May 28, 2021, 2:36pm

yes, I have logging.
those are few runs of same function:
2021-05-28 13:41:02,180 | SERVER_CODE | INFO | [10439] newPendedJob res 1 {
created: 1622209262000,
global_message: ‘testing from custom’,
negotiations_ready_to_save: ‘[]’,
type: ‘standard’,
ownerId: null,
error_object: null,
negotiations_saved: ‘[]’,
___class: ‘pendedJobs’,
crms_opportunity: null,
gear_finder_found_suppliers: null,
step: 2,
updated: null,
has_crms_opportunity: false,
suppliers_found: null,
objectId: ‘314BF393-1276-4949-9ABA-A87A6DED7240’,
all_suppliers: null,
status: ‘pending’
}
2021-05-28 13:41:05,360 | SERVER_CODE | INFO | [10439] res: [ 1, 1, 1 ]
2021-05-28 13:41:05,364 | SERVER_CODE | INFO | [10439] Processing finished in 3617.668ms

2021-05-28 14:10:32,872 | SERVER_CODE | INFO | [5554] myCustomEvent, context: {
___jsonclass: ‘com.backendless.servercode.RunnerContext’,
deviceType: ‘JS’,
crossHandlerData: {},
userLocale: ‘en’,
httpHeaders: null,
userId: ‘53FC6A47-79C6-561E-FFED-4EBA0ABDA400’,
eventContext: null,
userRoles: [ ‘AuthenticatedUser’, ‘JSUser’, ‘dashboardAdmins’ ],
userToken: ‘05475B0C-3B02-413C-9FBF-ADAA1FD2164F’,
prematureResult: null,
missingProperties: {},
appId: ‘4BAEABFC-6FEF-EB39-FFE3-162B0D48F300’,
httpResponseHeaders: {},
userRole: [ ‘AuthenticatedUser’, ‘JSUser’, ‘dashboardAdmins’ ]
}
2021-05-28 14:10:32,873 | SERVER_CODE | INFO | [5554] args: {
sendTo: [ ‘testovtestovtest@outlook.com’ ],
templateName: ‘testNewTemplate’
}
2021-05-28 14:10:33,254 | SERVER_CODE | INFO | [5554] newPendedJob res 1 {
created: 1622211033000,
global_message: ‘testing from custom’,
negotiations_ready_to_save: ‘[]’,
type: ‘standard’,
ownerId: ‘53FC6A47-79C6-561E-FFED-4EBA0ABDA400’,
error_object: null,
negotiations_saved: ‘[]’,
___class: ‘pendedJobs’,
crms_opportunity: null,
gear_finder_found_suppliers: null,
step: 2,
updated: null,
has_crms_opportunity: false,
suppliers_found: null,
objectId: ‘700612C3-58C1-4352-99B4-6C6AA4F70E02’,
all_suppliers: null,
status: ‘pending’
}
2021-05-28 14:10:35,736 | SERVER_CODE | INFO | [5554] res: [ 1, 1, 1 ]
2021-05-28 14:10:35,740 | SERVER_CODE | INFO | [5554] Processing finished in 2930.491ms

2021-05-28 14:12:42,472 | SERVER_CODE | INFO | [7520] args: {
sendTo: [ ‘testovtestovtest@outlook.com’ ],
templateName: ‘testNewTemplate’
}
2021-05-28 14:12:43,056 | SERVER_CODE | INFO | [7520] newPendedJob res 1 {
created: 1622211162000,
global_message: ‘testing from custom’,
negotiations_ready_to_save: ‘[]’,
type: ‘standard’,
ownerId: ‘53FC6A47-79C6-561E-FFED-4EBA0ABDA400’,
error_object: null,
negotiations_saved: ‘[]’,
___class: ‘pendedJobs’,
crms_opportunity: null,
gear_finder_found_suppliers: null,
step: 2,
updated: null,
has_crms_opportunity: false,
suppliers_found: null,
objectId: ‘E48A9BE2-FEDD-4AA5-9A36-25E453E753F5’,
all_suppliers: null,
status: ‘pending’
}
2021-05-28 14:12:44,832 | SERVER_CODE | INFO | [7520] res: [ 1, 1, 1 ]
2021-05-28 14:12:44,836 | SERVER_CODE | INFO | [7520] Processing finished in 2423.900ms

there is promise.all for three addRelation commands, as you can see it takes more than 1 second (the line with “res: [ 1, 1, 1 ]”)

mark-piller · May 28, 2021, 2:42pm

Please help me understand how to interpret the following line:

2021-05-28 14:12:44,832 | SERVER_CODE | INFO | [7520] res: [ 1, 1, 1 ]

yuriy · May 28, 2021, 2:53pm

it’s standard backendless response for addRelation command, which is in promises array (three operations). The info I talked about is in timestamps. before operation: 2021-05-28 14:12:43,056
after operation: 2021-05-28 14:12:44,832 Hence it took about 1.7 seconds

mark-piller · May 28, 2021, 3:03pm

I am talking about measuring individual steps and API calls made inside of the logic. We need to see the breakdown and timings of each individual call there to understand where the time is spent.

yuriy · May 28, 2021, 3:08pm

Sorry, I’m not quite follow. Here is my code, as you can see there is console.log after each call to API. What additional logging can I add here?
let pended_jobs = {
“global_message”:“testing from custom”,
“step”:2,
“negotiations_ready_to_save”:JSON.stringify([]),
// “negotiations”:JSON.stringify(req.args.negotiations),
“negotiations_saved”:JSON.stringify([]),
“has_crms_opportunity”:false,
“crms_opportunity”:null,
“type”:‘standard’
}
return Backendless.Data.of(“pendedJobs”).save(pended_jobs)
.then(res=>{
let pa = [];
console.log(“newPendedJob res 1”, res);
pa.push(Backendless.Data.of(“pendedJobs”).addRelation({“objectId”:res.objectId},“user_job”,[{“objectId”: ‘5FA21F96-7E07-4270-AC3F-207B1985B8E2’}]))
pa.push(Backendless.Data.of(“pendedJobs”).addRelation({“objectId”:res.objectId},“user_renter”,[{“objectId”: ‘53FC6A47-79C6-561E-FFED-4EBA0ABDA400’}]))
pa.push(Backendless.Data.of(“pendedJobs”).addRelation({“objectId”:res.objectId},“company_renter”,[{“objectId”: ‘4AA92FFE-2657-5D0F-FF46-978450525A00’}]))
return Promise.all¶
})
.then( function( res ) {
console.log( "res: ", res );
return Promise.resolve({res:res});
})

mark-piller · May 28, 2021, 3:27pm

There are 4 API calls here. I’d like to see how long each one takes.

yuriy · May 28, 2021, 3:33pm

well, first api call you can compare timestamps, like those (since previous console.log was just before api call):
2021-05-28 14:12:42,472 | SERVER_CODE | INFO | [7520] args: {
sendTo: [ ‘testovtestovtest@outlook.com’ ],
templateName: ‘testNewTemplate’
}
2021-05-28 14:12:43,056 | SERVER_CODE | INFO | [7520] newPendedJob res 1
but next three api calls are placed in one promise array, executed simultaneously. With console.log just after this call.
I can rewrite it to one by one call but it will be even slower. You want this rewrite?

mark-piller · May 28, 2021, 3:36pm

Yes, please

yuriy · May 28, 2021, 4:02pm

ok, I rewrote this test with one by one api call with additional console.timeLog:
2021-05-28 16:01:05,635 | SERVER_CODE | INFO | [27863] args: {
sendTo: [ ‘testovtestovtest@outlook.com’ ],
templateName: ‘testNewTemplate’
}
2021-05-28 16:01:05,897 | SERVER_CODE | INFO | [27863] default: 260.842ms
2021-05-28 16:01:05,897 | SERVER_CODE | INFO | [27863] res 1 {
created: 1622217665000,
global_message: ‘testing from custom’,
negotiations_ready_to_save: ‘[]’,
type: ‘standard’,
ownerId: ‘53FC6A47-79C6-561E-FFED-4EBA0ABDA400’,
error_object: null,
negotiations_saved: ‘[]’,
___class: ‘pendedJobs’,
crms_opportunity: null,
gear_finder_found_suppliers: null,
step: 2,
updated: null,
has_crms_opportunity: false,
suppliers_found: null,
objectId: ‘56A8C87D-2226-461B-A5AD-A48B31665E3C’,
all_suppliers: null,
status: ‘pending’
}
2021-05-28 16:01:06,438 | SERVER_CODE | INFO | [27863] default: 802.191ms
2021-05-28 16:01:06,439 | SERVER_CODE | INFO | [27863] res2: 1
2021-05-28 16:01:06,988 | SERVER_CODE | INFO | [27863] default: 1352.251ms
2021-05-28 16:01:06,989 | SERVER_CODE | INFO | [27863] res3: 1
2021-05-28 16:01:07,799 | SERVER_CODE | INFO | [27863] default: 2163.245ms
2021-05-28 16:01:07,800 | SERVER_CODE | INFO | [27863] res4: 1

here is code, just in case:

var shared = {};
let pended_jobs = {
        "global_message":"testing from custom",
        "step":2,
        "negotiations_ready_to_save":JSON.stringify([]),
        // "negotiations":JSON.stringify(req.args.negotiations),
        "negotiations_saved":JSON.stringify([]),
        "has_crms_opportunity":false,
        "crms_opportunity":null,
        "type":'standard'
    }
return Backendless.Data.of("pendedJobs").save(pended_jobs)
.then(res=>{
    let pa = [];
    shared.objectId = res.objectId;
    console.timeLog();
    console.log("res 1", res);
            return Backendless.Data.of("pendedJobs").addRelation({"objectId":shared.objectId},"user_job",[{"objectId": '5FA21F96-7E07-4270-AC3F-207B1985B8E2'}])
})

.then( function( res ) {
console.timeLog();
console.log( "res2: ", res );
return Backendless.Data.of(“pendedJobs”).addRelation({“objectId”:shared.objectId},“user_renter”,[{“objectId”: ‘53FC6A47-79C6-561E-FFED-4EBA0ABDA400’}])
})
.then( function( res ) {
console.timeLog();
console.log( "res3: ", res );
return Backendless.Data.of(“pendedJobs”).addRelation({“objectId”:shared.objectId},“company_renter”,[{“objectId”: ‘4AA92FFE-2657-5D0F-FF46-978450525A00’}])
})
.then( function( res ) {
console.timeLog();
console.log( "res4: ", res );
return Promise.resolve({res:res});
})

mark-piller · May 28, 2021, 4:15pm

at what point do you call console.time() ?

yuriy · May 28, 2021, 4:17pm

it’s just before “var shared = {}”

mark-piller · May 28, 2021, 4:27pm

So the timing of the calls are:

saving pendedJobs object - 260 ms
adding first relation - 542 ms
adding second relation - 550 ms
adding third relation - 811 ms

We strive for subsecond response for an API call, so all of this is in line with our expections. What you can do to speed up the execution time is change the code to use Transactions API:
https://backendless.com/docs/js/data_transactions_overview.html

Regards,
Mark

yuriy · May 28, 2021, 4:30pm

hmm, but it definitely were running faster a year (something like) ago on cloud 99, before v6

yuriy · May 28, 2021, 4:55pm

I found old logs, from june2020, this operations - promises array of 4 (or 3) AddRelations took something like 400ms, so about 4 times faster than now

mark-piller · May 28, 2021, 5:22pm

I cannot react to this one way or the other especially for results from a year ago. There is no difference between Cloud9 and Cloud99 from the performance perspective and the results you get now is what’s expected, as I said, subsecond response time for an API call is expected.