Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Problem with "Skipped" #1304

Closed
ingowalther opened this issue Aug 20, 2020 · 33 comments · Fixed by #1310
Closed

Problem with "Skipped" #1304

ingowalther opened this issue Aug 20, 2020 · 33 comments · Fixed by #1310

Comments

@ingowalther
Copy link

ingowalther commented Aug 20, 2020

Question Answer
Infection version 0.17.2@31e4af4be7e7508bed086d8254f010a56ff79bea
Test Framework version 9.2.6
PHP version 7.4.3
Platform Ubuntu
Github Repo -

In version 0.16.4 most mutations do not run in timeouts. However, after updating to version 0.17.2, some of these mutants will be "skipped".

I also checked that the mutants with "skipped" are not generated by the new "instanceof" mutator.

I don't understand exactly why this happens? Is this a bug or intentional behavior?

Output Infection 0.17.2:

    ____      ____          __  _
   /  _/___  / __/__  _____/ /_(_)___  ____
   / // __ \/ /_/ _ \/ ___/ __/ / __ \/ __ \
 _/ // / / / __/  __/ /__/ /_/ / /_/ / / / /
/___/_/ /_/_/  \___/\___/\__/_/\____/_/ /_/

Infection - PHP Mutation Testing Framework version 0.17.2@31e4af4be7e7508bed086d8254f010a56ff79bea

[notice] You are running Infection with PCOV enabled.
#!/usr/bin/env php

Running initial test suite...

PHPUnit version: 9.2.6

 1739 [============================] 21 secs

Generate mutants...

Processing source code files: 943/943
.: killed, M: escaped, U: uncovered, E: fatal error, T: timed out, S: skipped

..................................................   (  50 / 4095)
...............S..................................   ( 100 / 4095)
<skip>
..................................................   (4050 / 4095)
.............................................        (4095 / 4095)

4095 mutations were generated:
    4055 mutants were killed
       0 mutants were not covered by tests
       0 covered mutants were not detected
       0 errors were encountered
       2 time outs were encountered
      38 mutants required more time than configured

Metrics:
         Mutation Score Indicator (MSI): 100%
         Mutation Code Coverage: 100%
         Covered Code MSI: 100%

Please note that some mutants will inevitably be harmless (i.e. false positives).

Time: 12m 58s. Memory: 0.15GB

Output Infection 0.16.4:

You are running Infection with PCOV enabled.

    ____      ____          __  _
   /  _/___  / __/__  _____/ /_(_)___  ____
   / // __ \/ /_/ _ \/ ___/ __/ / __ \/ __ \
 _/ // / / / __/  __/ /__/ /_/ / /_/ / / / /
/___/_/ /_/_/  \___/\___/\__/_/\____/_/ /_/

Infection - PHP Mutation Testing Framework 0.16.4@c1ef0b16b3e8d171f10ba8bfe8b6c93d482a68b4
#!/usr/bin/env php

Running initial test suite...

PHPUnit version: 9.2.6

 1741 [============================] 22 secs

Generate mutants...

Processing source code files: 943/943
.: killed, M: escaped, S: uncovered, E: fatal error, T: timed out

..................................................   (  50 / 3950)
..................E...............................   ( 100 / 3950)
<skip>
..................................................   (3900 / 3950)
..................................................   (3950 / 3950)

3950 mutations were generated:
    3947 mutants were killed
       0 mutants were not covered by tests
       0 covered mutants were not detected
       1 errors were encountered
       2 time outs were encountered

Metrics:
         Mutation Score Indicator (MSI): 100%
         Mutation Code Coverage: 100%
         Covered Code MSI: 100%

Please note that some mutants will inevitably be harmless (i.e. false positives).

Time: 12m 8s. Memory: 136.01MB
@ingowalther
Copy link
Author

Maybe @sanmai can help here?

@sanmai
Copy link
Member

sanmai commented Aug 20, 2020

You need to raise the timeout if you want Infection to run these mutations. Mutations do run in timeouts still, but since we filter out know predictable timeouts (which do not affect the score), you shall only see actual timeouts, e.g. mutations that cause your program to run endlessly or excessively long.

