Problem/Motivation

The Simpletest UI form takes quite a while to render.

It does not currently take advantage of Drupal's sophisticate page rendering caches.

We currently want to simplify TestDiscovery, the class which the UI form uses to gather the list of tests it displays: #1667822: Remove caching of test classes in TestDiscovery

As a consequence, the minor performance improvement that the TestDiscovery cache gave us will probably be removed, and so the form itself needs some attention.

Proposed resolution

Use dynamic caching to improve the performance of the form.

Remaining tasks

User interface changes

API changes

Data model changes

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

Mile23 created an issue. See original summary.

Version: 8.4.x-dev » 8.5.x-dev

Drupal 8.4.0-alpha1 will be released the week of July 31, 2017, which means new developments and disruptive changes should now be targeted against the 8.5.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

Mile23’s picture

Status: Active » Needs review
FileSize
7.83 KB

Here's a go.

The value of this patch is tightly coupled to #1667822: Remove caching of test classes in TestDiscovery :-)

The good news: Loading the form on an empty cache is ~23 seconds. Subsequent loads are <10 seconds. This is accomplished by making a hash of the discovered tests in a cache context implementation.

The bad news: The goal of having the cached form reflect changes to tests on the filesystem isn't fixed. That's because the form makes a call to TestDiscovery::getTestClasses(), which loads TestDiscovery's cache. This happens before the cache is removed by the cache context implementation in order to calculate the hash for the actual filesystem. This is a chicken/egg scenario, and the way to break the cycle is to do both the solution here and removing the cache from TestDiscovery in #1667822: Remove caching of test classes in TestDiscovery

This change is a performance improvement, and without it we still have the problem of cache invalidation within TestDiscovery, so we don't lose anything.

Status: Needs review » Needs work

The last submitted patch, 3: 2893117_3.patch, failed testing. View results

Mile23’s picture

Status: Needs work » Needs review
FileSize
9.16 KB
2.91 KB

Fixed the test.

Also we just invalidate caches all day long so TestDiscovery is up-to-date. This means cached requests are 11 seconds instead of 9, but still better than 23. Also this will likely change and be even more efficient after we remove TestDiscovery's cache, or at least refactor it.

And just a reminder: We're messing with this form so that we can decouple TestDiscovery away from having a cache, so that we can move TestDiscovery out of the simpletest module, so that we can deprecate simpletest. Right? :-) #2866082: [Plan] Roadmap for Simpletest #1667822: Remove caching of test classes in TestDiscovery

Lendude’s picture

