dev/core#1781 - CRM_Utils_Time - Allow TIME_FUNC to better isolate timing bugs
Overview
--------
`CRM_Utils_Time` is a helper for (a) getting the time and (b) setting the time
to a mocked value (for testing purposes).
Timing bugs can manifest as flaky tests.
This provides a new option, `TIME_FUNC`, which may help isolate some timing
bugs (provided the test consistently uses `CRM_Utils_Time`).
Before
------
When using `CRM_Utils_Time::setTime()`, it simulates a change in the clock, and
the clock is allowed to proceed at a natural/real pace.
This policy aims to be representative of real-world execution (wherein the
clock also executes at a natural pace). However, consider that the pace at
which the code executes depends on numerous factors (CPU speed, memory
managers, system-load, system-caches, the specific code/use-case, etc). If
your use-case relies on multiple calls to `getTime()`, and if you run the
use-case in repeated trials, then you may find somewhat chaotic variations
in the exact values of `getTime()`.
Consequently, if there is a timing-sensitive bug, you may find that some trials
pass while others fail, and it is impossible to reproduce the natural
circumstance of the failure.
After
-----
By default, `CRM_Utils_Time` still performs simulations where the clock
proceeds a natural/real pace.
However, if you see flaky results and suspect a timing bug, you can re-run the
test suite with alternative time functions (`TIME_FUNC`):
```bash
TIME_FUNC=frozen ## every call to getTime() yields the same, static value
TIME_FUNC=natural ## every call to getTime() progresses in tandem with the real/natural clock
TIME_FUNC=linear:333 ## every call to getTime() progresses by 333ms
TIME_FUNC=prng:333 ## every call to getTime() progresses by a random interval, up to 333ms
```
Now "time" is not so natural or chaotic - it's more synthetic and
deterministic, which can help with debugging.
For example, consider `CRM_Core_BAO_ActionScheduleTest` and its functions
`testMembershipEndDateRepeat`, `testEventTypeEndDateRepeat`, and
`testRepetitionFrequencyUnit` -- which (anecdotally) appear to be flaky. We
can run one of these tests with deterministic time functions:
```bash
for TIME_FUNC in frozen prng:333 prng:666 prng:1000 prng:1500 linear:333 linear:666 linear:1000 ; do
export TIME_FUNC
echo
echo "Running with TIME_FUNC=$TIME_FUNC"
env CIVICRM_UF=UnitTests phpunit6 tests/phpunit/CRM/Core/BAO/ActionScheduleTest.php --filter testRepetitionFrequencyUnit
done
```
We get different results depending on the `TIME_FUNC`. I've done multiple trials with each `TIME_FUNC`, and
results have been stable so far:
* PASSING: `frozen` `prng:333` `prng:666` `linear:333` `linear:666` `linear:1000` `linear:1500`
* FAILING: `prng:1000` `prng:1500`
This doesn't specifically tell you what the bug is. It could be a real bug
in the main logic or less important bug in the test logic. However, you can
now *reproduce it* (locally, in an IDE, etc) by setting `TIME_FUNC=prng:1500`.