Quoting from https://infection.github.io/2020/08/18/whats-new-in-0.17.0/

In addition to code coverage reports, Infection collects execution time report, thus Infection can execute the fastest tests first. Consider that for a given line you may have several tests taking a certain amount of time, say, 20 seconds. If you happen to have a timeout of 15 seconds configured, earlier Infection would have tried to run these tests anyway, even if we can tell beforehand that they will result in a timeout, exhausting allotted time.

With this version, Infection would try to skip these over-time-budged mutations. This change considerably speeds up mutation testing for projects with incoherent test coverage, while still letting to reap the benefits of mutation testing where it is possible.

For example, if one has a 15-second long integration test, setting a time limit to 10 seconds will effectively exclude all mutations covered by the test. Now one has a choice of either raising the timeout or tagging this test with a @coversNothing annotation.

@ingowalther
Copy link
Author

Hello @sanmai,

thx for your fast respone.

But I don't understand why mutants which did not cause a timeout in version 0.16.4 should cause a timeout in version 0.17.2?

@sanmai
Copy link
Member

sanmai commented Aug 20, 2020

There were some new mutations added, note you have 3950 mutations in the older version, and 4095 mutations in the newer. They might be hitting some over-covered code. It is hard to tell precisely without looking at the code.

Try increasing the timeout still (it's in infection.json.dist). Say, if you raise it tenfold, will these mutations become actual timeouts?

Or you can find these mutations on the log to figure out which lines they are hitting. Is there an increasingly long integration test?.. Tagging it as @coversNothing might help.

@ingowalther
Copy link
Author

ingowalther commented Aug 20, 2020

I had checked that the skipped mutations were not triggered by a new mutator.

I had already set the timeout to 300 and none of these mutations went into a timeout - but the mutations were no longer skipped.
But increasing the timeout this way is not very convenient for cases with real timeouts.

For infection only small unit tests and no long running integration tests are used in my setup.

@sanmai
Copy link
Member

sanmai commented Aug 20, 2020

If I can have a look at your project, we may figure something out. What do you think?

It doesn't have to be all open source for all I care, but if it is it'll make all things easier.

@ingowalther
Copy link
Author

Since this is a customer project, I can unfortunately not give you access to the project. I understand that it is so naturally difficult to reproduce the behaviour. I will try to create a minimal test case to reproduce the behaviour.

@sanmai
Copy link
Member

sanmai commented Aug 20, 2020

Sure. You can add debugging output right about here. At very least you could find out at what timeout you should be aiming at.

@DaveLiddament
Copy link

DaveLiddament commented Aug 24, 2020

I might be having a similar problem....

My project's complete test suite runs in 5 seconds (see output below using this commit).

I believe the infection timeout is defaulted to 10 seconds. If I understand this functionality correctly then surely no test takes more than 10 seconds to run, and therefore none should be marked as skipped?

Output:


    ____      ____          __  _
   /  _/___  / __/__  _____/ /_(_)___  ____
   / // __ \/ /_/ _ \/ ___/ __/ / __ \/ __ \
 _/ // / / / __/  __/ /__/ /_/ / /_/ / / / /
/___/_/ /_/_/  \___/\___/\__/_/\____/_/ /_/

Infection - PHP Mutation Testing Framework version 0.17.2@31e4af4be7e7508bed086d8254f010a56ff79bea


Running initial test suite...

PHPUnit version: 7.5.20

  243 [============================] 5 secs

Generate mutants...

Processing source code files: 108/108
.: killed, M: escaped, U: uncovered, E: fatal error, T: timed out, S: skipped

SM...S..SS.SSSSS.S..SSSSSS...S..MMS.SSSMS.....S.S.   ( 50 / 589)
S.MS.SS.S.S...M.SS.S...S.SSS.M.............M.S.SSM   (100 / 589)
SM..SSS...........SSSS...........................S   (150 / 589)
.S......S.SSMM.S...S...S...SS..S....S.....M..MMM..   (200 / 589)
......S.....M.M.SSSS.SSSSSSSSSSS..M.S.MSSSM..S....   (250 / 589)
S..S......S....S..M..........S....S..M.S.S.S...SSS   (300 / 589)
SUSSUSSUS..M..USM......M...M...M.SSSSSSSSSSUSSSSSS   (350 / 589)
SS...M...S..MMS..MMSSSSSSSS......SSSSSSSSSSSSSSSSS   (400 / 589)
SSSSSSSSSSSSSSS..SSSS..SSSS.S..S...MM....MS..S.S..   (450 / 589)
....S.T.SSS..M....T.M...ST.S.......S.SSSSSS.M.....   (500 / 589)
.M..........MMMM.....MMMM.......MMM....M...M...MMM   (550 / 589)
.M..M....MMM.......M..MMMM......MMMMS..              (589 / 589)

589 mutations were generated:
     324 mutants were killed
       5 mutants were not covered by tests
      70 covered mutants were not detected
       0 errors were encountered
       3 time outs were encountered
     187 mutants required more time than configured

Metrics:
         Mutation Score Indicator (MSI): 81%
         Mutation Code Coverage: 98%
         Covered Code MSI: 82%

Please note that some mutants will inevitably be harmless (i.e. false positives).

Time: 1m 5s. Memory: 0.04GB

Increasing timeout to 90 seconds does decrease the number of mutants marked as skipped. My best guess is that this functionality is working but the timing is wrong.

@DaveLiddament
Copy link

OK, does this recreate the problem: https://infection-php.dev/r/608

Assuming playground has a timeout of 10s. This test should only run 5s. So no reason for any to be skipped?

sanmai added a commit to sanmai/infection that referenced this issue Aug 24, 2020
@helpr helpr bot added the Has PR label Aug 24, 2020
@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

Thank you for the demo. There's indeed something fishy here.

@DaveLiddament
Copy link

@sanmai I was looking at PR that added functionality, but can't see issue. I added this comment: #1171 (comment) assuming it's a timing issue then adding in VO for time intervals would help find issues sooner.

@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

This issue might have been here for a long time. There isn't a problem in #1171 per se, but rather there are some broken assumptions down the call stack.

Can you see if #1310 improves the situation for you?

@ingowalther you're welcome to try the new workaround too.

sanmai added a commit to sanmai/infection that referenced this issue Aug 24, 2020
TestLocator returns non-unique tests, and JUnitTestCaseSorter works around that; we have to do that too.
sanmai added a commit to sanmai/infection that referenced this issue Aug 24, 2020
Fixes infection#1304

TestLocator returns non-unique tests, and JUnitTestCaseSorter works around that; we have to do that too.
@DaveLiddament
Copy link

@sanmai Can I check my assumption here....

I am assuming that timeout > total test execution time (as reported by infection) then there should be 0 mutants marked as S?

E.g.


Running initial test suite...

PHPUnit version: 7.5.20

  252 [============================] 6 secsProcessing source code files:   0/108

Generate mutants...

Having a timeout of >7 would produce 0 skipped mutants?

If my assumption is correct then this PR does not appear to have fixed the issue.

@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

Do you say that you still have this issue even with #1310?

@ingowalther
Copy link
Author

For my testsuite I can confirm that this pull-request eliminates the unwanted "skipped" cases.

@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

@DaveLiddament for SARB with #1310 I'm getting the following report with 0 skipped for timeout of 5 seconds:

728 mutations were generated:
     597 mutants were killed
      58 mutants were not covered by tests
      70 covered mutants were not detected
       0 errors were encountered
       3 time outs were encountered
       0 mutants required more time than configured

I wonder if you can confirm this. Should I use a shorter timeout value?

@DaveLiddament
Copy link

DaveLiddament commented Aug 24, 2020

@sanmai

@DaveLiddament for SARB with #1310 I'm getting the following report with 0 skipped for timeout of 5 seconds:

Great. Looks like you've solved it. Thanks for getting this fixed.

I can't recreate your results locally (I'm still getting skipped mutants). As it works for you and the originally bug submitter this must be me not setting up something correctly.