Just some nitpicks, the rest looks good to me:

  1. +++ b/core/modules/simpletest/src/Cache/Context/TestDiscoveryCacheContext.php
    @@ -0,0 +1,105 @@
    +  public function __construct(TestDiscovery $test_discovery, PrivateKey $private_key, CacheBackendInterface $cache) {
    

    params are missing in the docblock

  2. +++ b/core/modules/simpletest/src/Form/SimpletestTestForm.php
    @@ -47,9 +57,10 @@ public static function create(ContainerInterface $container) {
    +  public function __construct(RendererInterface $renderer, TestDiscovery $test_discovery, CacheBackendInterface $cache) {
    

    new param is missing in the docblock

  3. +++ b/core/modules/simpletest/tests/src/Kernel/Cache/Context/TestDiscoveryCacheContextTest.php
    @@ -0,0 +1,57 @@
    +  public function testContext() {
    

    missing docblock

Did some benchmarking:

AB test for 10 requests without patch applied:

Document Path: /admin/config/development/testing/
Document Length: 5156895 bytes

Concurrency Level: 1
Time taken for tests: 129.257 seconds
Complete requests: 10
Failed requests: 0
Write errors: 0
Total transferred: 51581900 bytes
HTML transferred: 51568950 bytes
Requests per second: 0.08 [#/sec] (mean)
Time per request: 12925.723 [ms] (mean)
Time per request: 12925.723 [ms] (mean, across all concurrent requests)
Transfer rate: 389.71 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 27 1121 2299.6 31 5687
Processing: 7151 11805 2278.1 12946 13189
Waiting: 7126 11778 2277.0 12918 13162
Total: 12213 12926 310.8 13015 13224

AB test for 10 requests with patch applied:

Document Path: /admin/config/development/testing/
Document Length: 5158552 bytes

Concurrency Level: 1
Time taken for tests: 71.464 seconds
Complete requests: 10
Failed requests: 1
(Connect: 0, Receive: 0, Length: 1, Exceptions: 0)
Write errors: 0
Total transferred: 51598619 bytes
HTML transferred: 51585519 bytes
Requests per second: 0.14 [#/sec] (mean)
Time per request: 7146.401 [ms] (mean)
Time per request: 7146.401 [ms] (mean, across all concurrent requests)
Transfer rate: 705.10 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 30 2272 2890.6 45 5749
Processing: 71 4874 5744.4 5726 19161
Waiting: 42 4838 5724.8 5696 19062
Total: 5686 7146 4238.3 5821 19207

conclussion

Running this multiple times gives fairly consistent results. So this indicates that the initial request that builds the dynamic cache is considerably longer, but after that things speed up nicely.

dawehner’s picture

+++ b/core/modules/simpletest/src/Form/SimpletestTestForm.php
@@ -110,6 +129,10 @@ public function buildForm(array $form, FormStateInterface $form_state) {
+        'keys' => ['test_discovery'],

Is there a better name? test_discovery doesn't indicate for me that this caches the simpletest admin UI. What about using something like 'simpletest_ui_table' or so?

Mile23’s picture

Updated docblocks, changed the key name.

Honestly I'm not sure what the key is for, because it's basically undocumented. But apparently it needs to be there in order to make the caching context work. It seems like it's just another hash to go in the cache id column.

Lendude’s picture

Status: Needs review » Reviewed & tested by the community

All feedback has been addressed, looks good to me

Wim Leers’s picture

Status: Reviewed & tested by the community » Needs review
Issue tags: +D8 cacheability
  1. +++ b/core/modules/simpletest/simpletest.services.yml
    @@ -1,4 +1,15 @@
    +  cache.simpletest:
    

    Why call this simpletest and not just test in general? It's about discovered tests, not just simpletest tests?

  2. +++ b/core/modules/simpletest/simpletest.services.yml
    @@ -1,4 +1,15 @@
    +  cache_context.test_discovery:
    +    class: Drupal\simpletest\Cache\Context\TestDiscoveryCacheContext
    +    arguments: ['@test_discovery', '@private_key', '@cache.simpletest']
    +    tags:
    +      - { name: cache.context}
    

    Woah, fancy!

  3. +++ b/core/modules/simpletest/src/Cache/Context/TestDiscoveryCacheContext.php
    @@ -0,0 +1,109 @@
    +  public function getContext() {
    +    if (empty($this->hash)) {
    +      // Remove TestDiscovery's internal cache so it scans the filesystem.
    +      // @todo Change this for
    +      //   https://www.drupal.org/project/drupal/issues/1667822
    +      $this->simpletestCache->delete('simpletest:discovery:classes');
    +      $tests = $this->testDiscovery->getTestClasses();
    +      $this->hash = $this->hash(serialize($tests));
    +    }
    +    return $this->hash;
    +  }
    

    Even though it's fancy to have this cache context, this means we're potentially caching many, many variations of the SimpleTest UI. Why can't we just rely on a cache tag?

Berdir’s picture

I also don't really understand what this is doing exactly.

It defines a new cache bin "simpletest", but TestDiscovery uses cache.discovery, so how is invalidating/deleting in the new bin affecting anything?

Maybe this shouldn't be split from removing caching but just be done at the same time?

Also seems like this needs more than ApacheBench testing but actual profiling with blackfire or so?

Berdir’s picture

Ah I missed that this changes the bin, forget that part.

But even more then, doesn't seem very useful to introduce a new cache bin as a temporary measure to remove it again then?

Lendude’s picture

Why can't we just rely on a cache tag?

How/when would you invalidate that tag? I don't see it, but maybe I'm missing something?

Also seems like this needs more than ApacheBench testing but actual profiling with blackfire or so?

Really? For the simpletest UI page? The only thing I care about there is the load time, efficiency be damned. ¯\_(ツ)_/¯

Mile23’s picture

I will give you USD$50 if this patch introduces a performance hit by any metric. :-)

I added a bin because the module is the only thing using the bin. It is a bit out of scope here, so we'll remove it. That means our cache context service is dependent on cache.discovery but no biggie. It also means that the cache of discovered tests will persist even if you remove the simpletest module, but again: Better scope for #1667822: Remove caching of test classes in TestDiscovery

So that takes care of #11 and #12, but leaves #10.3:

Even though it's fancy to have this cache context, this means we're potentially caching many, many variations of the SimpleTest UI. Why can't we just rely on a cache tag?

The only thing that can invalidate the form cache is a change to the file system. If the tests change at all, then we want to update the form cache.

If that's a tag, then we have to invalidate the tag somewhere. The only place to do that is in the form itself, because this form is literally the only thing in Drupal that cares. :-)

A cache context does this for us automatically, but as you say fills the DB up with cached form stuff. This is mitigated by:

Status: Needs review » Needs work

The last submitted patch, 14: 2893117_14.patch, failed testing. View results

Mile23’s picture

Status: Needs work » Needs review

Unrelated fail.

Berdir’s picture

Status: Needs review » Needs work

I'm sorry, my comment wasn't very useful, was a bit in a hurry.

I didn't mean to say that I'm worried about regressions. What I'm saying is that now the whole thing is a blackbox, we do now how long it takes and we know that is an improvement. But we have no idea which part takes how long. One look at a blackfire.io report might show us a way for some additional improvements.

I gave it a try and what I'm seeing is what I already suspected from the code. Having the render cache removes a huge amount of theme processing, but you're calling the TestDiscovery twice and you are now invalidating it on every request as well. As far as I see, you're basically adding more code to work around the cache as there is actual caching code, so I just don't see how splitting this into two steps is useful.

TestDiscovery::getTestClasses() now makes up 60% of the execution time, which means that by adding a property to store it, we can save another 30% of the execution time.

The total execution time for me per request is 1.6s, which a fast CPU and reasonably fast SDD.

So why exactly is that cache delete/invalidate necessary? My suggestion would be to replace the persistent cache with a static cache/property on TestDiscovery, through out all the cache and cache invalidation code and the result should be about 30% faster than it is now :)

I can maybe work a bit on it on the weekend.

Berdir’s picture

FileSize
36.68 KB

Forgot the blackfire.io screenshot:

Mile23’s picture

So why exactly is that cache delete/invalidate necessary? My suggestion would be to replace the persistent cache with a static cache/property on TestDiscovery, through out all the cache and cache invalidation code and the result should be about 30% faster than it is now :)

Agreed. And in fact I should have said that this was the ideal solution, and then explained why I did it this way instead. And here's that explanation:

As far as I see, you're basically adding more code to work around the cache as there is actual caching code, so I just don't see how splitting this into two steps is useful.

That's why there are a lot of @todos.

In order to remove the TestDiscovery cache, we'd have to change a service API. Literally the only thing in core using this API is the form under discussion here, but that's what we'd be doing. We'd also have to make an update function to remove the cached discovered stuff, which should be tested.

That's out of scope here, but it will all happen. :-)

Mile23’s picture

Status: Needs work » Needs review
Berdir’s picture

> That's why there are a lot of @todos.

Yeah, there are literally more @todo's in the patch than there is actual caching code. @todo's that completely remove the caching by writing and deleting it on every request.

> In order to remove the TestDiscovery cache, we'd have to change a service API. Literally the only thing in core using this API is the form under discussion here, but that's what we'd be doing.
We change the implementation, not the API. The only change is in the constructor and protected property which is excluded from BC. And even if we'd keep that, we could simply stop using it. This change is perfectly OK for a minor update and exactly what you want to do in that follow-up .

> We'd also have to make an update function to remove the cached discovered stuff, which should be tested.

I don't see why that's necessary. It's a cache, it will be cleared on the next cache clear. And everyone updating from 8.4 to 8.5 will during the update do at least 2 if not more cache clears. We did update functions to clear caches before but because it was required for Drupal to work correctly after the update, this is just a bit of stale data.

Also, even if we would leave the cache in place, we' need a static property because this change results in two calls to getTestClasses() as shown in my screenshot above, so...

> I will give you USD$50 if this patch introduces a performance hit by any metric. :-)

I think that counts as "any metric" (whole page is faster, but there are additional, unecessary calls that didn't exist before), so cool, thanks! I accept amazon vouchers ;)

Here is a counter-proposal, replacing the optional cache with a statically cached property which is similar to what you already did in the cache context, I think that's worth keeping as calcuting the cache of that huge array is probably not trivial. Although not having it would simplify the kernel test you added. I also added a !empty($types) to the cache logic because it would have still returned all through the cache when calling it with some types only. I also noticed that simpletest_clean_environment() has bogus cache clear calls, it didn't clear the actually relevant cache but two bogus non-existing cache entries. And I removed the max-age line, max-age defaults to unlimited, only needs to be specified if something is not cacheable or only for a specific time.

Execution time here is now down to 1.16s and blackfire shows that the second call is now basically free:

This patch that removes the caching is even a bit smaller than yours and we also fix the other issue.

Status: Needs review » Needs work

The last submitted patch, 21: 2893117_21.patch, failed testing. View results

Mile23’s picture

Status: Needs work » Reviewed & tested by the community

Yup, that's the two things in one.

It also allows us to decouple TestDiscovery from simpletest #2863055: Move TestDiscovery out of simpletest module, minimize dependencies and eventually decouple simpletest from Drupal #2866082: [Plan] Roadmap for Simpletest

Setting to RTBC even though it's partially my work so that we can get maintainer eyes on this and figure out if it should be two issues or one, or whatever. The fail in #22 seems to be unrelated.

Also: Must collect in person. :-)

Version: 8.5.x-dev » 8.6.x-dev

Drupal 8.5.0-alpha1 will be released the week of January 17, 2018, which means new developments and disruptive changes should now be targeted against the 8.6.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

Mile23’s picture

Patch still applies, running tests for #21 in 8.6.x.

  • catch committed c8dbe3a on 8.6.x
    Issue #2893117 by Mile23, Berdir: Improve HTML caching of Simpletest UI...
catch’s picture

Version: 8.6.x-dev » 8.5.x-dev
Status: Reviewed & tested by the community » Fixed

Committed/pushed to 8.6.x and cherry-picked to 8.5.x. Thanks!

  • catch committed f8a87ec on 8.5.x
    Issue #2893117 by Mile23, Berdir: Improve HTML caching of Simpletest UI...
xjm’s picture

I think this may have broken 8.5.x:
https://www.drupal.org/pift-ci-job/870735

Berdir’s picture

I saw such errors in an issue too, but I can't really imagine how they would be connected.

This is only about the simpletest UI. run-tests.sh was never using caches (at least not anymore since a long time) and those are phpunit tests actually.

Berdir’s picture

@xjm: If you haven't seen yet: #2817833: Delay sql map table creation

xjm’s picture

Yep, thanks.

Mile23’s picture

Woot. Thanks everybody. I still owe @Berdir $50.

Next up in Mission: Destroy Simpletest: #2460521: Deprecate hook_simpletest_alter()

xjm’s picture

Version: 8.5.x-dev » 8.6.x-dev
Issue summary: View changes
Status: Fixed » Needs work
FileSize
846.92 KB

Alright, so while this did not break HEAD, it did break the Simpletest UI. On my local development environment (installed in a subdirectory FWIW), if I enable SimpleTest and navigate to the UI, it briefly flashes an exception message (attached) and then redirects to the installer with the "Drupal already installed" message.

I confirmed that if I revert this commit, it resolves the issue.

The form is slow as heck, but slow is better than broken, so reverting. :) Also moving it to 8.6.x as (given the above) the issue may be disruptive.

  • xjm committed 9139b08 on 8.5.x
    Revert "Issue #2893117 by Mile23, Berdir: Improve HTML caching of...

  • xjm committed 66dda07 on 8.6.x
    Revert "Issue #2893117 by Mile23, Berdir: Improve HTML caching of...
Mile23’s picture

I can't repro.

SHOW VARIABLES LIKE 'max_allowed_packet'; says 67108864.

Docs: https://www.drupal.org/node/259580

Are we saying the form takes up too big a cache entry?

Mile23’s picture

Status: Needs work » Needs review
FileSize
10.81 KB
1.82 KB

This is #21, with an added test that exercises all of simpletest's routes.

xjm’s picture

max-allowed-packet 16777216

So yeah looks like my Homebrew default has 16 MB rather than 64 MB. Unfortunately I can't test increasing it right at the moment.

https://www.drupal.org/docs/8/system-requirements/database-server doesn't specify a requirement for this one way or the other.

Berdir’s picture

Maybe it should at least mention it though. At least there is a documentation page on the mysql has gone away error. Because it is a pretty common problem, https://drupal.stackexchange.com/search?q=max_allowed_packet has quite a few questions about it.

#1281408: Add a compressing serializer decorator would also help ;)

Mile23’s picture

This form is pretty much the edge case for everything. :-)

Updated the database docs: https://www.drupal.org/docs/8/system-requirements/database-server#commen...

Mile23’s picture

Status: Needs review » Reviewed & tested by the community

Seting to RTBC to see if there's anything else we need to do for this issue.

alexpott’s picture

Status: Reviewed & tested by the community » Needs work
+++ b/core/modules/simpletest/tests/src/Functional/FormRouteTest.php
@@ -0,0 +1,52 @@
+class FormRouteTest extends BrowserTestBase {

For me this test is duplicating parts of other more extensive tests - for example \Drupal\simpletest\Tests\SimpleTestBrowserTest::testTestingThroughUI() and \Drupal\simpletest\Tests\SimpleTestTest() which do a far more extensive test of running tests via the UI. If we want to test the other routes - fine but then we should have explicit tests that test what each route actually does. The other new thing that is being tested here is the admin/config/development/testing/settings route but we're not actually testing the impact of the changes to simpletest_clean_environment() made here.

Also I have max_allowed_packet set to 16mb and the form works fine before and after the applying the patch - at least on PHP 7.1.

Mile23’s picture

Status: Needs work » Needs review
FileSize
1.82 KB
8.99 KB

We really can't test changes to simpletest_clean_environment() but we could if: #2800267: Turn simpletest_clean*() functions into a helper class

The tests you mention get some PHPUnit cleanup in #2932909: Convert web tests to browser tests for Simpletest module

Here's the same patch without the test from #38. It's basically @Berdir's patch from #21.

I'm at a loss as to why we'd see MySQL 2006, other than a misconfigured DB or some other similar concern.

dawehner’s picture

Maybe a more radical approach than doing HTML based caching. An alternative would be do pure frontend rendering, and pass along the discovered tests to some JS using drupalSettings.

Mile23’s picture

I thought we were trying to get rid of this form.

The reason we're doing this exercise is so that we can decouple TestDiscovery from simpletest so that we can deprecate all or part of simpletest.

It might be that we want to keep the form to display test results, and that it would help us to, for instance, display incoming results as a stream if it were in JS. If that's the case, RTBC here, file a follow-up, and get to work.

jibran’s picture

Status: Needs review » Reviewed & tested by the community

Back to RTBC as #43 is addressed.

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 44: 2893117_44.patch, failed testing. View results

yogeshmpawar’s picture

Assigned: Unassigned » yogeshmpawar
yogeshmpawar’s picture

Assigned: yogeshmpawar » Unassigned
Status: Needs work » Needs review
FileSize
9.11 KB

Straight Re-roll because #44 patch failed to apply on 8.6.x branch.

Anonymous’s picture

Status: Needs review » Reviewed & tested by the community

Thanks for good reroll. Back to RTBC!

catch’s picture

Status: Reviewed & tested by the community » Fixed

The last time there was a lot of discussion about this form, we got to "Stop using the UI test runner, but keep the form as a test command generator", so it's worth making improvements to the form, even if we change what submitting it does eventually.

Committed 259bf40 and pushed to 8.6.x. Thanks!

  • catch committed 259bf40 on 8.6.x
    Issue #2893117 by Mile23, Berdir, Yogesh Pawar, xjm, catch, alexpott:...
Mile23’s picture

Thanks!

Actually what we got to was: Leave the Simpletest UI form as-is for the D8 cycle, figure out if we hate it in D9.

#2866082: [Plan] Roadmap for Simpletest

That's based on #2750461: Remove Simpletest UI because we don't want to maintain a graphical test runner and #2312191: Change Simpletest UI from a test runner to a CLI snippet generator.

Status: Fixed » Closed (fixed)

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