How to identify slow unit tests when using maven-surefire-plugin in parallel mode?

Question

With a view to managing / reducing our build times, I want to identify which unit tests are taking the most time - in a parallel test environment using the maven-surefire-plugin.

We are using JUnit (4.10) for unit tests. We use maven (2.2.1 - some plugins we use don't yet support maven 3) as our primary build tool, and the maven-surefire-plugin (2.19) to run unit tests.

We are using the maven-surefire-plugin in parallel mode, where both the individual methods are run in parallel and the unit test classes are run in parallel - this is very important, as it significantly reduces build unit test time. The maven-surefire-plugin is configured in the .pom as follows:

  <plugin>
    <groupId>org.apache.maven.plugins</groupId>
    <artifactId>maven-surefire-plugin</artifactId>
    <version>2.19</version>
    <configuration>
      <argLine>-Xmx2G -XX:MaxPermSize=1G -XX:-UseSplitVerifier</argLine>
      <failIfNoTests>false</failIfNoTests>
      <parallel>classesAndMethods</parallel>
      <useUnlimitedThreads>true</useUnlimitedThreads>
    </configuration>
  </plugin>

However, one of the implications of this is that in the console output, the time elapsed for each JUnit test class is the aggregate time for all the methods in the class.

For example, if a test class had 10 unit test methods, each of which took 1 second to run, then the test class would take about 1 second to run (each method being run in parallel), but the output would be something like:

Running com.package.QuickParallelTest Tests run: 10, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 10.0 sec - in com.package.QuickParallelTest

This makes it difficult to distinguish in the console output from another test class with 10 unit test methods, of which 9 run almost instantly and 1 takes almost 10 seconds to run. In this case, the test class would take about 10 seconds to run (because of the one slow test method), but the maven-surefire-plugin console output would be effectively the same:

Running com.package.SlowParallelTest Tests run: 10, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 10.0 sec - in com.package.SlowParallelTest

Ideally, I would like the time elapsed to indicate how long the test class took to run (in parallel), not the aggregate time taken to run the methods separately (as if single-threaded).

So, my question(s) is/are:

1. Is there maven-surefire-plugin setting that I am missing, so that the print summary would show time taken per class rather than aggregate for methods?
2. Is this is a known "bug" (or "feature") in the maven-surefire-plugin? (I've checked the SureFire JIRA, but couldn't find anything like this.)
3. Is there an alternative way for me to identify which tests are taking a long time and are therefore prime for optimisation.

EDIT:

I've tried playing with some additional configuration settings. Curiously, adding the the following to the configuration in the .pom seems to change the time elapsed in the console output to be the time taken in running the test class - however, this is (in my mind) counter-intuitive, since these settings are the default settings:

    <configuration>
      ...
      <forkCount>1</forkCount>
      <reuseForks>true</reuseForks>
    </configuration>

Brittnee

Just as a comment for future readers - in a production context, including the configuration setting <printSummary>false</printSummary>, which means no performance data is printed to the console, can improve build times - you can then comment out that setting when profiling build performance. – Brittnee

Alternative to @Brittnee 's comment, one can use <redirectTestOutputToFile>true</redirectTestOutputToFile> which skips printing the logs to stdout, but saves them as text files (to be retrieved later). This has the added advantage of having each Test's output in a separate file, which would otherwise be jumbled in a parallel execution. – Raid

Answer 1

Adding to the Maven Surefire Plugin configuration the reportFormat entry and setting its value to plain (instead of the default brief) would give you elapsed time per method.

<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-surefire-plugin</artifactId>
            <version>2.19</version>
            <configuration>
                <argLine>-Xmx2G -XX:MaxPermSize=1G -XX:-UseSplitVerifier</argLine>
                <failIfNoTests>false</failIfNoTests>
                <parallel>classesAndMethods</parallel>
                <useUnlimitedThreads>true</useUnlimitedThreads>
                <reportFormat>plain</reportFormat>
            </configuration>
        </plugin>
    </plugins>
</build>

Output with default reportFormat (brief):

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running com.sample.mocking.InternalServiceTestCase
Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.241 sec - in com.sample.mocking.InternalServiceTestCase

Output with plain value:

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running com.sample.mocking.InternalServiceTestCase
Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.187 sec - in com.sample.mocking.InternalServiceTestCase
test(com.sample.mocking.InternalServiceTestCase)  Time elapsed: 0.005 sec
mockTest(com.sample.mocking.InternalServiceTestCase)  Time elapsed: 0.17 sec
mockTestFailureTollerance(com.sample.mocking.InternalServiceTestCase)  Time elapsed: 0.007 sec
mockProcessfile(com.sample.mocking.InternalServiceTestCase)  Time elapsed: 0.003 sec

This option may give you further details on tests and execution time.

Erikerika

Thanks - this is very helpful. I had seen that setting, but discounted it since the documentation (as you link to) states that it "only applies to the output format of the output files". Using this setting has been helpful in identifying unit test bottlenecks. It's not a panacea, though, as it seems the surefire plugin starts the clock on each method when it is sent for execution, rather than when it starts execution. (I may be wrong, but that's my interpretation of the time elapsed data that I am seeing.) – Brittnee