Support Topics Documentation Slack YouTube Blog

API slowdown?

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!

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

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 ]”)

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 ]

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

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.

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});
})

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

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?

Yes, please

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});
})

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

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

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

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

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

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.