Big time execution variance in an API service

Server Code Codeless
1

App ID 4A47197B-AE30-FA84-FF56-0071F4010900
Service homeworkAdd*

I have a rather simple API service that takes an incoming array of 10 strings, then:

  1. Saves it to a DB table
  2. Loads & updates 3 other table objects

Usually, it is completed in <10 seconds but once per 100 executions, it times out unexpectedly.
Furthermore, if you look at the logs, it is the first step that gets delays, which is a simple save to a DB table.

image
image962Ă—386 45 KB

See below that this first step takes 20 seconds.

2021-05-29 19:02:56,925 | SERVER_CODE |  INFO | [27351] [70B0A5A4-7DEA-AA69-FFB5-DD4BEA06C800] [INVOKE SERVICE] services.closeImport.homeworkAdd
2021-05-29 19:03:16,648 | SERVER_CODE |  INFO | [27351] homeworkAdd: saved report
2021-05-29 19:03:16,650 | SERVER_CODE |  INFO | [27351] {
  data: null,
  created: 1622314996000,
  contactParent: false,
  slots_slug: null,
  ownerId: null,
  message: null,
  report: 'Shah did well, but had a little difficulty subtracting minutes from time. We worked on some time problems in class. I also assigned some more for homework. Thank you. ',
  file2: null,
  ___class: 'reports',
  file3: null,
  sessionQuality: null,
  file1: '<a href=https://storage.googleapis.com/media.landbot.io/28643/customers/106685286/V44RZIDCB8K9HQ3JWY0E4Q3WH8YTPGJK.docx>&#x1F4CE; &nbsp;  Attachment 1</a>',
  bgFeedback: 'none/ntr',
  updated: null,
  objectId: '610B9822-DCA7-4381-983C-C333B1021D02',
  calendarObjectId: null
}
2021-05-29 19:03:16,733 | SERVER_CODE |  INFO | [27351] homeworkAdd: saved slot
2021-05-29 19:03:16,811 | SERVER_CODE |  INFO | [27351] homeworkAdd: loaded calendar events
2021-05-29 19:03:16,811 | SERVER_CODE |  INFO | [27351] {
  subjectsObjectId: '90C190C1-F2CC-47DF-AF53-22B40B424F63',
  ___class: 'calendar',
  tutor_name: 'Sam Mansourou',
  objectId: 'F8F30B0D-5AA5-4CEF-B40C-481351331518'
}
2021-05-29 19:03:16,888 | SERVER_CODE |  INFO | [27351] homeworkAdd: loaded tutor
2021-05-29 19:03:16,889 | SERVER_CODE |  INFO | [27351] {
  UTC_offSet: null,
  timezone: 'US/Eastern',
  created: 1618357510000,
  emailacct: null,
  subjects: 'English,History,Math,MathEnglishCombo',
  opp_status: 'enrolled',
  grades: 'Grade 1,Grade 2,Grade 3,Grade 4,Kindergarten',
  ownerId: null,
  zoomid: '4889311496',
  email2: null,
  score: '6.4',
  bgEmail: 'us@brilliantgrades.com',
  tutor_name: 'Sam Mansourou',
  phone: '+17542549457',
  tip_level: '21',
  bgPhone: '+19175632694',
  maxslots: '8',
  ___class: 'tutors',
  updated: 1622274656000,
  objectId: 'E418FF33-D9FD-4A64-A385-BF46C28991E4',
  lead_id: 'lead_pjqox08T0cEFMhbxK7ieDv3BeFfJAMUURPjFOsHhstg',
  email: 'smansourou1@yahoo.com'
}
2021-05-29 19:03:26,926 | SERVER_CODE | ERROR | [27351] Task execution is aborted due to timeout

Here’s a usual case where it does not time out:

