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

xwiki-platform-store-filesystem-oldcore is flickering #127

Open
vmassol opened this issue Apr 9, 2020 · 16 comments
Open

xwiki-platform-store-filesystem-oldcore is flickering #127

vmassol opened this issue Apr 9, 2020 · 16 comments

Comments

@vmassol
Copy link
Contributor

vmassol commented Apr 9, 2020

See #62 for the context.

org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal org.pitest:pitest-maven:1.4.10:mutationCoverage (pitest-check) on project xwiki-platform-store-filesystem-oldcore: Mutation score of 35 is below threshold of 36

(happened at https://ci.xwiki.org/job/xwiki-platform_pitest/626/console)

@oscarlvp you asked for the pitest report but I don't have access to it when a pitest execution flickers since it happes on the CI and usually I can't reproduce locally. Also since we run job in transient docker containers, I don't have the target directory output, it's discarded. To get it, we would need to modify our generic pipeline code to save it somehow.

Tried to reproduce locally and couldn't with mvn clean install -Pquality -Dxwiki.pitest.skip=false.

@oscarlvp
Copy link
Member

oscarlvp commented Apr 9, 2020

PIT's log on that module for failing build

https://ci.xwiki.org/job/xwiki-platform_pitest/626/consoleFull

[INFO] --- pitest-maven:1.4.10:mutationCoverage (pitest-check) @ xwiki-platform-store-filesystem-oldcore ---
[INFO] Found plugin : Default csv report plugin
[INFO] Found plugin : Default xml report plugin
[INFO] Found plugin : JSON report plugin
[INFO] Found plugin : Pseudo and partially-tested methods JSON report
[INFO] Found plugin : Pseudo and partially-tested methods HTML report
[INFO] Found plugin : Default html report plugin
[INFO] Found plugin : Static initializer code detector plugin
[INFO] Found plugin : Static initializer filter plugin
[INFO] Found plugin : Excluded annotations plugin
[INFO] Found plugin : Inlined finally block filter plugin
[INFO] Found plugin : Try with resources filter
[INFO] Found plugin : Implicit null check filter
[INFO] Found plugin : Method reference null check filter
[INFO] Found plugin : For each loop filter
[INFO] Found plugin : Logging calls filter
[INFO] Found plugin : Infinite for loop filter
[INFO] Found plugin : Long running iterator loop filter
[INFO] Found plugin : For loop counter filter
[INFO] Found plugin : Kotlin junk mutations filter
[INFO] Found plugin : Max mutations per class limit
[INFO] Found plugin : Equals shortcut equivalent mutant filter
[INFO] Found plugin : Trivial return vals equivalence filter
[INFO] Found plugin : Mutant export plugin
[INFO] Found plugin : Stop methods filter
[INFO] Found plugin : Avoids null mutation in non-nullable methods, as marked by the Kortlin compiler
[INFO] Found shared classpath plugin : Default mutation engine
[INFO] Found shared classpath plugin : Extreme mutation engine
[INFO] Found shared classpath plugin : JUnit plugin
[INFO] Found shared classpath plugin : TestNG plugin
[INFO] Found shared classpath plugin : JUnit 5 test framework support
[INFO] Adding org.pitest:pitest to SUT classpath
[INFO] Adding org.pitest:pitest-junit5-plugin to SUT classpath
[INFO] Adding eu.stamp-project:descartes to SUT classpath
[INFO] Mutating from /root/workspace/xwiki-platform_pitest/xwiki-platform-core/xwiki-platform-store/xwiki-platform-store-filesystem-oldcore/target/classes
[INFO] Defaulting target classes to match packages in build directory
4:16:33 PM PIT >> INFO : Verbose logging is disabled. If you encounter a problem, please enable it before reporting an issue.
4:16:33 PM PIT >> INFO : Sending 60 test classes to minion
4:16:33 PM PIT >> INFO : Sent tests to minion
4:16:33 PM PIT >> INFO : MINION : 4:16:33 PM PIT >> INFO : Checking environment

4:16:34 PM PIT >> INFO : MINION : 4:16:34 PM PIT >> INFO : Found  28 tests

4:16:34 PM PIT >> INFO : MINION : 4:16:34 PM PIT >> INFO : Dependency analysis reduced number of potential tests by 0

4:16:34 PM PIT >> INFO : MINION : 4:16:34 PM PIT >> INFO : 28 tests received

�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|4:16:37 PM PIT >> INFO : Calculated coverage in 3 seconds.
4:16:37 PM PIT >> INFO : Created  39 mutation test units
4:16:42 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:16:48 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:16:49 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:16:53 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:16:54 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�/�-�\4:16:58 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:16:59 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:16:59 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:04 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:05 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:06 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:06 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:11 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:12 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:13 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:18 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
4:17:19 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\4:17:20 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�|�/�-4:17:24 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�\4:17:25 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�|�/�-�\4:17:26 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�|�/�-�\4:17:29 PM PIT >> INFO : Completed in 55 seconds
================================================================================
- Mutators
================================================================================
> ""
>> Generated 4 Killed 1 (25%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 3 
--------------------------------------------------------------------------------
> void
>> Generated 52 Killed 15 (29%)
> KILLED 7 SURVIVED 3 TIMED_OUT 8 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 34 
--------------------------------------------------------------------------------
> "A"
>> Generated 4 Killed 1 (25%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 3 
--------------------------------------------------------------------------------
> null
>> Generated 59 Killed 24 (41%)
> KILLED 15 SURVIVED 0 TIMED_OUT 9 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 35 
--------------------------------------------------------------------------------
> false
>> Generated 7 Killed 2 (29%)
> KILLED 2 SURVIVED 0 TIMED_OUT 0 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 5 
--------------------------------------------------------------------------------
> true
>> Generated 7 Killed 2 (29%)
> KILLED 2 SURVIVED 0 TIMED_OUT 0 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 5 
--------------------------------------------------------------------------------
> 1L
>> Generated 1 Killed 1 (100%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 0 
--------------------------------------------------------------------------------
> 0L
>> Generated 1 Killed 1 (100%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 0 
--------------------------------------------------------------------------------
================================================================================
- Timings
================================================================================
> scan classpath : < 1 second
> coverage and dependency analysis : 3 seconds
> build mutation tests : < 1 second
> run mutation analysis : 52 seconds
--------------------------------------------------------------------------------
> Total  : 55 seconds
--------------------------------------------------------------------------------
================================================================================
- Statistics
================================================================================
>> Generated 135 mutations Killed 47 (35%)
>> Ran 46 tests (0.34 tests per mutation)

@oscarlvp
Copy link
Member

oscarlvp commented Apr 9, 2020

PIT's log for the previous successful build on the same module.

https://ci.xwiki.org/job/xwiki-platform_pitest/625/consoleFull

[INFO] --- pitest-maven:1.4.10:mutationCoverage (pitest-check) @ xwiki-platform-store-filesystem-oldcore ---
[INFO] Found plugin : Default csv report plugin
[INFO] Found plugin : Default xml report plugin
[INFO] Found plugin : JSON report plugin
[INFO] Found plugin : Pseudo and partially-tested methods JSON report
[INFO] Found plugin : Pseudo and partially-tested methods HTML report
[INFO] Found plugin : Default html report plugin
[INFO] Found plugin : Static initializer code detector plugin
[INFO] Found plugin : Static initializer filter plugin
[INFO] Found plugin : Excluded annotations plugin
[INFO] Found plugin : Inlined finally block filter plugin
[INFO] Found plugin : Try with resources filter
[INFO] Found plugin : Implicit null check filter
[INFO] Found plugin : Method reference null check filter
[INFO] Found plugin : For each loop filter
[INFO] Found plugin : Logging calls filter
[INFO] Found plugin : Infinite for loop filter
[INFO] Found plugin : Long running iterator loop filter
[INFO] Found plugin : For loop counter filter
[INFO] Found plugin : Kotlin junk mutations filter
[INFO] Found plugin : Max mutations per class limit
[INFO] Found plugin : Equals shortcut equivalent mutant filter
[INFO] Found plugin : Trivial return vals equivalence filter
[INFO] Found plugin : Mutant export plugin
[INFO] Found plugin : Stop methods filter
[INFO] Found plugin : Avoids null mutation in non-nullable methods, as marked by the Kortlin compiler
[INFO] Found shared classpath plugin : Default mutation engine
[INFO] Found shared classpath plugin : Extreme mutation engine
[INFO] Found shared classpath plugin : JUnit plugin
[INFO] Found shared classpath plugin : TestNG plugin
[INFO] Found shared classpath plugin : JUnit 5 test framework support
[INFO] Adding org.pitest:pitest to SUT classpath
[INFO] Adding org.pitest:pitest-junit5-plugin to SUT classpath
[INFO] Adding eu.stamp-project:descartes to SUT classpath
[INFO] Mutating from /root/workspace/xwiki-platform_pitest/xwiki-platform-core/xwiki-platform-store/xwiki-platform-store-filesystem-oldcore/target/classes
[INFO] Defaulting target classes to match packages in build directory
5:02:47 PM PIT >> INFO : Verbose logging is disabled. If you encounter a problem, please enable it before reporting an issue.
5:02:47 PM PIT >> INFO : Sending 60 test classes to minion
5:02:47 PM PIT >> INFO : Sent tests to minion
5:02:47 PM PIT >> INFO : MINION : 5:02:47 PM PIT >> INFO : Checking environment

5:02:48 PM PIT >> INFO : MINION : 5:02:48 PM PIT >> INFO : Found  28 tests

5:02:48 PM PIT >> INFO : MINION : 5:02:48 PM PIT >> INFO : Dependency analysis reduced number of potential tests by 0
5:02:48 PM PIT >> INFO : 28 tests received

�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|�/�-�\�|5:02:53 PM PIT >> INFO : Calculated coverage in 6 seconds.
5:02:53 PM PIT >> INFO : Created  39 mutation test units
5:02:59 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:02:59 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:02:59 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:01 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:05 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:05 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:05 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:07 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:11 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:12 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:12 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:14 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:18 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:18 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:19 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:22 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:25 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:25 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:25 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:31 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:31 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:31 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:32 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:37 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:38 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:38 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:43 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:43 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:43 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:49 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:49 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�/�-�\�|�/�-�\�|�/5:03:50 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�-�\�|�/�-�\�|5:03:55 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
5:03:56 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�/�-�\�|�/�-�\�|�/�-�\5:03:56 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�|�/�-5:04:01 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�\5:04:02 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�|�/�-�\5:04:02 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�|5:04:07 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�/5:04:07 PM PIT >> WARNING : Minion exited abnormally due to TIMED_OUT
�-�\5:04:07 PM PIT >> INFO : Completed in 80 seconds
================================================================================
- Mutators
================================================================================
> ""
>> Generated 4 Killed 1 (25%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 3 
--------------------------------------------------------------------------------
> void
>> Generated 52 Killed 18 (35%)
> KILLED 3 SURVIVED 0 TIMED_OUT 15 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 34 
--------------------------------------------------------------------------------
> "A"
>> Generated 4 Killed 1 (25%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 3 
--------------------------------------------------------------------------------
> null
>> Generated 59 Killed 24 (41%)
> KILLED 3 SURVIVED 0 TIMED_OUT 21 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 35 
--------------------------------------------------------------------------------
> false
>> Generated 7 Killed 1 (14%)
> KILLED 1 SURVIVED 1 TIMED_OUT 0 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 5 
--------------------------------------------------------------------------------
> true
>> Generated 7 Killed 1 (14%)
> KILLED 1 SURVIVED 1 TIMED_OUT 0 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 5 
--------------------------------------------------------------------------------
> 1L
>> Generated 1 Killed 1 (100%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 0 
--------------------------------------------------------------------------------
> 0L
>> Generated 1 Killed 1 (100%)
> KILLED 0 SURVIVED 0 TIMED_OUT 1 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 0 
--------------------------------------------------------------------------------
================================================================================
- Timings
================================================================================
> scan classpath : < 1 second
> coverage and dependency analysis : 6 seconds
> build mutation tests : < 1 second
> run mutation analysis : 1 minutes and 14 seconds
--------------------------------------------------------------------------------
> Total  : 1 minutes and 20 seconds
--------------------------------------------------------------------------------
================================================================================
- Statistics
================================================================================
>> Generated 135 mutations Killed 48 (36%)
>> Ran 10 tests (0.07 tests per mutation)

@vmassol
Copy link
Contributor Author

vmassol commented Apr 9, 2020

@oscarlvp cool, is that what you meant by the pitest logs? I thought you were talking about files in the target/ directory. If the console logs are enough I can make sure to include them in the issue reports. Thx

@oscarlvp
Copy link
Member

oscarlvp commented Apr 9, 2020

@vmassol No, no, I meant the files in the target directory, but I'm using these logs as an approximation, I'm comparing them, just now I was writing the next comment.

@vmassol
Copy link
Contributor Author

vmassol commented Apr 9, 2020

No, no, I meant the files in the target directory

Yeah it's better than nothing...

@oscarlvp
Copy link
Member

oscarlvp commented Apr 9, 2020

The difference between both builds lay in the void and null mutants.
For the failing build:

> void
>> Generated 52 Killed 15 (29%)
> KILLED 7 SURVIVED 3 TIMED_OUT 8 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 34 
--------------------------------------------------------------------------------
> null
>> Generated 59 Killed 24 (41%)
> KILLED 15 SURVIVED 0 TIMED_OUT 9 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 35 

For the successful build:

> void
>> Generated 52 Killed 18 (35%)
> KILLED 3 SURVIVED 0 TIMED_OUT 15 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 34 
--------------------------------------------------------------------------------
> null
>> Generated 59 Killed 24 (41%)
> KILLED 3 SURVIVED 0 TIMED_OUT 21 NON_VIABLE 0 
> MEMORY_ERROR 0 NOT_STARTED 0 STARTED 0 RUN_ERROR 0 
> NO_COVERAGE 35 

Notice how there are 15 TIMED_OUT void mutants in the successful build, while in the failing build 3 of these survived, 4 were killed and 8 remained as timed out.
Also notice that there are 21 TIMED_OUT null mutants in the successful build and the failing build reports 12 more killed and only 9 timed out.

So it seems that this is another case where the difference is due to TIMED_OUT mutants. I'll try to identify the mutants by executing PIT several times on the module.

@oscarlvp
Copy link
Member

After executing the analysis twice the following mutants SURVIVED to the first analysis and TIMED_OUT in the second:

Method Mutation
FilesystemStoreTools.deleteEmptyDirs(File, int) return true
FilesystemStoreTools.deleteEmptyDirs(File, int) return false

This produces a variation in the mutation score.
This method in particular seems to deal with external files.
As we have discussed previously it is not good to mutate methods like this one, as they may have global effects and affect the outcome of other mutants.
However it remains to be seen why these particular mutations could make the test executions take longer than expected.

The only test executing these mutants is

org.xwiki.store.filesystem.internal.FilesystemStoreToolsTest.initialize(File)

which uses mocks. We have seen flickering in other modules with similar tests using mocks and covering code that manipulates files.
It seems that this combination is not quite suited for mutation analysis.

There were 35 TIMED_OUT mutants, so, more executions could yield more variations in the result.

As an example, the following mutants were KILLED in one execution and TIMED_OUT in the other.

Method Mutation
FilesystemStoreTools.initialize() void
DefaultAttachmentFileProvider.getAttachmentContentFile() return null
DefaultAttachmentFileProvider.getAttachmentVersionContentFile() return null
DefaultAttachmentFileProvider.getAttachmentVersioningMetaFile() return null
AttachmentArchiveSaveRunnable.addSaver(StreamProvider, FilesystemStoreTools, File) void
WikiDeletedListener.onEvent(Event, Object)

But as they are considered as detected in both executions, then they do not affect the score.

@oscarlvp
Copy link
Member

oscarlvp commented May 6, 2020

@vmassol Did you decide what to do with this issue based on the previous information?

@vmassol
Copy link
Contributor Author

vmassol commented May 6, 2020

Hi @oscarlvp. Thanks for pinging me. Actually I looked again at your comments yesterday. From what I see the next step is to be able to find the new test source code generated by a mutation and run it manually to find out why it takes long to execute, right?

@oscarlvp
Copy link
Member

oscarlvp commented May 6, 2020

@vmassol remember that the mutation will only change the code of the method not the code of the test. In this case, reproducing the mutation is simple. In the first table from the previous comment you can see the methods and the mutations.

@vmassol
Copy link
Contributor Author

vmassol commented May 6, 2020

@oscarlvp Sorry my bad, I wrote it too fast without thinking, yes I meant the mutation of the sources (not the test). Ok I need to be able to reproduce locally first and then find where it's stored in the target dir but that should be easy. My question was: is that what's needed now to progress or did you have something else in mind? Thx!

@oscarlvp
Copy link
Member

oscarlvp commented May 7, 2020

@vmassol Yes, I think this should reveal the actual effect of the mutation and it requires a good understanding of the code base.

@vmassol
Copy link
Contributor Author

vmassol commented May 9, 2020

@oscarlvp so I'm not exactly sure what I should do. Here's what I did:

  • Modified FilesystemStoreTools.deleteEmptyDirs(File, int) by replacing its content with return true; and executed FilesystemStoreToolsTest.
  • Modified FilesystemStoreTools.deleteEmptyDirs(File, int) by replacing its content with return false; and executed FilesystemStoreToolsTest.

In both cases the tests succeeded and they executed in less than 2 seconds.

What am I missing?

Thanks

@oscarlvp
Copy link
Member

oscarlvp commented May 9, 2020

@vmassol the issue may not happen all the time, as there is some flickering. Also you have to compare the time of the mutant with respect to the time of the original code. PIT sets the timeout of the mutant using the time of the original code as reference.
On the other hand, yes, these mutant survive when PIT does not signal a timeout, so maybe you'll have to verify if there should be a test to improve or add for a new test for this.

@vmassol
Copy link
Contributor Author

vmassol commented May 10, 2020

@vmassol the issue may not happen all the time, as there is some flickering.

I really don't understand how there can be some flickering here TBH. So I've modified the method to always return false and executed for i in seq 1 50; do mvn clean install -Dtest=FilesystemStoreToolsTest >> results.txt; done and checked the execution times for the tests and they range between 0.4s and 0.9s (for all 50 runs).

Also you have to compare the time of the mutant with respect to the time of the original code. PIT sets the timeout of the mutant using the time of the original code as reference.

I don't understand this part. The time of the original code is when that code was modified so it could have been like 10 years before.

Also what is the default timeout? From what I see it's 4s right?

At https://pitest.org/quickstart/maven/ it says:

timeoutFactor
A factor to apply to the normal runtime of a test when considering if it is stuck in an infinite loop.

Defaults to 1.25

timeoutConstant
Constant amount of additional time to allow a test to run for (after the application of the timeoutFactor) before considering it to be stuck in an infinite loop.

Defaults to 4000

We don't override timeoutConstant and we use 1.25 for timeoutFactor so I guess our timeout is 1.25 * 4000 = 5s ?

On the other hand, yes, these mutant survive when PIT does not signal a timeout, so maybe you'll have to verify if there should be a test to improve or add for a new test for this.

Sure, I agree, but that's not the point here. The poins is to have pitest/descartes be stable and don't fail the build for wrong reasons.

What can I try more?

Thanks!

@oscarlvp
Copy link
Member

Also you have to compare the time of the mutant with respect to the time of the original code. >>PIT sets the timeout of the mutant using the time of the original code as reference.

I don't understand this part. The time of the original code is when that code was modified so it could have been like 10 years before.

I meant execution time for the original code without mutation and the mutated code when the tests are executed.
The actual formula to compute the mutation timeout is

mutant_timeout = execution_time_original_code * 1.25 + 4000

You can check the actual implementation here

If you say that the mutated code does not delay the test execution that much, then my guess (a wild guess) is that something in the code instrumented by PIT is causing the issue. Maybe it has to be with the mocks since these test do use them and similar tests have shown the same timeout instability in the past. PIT does a couple of weird things to support mocks, but I don't know for sure if that is the real issue.

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

No branches or pull requests

2 participants