fix(ecs): stop a re-arming setTimeout from hanging the scene on a large dt (#1420)

* fix(ecs): stop a re-arming setTimeout from hanging the scene on a large dt

A timer callback that schedules a new timer mutates the Map the timer
system is iterating, and for..of visits entries inserted mid-iteration.
Since the loop also applies the frame's full 1000 * dt to those new
timers, any interval <= 1000 * dt fires immediately within the same pass,
so a self-re-arming setTimeout loops forever once dt exceeds its interval
and the scene worker never returns.

Seed timers armed inside a firing callback with the negative of the time
already consumed this frame before the parent fired, so the loop's
+= elapsedMs nets to the true elapsed time. Re-arming chains then stay
phase-accurate (matching setInterval) and catch up a bounded number of
times instead of looping. Top-level timers, including setTimeout(cb, 0),
are unchanged.

* test: update snapshots for timer re-arm fix

Author: robtfm

packages/@dcl/ecs/src/runtime/helpers/timers.ts

@@ -99,54 +99,70 @@ type TimerData = {
 export function createTimers(targetEngine: IEngine): Timers {
   const timers: Map<TimerId, TimerData> = new Map()
   let timerIdCounter = 0
+  // While a timer's callback is running this holds the time already consumed this
+  // frame before that timer's logical fire instant (`elapsedMs - residualMs`);
+  // `null` otherwise. A timer armed from within the callback is seeded with the
+  // negative of this, so its delay is measured from the parent's fire instant
+  // rather than from the start of the frame.
+  let armContext: { accruedMs: number } | null = null
 
   function system(dt: number) {
+    const elapsedMs = 1000 * dt
     for (const [timerId, timerData] of timers) {
-      timerData.accumulatedTime += 1000 * dt
+      timerData.accumulatedTime += elapsedMs
 
       if (timerData.accumulatedTime < timerData.interval) {
         continue
       }
 
+      // Time elapsed past this timer's logical fire instant this frame.
+      const residualMs = timerData.recurrent
+        ? timerData.accumulatedTime % timerData.interval
+        : timerData.accumulatedTime - timerData.interval
+
       if (timerData.recurrent) {
-        // For intervals, subtract full interval periods to handle accumulated time
-        const fullIntervals = Math.floor(timerData.accumulatedTime / timerData.interval)
-        timerData.accumulatedTime -= fullIntervals * timerData.interval
+        // Collapse any missed periods into a single callback, keep the remainder.
+        timerData.accumulatedTime = residualMs
       } else {
         timers.delete(timerId)
       }
 
+      armContext = { accruedMs: elapsedMs - residualMs }
       timerData.callback()
+      armContext = null
     }
   }
 
   targetEngine.addSystem(system, Number.MAX_SAFE_INTEGER, '@dcl/ecs/timers')
 
+  function addTimer(callback: TimerCallback, interval: number, recurrent: boolean): TimerId {
+    const timerId = timerIdCounter++
+    let accumulatedTime = 0
+
+    if (armContext) {
+      // Armed from inside a firing callback: this timer is appended to the map
+      // being iterated, so the loop will still add this frame's elapsed to it.
+      // Inherit the residual so that `+= elapsedMs` nets to the true time
+      // elapsed since the parent fired (phase-accurate). Each successive arming
+      // starts one interval lower, so a re-arming chain terminates this frame.
+      accumulatedTime = -armContext.accruedMs
+    }
+
+    timers.set(timerId, { callback, interval, recurrent, accumulatedTime })
+    return timerId
+  }
+
   return {
     setTimeout(callback: TimerCallback, ms: number): TimerId {
-      const timerId = timerIdCounter++
-      timers.set(timerId, {
-        callback,
-        interval: ms,
-        recurrent: false,
-        accumulatedTime: 0
-      })
-      return timerId
+      return addTimer(callback, ms, false)
     },
 
     clearTimeout(timerId: TimerId): void {
       timers.delete(timerId)
     },
 
     setInterval(callback: TimerCallback, ms: number): TimerId {
-      const timerId = timerIdCounter++
-      timers.set(timerId, {
-        callback,
-        interval: ms,
-        recurrent: true,
-        accumulatedTime: 0
-      })
-      return timerId
+      return addTimer(callback, ms, true)
     },
 
     clearInterval(timerId: TimerId): void {

test/ecs/timers.spec.ts

@@ -304,7 +304,7 @@ describe('Timer helpers', () => {
       expect(called).toBe(true)
     })
 
-    it('should handle callback that schedules another timer', async () => {
+    it('a timer scheduled inside a callback is measured from when it was armed', async () => {
       const engine = Engine()
       const timers = createTimers(engine)
       const order: number[] = []
@@ -316,10 +316,86 @@ describe('Timer helpers', () => {
         }, 100)
       }, 100)
 
-      await engine.update(0.1) // Both callbacks fire in the same frame
+      // Outer fires at 100ms; the inner is armed at that instant and asks for
+      // 100ms more, so it must NOT fire in the same frame.
+      await engine.update(0.1)
+      expect(order).toEqual([1])
+
+      // It fires on the next frame, ~100ms after it was armed.
+      await engine.update(0.1)
       expect(order).toEqual([1, 2])
     })
 
+    it('does not lock up when a setTimeout re-arms itself under a large dt', async () => {
+      const engine = Engine()
+      const timers = createTimers(engine)
+      let count = 0
+      const rearm = () => {
+        count++
+        timers.setTimeout(rearm, 1000) // re-arm every 1s
+      }
+      timers.setTimeout(rearm, 1000)
+
+      // 10s in a single frame: the chain must catch up a bounded, correct number
+      // of times (10) and return — not loop forever.
+      await engine.update(10)
+      expect(count).toBe(10)
+    })
+
+    it('a re-arming setTimeout catches up at the requested rate, like setInterval', async () => {
+      const engine = Engine()
+      const timers = createTimers(engine)
+      let rearmCount = 0
+      let intervalCount = 0
+
+      const rearm = () => {
+        rearmCount++
+        timers.setTimeout(rearm, 250)
+      }
+      timers.setTimeout(rearm, 250)
+      timers.setInterval(() => intervalCount++, 250)
+
+      // Uneven frames (100ms) vs a 250ms period exercises the residual carry; a
+      // re-arming setTimeout should stay in lock-step with setInterval.
+      for (let i = 0; i < 30; i++) {
+        await engine.update(0.1)
+        expect(rearmCount).toBe(intervalCount)
+      }
+    })
+
+    it('a finite chain of zero-delay timers runs within the same frame', async () => {
+      const engine = Engine()
+      const timers = createTimers(engine)
+      const order: number[] = []
+
+      // A common pattern: each callback schedules the next step with a 0ms delay,
+      // expecting them to run promptly in sequence within the frame (not one per
+      // frame). A finite chain of distinct timers terminates the same frame.
+      timers.setTimeout(() => {
+        order.push(1)
+        timers.setTimeout(() => {
+          order.push(2)
+          timers.setTimeout(() => order.push(3), 0)
+        }, 0)
+      }, 0)
+
+      await engine.update(0.016)
+      expect(order).toEqual([1, 2, 3])
+    })
+
+    it('a top-level setTimeout(0) still fires on the next frame', async () => {
+      const engine = Engine()
+      const timers = createTimers(engine)
+      let called = false
+      timers.setTimeout(() => {
+        called = true
+      }, 0)
+
+      expect(called).toBe(false)
+      await engine.update(0.016)
+      expect(called).toBe(true)
+    })
+
     it('should handle interval that clears itself', async () => {
       const engine = Engine()
       const timers = createTimers(engine)

test/snapshots/development-bundles/static-scene.test.ts.crdt

@@ -1,4 +1,4 @@
-SCENE_COMPILED_JS_SIZE_PROD=564k bytes
+SCENE_COMPILED_JS_SIZE_PROD=564.1k bytes
 THE BUNDLE HAS SOURCEMAPS
 (start empty vm 0.21.0-3680274614.commit-1808aa1)
   OPCODES ~= 0k
@@ -12,7 +12,7 @@ EVAL test/snapshots/development-bundles/static-scene.test.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 73k
-  MALLOC_COUNT = 16289
+  MALLOC_COUNT = 16301
   ALIVE_OBJS_DELTA ~= 3.24k
 CALL onStart()
   main.crdt: PUT_COMPONENT e=0x200 c=1 t=0 data={"position":{"x":5.880000114440918,"y":2.7916901111602783,"z":7.380000114440918},"rotation":{"x":0,"y":0,"z":0,"w":1},"scale":{"x":1,"y":1,"z":1},"parent":0}
@@ -57,4 +57,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 5k
   MALLOC_COUNT = -5
   ALIVE_OBJS_DELTA ~= 0.00k
-  MEMORY_USAGE_COUNT ~= 1425.94k bytes
+  MEMORY_USAGE_COUNT ~= 1426.65k bytes

test/snapshots/development-bundles/testing-fw.test.ts.crdt

@@ -1,4 +1,4 @@
-SCENE_COMPILED_JS_SIZE_PROD=564.5k bytes
+SCENE_COMPILED_JS_SIZE_PROD=564.6k bytes
 THE BUNDLE HAS SOURCEMAPS
 (start empty vm 0.21.0-3680274614.commit-1808aa1)
   OPCODES ~= 0k
@@ -12,7 +12,7 @@ EVAL test/snapshots/development-bundles/testing-fw.test.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 83k
-  MALLOC_COUNT = 16841
+  MALLOC_COUNT = 16853
   ALIVE_OBJS_DELTA ~= 3.40k
 CALL onStart()
   LOG: ["Adding one to position.y=0"]
@@ -63,4 +63,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 6k
   MALLOC_COUNT = -53
   ALIVE_OBJS_DELTA ~= -0.01k
-  MEMORY_USAGE_COUNT ~= 1431.70k bytes
+  MEMORY_USAGE_COUNT ~= 1432.41k bytes

test/snapshots/development-bundles/two-way-crdt.test.ts.crdt

@@ -1,4 +1,4 @@
-SCENE_COMPILED_JS_SIZE_PROD=564.5k bytes
+SCENE_COMPILED_JS_SIZE_PROD=564.7k bytes
 THE BUNDLE HAS SOURCEMAPS
 (start empty vm 0.21.0-3680274614.commit-1808aa1)
   OPCODES ~= 0k
@@ -12,7 +12,7 @@ EVAL test/snapshots/development-bundles/two-way-crdt.test.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 83k
-  MALLOC_COUNT = 16841
+  MALLOC_COUNT = 16853
   ALIVE_OBJS_DELTA ~= 3.40k
 CALL onStart()
   LOG: ["Adding one to position.y=0"]
@@ -63,4 +63,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 6k
   MALLOC_COUNT = -53
   ALIVE_OBJS_DELTA ~= -0.01k
-  MEMORY_USAGE_COUNT ~= 1431.70k bytes
+  MEMORY_USAGE_COUNT ~= 1432.41k bytes

test/snapshots/production-bundles/append-value-crdt.ts.crdt

@@ -10,7 +10,7 @@ EVAL test/snapshots/production-bundles/append-value-crdt.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 85k
-  MALLOC_COUNT = 15153
+  MALLOC_COUNT = 15161
   ALIVE_OBJS_DELTA ~= 3.40k
 CALL onStart()
   Renderer: APPEND_VALUE e=0x200 c=1063 t=0 data={"button":0,"hit":{"position":{"x":1,"y":2,"z":3},"globalOrigin":{"x":1,"y":2,"z":3},"direction":{"x":1,"y":2,"z":3},"normalHit":{"x":1,"y":2,"z":3},"length":10,"meshName":"mesh","entityId":512},"state":1,"timestamp":1,"analog":5,"tickNumber":0}
@@ -56,4 +56,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 15k
   MALLOC_COUNT = 31
   ALIVE_OBJS_DELTA ~= 0.01k
-  MEMORY_USAGE_COUNT ~= 1068.72k bytes
+  MEMORY_USAGE_COUNT ~= 1069.14k bytes

test/snapshots/production-bundles/billboard.ts.crdt

@@ -1,4 +1,4 @@
-SCENE_COMPILED_JS_SIZE_PROD=288.8k bytes
+SCENE_COMPILED_JS_SIZE_PROD=288.9k bytes
 (start empty vm 0.21.0-3680274614.commit-1808aa1)
   OPCODES ~= 0k
   MALLOC_COUNT = 1005
@@ -10,7 +10,7 @@ EVAL test/snapshots/production-bundles/billboard.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 87k
-  MALLOC_COUNT = 17670
+  MALLOC_COUNT = 17678
   ALIVE_OBJS_DELTA ~= 3.87k
 CALL onStart()
   OPCODES ~= 0k
@@ -78,4 +78,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 12k
   MALLOC_COUNT = 0
   ALIVE_OBJS_DELTA ~= 0.00k
-  MEMORY_USAGE_COUNT ~= 1254.70k bytes
+  MEMORY_USAGE_COUNT ~= 1255.12k bytes

test/snapshots/production-bundles/cube-deleted.ts.crdt

@@ -10,7 +10,7 @@ EVAL test/snapshots/production-bundles/cube-deleted.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 76k
-  MALLOC_COUNT = 14273
+  MALLOC_COUNT = 14281
   ALIVE_OBJS_DELTA ~= 3.17k
 CALL onStart()
   OPCODES ~= 0k
@@ -43,4 +43,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 6k
   MALLOC_COUNT = 1
   ALIVE_OBJS_DELTA ~= 0.00k
-  MEMORY_USAGE_COUNT ~= 1031.00k bytes
+  MEMORY_USAGE_COUNT ~= 1031.41k bytes

test/snapshots/production-bundles/cube.ts.crdt

@@ -10,7 +10,7 @@ EVAL test/snapshots/production-bundles/cube.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 75k
-  MALLOC_COUNT = 14246
+  MALLOC_COUNT = 14254
   ALIVE_OBJS_DELTA ~= 3.16k
 CALL onStart()
   OPCODES ~= 0k
@@ -33,4 +33,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 3k
   MALLOC_COUNT = 0
   ALIVE_OBJS_DELTA ~= 0.00k
-  MEMORY_USAGE_COUNT ~= 1020.75k bytes
+  MEMORY_USAGE_COUNT ~= 1021.17k bytes

test/snapshots/production-bundles/cubes.ts.crdt

@@ -10,7 +10,7 @@ EVAL test/snapshots/production-bundles/cubes.js
   REQUIRE: ~system/EngineApi
   REQUIRE: ~system/Runtime
   OPCODES ~= 127k
-  MALLOC_COUNT = 21007
+  MALLOC_COUNT = 21015
   ALIVE_OBJS_DELTA ~= 5.16k
 CALL onStart()
   OPCODES ~= 0k
@@ -1653,4 +1653,4 @@ CALL onUpdate(0.1)
   OPCODES ~= 725k
   MALLOC_COUNT = 0
   ALIVE_OBJS_DELTA ~= 0.00k
-  MEMORY_USAGE_COUNT ~= 1479.18k bytes
+  MEMORY_USAGE_COUNT ~= 1479.60k bytes