Problem/Motivation

Chromedriver can return an HTML page before aggregates are written to disk. This is by design for both the aggregation system and performance tests, but it looks like the writing to disk can happen during tearDown which is less good. Only affects sqlite.

Steps to reproduce

See test failures in @Spokje's 100x here:
https://www.drupal.org/project/drupal/issues/3352459#comment-15260203

Proposed resolution

When collecting performance logs from chromedriver, keep polling until page events are no longer coming through, largest contentful paint has been recorded, and network requests have responded - this should ensure all network requests have completed before running tearDown.

Should also improve test performance when we're sending open telemetry data to an endpoint, since it will return earlier than the current largest contentful paint detection when there is only one of those events on a page (which happens in some scenarios).

Remaining tasks

User interface changes

API changes

Data model changes

Release notes snippet

CommentFileSizeAuthor
#16 200.patch4.15 KBcatch
#14 200.patch2.87 KBcatch
#8 3392125-8.patch2.79 KBcatch
#2 3392125.patch2.65 KBcatch
#7 3392125-6.patch2.01 KBcatch
#5 3392125-5.patch1.12 KBcatch
#3 3392125-3.patch2.61 KBcatch

Issue fork drupal-3392125

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

catch created an issue. See original summary.

catch’s picture

catch
he/him
Primary language English
commented
Title: Random test failure in rupal\Tests\demo_umami\FunctionalJavascript\PerformanceTest » Random test failure in Drupal\Tests\demo_umami\FunctionalJavascript\PerformanceTest
Status: Active » Needs review
StatusFileSize
new 3392125.patch2.65 KB

This ensures that at least one largest contentful paint event has fired before we stop checking performance log messages, the LCP event can't fire until the page is actually rendering which means at least CSS has to have been served by that point.

A more comprehensive solution would be to count the number of js and css requests from the log and don't stop polling the log until we've also received responses for each file although I'm not sure how complex that would be to actually implement yet.

catch’s picture

catch
he/him
Primary language English
commented
StatusFileSize
new 3392125-3.patch2.61 KB

Well that didn't work, what about just leaving it at $lcp_count === 2.

catch’s picture

catch
he/him
Primary language English
commented

That seems to work, but it will make the tests ridiculously slow on pages that only have a single largest contentful paint event, there's already a follow-up to optimize this though #3379757: Track largestContentfulPaint::candidate events in PerformanceTestBase and allow assertions on them which should be pretty stable too (possibly more because it will stop polling only once paint and network events stop coming through in the logs).

catch’s picture

catch
he/him
Primary language English
commented
StatusFileSize
new 3392125-5.patch1.12 KB

Without the 100x stuff, and marking with @group #slow.

spokje’s picture

spokje
Primary language Dutch
commented

Looks like this comment needs an update?

diff --git a/core/tests/Drupal/Tests/PerformanceTestTrait.php b/core/tests/Drupal/Tests/PerformanceTestTrait.php
@@ -143,7 +143,7 @@ protected function processChromeDriverPerformanceLogs(?string $service_name): Pe
       }
       // Only check once if $service_name is not set, since
       // largestContentfulPaint is not currently asserted on.