Can you see anything I'm obviously doing wrong? If not just put this down to user error on my part....

PHP version

php -v
PHP 7.4.9 (cli) (built: Aug  7 2020 14:56:37) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
    with Zend OPcache v7.4.9, Copyright (c), by Zend Technologies
    with Xdebug v2.9.6, Copyright (c) 2002-2020, by Derick Rethans

Infection output

vagrant@sarb74:~/sarb$ ../infection/bin/infection

    ____      ____          __  _
   /  _/___  / __/__  _____/ /_(_)___  ____
   / // __ \/ /_/ _ \/ ___/ __/ / __ \/ __ \
 _/ // / / / __/  __/ /__/ /_/ / /_/ / / / /
/___/_/ /_/_/  \___/\___/\__/_/\____/_/ /_/

Infection - PHP Mutation Testing Framework version not-installed


Running initial test suite...

PHPUnit version: 7.5.20

  250 [============================] 6 secs

Generate mutants...

Processing source code files: 108/108
.: killed, M: escaped, U: uncovered, E: fatal error, T: timed out, S: skipped

M.................................................   ( 50 / 589)
.M............M...M......MM................M..M.M.   (100 / 589)
..................................................   (150 / 589)
.........M.M..............................M..MMM..   (200 / 589)
............M.M...................M..M.M..........   (250 / 589)
..................M..................M.........SSS   (300 / 589)
.U.SUSSUS..M..UM.......M...M...M..SSSS.SSSSUSSSSSS   (350 / 589)
SS...M...S..MMS..MMSSSSS.........SSSSSSSSSSSSSSSSS   (400 / 589)
SSSSSSSSSSSSSSS..SSSS..SSSS.S......MM....M........   (450 / 589)
.....T.......M....T.M...T.............M...........   (500 / 589)
.M..........MMMM.....MMMM.......MMM....M...M...MMM   (550 / 589)
.M..M....MMM.......M..MMMM......MMMM...              (589 / 589)