2021-05-29 00:13:58,986 | SERVER_CODE |  INFO | [2105] [F0336A80-E810-1560-FFA1-80D5619FCC00] [INVOKE SERVICE] services.closeImport.homeworkAdd
2021-05-29 00:13:59,501 | SERVER_CODE |  INFO | [2105] homeworkAdd: saved report
2021-05-29 00:13:59,503 | SERVER_CODE |  INFO | [2105] {
  data: null,
  created: 1622247239000,
  contactParent: false,
  slots_slug: null,
  ownerId: null,
  message: null,
  report: 'Hello! Grant and I had a great session.  He read a short informational story about bees. He correctly answered 2 out of 2 comprehension questions and 1 out of 1 word meaning question! Way to go, Grant! Next, I asked Grant to help me make a chart about grammar rules. Grant did amazing and listed 5 important rules! He even included when to add -es to the end of words. We worked on a second grade grammar paper, and Grant answered all of it correctly! Super work, Grant! Near the end of our session, we played a multiplication game. Grant had to choose a factor from the first column, a factor from another column, and multiply them. Then Grant had to see if the product was in the last column. Grant did very well and won the game! For homework, I am including a grammar page and the multiplication game. Below is a link to a multiplication game I think will help Grant with memorizing more of the facts. Next week, we will write a story about the Minecraft toys and practice reading comprehension strategies.  https://www.mathplayground.com/math_monster_multiplication.html',
  file2: null,
  ___class: 'reports',
  file3: null,
  sessionQuality: null,
  file1: '<a href=https://storage.googleapis.com/media.landbot.io/28643/customers/106576620/2HRRHJOXWAZYWS4OY58YA8ZQIXM0MXPY.pdf>&#x1F4CE; &nbsp;  Attachment 1</a>',
  bgFeedback: 'none/ntr',
  updated: null,
  objectId: 'B0F251A5-C6AC-4293-AEF1-697846263480',
  calendarObjectId: null
}
2021-05-29 00:14:00,310 | SERVER_CODE |  INFO | [2105] homeworkAdd: saved slot
2

Hello @Andreas_Marinopoulos

An internal ticket BKNDLSS-25336 for your problem has been created. We will let you know the result.

Regards,
Inna

1 Like
3

Hi Andreas,

We made a few optimizations in our system. Could you please check if you still experience timeouts?

Regards,
Mark

1 Like
4

Ok will set it live again and let you know over the next couple of days. Thanks Mark.

5

Works fine now, thanks

6

Hi there, I am continuing to get sporadic timeout errors from this API service, which does not make sense, as most of the time, it is complete in a few seconds, which proves that the code is not complex at all.

Any thoughts?

image
image2412Ă—1512 236 KB

7

We’ve reopened the task [BKNDLSS-25336].
But because of the sporadic nature of this error the investigation can take more time.

8

New timeout

image
image2320Ă—1500 265 KB

9

I am having the same issue again with this API service called homeworkAdd.

I am getting quite a few timeouts on an API service that should not time out, it’s rather simple. It usually takes 10-20 seconds.

image
image1678Ă—102 34.4 KB

I have 4x20sec enhanced code execution time on my account.

image
image872Ă—248 14.4 KB

But sometimes it timeout at 110 seconds.

image
image1552Ă—662 132 KB

What should I do?

My App ID is 4A47197B-AE30-FA84-FF56-0071F4010900.

10

Ha e you added any debugging output to see how much time is spent in every line/block of the service?

11

What I see is the timestamps on each step in the main log. If you look at my screenshot above, the timeout occurs on the second step. It saves the report correctly, prints the “saved report” block, then attempts to load a list from a table weekly_slots, and times out, as the next printout does not occur.

image
image956Ă—1022 110 KB

But this should not be the case, it is a small list, usually 1-3 objects. I do not see why this happens.

12

Could you try re-creating that request in REST Console and see how long the invocation takes there?

13

I just found the time to recreate the request in REST Console (as I had 2 more errors last night. It was very fast. Most requests take 10 seconds.

image
image3132Ă—1106 267 KB

But last nigth I got 2 errors like this:

image
image1672Ă—468 84.8 KB

What is strange is that my script execution time is very long, so I don’t even know why it would time out at 39 seconds.

image
image980Ă—334 15.1 KB

14

How fast is the REST request to load the objects from the database?

15

Not sure where I can see the exact time on the UI but it was almost immediate.

16

You can check it in the browser’s Dev tools’ Network tab. Here’s a video:

17

Does this help?

image
image2210Ă—536 77.2 KB

18

Just to confirm what you have so far:

  1. an API call made in Codeless logic times out
  2. the same API call made from REST Console executes in less than 800ms

Regards,
Mark

19

Yes. To clarify. The API call usually takes less than 10000ms. Once in a while, it times out with the error message above.

20

We would need steps to reproduce the issue. Were you able to see if the API call when made independently from the API service takes longer time?