Early Bird Registration for DrupalCon Portland 2024 is open! Register by 23:59 PST on 31 March 2024, to get $100 off your ticket.
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
Comment | File | Size | Author |
---|---|---|---|
#48 | 1205162-47.patch | 2.54 KB | jhedstrom |
Comments
Comment #1
rfayWe 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?
Comment #2
jthorson CreditAttribution: jthorson commentedThis 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).
Comment #3
janip CreditAttribution: janip commentedPlease 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).
Comment #4
xjmAwesome! 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:
(Not sure if that's desirable or not.)
Couple minor cleanups to add:
These should have periods at the end of the comment.
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!
Comment #5
janip CreditAttribution: janip commentedMinor cleanups (added periods and a documentation block).
Comment #6
janip CreditAttribution: janip commentedSome test coverage (asserting that the duration assert is persisted and that the duration is numeric).
Comment #7
xjm@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.)
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
Comment #8
BerdirThis 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
Comment #9
kerasai CreditAttribution: kerasai commented#6: simpletest_test_duration_for_individual_tests-1205162-6.patch queued for re-testing.
Comment #11
deekayen CreditAttribution: deekayen commentedSince #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.
Comment #12
deekayen CreditAttribution: deekayen commentedRe: #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.
Comment #13
xjm11: simpletest_test_duration_for_individual_tests-1205162-11.patch queued for re-testing.
Comment #15
jhedstromThe patch here has tests, removing tag.
Comment #16
MixologicNot 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.
Comment #17
MixologicI always forget to do this.
Comment #19
dawehnerOh nice! This just lead to a gigantic flashback, see #329407: Make simpletest report running time
Comment #20
MixologicFixes the test, and changes it to milliseconds because junit thinks on that level.
Comment #21
MixologicI fail at counting. Thats why I let computers do it for me.
Comment #22
MixologicWhen 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.
Comment #24
MixologicAaand its midnight.
Comment #25
MixologicI 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.
Comment #26
pwolanin CreditAttribution: pwolanin as a volunteer and at Acquia commentedLooks good, but maybe use
microtime(TRUE);
for tests that take less than a second?Comment #27
Mixologicupdated to use microtime, but to round it to milliseconds.
Comment #28
MixologicAlso, the test results look better now that we've got subsecond responses properly accounted for:
https://dispatcher.drupalci.org/job/DCI_XML/137/testReport/
Comment #29
pwolanin CreditAttribution: pwolanin as a volunteer and at Acquia commentedThis would be a useful addition, let's get it in.
Comment #32
dawehnerThis has been RTBC before.
Comment #33
tim.plunkett+1! This would be great.
Comment #34
YesCT CreditAttribution: YesCT commentedComment #35
MixologicSince 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....
Comment #36
jhedstromI 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.Comment #37
MixologicIt would add one per "test", minus the phpunit tests, so 14324 - 8826 = 5498 additional duration messages for a complete simpletest run.
Comment #39
MixologicSigh. I wonder why that test failed? Is that a testbot problem? I should probably report that to the testbot maintainers.
Comment #40
MixologicComment #41
Mixologicmoving back to rtbc. Needs work was an erroneous testbot issue.
Comment #42
xjmSomewhere 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.
Comment #44
Fabianx CreditAttribution: Fabianx as a volunteer and at Tag1 Consulting commentedBack to major as this has an important impact for testing. (e.g. we see regressions easier)
Comment #46
MixologicI 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?
Comment #47
dawehnerWe still don't have the tests ...
Comment #48
jhedstromLooks like the test got removed right after I removed the 'needs tests' tag in #16. Here's the test from #6 back.
Comment #49
Fabianx CreditAttribution: Fabianx as a volunteer and at Tag1 Consulting commentedRTBC - Not sure how / if that works with BrowserTestBase though.
Comment #50
dawehnerYeah, IMHO its bad that this patch doesn't yet support BrowserTestBase.
Comment #51
xjmLet'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.
Comment #52
xjmOr should we make the timer part of
run-tests
instead? Or?Comment #53
xjmNR 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).
Comment #54
MixologicThere 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:
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?
Comment #61
quietone CreditAttribution: quietone as a volunteer commentedTriaging 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.