In support of additional performance metrics, Simpletest should report test duration for individual tests and for the entire run. Spinoff from #1205140: Capture duration for test runs

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

rfay’s picture

Priority: Normal » Major

We have serious overall test time increases on the testbots, which means everybody waits more, and our resources are used more. Moving to major.

Related: #1744302: [meta] Resolve known performance regressions in Drupal 8 and #1851088: Massively slowed D8 tests?

jthorson’s picture

This would certainly help provide us one more metric we can use to troubleshoot, and/or use to identify any particular tests which are taking longer than expected (or at least help identify if there are any tests which we should prioritize for potential optimization).

janip’s picture

Please find attached a patch that persists the duration for individual tests and displays the duration(s) in test title.

The duration is persisted as an assert message in simpletest table using message group "Duration" (I wanted to keep the database schema unchanged).

xjm’s picture

Issue tags: +Needs tests

Awesome! The only downside I can see to this method is that it adds an additional assertion to every test method, which would be 1500 or so additional assertions over the whole test suite. I couldn't figure out a way to add it to the result metadata separately from adding an assertion, though.

Otherwise, we could also do what's done for the completion check:

// Remove the completion check record.                                 
TestBase::deleteAssert($completion_check_id);

(Not sure if that's desirable or not.)

Couple minor cleanups to add:

+++ b/core/modules/simpletest/lib/Drupal/simpletest/TestBase.phpundefined
@@ -684,6 +684,8 @@ public function run(array $methods = array()) {
+          // Record the start time of the test for calculating test duration

@@ -709,6 +711,9 @@ public function run(array $methods = array()) {
+          // Save the test duration

+++ b/core/modules/simpletest/simpletest.pages.incundefined
@@ -268,6 +268,12 @@ function simpletest_result_form($form, &$form_state, $test_id) {
+      // Display test duration in test group title

These should have periods at the end of the comment.

+++ b/core/modules/simpletest/lib/Drupal/simpletest/Tests/SimpleTestTest.phpundefined
@@ -306,13 +306,17 @@ function getResultFieldSet() {
+  function startsWith($haystack, $needle) {
+    return !strncmp($haystack, $needle, strlen($needle));
+  }

This method needs a documentation block.

Finally, we probably also need to add coverage to SimpleTest's self-tests asserting that the time is added/displayed.

This will be a really useful feature!

janip’s picture

Minor cleanups (added periods and a documentation block).

janip’s picture

Some test coverage (asserting that the duration assert is persisted and that the duration is numeric).

xjm’s picture

@janip, Can you add a test-only patch exposing the failures without the feature? (You can attach the test-only patch first, followed by the combined patch in the same comment. That way testbot will interpret them correctly and not mark the issue "needs work".)

Do we want to also add test coverage for the rendered title suffix on the test results page? (I'm not sure what coverage that page has, if any.)

+++ b/core/modules/simpletest/lib/Drupal/simpletest/Tests/SimpleTestTest.phpundefined
@@ -314,6 +327,20 @@ function getResultFieldSet() {
+   * @param $haystack
+   *   Haystack (text) to search from.
+   * @param $needle
+   *   Needle (text) to search for.
+   * @return
+   *   TRUE if haystack starts with needle, FALSE otherwise.

Ome more thing here, the parameters and return values need datatype documentation. There should also be a blank line before the @return. Reference: http://drupal.org/node/1354#param-return-data-type

Berdir’s picture

This is really useful.

- I think a single total time per test (not test method) would be enough. You don't really know which one it was that actually took that longer anyway.
- Wondering if we want to make it optional, similar to only debugging the page requests if verbose is on. As long as it is not displayed in the console and reported back to qa.drupal.org, it's not helpful on the bots anyway and just increases test run time

kerasai’s picture

Status: Needs review » Needs work
Issue tags: +Needs tests

The last submitted patch, simpletest_test_duration_for_individual_tests-1205162-6.patch, failed testing.

deekayen’s picture

Status: Needs work » Needs review
FileSize
4.65 KB

Since #6, core/modules/simpletest/simpletest.pages.inc was moved to core/modules/simpletest/lib/Drupal/simpletest/Form/SimpletestResultsForm.php.

Attempting to get this back on track with a reroll of #6. I made some docblock updates requested by xjm in #7, otherwise it's the same. Contrary to #8's suggestion, I like the idea of having access to deeper levels of timing. If you get the scope too wide on the timing, I think it loses some meaning and value.

deekayen’s picture

Re: #8, I considered making it optional, but then doesn't adding a set of if statements to check for an optional condition also increase run time? I think if it gets output conditionally, the argument isn't runtime rather that it's just something of classifying it to be a verbose type of output or not.

xjm’s picture

Status: Needs review » Needs work
jhedstrom’s picture

Issue summary: View changes
Issue tags: -Needs tests

The patch here has tests, removing tag.

Mixologic’s picture

Not totally a reroll, more like an experiment. If we do not treat the duration logging as a Passing assertion, and as a debug message instead, it can show up in other places in the interface without special handling on either qa.drupal.org (soon sooon soooon to be deprecated) as well as on the drupalci infrastructure.

Mixologic’s picture

Status: Needs work » Needs review

I always forget to do this.

Status: Needs review » Needs work
dawehner’s picture

Oh nice! This just lead to a gigantic flashback, see #329407: Make simpletest report running time

Mixologic’s picture

Fixes the test, and changes it to milliseconds because junit thinks on that level.

Mixologic’s picture

I fail at counting. Thats why I let computers do it for me.

Mixologic’s picture

When the computers count for me, they need to count better. Adjusts the microtime to actually put out ms like I thought I was already doing. I shouldnt use the testbots to debug.

Status: Needs review » Needs work
Mixologic’s picture

Aaand its midnight.

Mixologic’s picture

I prematurely optimized for jenkins and it didnt need it: https://dispatcher.drupalci.org/job/DCI_XML/77/testReport/ is what it'd look like on dispatcher with time() vs microtime(TRUE) * 10.

patch reverted back to 16, but with the test fix of 20.

pwolanin’s picture

Looks good, but maybe use microtime(TRUE); for tests that take less than a second?

Mixologic’s picture

Also, the test results look better now that we've got subsecond responses properly accounted for:

https://dispatcher.drupalci.org/job/DCI_XML/137/testReport/

pwolanin’s picture

Status: Needs review » Reviewed & tested by the community

This would be a useful addition, let's get it in.

Status: Reviewed & tested by the community » Needs work

Status: Needs work » Needs review
dawehner’s picture

Status: Needs review » Reviewed & tested by the community

This has been RTBC before.

tim.plunkett’s picture

+1! This would be great.

YesCT’s picture

Issue tags: +Performance
Mixologic’s picture

Since this adds a bunch of debug messages, it'd be nice if somebody ran this on the UI side of things to make sure it doesnt overtly bloat the output....

jhedstrom’s picture

I ran BookTest (one of the more monstrous test classes), and it only added 14 duration messages, so I don't think this bloats the output by any means.

Mixologic’s picture

It would add one per "test", minus the phpunit tests, so 14324 - 8826 = 5498 additional duration messages for a complete simpletest run.

Status: Reviewed & tested by the community » Needs work
Mixologic’s picture

Sigh. I wonder why that test failed? Is that a testbot problem? I should probably report that to the testbot maintainers.

Mixologic’s picture

Status: Needs work » Needs review
Mixologic’s picture

Status: Needs review » Reviewed & tested by the community

moving back to rtbc. Needs work was an erroneous testbot issue.

xjm’s picture

Category: Feature request » Task
Priority: Major » Normal
Status: Reviewed & tested by the community » Needs work
Issue tags: +Needs tests

Somewhere along the way we lost the test coverage the patch used to have.

As it's a testing infrastructure improvement, let's call this a task instead of a feature. Not sure it's major though.

Version: 8.0.x-dev » 8.1.x-dev

Drupal 8.0.6 was released on April 6 and is the final bugfix release for the Drupal 8.0.x series. Drupal 8.0.x will not receive any further development aside from security fixes. Drupal 8.1.0-rc1 is now available and sites should prepare to update to 8.1.0.

Bug reports should be targeted against the 8.1.x-dev branch from now on, and new development or disruptive changes should be targeted against the 8.2.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

Fabianx’s picture

Priority: Normal » Major
Issue tags: +Needs backport to D7, +Favorite of Fabianx

Back to major as this has an important impact for testing. (e.g. we see regressions easier)

Version: 8.1.x-dev » 8.2.x-dev

Drupal 8.1.9 was released on September 7 and is the final bugfix release for the Drupal 8.1.x series. Drupal 8.1.x will not receive any further development aside from security fixes. Drupal 8.2.0-rc1 is now available and sites should prepare to upgrade to 8.2.0.

Bug reports should be targeted against the 8.2.x-dev branch from now on, and new development or disruptive changes should be targeted against the 8.3.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

Mixologic’s picture

Status: Needs work » Needs review

I retested this against 8.3.x, and it still passes

The testbots cost real money, and we cant start saving that if we don't have any data about what tests cost us in terms of time.

I'd like to see this go in so that we can start measuring how much time the testbots actually take to run individual tests.

So, regarding #42, yes, there used to be test coverage, but the patch used to do more than it does now.

Just so I understand the kinds of test coverage we're looking for here, are we looking to make sure that other changes do not inadvertently break the behavior we're introducing?

dawehner’s picture

Status: Needs review » Needs work

We still don't have the tests ...

jhedstrom’s picture

Looks like the test got removed right after I removed the 'needs tests' tag in #16. Here's the test from #6 back.

Fabianx’s picture

Status: Needs review » Reviewed & tested by the community

RTBC - Not sure how / if that works with BrowserTestBase though.

dawehner’s picture

Yeah, IMHO its bad that this patch doesn't yet support BrowserTestBase.

xjm’s picture

Let's add a followup to support BTB and make sure we do that in time to convert the tests?

Right now it's only a small % that will be missing info, but it will be a much bigger number next minor.

xjm’s picture

Or should we make the timer part of run-tests instead? Or?

xjm’s picture

Status: Reviewed & tested by the community » Needs review

NR I guess. I'm okay with committing this as-is and having a followup, but if it turns out simpletest itself is not the right place to implement this in the modern architecture, or if it needs to be decoupled somehow, then we'd have to deal with BC and redo things possibly. So seems good to check whether an alternate approach makes sense now (versus 2011/12/13 when we started working on this).

Mixologic’s picture

There are better ways to solve this for sure, but, it gets a little complicated.

From a reporting perspective, the place where we need to put the timing data is in the Junit XML formatted output that drupalCI creates out of the simpletest database table.

Adding a Debug assertion to the testing database as a 'Duration' was an expedient hack to get timing data into somewhere that drupalci can consume it, but it definitely predates BrowserTestBase and skips UnitTestBase too, and isn't ideal.

So, a more proper approach to add timing data would be to add a column for duration to the simpletest database table.

All of the phpunit xml files already have timing data on them, we just happen to ignore those metrics when we convert them from xml to simpletest 'rows' : http://cgit.drupalcode.org/drupal/tree/core/modules/simpletest/simpletes...

An example phpunit xml looks like so:

<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
  <testsuite name="Drupal\Tests\views\FunctionalJavascript\GlossaryViewTest" file="/var/www/html/core/modules/views/tests/src/FunctionalJavascript/GlossaryViewTest.php" tests="2" assertions="16" failures="0" errors="0" time="22.769749">
    <testcase name="testGlossaryDefault" class="Drupal\Tests\views\FunctionalJavascript\GlossaryViewTest" file="/var/www/html/core/modules/views/tests/src/FunctionalJavascript/GlossaryViewTest.php" line="79" assertions="8" time="11.278871"/>
    <testcase name="testGlossaryLanguagePrefix" class="Drupal\Tests\views\FunctionalJavascript\GlossaryViewTest" file="/var/www/html/core/modules/views/tests/src/FunctionalJavascript/GlossaryViewTest.php" line="101" assertions="8" time="11.490878"/>
  </testsuite>
</testsuites>

So we could would also modify simpletest_phpunit_testcase_to_row to provide the testcase timing data, and the simpletest database would have the duration data for all tests.

Where this gets tricky is that we have a discrepancy in the data model between what is a "row" in the simpletest database.

PhpUnit tracks test methods, and only counts the assertions for each method, and only provides the failure and error counts at the class level.

Simpletest tracks a row in the database for each assertion, and the insert it happening at 'assert' time, so its difficult to get the higher level test method timing.

And adding *just* the assertion timing would be difficult as well because assert is called from so many other types of functions, it'd be difficult to wrap, and it really wouldnt tell us how long the actual test took, just how long the asserts took, which is likely negligible.

So I think the best path forward is a combination of the two:

1. We keep the Duration debug messages in for simpletest tests.
2. We modify the database columns, add duration, and make sure we capture the phpunit durations.
3. We modify drupalCI to watch for both duration types, and output it into its Junit Xml.
4. Once we've got everything converted to phpunit, we can get rid of junit xml processing on drupalci, and just push the phpunit xml output directly to jenkins.

Thoughts?

Version: 8.2.x-dev » 8.3.x-dev

Drupal 8.2.6 was released on February 1, 2017 and is the final full bugfix release for the Drupal 8.2.x series. Drupal 8.2.x will not receive any further development aside from critical and security fixes. Sites should prepare to update to 8.3.0 on April 5, 2017. (Drupal 8.3.0-alpha1 is available for testing.)

Bug reports should be targeted against the 8.3.x-dev branch from now on, and new development or disruptive changes should be targeted against the 8.4.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

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

Drupal 8.3.6 was released on August 2, 2017 and is the final full bugfix release for the Drupal 8.3.x series. Drupal 8.3.x will not receive any further development aside from critical and security fixes. Sites should prepare to update to 8.4.0 on October 4, 2017. (Drupal 8.4.0-alpha1 is available for testing.)

Bug reports should be targeted against the 8.4.x-dev branch from now on, and new development or disruptive changes should 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.

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

Drupal 8.4.4 was released on January 3, 2018 and is the final full bugfix release for the Drupal 8.4.x series. Drupal 8.4.x will not receive any further development aside from critical and security fixes. Sites should prepare to update to 8.5.0 on March 7, 2018. (Drupal 8.5.0-alpha1 is available for testing.)

Bug reports should be targeted against the 8.5.x-dev branch from now on, and new development or disruptive changes should 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.

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

Drupal 8.5.6 was released on August 1, 2018 and is the final bugfix release for the Drupal 8.5.x series. Drupal 8.5.x will not receive any further development aside from security fixes. Sites should prepare to update to 8.6.0 on September 5, 2018. (Drupal 8.6.0-rc1 is available for testing.)

Bug reports should be targeted against the 8.6.x-dev branch from now on, and new development or disruptive changes should be targeted against the 8.7.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

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

Drupal 8.6.x will not receive any further development aside from security fixes. Bug reports should be targeted against the 8.8.x-dev branch from now on, and new development or disruptive changes should be targeted against the 8.9.x-dev branch. For more information see the Drupal 8 and 9 minor version schedule and the Allowed changes during the Drupal 8 and 9 release cycles.

Version: 8.8.x-dev » 8.9.x-dev

Drupal 8.8.7 was released on June 3, 2020 and is the final full bugfix release for the Drupal 8.8.x series. Drupal 8.8.x will not receive any further development aside from security fixes. Sites should prepare to update to Drupal 8.9.0 or Drupal 9.0.0 for ongoing support.

Bug reports should be targeted against the 8.9.x-dev branch from now on, and new development or disruptive changes should be targeted against the 9.1.x-dev branch. For more information see the Drupal 8 and 9 minor version schedule and the Allowed changes during the Drupal 8 and 9 release cycles.

quietone’s picture

Project: Drupal core » SimpleTest
Version: 8.9.x-dev » 8.x-3.x-dev
Component: simpletest.module » Code

Triaging issues in simpletest.module to determine if they should be in the Simpletest Project or core.

This look like it belongs in the Simpletest project.