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)