589 mutations were generated:
     441 mutants were killed
       5 mutants were not covered by tests
      69 covered mutants were not detected
       0 errors were encountered
       3 time outs were encountered
      71 mutants required more time than configured

Metrics:
         Mutation Score Indicator (MSI): 85%
         Mutation Code Coverage: 99%
         Covered Code MSI: 86%

Please note that some mutants will inevitably be harmless (i.e. false positives).

Time: 1m 11s. Memory: 0.04GB

Config:

cat infection.json.dist 
{
    "source": {
        "directories": [
            "src"
        ]
    },
    "logs": {
        "text": "infection.log"
    },
    "mutators": {
        "@default": true
    }
}

Git sha of infection:

vagrant@sarb74:~/sarb$ cd ../infection/
vagrant@sarb74:~/infection$ git log -n1
commit 5805de372de36236814a14204c4b3d2647c028d6
Author: Alexey Kopytko <alexey@kopytko.com>
Date:   Mon Aug 24 22:52:42 2020 +0900

    Extend test case to include summation

@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

Try rm -fr vendor/infection in your project. You might be using old files.

Or, even better, do make compile and then, from your project's root, run ../infection/build/infection.phar

(With infection.phar -j4 --no-progress I'm getting 35 seconds for a full run)

@DaveLiddament
Copy link

I've created a new VM. Built a PHAR for infection and run it...

If I leave default timeout of 10s, then I still get mutants marked as S.
If I up timeout to 20s then I get no mutants marked as skipped.

So yes, your fix has made it work.

That said I still don't understand why the timeout needs to be so high. If the entire test suite runs in 6 seconds (as reported by infection and I've independently timed it as well), then why does a timeout of 10 still mean mutants are skipped?
If I've understood the release notes, a timeout value that is greater than the test execution time should mean no mutants are marked as skipped.

@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

a timeout value that is greater than the test execution time should mean no mutants are marked as skipped

This is how it should be, but you're correct it is not yet so. Still looking into this.

I think this should output the full time needed to run all tests:

