co19/LibTest/async/Timer/Timer.periodic_A02_t01 is flaky

[liamappelbe]

The tests

co19/LibTest/async/Timer/Timer.periodic_A02_t01 RuntimeError (expected Pass)

are failing on configurations

vm-linux-debug-simriscv64

The test went from flaky to failing. From the log, it seems like a duration is slightly longer than expected. So it will probably revert to flaky again.

[dcharkes]

It's flaky on multiple configs: https://dart-ci.web.app/#showLatestFailures=false&test=co19/LibTest/async/Timer/Timer.periodic_A02_t01

Also went to failing today on Windows.

--- Command "vm" (took 04.000021s):
set DART_CONFIGURATION=DebugX64C & set DART_SUPPRESS_WER=1 & set DART_CRASHPAD_HANDLER=C:\b\s\w\ir\cache\builder\sdk\out\DebugX64C\crashpad_handler.exe & out\DebugX64C\dart.exe --sound-null-safety -Dtest_runner.configuration=vm-win-debug-x64c --ignore-unrecognized-flags --packages=C:\b\s\w\ir\cache\builder\sdk\.dart_tool\package_config.json C:\b\s\w\ir\cache\builder\sdk\tests\co19\src\LibTest\async\Timer\Timer.periodic_A02_t01.dart

exit code:
255

stdout:
unittest-suite-wait-for-done

stderr:
Unhandled exception:
Expect.isTrue(falseexpected=0:00:00.040000, actual=0:00:00.042635) fails.
#0      _fail (file:///C:/b/s/w/ir/cache/builder/sdk/tests/co19/src/Utils/expect.dart:18:5)
dart-lang/sdk#1      Expect.isTrue (file:///C:/b/s/w/ir/cache/builder/sdk/tests/co19/src/Utils/expect_common.dart:23:7)
dart-lang/sdk#2      check.<anonymous closure> (file:///C:/b/s/w/ir/cache/builder/sdk/tests/co19/src/LibTest/async/Timer/Timer.periodic_A02_t01.dart:34:12)
dart-lang/sdk#3      _Timer._runTimers (dart:isolate-patch/timer_impl.dart:398:19)
dart-lang/sdk#4      _Timer._handleMessage (dart:isolate-patch/timer_impl.dart:429:5)
dart-lang/sdk#5      _RawReceivePort._handleMessage (dart:isolate-patch/isolate_patch.dart:184:12)

--- Re-run this test:
python3 tools/test.py -n vm-win-debug-x64c co19/LibTest/async/Timer/Timer.periodic_A02_t01

I think the test is too strict, the documentation mentions:

the time between two consecutive callbacks can be shorter and longer than duration

The only thing from the documentation we can rely on is:

No more than n callbacks will be made in duration * n time,

However, this test calls it with duration 0 and negative numbers. Which makes the documentation meaningless.

@lrhn What should Timer.periodic with 0 do? A hot loop? 🔥 And negative duration? 🤔 We should probably update the documentation to say negative duration is considered 0 or throw? And we should specify what the behavior is with duration 0.

I think if we say duration 0 is equal duration 0.000000000000001, we still can't write a meaningfull test, because we can only test that the maximum number of callbacks below infinite.

[lrhn]

A Timer.periodic(Duration.zero, ...) whould still only trigger as a timer event, so after the current microtask queue has emptied. That we can check: Schedule microtask, start timer, schedule other microtask, have one of those microtasks schedule further microtasks iteratively for a while. Ensure that all of those microtasks have run before the timer callback.
Then have the timer callback start more microtasks again. Check that all of those have completed before the next timer callback.
Then stop, after a few successful itertions of that.

Can maybe even start a timer with a non-zero delay, the check that at least one zero-duration timer event happens before that. (Maybe more. Maybe not, depending on other delays, and how we actually schedule - which should be scheduling another timer after the previous one has run, which may or may not be after the non-zero timer was due.)

I believe a negative duration counts as a zero duration. (That was probably a mistake, but it is what we have, and it's also not worth changing/breaking.)

The one thing we (try to) promise with timers is that they're never early. If they are early, it's due to rounding of timers (asking for a delay of 0.100893 seconds, which Duration supports, when the timer only has millisecond granularity, like on the web, means it might trigger after 0.100 seconds — and I think modern web timers are actually incredibly imprecise to avoid them being used in timing attacks, so it could be worse).
That's the "no more than N calls in N×duration (possibly rounded-down)", but fewer is allowed.

The other thing we do, if there are fewer than N ticks, is to increment the tick counter to include how many ticks were skipped, rather than having up to N due timers run all at the same time.
That one should be checked to always increment by one per callback for a zero-timer. (The normal behavior would imply dividing by zero for a zero-duration timer, so it shouldn't try to do that. I hope that's what we have specified and implemented, but it's been a while since I looked, so this is from memory.)

We can't say anything about the absolute timing, only that each callback is definitely a timer event, and the next callback shouldn't happen before any other timer event which was already due when the current callback was called (and likely when it returned).

So, basically, a Timer.periodic(Duration.zero, ...) should trigger a new callback as a new zero-duration timer started when the current callback completes. That means "call back as soon as all microtasks, and any other due events and their microtasks, have been handled".

Since it's hard to know for sure which events are definitely due, there are limits to how precisely this can be tested, but some things should be possible.

[dcharkes]

@sgrekhov @eernstg Could you please work on fixing this test?

[lrhn]

That said, in this case, which is a simlulated CPU, we probably just need to increase the safety margin. Which make the test rather meaningless.

So I'd change it to check that whenever it triggers, it triggers no earlier than a previously scheduled zero-timer event, no earlier than any currently or later scheduled microtasks, and earlier than a later scheduled zero or non-zero timer.

Without actual precise timing (which on a simulated CPU can become stale very quickly), it's hard to know anything else.

[eernstg]

Thanks for the input, I just landed #2472.