-      if ($lcp_count === 2 || !isset($service_name)) {
+      if ($lcp_count === 2) {
         break;
       }
       sleep(1);

Also, do we want to fix a test by making it slower whilst waiting on another issue to make it better?
Personally this feels like we should rollback the original issue, but that's probably just me.

catch’s picture

catch
he/him
Primary language English
commented
StatusFileSize
new 3392125-6.patch2.01 KB

Started looking at #3379757: Track largestContentfulPaint::candidate events in PerformanceTestBase and allow assertions on them and maybe it is this simple?

catch’s picture

catch
he/him
Primary language English
commented
StatusFileSize
new 3392125-8.patch2.79 KB

Apparently git add isn't simple enough for me... complete patch this time.

catch opened merge request !4954

catch’s picture

catch
he/him
Primary language English
commented

OK that approach is looking good and should result in much faster telemetry tests once we have an otel endpoint connected. Converted to an MR.

catch’s picture

catch
he/him
Primary language English
commented
Issue summary: View changes

Got this on ManageFieldsFunctionalTest (which isn't functional javascript so not affected by any of these tests):

1)
    Drupal\Tests\field_ui\Functional\ManageFieldsFunctionalTest::testDefaultValue
    Drupal\Core\Installer\Exception\InstallerException: Resolve all issues
    below to continue the installation. For help configuring your database
    server, see the installation handbook, or contact your hosting
    provider.Failed to connect to database. The database engine reports the
    following message: SQLSTATE[HY000]: General error: 5 database is
    locked.Does the database file exist?Does web server have permission to
    write to the database file?Does the web server have permission to write to
    the directory the database file should be created in?

Everything else is green so ready for review I think.

catch’s picture

catch
he/him
Primary language English
commented

Tested locally with the otel stack and giving up as soon as the performance log is empty is too aggressive, but if we wait for at least one lcp event and then check for an empty log, it seems fine.

I think this is a good incremental improvement to get rid of the random test failure, but also will see if we can do more in #3379757: Track largestContentfulPaint::candidate events in PerformanceTestBase and allow assertions on them like possibly checking for an equal number of http requests and responses instead of, or as well as, the LCP event.

spokje’s picture

spokje
Primary language Dutch
commented
Status: Needs review » Needs work

I've been shot down for random-test-failure-fixing patches for the below:

I think this needs a test with the change running 8500-10.000x failure free, whilst at the same time running a test running the current situation (in this case even 100x will fail a lot on sqllite).

Also currently the MR (if that's what should be committed?) is running one test only, so no matter the above, this isn't NR at the moment, me thinks.

catch’s picture

catch
he/him
Primary language English
commented
StatusFileSize
new 200.patch2.87 KB

Let's see if we can get 200 runs out of drupalci.

Also fixed up the MR cruft.

andypost’s picture

andypost
he/him
Primary language Russian
commented
Status: Needs work » Needs review

Looks like 200 times passed

catch’s picture

catch
he/him
Primary language English
commented
StatusFileSize
new 200.patch4.15 KB

Additional check that the number of requests made and responses returned is the same. This is as robust as I can think of. Also expanded the code comments to explain the logic.

catch’s picture

catch
he/him
Primary language English
commented

Seeing one or two test failures, but these are generic random sqlite test failures the same as the one in #11, not related to this issue:
https://www.drupal.org/pift-ci-job/2780228
https://www.drupal.org/pift-ci-job/2780232
https://www.drupal.org/pift-ci-job/2780234
https://www.drupal.org/pift-ci-job/2780211
https://www.drupal.org/pift-ci-job/2780220

1) Drupal\Tests\demo_umami\FunctionalJavascript\PerformanceTest::testPagesAnonymous
Drupal\Core\Installer\Exception\InstallerException: Resolve all issues below to continue the installation. For help configuring your database server, see the installation handbook, or contact your hosting provider.Failed to connect to database. The database engine reports the following message: SQLSTATE[HY000]: General error: 5 database is locked.Does the database file exist?Does web server have permission to write to the database file?Does the web server have permission to write to the directory the database file should be created in?

i.e. it's not complaining about trying to rm a non-empty directory.

catch’s picture

catch
he/him
Primary language English
commented
Issue summary: View changes
catch’s picture

catch
he/him
Primary language English
commented

Updated #3055983: Locks on SQLite - consistent fails on PHP 8.4 and PHP 8.5.

spokje’s picture

spokje
Primary language Dutch
commented
Status: Needs review » Reviewed & tested by the community

Thanks @catch, looks good to me.

_Very_ unsure if #3055983: Locks on SQLite - consistent fails on PHP 8.4 and PHP 8.5 is about the same (known) problem, that, when running a test multiple times on SQLite, the DB locks.
If I understand that issue correctly, the lock happened on a normal test-run where all test are ran only once?
But the locked DB-problem reported here hasn't got anything to do with the random that was fixed here.

Anyway, this is RTBC for me (although one could mega-nitpick the empty line added as line 151).

catch’s picture

catch
he/him
Primary language English
commented

@Spokje oh interesting I forgot there's a locking issue specific to multiple runs of the same test, however I also saw the same error on ManageFieldsFunctionalTest on an MR run here, so maybe it's very occasional on real MR runs and very common when running the same test multiple times (although even this doesn't necessarily mean it's exactly the same problem as that issue, but the fix might be the same).

edit: pushed a commit to remove the blank line.

spokje’s picture

spokje
Primary language Dutch
commented

Thanks @catch, a final(?) question: After this is committed, will #3379757: Track largestContentfulPaint::candidate events in PerformanceTestBase and allow assertions on them still be relevant?

catch’s picture

catch
he/him
Primary language English
commented

@Spokje the 'optimize' bit should be done here, however there's a possibility we could still do 'expected number of LCP events', so we might want to keep it open for that.

  • longwave committed 93d24db9 on 11.x 
    Issue #3392125 by catch, Spokje: Random test failure in Drupal\Tests\...
longwave’s picture

longwave
he/him
Primary language English
Location UK
commented
Status: Reviewed & tested by the community » Fixed

Committed 93d24db and pushed to 11.x. Thanks!

Status: Fixed » Closed (fixed)

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