Problem/Motivation

TestTime->getRequestTime() can produce inconsistent results due to rounding in the calculation.

Steps to reproduce

We did the following in a kernel test:

  public function testTimeRoundingError(): void {
    \Drupal::time()->setTime('+100 seconds');
    $timestamp = \Drupal::time()->getRequestTime();
    for ($i = 1; $i <= 10; ++$i) {
      time_nanosleep(0, 100000000);
      $this->assertSame(0, $timestamp - \Drupal::time()->getRequestTime(), "after 0.$i seconds");
    }
  }

This fails for us with a random-ish value in the message, e.g. "after 0.3 seconds" then "after 0.7 seconds" etc.

I looked into the calculation, and it seems way too smart.

Proposed resolution

Add the test.
Fix the calculation.

Remaining tasks

User interface changes

API changes

Data model changes

Issue fork datetime_testing-3513073

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

About issue forks

Comments

donquixote created an issue. See original summary.

donquixote’s picture

donquixote commented

Some equation juggling which may or may not be helpful.
Note that `(int)` behaves like floor() for positive numbers and like ceil() for negative numbers, which makes it harder to reason about.
But the bug still happens if we replace (int) with floor().

getRequestTime() = getCurrentTime() - (REAL.CURRENT_TIME - REAL.REQUEST_TIME)
getCurrentTime() = floor(getCurrentMicroTime())
getCurrentMicroTime() = SPECIFIED_TIME + getMicroTimePassed()
getMicroTimePassed() = REAL.CURRENT_MICRO_TIME - TIME_STARTED

getRequestTime() = floor(REAL.CURRENT_MICRO_TIME - TIME_STARTED)
- REAL.CURRENT_TIME
+ REAL.REQUEST_TIME
+ SPECIFIED_TIME

getRequestTime() = floor(REAL.CURRENT_TIME + REAL.CURRENT_TIME_FRACTION - TIME_STARTED)
- REAL.CURRENT_TIME
+ REAL.REQUEST_TIME
+ SPECIFIED_TIME

getRequestTime() = floor(REAL.CURRENT_TIME_FRACTION - TIME_STARTED)
+ REAL.REQUEST_TIME
+ SPECIFIED_TIME

getRequestTime() = floor(REAL.CURRENT_TIME_FRACTION - TIME_STARTED_FRACTION)
- TIME_STARTED_SECONDS
+ REAL.REQUEST_TIME
+ SPECIFIED_TIME

Here we split float variables into varname_int + varname_fraction, so that we can move the integer part out of the floor() call.
This would not be possible with just (int) due to the asymmetry mentioned above.

The problem would go away if TIME_STARTED_FRACTION is zero.

ptmkenny’s picture

ptmkenny commented

Thanks for reporting this. As a maintainer, I'm happy to review an MR that contains a fix for this and a test, but I don't have the time to work on the code myself.

I also didn't start maintaining this module until a few years after that code was committed, so I'm not able to explain why it is written the way it is.

ptmkenny’s picture

ptmkenny commented

Duplicate, please ignore.

jonathanshaw made their first commit to this issue’s fork.

jonathanshaw opened merge request !29

jonathanshaw’s picture

jonathanshaw
Primary language English
Location Stroud, UK
commented
Priority: Normal » Major
Status: Active » Reviewed & tested by the community

The problem is worse than one might realise from the IS. Because of the rounding fluctuation, the request time can go jump backwards as well as forwards. This can cause very obscure intermittent caching bugs, the kind that eat days of developer time.

I'm not completely sure the fix in the MR is the best solution - maybe deeper insight could see a better solution - but it works in practice and has a test so I suggest we commit it for now.

ptmkenny’s picture

ptmkenny commented

Thanks! I added an additional part to the test to make it clear that the caching persists even when resetTime() is called. (I think it makes sense to keep the cache even if resetTime() is called, but we may decide to change this later; the test makes it explicit.)

ptmkenny’s picture

ptmkenny commented
Status: Reviewed & tested by the community » Fixed

Now that this issue is closed, review the contribution record.

As a contributor, attribute any organization that helped you, or if you volunteered your own time.

Maintainers, credit people who helped resolve this issue.

jonathanshaw’s picture

jonathanshaw
Primary language English
Location Stroud, UK
commented

Thanks @ptmkenny.

I agree it's probably safer to keep the cache, it prevents any risk of rounding errors creeping in and making the time go backwards if time gets frozen/unfrozen repeatedly in quick succession.

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.