Allan Jones created SUREFIRE-2096: ------------------------------------- Summary: Major performance difference between 3.0.0-M5 and 3.0.0-M6/3.0.0-M7 Key: SUREFIRE-2096 URL: https://issues.apache.org/jira/browse/SUREFIRE-2096 Project: Maven Surefire Issue Type: Bug Components: Maven Failsafe Plugin, Maven Surefire Plugin Affects Versions: 3.0.0-M7, 3.0.0-M6 Reporter: Allan Jones
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]}} jobs w 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. -- This message was sent by Atlassian Jira (v8.20.7#820007)