dev/core#1781 - CRM_Utils_Time - Allow TIME_FUNC to better isolate timing bugs
authorTim Otten <totten@civicrm.org>
Wed, 27 May 2020 23:48:27 +0000 (16:48 -0700)
committerTim Otten <totten@civicrm.org>
Wed, 27 May 2020 23:48:27 +0000 (16:48 -0700)
commitea9371f921e9be20f371330b5c72735a7267b868
tree22d512b8356f8bca2cb520e0fa1b2f7a102977e2
parent5b8234802a75cca416748eecef29e0efb03e6c7a
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`.
CRM/Utils/Time.php