Major performance difference between 3.0.0-M5 and 3.0.0-M6/3.0.0-M7

After upgrading surefire/failsafe to the latest milestone (3.0.0-M7), we faced a major performance problem in our integration tests. They increased nearly 23 minutes (+30%).

This is the 2nd upgrade attempt. When 3.0.0-M6 was released, we did the upgrade and after a couple of days we had to revert back to 3.0.0-M5 because all our integration test jobs were running nearly 30% slower.

---

 

These are the latest results we have:

Before with 3.0.0-M5:

[2022-06-07T06:59:56.398Z] [INFO] Main Server DB Tests [project-test-db] SUCCESS [ 01:16 h]

 

After with 3.0.0-M7:

[2022-06-07T18:09:21.297Z] [INFO] Main Server DB Tests [project-test-db] SUCCESS [ 01:39 h]

---

 

Our integration tests are organized in 3 reusable forks. They are JUnit 5 Suites. On 3.0.0-M5, the maven output log was only showing the Suites and their time (the whole output):

[2022-06-07T05:38:02.737Z] [INFO] Running AbcIntegrationTestCategoryDynamicSuite
[2022-06-07T05:38:02.995Z] [INFO] Running DatabaseBasedIntegrationTestCategoryDynamicSuite
[2022-06-07T05:38:02.996Z] [INFO] Running OptimizerSpecificTestCategoryDynamicSuite
[2022-06-07T06:07:10.541Z] [WARNING] Tests run: 1244, Failures: 0, Errors: 0, Skipped: 3, Time elapsed: 1,743.768 s - in DatabaseBasedIntegrationTestCategoryDynamicSuite
[2022-06-07T06:07:15.833Z] [INFO] Running DefServiceIntegrationTestCategoryDynamicSuite
[2022-06-07T06:17:52.723Z] [WARNING] Tests run: 703, Failures: 0, Errors: 0, Skipped: 7, Time elapsed: 2,376.439 s - in AbcIntegrationTestCategoryDynamicSuite
[2022-06-07T06:17:52.723Z] [INFO] Running MnoRestServiceIntegrationTestDynamicSuite
[2022-06-07T06:27:59.428Z] [WARNING] Tests run: 1009, Failures: 0, Errors: 0, Skipped: 2, Time elapsed: 1,243.484 s - in DefServiceIntegrationTestCategoryDynamicSuite
[2022-06-07T06:28:07.556Z] [INFO] Running TransactionAwareDefServiceIntegrationTestCategoryDynamicSuite
[2022-06-07T06:36:44.297Z] [WARNING] Tests run: 69, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 3,519.25 s - in OptimizerSpecificTestCategoryDynamicSuite
[2022-06-07T06:36:50.852Z] [INFO] Running GhiIntegrationTestCategoryDynamicSuite
[2022-06-07T06:42:27.435Z] [WARNING] Tests run: 185, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 335.077 s - in GhiIntegrationTestCategoryDynamicSuite
[2022-06-07T06:42:37.405Z] [INFO] Running JdoIntegrationTestCategoryDynamicSuite
[2022-06-07T06:45:28.867Z] [WARNING] Tests run: 1028, Failures: 0, Errors: 0, Skipped: 2, Time elapsed: 1,038.893 s - in TransactionAwareDefServiceIntegrationTestCategoryDynamicSuite
[2022-06-07T06:45:34.135Z] [INFO] Running JklAuthorizationRestServiceIntegrationTestDynamicSuite
[2022-06-07T06:46:41.815Z] [INFO] Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 57.734 s - in JklAuthorizationRestServiceIntegrationTestDynamicSuite
[2022-06-07T06:46:41.815Z] [INFO] Running JklBroadcastIntegrationTestCategoryDynamicSuite
[2022-06-07T06:48:03.233Z] [INFO] Tests run: 3176, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 317.062 s - in JdoIntegrationTestCategoryDynamicSuite
[2022-06-07T06:48:03.233Z] [INFO] Tests run: 17, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 74.634 s - in JklBroadcastIntegrationTestCategoryDynamicSuite
[2022-06-07T06:48:03.233Z] [INFO] Running JklRestServiceIntegrationTestCategoryDynamicSuite
[2022-06-07T06:48:05.132Z] [INFO] Running EnversIntegrationTestCategoryDynamicSuite
[2022-06-07T06:48:07.031Z] [WARNING] Tests run: 1092, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 1,819.178 s - in MnoRestServiceIntegrationTestDynamicSuite
[2022-06-07T06:48:15.148Z] [INFO] Running LdapIntegrationTestCategoryDynamicSuite
[2022-06-07T06:49:11.394Z] [INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 48.07 s - in LdapIntegrationTestCategoryDynamicSuite
[2022-06-07T06:49:11.394Z] [INFO] Tests run: 62, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 58.879 s - in EnversIntegrationTestCategoryDynamicSuite
[2022-06-07T06:49:11.395Z] [INFO] Running ObjectSecurityIntegrationTestCategoryDynamicSuite
[2022-06-07T06:49:11.395Z] [INFO] Running SecondLevelCacheTestCategoryDynamicSuite
[2022-06-07T06:50:47.898Z] [INFO] Tests run: 160, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 85.201 s - in ObjectSecurityIntegrationTestCategoryDynamicSuite
[2022-06-07T06:50:47.898Z] [INFO] Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 93.342 s - in SecondLevelCacheTestCategoryDynamicSuite
[2022-06-07T06:50:47.898Z] [INFO] Running MnoAuthorizationRestServiceIntegrationTestDynamicSuite
[2022-06-07T06:50:48.830Z] [WARNING] Tests run: 277, Failures: 0, Errors: 0, Skipped: 2, Time elapsed: 167.534 s - in JklRestServiceIntegrationTestCategoryDynamicSuite
[2022-06-07T06:50:53.013Z] [INFO] Running MnoRestServiceWithGhiIntegrationTestDynamicSuite
[2022-06-07T06:50:58.272Z] [INFO] Running PqrTestCategoryDynamicSuite
[2022-06-07T06:52:19.688Z] [INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 90.355 s - in MnoAuthorizationRestServiceIntegrationTestDynamicSuite
[2022-06-07T06:52:20.254Z] [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 87.234 s - in MnoRestServiceWithGhiIntegrationTestDynamicSuite
[2022-06-07T06:53:16.466Z] [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 131.736 s - in PqrTestCategoryDynamicSuite
[2022-06-07T06:53:16.466Z] [INFO] 
[2022-06-07T06:53:16.466Z] [INFO] Results:
[2022-06-07T06:53:16.466Z] [INFO] 
[2022-06-07T06:53:16.466Z] [WARNING] Tests run: 9066, Failures: 0, Errors: 0, Skipped: 19

 

---

Now with 3.0.0-M7 (or even 3.0.0-M6), we see a line for every single test inside the suite in maven output (just beginning of the output):

[2022-06-07T16:32:36.387Z] [INFO] Running com.aaa.ccc.testcommon.suite.order.b.AbcIntegrationTestCategoryDynamicSuite
[2022-06-07T16:32:36.388Z] [INFO] Running com.aaa.ccc.testcommon.suite.order.a.OptimizerSpecificTestCategoryDynamicSuite
[2022-06-07T16:32:36.388Z] [INFO] Running com.bbb.workflow.statemachine.abc.statemachine.AbcStatePart2IntegrationTest
[2022-06-07T16:32:36.388Z] [INFO] Running com.bbb.optimization.service.EngineIntegrationTest
[2022-06-07T16:32:36.388Z] [INFO] Running com.aaa.ccc.testcommon.suite.order.c.DatabaseBasedIntegrationTestCategoryDynamicSuite
[2022-06-07T16:32:36.388Z] [INFO] Running com.bbb.bi.TableHelperIntegrationTest
[2022-06-07T16:33:15.086Z] [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 38.042 s - in com.bbb.bi.TableHelperIntegrationTest
[2022-06-07T16:33:15.086Z] [INFO] Running com.bbb.agreement.importer.dao.jdbc.AdvDaoIntegrationTest
[2022-06-07T16:33:15.086Z] [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.246 s - in com.bbb.agreement.importer.dao.jdbc.AdvDaoIntegrationTest
[2022-06-07T16:33:15.086Z] [INFO] Running com.bbb.housekeeping.task.DefabcIntegrationTest

---

 

 

I did some investigation and my initial guess is that it's related to: 

https://issues.apache.org/jira/browse/SUREFIRE-1926 and https://github.com/apache/maven-surefire/pull/419/files (which makes all methods in PluginConsoleLogger synchronized)

 

I had no issues with the previous behaviour that was only logging the Suites, and not the individual tests. I also don't mind logging each individual test in maven output, but without the expense of such huge performance difference. I tried to see if there was a way to disable or configure this behaviour, but with no luck.