Unexpected sequence of events

Developers Workers
1

When doing load-testing, I noticed something I didn’t expect.

So i setup a test:

  const { default: log } = await import('./libs/logging');
  await log.init();
  await new Promise(resolve => setTimeout(resolve, 200));
  log.set('1');
  await new Promise(resolve => setTimeout(resolve, 400));
  log.set('2');
  await new Promise(resolve => setTimeout(resolve, 500));
  log.set('3');
  await new Promise(resolve => setTimeout(resolve, 700));
  log.set('4');
  await new Promise(resolve => setTimeout(resolve, 400));
  log.set('5');
  await new Promise(resolve => setTimeout(resolve, 200));
  log.set('6');
  await new Promise(resolve => setTimeout(resolve, 100));
  log.set('7');
  await new Promise(resolve => setTimeout(resolve, 200));
  log.set('8');
  await new Promise(resolve => setTimeout(resolve, 700));
  log.set('9');
  await new Promise(resolve => setTimeout(resolve, 1000));
  log.set('10');
  await new Promise(resolve => setTimeout(resolve, 200));
  log.set('11');
  await new Promise(resolve => setTimeout(resolve, 2000));
  log.set('12');
  await new Promise(resolve => setTimeout(resolve, 2000));
  log.set('13');
  await new Promise(resolve => setTimeout(resolve, 300));
  log.set('14');
  await new Promise(resolve => setTimeout(resolve, 100));
  log.set('15');
  await new Promise(resolve => setTimeout(resolve, 1000));
  log.set('16');
  await new Promise(resolve => setTimeout(resolve, 300));
  log.set('17');
  const result = await log.sendlog();
  return new Response(result, {
    status: 200,
    statusText: 'OK',
  });

The logger is simple:

  1. The init sets an an object with an empty array and then add each log entry to it.
  2. sendlog joins the array and send it to my logger.
  3. When I send a single test request, I get the expected: 1 - 2 - 3 - 4 - 5 - 6 - 7 - 8 - 9 - 10 - 11 - 12 - 13 - 14 - 15 - 16 - 17 in the logger.

However, if I do many requests - 60+, the logger is no longer in sequence at all times, I start seeing strings like: 1 - 12 - 2 - 3 - 4 - 5 - 6 - 7 - 13 - 8 - 14 - 15 - 9 - 16 - 17 and 1 - 9 - 10 - 2 - 11 - 3 - 10 - 11 - 4 - 5 - 6 - 7 - 12 - 8 - 9 - 12 - 10 - 11 - 13 - 14 - 15 - 13 - 14 - 15 - 16 - 17 seemingly at random.

Am I missing something here or is it this easy to shoot ourselves in the foot?

2

I guess it’s due to workers persisting and not shutting down/restarting after each request, so using a locally scoped array works just fine.

EDIT: Lesson learned about doing proper instantiation…

2 Likes