Random fail in Drupal\KernelTests\Core\Entity\ContentEntityChangedTest::testChanged

and ChangedTestItem::preSave() has a call out to time() in it

Looks like this is really catch! There are a lot of operations to accumulate the necessary number of milliseconds, allowing you to jump to the next second between calls of preSave() for each translation in ContentEntityStorageBase::invokeFieldMethod().

On my local machine difference between two calls of preSave() (between translations entities) is 3 ms.
For proof of concept, that it can lead to 1 second a difference:

• The first patch contains a payload (2000 additional languages).
• The second patch is launched many times (x10000)

In both cases are used milliseconds (limited by the int type) instead of seconds in 'changed' value for more information.

Or #11 enough to confirm the reason of fail?

Sorry. I forgot to turn off the second test (testRevisionChanged) and as a result 10000_runs always failed (I aborted CI). Also, 2000 languages clearly go beyond time limit (even php7 failed, who would have known :).

In order not to create unnecessary noise, I created a separate experiment for experiments. And this gave the results:

• 500 languages payload: https://www.drupal.org/pift-ci-job/674424 - 10/10 fails (accumulate diff around 903-1010 ms).
• 10k runs: https://www.drupal.org/pift-ci-job/674425 - 5/10000 fails (diff in 1 ms for all 5 cases)

Mini idea just round microseconds. This should give a reserve of 1 second. But I'm not sure how this will affect other tests.

Okay. It was a stupid idea - threshold simply shifted from .999 to .499 :(
And looks like it is not fandom fail, because preSave() is called for each translations and as a result it can give different time value.

Repeating fails make one think about this assertion critically:

    // Update a non-translatable field to make sure that the changed timestamp
    // is updated for all translations.
    $entity->set('not_translatable', $this->randomString())->save();

    $this->assertTrue(
      $entity->getChangedTime() > $changed_en,
      'Changed time of original language did change.'
    );

    $this->assertTrue(
      $german->getChangedTime() > $changed_de,
      'Changed time of the German translation did change.'
    );

    $this->assertEquals($entity->getChangedTime(), $german->getChangedTime(), 'When editing a non-translatable field the updated changed time is equal across all translations.');

getChangedTime() returns the time in seconds. Therefore, by this assert (last in listing), we can at best be able to verify that the request for changing the $entity and $german in one second interval (that rather rough approximation).

Therefore, we can make:

• variant 1: set the assert more loyal with comment (variant 1).
• variant 2: add sleep to postSave, this ensures that the operation with all entities was one cycle (see ContentEntityStorageBase::invokeFieldMethod())
• variant 3: forcibly wait for the beginning of a second for all original entities (this is looks better than coping original value to translation, otherwise what do we test?)

#21:

Or, as I started to do with this patch, weave in the Time service, swap it out with test version so that we can adjust REQUEST_TIME through ContentEntityChangedTest.

Sounds nice irrespective of this issue!

Thank you @gambry! This is useful. I tried to play with microtime(true) & usleep(). But the code is more complicated because of this. Like this:

      $microtime_left = microtime(true);
      $P = 1000000;
      $step = ($P - ($microtime_left * $P) % $P) / $P;
      $wait = $microtime_left + $step;
      time_sleep_until($wait);
...
      $this->value = round(microtime(true));

So I left a more rude, but readable code:
time_sleep_until(time() + 1.1);

Sorry, it was example with microtime + time_sleep_until, but with usleep it works also unstable (just change time_sleep_until($wait) to usleep($step))

Thank you, @catch and @Jo Fitzgerald for review and help with it.

+++ b/core/modules/system/tests/modules/entity_test/src/Plugin/Field/FieldType/ChangedTestItem.php
@@ -31,11 +31,12 @@ public function preSave() {
-      // to set a real time value here. But for the stability of the test,
-      // change the entity with the original language at the beginning of the
-      // second. Comply with this requirement on real sites do not need to.
+      // to set a real time value here. For the stability of the test, set the
+      // time of the original language to the current time plus just over one
+      // second to simulate two different request times.

It looks much better, but the one who will read this can have several questions:

1. Why we need "simulate two different request times" only for original entities instead of all entities?
2. Why we wait here, if we already wait in EntityTestMulChanged::save() via sleep(1)?

In fact, we care here precisely for the processing of all translations in the same second as the original instance.
Example:

• original instance has been changed in 1490000000,999
• translation instance has been changed in 1490000001,000 (because it does not happen instantly)

As a result, the difference is one second, which leads to a fail in the test.

After patch we have:

• a guarantee of about 100 milliseconds on the left (time_sleep_until() is not reliable near 1-3ms)
• a guarantee of about 900 milliseconds on the right (translation processing near 1ms on d.org CI)

This is only necessary for the test system, because it uses time() instead of REQUEST_TIME.

#33: What I wanted to say is that perhaps the commentary can be even clearer. But maybe not. The question of this does not block the issue. Whoever wants, will reads the issue in which these lines appeared :)

+1 to RTBC.

And yep, #30 comment makes a lot of sense for another random fail https://www.drupal.org/pift-ci-job/743965:

Drupal\KernelTests\Core\Entity\ContentEntityChangedTest::testRevisionChanged
Changed time of original language has been updated by new revision.
Failed asserting that false is true.

We haven't issue for this fail, but the shortage of the current fix (additional wait of 1 second) should help with its. Woot!