Debounce not debouncing?

[stephencelis]

This seemingly simple expectation fails:

func testDebounce() async {
  let timer = AsyncTimerSequence.repeating(every: .seconds(1)) //  clock: .suspending
    .prefix(10)
    .debounce(for: .seconds(2))                                //  clock: .continuous

  var ticks = 0
  for await _ in timer {
    ticks += 1
  }
  XCTAssertEqual(ticks, 1)  // Only final tick should emit
}

❌ testDebounce(): XCTAssertEqual failed: ("9") is not equal to ("1")
Test Case '-[ClocksTests.ClocksTests testDebounce]' failed (10.207 seconds).

This is on the main branch using Xcode 14 beta 2's Swift.

The test took 10 seconds to run, but this makes it seems like it is completing too soon? I'd expect the debounce to make it take more like 12 seconds?

I also get different results depending on the clock. If I use a continuous clock for the timer (instead of the default suspending clock), I get the same failure:

func testDebounce() async {
  let timer = AsyncTimerSequence.repeating(every: .seconds(1), clock: .continuous)
    .prefix(10)
    .debounce(for: .seconds(2), clock: .continuous)

  var ticks = 0
  for await _ in timer {
    ticks += 1
  }
  XCTAssertEqual(ticks, 1)  // Only final tick should emit
}

❌ testDebounce(): XCTAssertEqual failed: ("9") is not equal to ("1")
Test Case '-[ClocksTests.ClocksTests testDebounce]' failed (0.017 seconds).

But I get this failure much, much, much more quickly (in 10 milliseconds instead of over 10 seconds 😲)...

Finally, with both clocks suspending, I get another result that seems wrong:

func testDebounce() async {
  let timer = AsyncTimerSequence.repeating(every: .seconds(1), clock: .suspending)
    .prefix(10)
    .debounce(for: .seconds(2), clock: .suspending)

  var ticks = 0
  for await _ in timer {
    ticks += 1
  }
  XCTAssertEqual(ticks, 1)  // Only final tick should emit
}

❌ testDebounce(): XCTAssertEqual failed: ("0") is not equal to ("1")
Test Case '-[ClocksTests.ClocksTests testDebounce]' failed (10.085 seconds).

This time it takes the full 10 seconds (again, should it probably be closer to 12?), and now I get no emissions at all.

[stephencelis]

@phausler Should I be opening these kinds of clock issues here or directly on Swift? It seems like the issues outlined above may be both issues with the debounce operator but also issues with clocks as shipped in the latest beta.

[phausler]

well I think there are separable issues here; the clocks did have some issues iirc in beta 2 (which I believe I was able to address in a PR that already got merged). And the debounce/timer code is a completely distinct thing. We should try and identify if it is something that 1st off still exists on main's recent builds of swift (including those fixes) and if this is an issue with how timer or debounce work (my guess is you have the buggy code; which a quick way to test that is use the suspending clock for everything).

[stephencelis]

@phausler Unfortunately I haven't had much luck running the main branch of Async Algorithms with more recent snapshots due to a mismatch in availability checking (iOS 9999 vs iOS 16, as an example), so I'm unable to easily confirm the behavior of the above in anything more recent than beta 2.

[mbrandonw]

Now that the Xcode 14 RC is out we wanted to revisit this. Looks like the bug is still there. This simple test fails when building main for iOS 16:

func testDebounce() async {
  let timer = AsyncTimerSequence.repeating(every: .seconds(1), clock: .continuous)
    .prefix(2)
    .debounce(for: .seconds(2), clock: .continuous)

  var ticks = 0
  for await _ in timer {
    ticks += 1
  }
  XCTAssertEqual(ticks, 1)  // Only final tick should emit
}

❌ testDebounce(): XCTAssertEqual failed: ("0") is not equal to ("1")

Same for when using a .suspending clock too.

[FranzBusch]

I just quickly tested this against my latest PR that refactors debounce #198 and it also fails so I looked into what is actually happening. My little logging output looks like this:

next
element produced Instant(_value: 443885.520951041 seconds)
element produced Instant(_value: 443886.52470637497 seconds)
upstream finished

Which shows that the two values were produced by the timer and then the upstream finishes right away and that finished caused the downstream continuation to be resumed with nil. However, I just missed the important sentence in the documentation of debounce:

If the completing event happens during the scheduled duration the last cached notification is emitted before the completion event is forwarded to the output observable.

So I just quickly changed my code to resume the continuation with the last cached element and it passes this test now. If you could to give my branch a try and see if that works for your setup and report back that would be great :)

[mbrandonw]

Hi @FranzBusch, I can confirm that the test I wrote does pass on your branch.

However, there is another problem that @stephencelis alluded to before, and it's a little more subtle. Right now, when pointed at your branch, the test finishes in 2 seconds. However, it should have taken 4 seconds.

The timer takes 2 seconds to finish its 2 emissions, and that last emission should then be debounced for another 2 seconds, making the whole suite be 4 seconds (give or take a bit since it isn't an exact science). So it seems the debounced sequence is completing without actually doing the debouncing.

To see this, run the following test on your branch:

func testDebounce() async throws {
  actor Finished {
    var instant: ContinuousClock.Instant?
    func setInstant(_ instant: ContinuousClock.Instant) { self.instant = instant }
  }

  let clock = ContinuousClock()

  let timer = AsyncTimerSequence.repeating(every: .seconds(1), clock: clock)
    .prefix(2)
    .debounce(for: .seconds(2), clock: clock)

  let start = clock.now
  let finished = Finished()
  for await _ in timer {
    await finished.setInstant(clock.now)
  }
  guard let finishedInstant = await finished.instant
  else { XCTFail(); return }

  let duration = start.duration(to: finishedInstant)
  XCTAssertGreaterThan(duration.components.seconds, 4)
}

❌ testDebounce(): XCTAssertGreaterThan failed: ("2") is not greater than ("4")

[FranzBusch]

The timer takes 2 seconds to finish its 2 emissions, and that last emission should then be debounced for another 2 seconds, making the whole suite be 4 seconds (give or take a bit since it isn't an exact science). So it seems the debounced sequence is completing without actually doing the debouncing.

I don't know if I agree on this. I couldn't find any docs that says that if the upstream finishes the last element is still debounced. From my quote above it actually looks more like if the upstream finishes the downstream also finishes right away without debouncing anymore. I haven't compared to Combine or other RX implementations yet.

Changing this is quite trivial, I just need to conform that this is the actual behaviour we want.

[mbrandonw]

Yeah true, not sure which behavior is correct.

Interestingly, this current async debounce differs from Combine, which just completely ignores the buffered value if the source publisher completes before the duration passes. I didn't realize that was the case until I just wrote a test for it.

On the flip side, RxJS behaves like what is implemented in this repo. When the source completes it immediately emits the most recent buffered value. In isolation, Combine's approach makes the most sense to me, but each choice probably has their uses in practice, and so someday maybe it should even be customizable.

[FranzBusch]

Yep, I just came to the same conclusion. What I think we should 100% do is document our behaviour better around what happens in the event of an error or finish from the upstream. I would like to get @phausler opinion here what the correct behaviour is that we should use!