phpdbg -qrr vendor/bin/phpunit --log-junit=junit.xml
grep testcase junit.xml  | grep -o time=.* | cut -f2 -d'"' | paste -sd+ | bc

So timeout of 1 second should work, but it does not.

@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

Infection tells me that these tests took this much:

  ["EndToEndTest::testHappyPath"]=>float(0.617619)
  ["EndToEndTest::testInvalidBaselineSupplied"]=>float(0.617619)

Although looking at JUnit report I do not see exactly these numbers (grep testHappyPath junit.xml).

It appears these lines have something to do with these slightly inflated times.

What I can say that we've dealt with the blown-up-out-of-proportion numbers, and what we have here is a slightly different issue.

@sanmai
Copy link
Member

sanmai commented Aug 24, 2020

@DaveLiddament Could you try with the latest from #1310?

So far I'm getting 0 skipped with timeout of 1 second.

@DaveLiddament
Copy link

@sanmai yes that works!

Fantastic work, both on this new feature and getting this fix in. Thanks very much for all you effort today.

@ingowalther
Copy link
Author

Yeah! Thanks for your work @sanmai!

maks-rafalko pushed a commit that referenced this issue Aug 25, 2020
…1310)

* TestLocator returns non-unique tests, but Mutation didn't know that

Fixes #1304

TestLocator returns non-unique tests, and JUnitTestCaseSorter works around that; we have to do that too.

* Extend test case to include summation

* Timings are per test suite, not per test, therefore we have to unique by test suite name

* Fix PHPStan warning

* Extract adding logic into JUnitTestCaseTimeAdder
@helpr helpr bot added PR merged and removed Has PR labels Aug 25, 2020
sanmai added a commit to sanmai/infection that referenced this issue Aug 25, 2020
…nfection#1310)

* TestLocator returns non-unique tests, but Mutation didn't know that

Fixes infection#1304

TestLocator returns non-unique tests, and JUnitTestCaseSorter works around that; we have to do that too.

* Extend test case to include summation

* Timings are per test suite, not per test, therefore we have to unique by test suite name

* Fix PHPStan warning

* Extract adding logic into JUnitTestCaseTimeAdder
@maks-rafalko
Copy link
Member

Thank you guys for providing examples, especially nice to see Playground example ;)

Thank you @sanmai for such a quick fix.

Released: https://github.com/infection/infection/releases/tag/0.17.3

maks-rafalko pushed a commit that referenced this issue Aug 25, 2020
…1310)

* TestLocator returns non-unique tests, but Mutation didn't know that

Fixes #1304

TestLocator returns non-unique tests, and JUnitTestCaseSorter works around that; we have to do that too.

* Extend test case to include summation

* Timings are per test suite, not per test, therefore we have to unique by test suite name

* Fix PHPStan warning

* Extract adding logic into JUnitTestCaseTimeAdder
@ingowalther
Copy link
Author

Thanks @maks-rafalko!
Will there be a phar Release?

@maks-rafalko
Copy link
Member

Sure, it's automatically deployed after successful build for tags, so give it some time please

@ingowalther
Copy link
Author

I didn't mean to push, I just didn't know how the process worked. Thanks for the explanation.

Thanks for the great work on Infection! I wish you a nice day

@sanmai
Copy link
Member

sanmai commented Aug 25, 2020

@ingowalther should be there.

@duncan3dc
Copy link
Contributor

duncan3dc commented Nov 8, 2020

Hi everyone, I think I'm experiencing the same issue (or a very similar one).
Rather than provide a new reproduction case, I think the existing one from this issue is still exhibiting the problem in the playground:
https://infection-php.dev/r/5z0

@maks-rafalko
Copy link
Member

maks-rafalko commented Nov 8, 2020

Well, in the playground, there is a "timeout": 3 setting configured, that is hidden from the user in UI

It's clearly visible in this example: https://infection-php.dev/r/4yv

When I set timeout to 1, there are no Skipped mutants: https://infection-php.dev/r/6yg

Are you sure you experiencing the very same issue with timeout properly set? Do you have any example?

@duncan3dc
Copy link
Contributor

Ah ok, let me work on small reproduction case then

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants