clearTimeout() does not always work

[cpetrov]

Problem description

When calling clearTimeout() asynchronously, it does not always cancel timeouts. In the snippets below, about 1/3 of the setTimeout() callbacks will be called, although they have been scheduled in cleared timeouts.

See the second snippet for a more illustrative example of the issue that shows that some setTimeout() callbacks are executed even after their timeouts have been cleared.

Expected behavior

Timeouts must never be executed after clearTimeout() with their id is called.

Environment

• Tabris.js version: starting from 3.0.0 to at least 3.5.0-dev.20200514
• OS: iOS

Code snippet

Simple snippet

import 'tabris';

for (let i = 0; i < 3000; i++) {
  const timeout = setTimeout(() => console.error('unexpected callback call'), 1000);
  setTimeout(() => clearTimeout(timeout));
}

Verbose snippet

import 'tabris';

let taskId = 0;
const status = {};
for (let i = 0; i < 3000; i++) {
  taskId++;
  status[taskId] = 'scheduled';
  const timeout = setTimeout((id =>
    () => {
      let message = `Called task ${id}`;
      if (status[id] === 'canceled') {
        message += ' although it was canceled. clearTimeout does not work?'; // about 1/3 of the tasks
      } else if (status[id] === 'scheduled') {
        message += ' as expected, because it was scheduled and never canceled. clearTimeout called too late?'; // never
      }
      console.error(message);
    }
  )(taskId), 1000);
  setTimeout((id =>
    () => {
      clearTimeout(timeout);
      status[id] = 'canceled';
    }
  )(taskId), 0);
}

[karolszafranski]

I tested both snippets, with the same results.

The first timer was scheduled at: 08:23:13.871 and invalidated at: 08:23:15.689.

15.689 - 13.871 = 1,818s

for loop used for scheduling timers is blocking the main loop for 1,8s. When clearTimeout is called it is too late for invalidation.

Assuming that timers are executed in the FIFO order (and it looks like that) the first one will always be called first - before the second one which invalidates the first one. Even if they are all delayed and they are because the main loop was blocked (UI not responsive and so on).

Log from the native bridge:

[08:23:13.871000][E][{ method = startTimer; }][{ properties = { delay = 1000; id = 1; repeat = 0; };}]
[08:23:13.871000][E][{ method = startTimer; }][{ properties = { delay = 0; id = 2; repeat = 0; };}]
[08:23:13.872000][E][{ method = startTimer; }][{ properties = { delay = 1000; id = 3; repeat = 0; };}]
[08:23:13.872000][E][{ method = startTimer; }][{ properties = { delay = 0; id = 4; repeat = 0; };}]
[08:23:13.872000][E][{ method = startTimer; }][{ properties = { delay = 1000; id = 5; repeat = 0; };}]
[08:23:13.872000][E][{ method = startTimer; }][{ properties = { delay = 0; id = 6; repeat = 0; };}]
(...)
[08:23:15.601000][E][{ method = startTimer; }][{ properties = { delay = 0; id = 5996; repeat = 0; };}]
[08:23:15.602000][E][{ method = startTimer; }][{ properties = { delay = 1000; id = 5997; repeat = 0; };}]
[08:23:15.602000][E][{ method = startTimer; }][{ properties = { delay = 0; id = 5998; repeat = 0; };}]
[08:23:15.602000][E][{ method = startTimer; }][{ properties = { delay = 1000; id = 5999; repeat = 0; };}]
[08:23:15.603000][E][{ method = startTimer; }][{ properties = { delay = 0; id = 6000; repeat = 0; };}]
(...)
[08:23:15.689000][E][{ method = cancelTimer; }][{ properties = { id = 1; };}]
[08:23:15.692000][E][{ method = cancelTimer; }][{ properties = { id = 3; };}]
[08:23:15.694000][E][{ method = cancelTimer; }][{ properties = { id = 5; };}]
[08:23:15.697000][E][{ method = cancelTimer; }][{ properties = { id = 7; };}]
...

In your snippets, you set up 3000 timers with 1s delay. Knowing that on my device it takes ~1,8s to set them up (main thread is blocked during that time) I changed the snippet so that it sets only 1500 times - and it worked as expected. Same when I set up 3000 timers but with longer timeout - set to 2s.

[karolszafranski]

I found that this issue does not occur in 2.x, what essentially means that Tabris.js 2 has a higher performance in this test case. It took 0.809s to schedule timers. That is fast enough to invalidate them on time.

We should take a look why there is such a difference between 2.x and 3.x in this case.