Huge performance issue between 6.5.2 and 6.11 #1384

juherr · 2017-03-13T20:12:27Z

Expected behavior

Duration of tests (6.5.2): 2sec on IntelliJ

Actual behavior

Duraction of tests (6.11): 15sec on IntelliJ

Is the issue reproductible on runner?

Test case sample

Just run https://github.com/ning/compress tests

From @cowtowncoder on Twitter: https://twitter.com/cowtowncoder/status/841148403115474944

cbeust · 2017-03-14T04:10:50Z

I created two scripts to run the tests with these two versions and the initial results don't reveal anything wrong:

$ time ./run-tests-6.5.2.sh
real    0m8.146s
real    0m7.849s
real    0m7.771s

$ time ./run-tests-6.11.sh
real    0m7.525s
real    0m7.590s
real    0m7.732s

In order to make sure I'm running the exact same tests, I created a testng.xml with the following classes:

<!DOCTYPE suite SYSTEM "http://beust.com/testng/testng-1.0.dtd">

<suite name="Compress"  verbose="2">

    <test name="Compress">
        <classes>
            <class name="com.ning.compress.lzf.LZFEncoderTest" />
            <class name="com.ning.compress.lzf.util.TestFileStreams" />
            <class name="com.ning.compress.lzf.TestLZFUncompressor" />
            <class name="com.ning.compress.lzf.TestLZFRoundTrip" />
            <class name="com.ning.compress.lzf.TestLZFOutputStream" />
            <class name="com.ning.compress.lzf.TestLZFInputStream" />
            <class name="com.ning.compress.lzf.TestLZFInputStream" />
            <class name="com.ning.compress.lzf.TestLZFDecoder" />
            <class name="com.ning.compress.lzf.TestLZFCompressingInputStream" />
            <class name="com.ning.compress.lzf.LZFEncoderTest" />
            <class name="com.ning.compress.lzf.LZFEncoderTest" />
<!--
            <class name="com.ning.compress.gzip.TestGzipUncompressor "/>
            -->
            <class name="com.ning.compress.gzip.TestGzipStreams" />
        </classes>
    </test>

</suite>

Note that I commented one test, since it fails (missing a file).

What this tells me is that if there's a problem, it might be on the IDEA plug-in side but not on the TestNG side.

FYI, here are the two scripts:

java -ea -classpath $HOME/.kobalt/cache/org/testng/testng/6.5.2/testng-6.5.2.jar:$HOME/.kobalt/cache/org/yaml/snakeyaml/1.6/snakeyaml-1.6.jar:$HOME/.kobalt/cache/junit/junit/4.10/junit-4.10.jar:$HOME/.kobalt/cache/org/hamcrest/hamcrest-core/1.1/hamcrest-core-1.1.jar:$HOME/.kobalt/cache/com/beust/jcommander/1.48/jcommander-1.48.jar:$HOME/t/compress/./kobaltBuild/classes:$HOME/t/compress/./kobaltBuild/test-classes:$HOME/.kobalt/cache/org/beanshell/bsh/2.0b4/bsh-2.0b4.jar org.testng.TestNG -d kobaltBuild/test-output src/main/resources/testng.xml

java -ea -classpath $HOME/.kobalt/cache/org/testng/testng/6.11/testng-6.11.jar:$HOME/.kobalt/cache/org/yaml/snakeyaml/1.6/snakeyaml-1.6.jar:$HOME/.kobalt/cache/junit/junit/4.10/junit-4.10.jar:$HOME/.kobalt/cache/org/hamcrest/hamcrest-core/1.1/hamcrest-core-1.1.jar:$HOME/.kobalt/cache/com/beust/jcommander/1.48/jcommander-1.48.jar:$HOME/t/compress/./kobaltBuild/classes:$HOME/t/compress/./kobaltBuild/test-classes:$HOME/.kobalt/cache/org/beanshell/bsh/2.0b4/bsh-2.0b4.jar org.testng.TestNG -d kobaltBuild/test-output src/main/resources/testng.xml

juherr · 2017-03-14T05:22:01Z

Strange because I reproduced the problem with maven and @cowtowncoder has it with eclipse.
I will try with cli asap.

krmahadevan · 2017-03-14T14:17:06Z

@cbeust - Here are my test results

Using 6.8.21
mvn clean test takes ~1 Minute.

Running TestSuite
Configuring TestNG with: TestNG652Configurator
Tests run: 44, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 58.202 sec - in TestSuite

Results :

Tests run: 44, Failures: 0, Errors: 0, Skipped: 0

[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 01:01 min
[INFO] Finished at: 2017-03-14T19:39:38+05:30
[INFO] Final Memory: 21M/311M
[INFO] ------------------------------------------------------------------------

Using TestNG 6.11
mvn clean test takes ~22 seconds more.

Running TestSuite
Configuring TestNG with: TestNG652Configurator
Tests run: 44, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 79.93 sec - in TestSuite

Results :

Tests run: 44, Failures: 0, Errors: 0, Skipped: 0

[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 01:23 min
[INFO] Finished at: 2017-03-14T19:42:50+05:30
[INFO] Final Memory: 21M/312M
[INFO] ------------------------------------------------------------------------

krmahadevan · 2017-03-14T14:50:29Z

@cbeust - But when I tried with only the TestNG CLI approach, I noticed that my test results were pretty much the same across both the versions.

<?xml version="1.0"?>
<!DOCTYPE suite SYSTEM "http://beust.com/testng/testng-1.0.dtd">
<suite name="Compress" verbose="2">
	<test name="Compress">
		<classes>
			<class name="com.ning.compress.gzip.TestGzipStreams"/>
			<class name="com.ning.compress.gzip.TestGzipUncompressor"/>
			<class name="com.ning.compress.lzf.LZFEncoderTest"/>
			<class name="com.ning.compress.lzf.TestLZFCompressingInputStream"/>
			<class name="com.ning.compress.lzf.TestLZFDecoder"/>
			<class name="com.ning.compress.lzf.TestLZFInputStream"/>
			<class name="com.ning.compress.lzf.TestLZFOutputStream"/>
			<class name="com.ning.compress.lzf.TestLZFRoundTrip"/>
			<class name="com.ning.compress.lzf.TestLZFUncompressor"/>
			<class name="com.ning.compress.lzf.util.TestFileStreams"/>
		</classes>
	</test>
</suite>

20:17 $ cat run-tests-6.8.21.sh
java -ea -classpath $HOME/.m2/repository/org/testng/testng/6.8.21/testng-6.8.21.jar:\
$HOME/.m2/repository/org/yaml/snakeyaml/1.6/snakeyaml-1.6.jar:\
$HOME/.m2/repository/junit/junit/4.10/junit-4.10.jar:\
$HOME/.m2/repository/org/hamcrest/hamcrest-core/1.1/hamcrest-core-1.1.jar:\
$HOME/.m2/repository/com/beust/jcommander/1.48/jcommander-1.48.jar:\
$HOME/githome/PlayGround/compress/target/classes:\
$HOME/githome/PlayGround/compress/target/test-classes:\
$HOME/.m2/repository/org/beanshell/bsh/2.0b4/bsh-2.0b4.jar \
org.testng.TestNG -d $HOME/githome/PlayGround/compress/test-output suite.xml

time sh run-tests-6.5.2.sh

real	1m19.419s

20:17 $ cat run-tests-6.11.sh
java -ea -classpath $HOME/.m2/repository/org/testng/testng/6.11/testng-6.11.jar:\
$HOME/.m2/repository/org/yaml/snakeyaml/1.17/snakeyaml-1.17.jar:\
$HOME/.m2/repository/junit/junit/4.10/junit-4.10.jar:\
$HOME/.m2/repository/org/hamcrest/hamcrest-core/1.1/hamcrest-core-1.1.jar:\
$HOME/.m2/repository/com/beust/jcommander/1.64/jcommander-1.64.jar:\
$HOME/githome/PlayGround/compress/target/classes:\
$HOME/githome/PlayGround/compress/target/test-classes:\
$HOME/.m2/repository/org/beanshell/bsh/2.0b4/bsh-2.0b4.jar \
org.testng.TestNG -d $HOME/githome/PlayGround/compress/test-output suite.xml

time sh run-tests-6.11.sh

real	1m19.198s

@juherr - I think the issue is perhaps not with TestNG but with something else.

juherr · 2017-03-14T15:24:05Z

@krmahadevan
It's strange because the behavior changes when we only change the TestNG version.
Could you check what is the suite.xml generated by IntelliJ and retry with this one?

krmahadevan · 2017-03-14T15:27:33Z

@juherr - I didn't run any tests from within an IDE. It was only via maven and then using TestNG CLI.

juherr · 2017-03-14T19:52:35Z

@krmahadevan The suite generated by IntelliJ is same as yours:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE suite SYSTEM "http://testng.org/testng-1.0.dtd">
<suite name="Default Suite">
  <test name="compress-lzf">
    <classes>
      <class name="com.ning.compress.lzf.util.TestFileStreams"/>
      <class name="com.ning.compress.gzip.TestGzipStreams"/>
      <class name="com.ning.compress.gzip.TestGzipUncompressor"/>
      <class name="com.ning.compress.lzf.TestLZFCompressingInputStream"/>
      <class name="com.ning.compress.lzf.TestLZFDecoder"/>
      <class name="com.ning.compress.lzf.TestLZFEncoder"/>
      <class name="com.ning.compress.lzf.TestLZFInputStream"/>
      <class name="com.ning.compress.lzf.TestLZFOutputStream"/>
      <class name="com.ning.compress.lzf.TestLZFRoundTrip"/>
      <class name="com.ning.compress.lzf.TestLZFUncompressor"/>
    </classes>
  </test> <!-- compress-lzf -->
</suite> <!-- Default Suite -->

juherr · 2017-03-14T20:11:35Z

The biggest perf issue comes from TestLZFRoundTrip and especially testLZFCompressionOnTestFiles.

bazhenov · 2017-06-28T10:49:18Z

Confirm the problem using maven.

I've downloaded provided code and run under TestNG 6.8.21 (mvn test -Dtest=TestLZFRoundTrip -DforkMode=never):

Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.02 sec - in com.ning.compress.lzf.TestLZFRoundTrip

Under TestNG 6.11

Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 24.103 sec - in com.ning.compress.lzf.TestLZFRoundTrip

Under TestNG 6.11 with all assertEquals() commented out in TestLZFRoundTrip

Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.202 sec - in com.ning.compress.lzf.TestLZFRoundTrip

jstack and JFR says the most of the time is spent inside assertArrayEquals()

"main" #1 prio=5 os_prio=31 tid=0x00007ff288802800 nid=0x1c03 runnable [0x000070000679d000]
 java.lang.Thread.State: RUNNABLE
	at java.lang.reflect.Array.get(Native Method)
	at org.testng.Assert.assertArrayEquals(Assert.java:153)
	at org.testng.Assert.assertEquals(Assert.java:112)
	at org.testng.Assert.assertEquals(Assert.java:178)
	at com.ning.compress.lzf.TestLZFRoundTrip.testLZFCompressionOnFile(TestLZFRoundTrip.java:87)
	at com.ning.compress.lzf.TestLZFRoundTrip.testLZFCompressionOnDir(TestLZFRoundTrip.java:54)

It seems like some changes in assertEquals()/assertArrayEquals() make frequent comparisons of arrays more costly.

Will dig this problem deeper a little bit later.

bazhenov · 2017-06-29T00:41:42Z

Ok. I figured it out. The problem is in polymorphic method assertEquals(byte[], byte[]). It was removed in f909a84. Now general assertEquals(Object, Object) is used instead. This puts us in a situation where each byte in array is wrapped in a Byte wrapper. This what slows the code down.

I'm not sure if it's worthwhile to put those methods back or not. Anyone?

juherr · 2017-06-29T07:39:37Z

@bazhenov I'm not sure to understand what is the difference between

static public void assertEquals(final byte[] actual, final byte[] expected) {
  assertArrayEquals(actual, expected, null);
}

and

static public void assertEquals(Object actual, Object expected, String message) {
  if (expected != null && expected.getClass().isArray()) {
    assertArrayEquals(actual, expected, message);
    return;
  }
  ...
}

because both methods are calling the same assertArrayEquals.

But thanks for the analyze. I will dig about it.

bazhenov · 2017-06-29T11:06:00Z

Actually, no. In 6.8.21 flow ends up in specialized assertEquals(byte[], byte[], String) method with straightforward for-loop

static public void assertEquals(final byte[] actual, final byte[] expected, final String message) {
  if(expected == actual) {
    return;
  }
  if(null == expected) {
    fail("expected a null array, but not null found. " + message);
  }
  if(null == actual) {
    fail("expected not null array, but null found. " + message);
  }

  assertEquals(actual.length, expected.length, "arrays don't have the same size. " + message);

  for(int i= 0; i < expected.length; i++) {
    if(expected[i] != actual[i]) {
      fail("arrays differ firstly at element [" + i +"]; "
          + "expected value is <" + expected[i] +"> but was <"
          + actual[i] + ">. "
          + message);
    }
  }
}

This code was removed in 66373cd

juherr · 2017-06-29T12:23:19Z

O, it makes sense now. Thank!

krmahadevan · 2017-07-06T04:27:49Z

@bazhenov - Since you have done all the hard work of analyzing what is causing this issue, it would be great if you could also send a pull request that fixes this.

bazhenov · 2017-07-06T04:56:42Z

I'd like to provide a pull-request if authors don't mind returning those polymorphic methods.

juherr · 2017-07-07T06:56:36Z

@bazhenov I suppose we don't have the choice :) Feel free to add the duplication with an explanation of its reason.

krmahadevan · 2017-07-22T18:39:53Z

ping @bazhenov . Gentle reminder on the PR part.

bazhenov · 2017-07-25T11:12:51Z

yup, was on a vacation. Will make a patch in spare time.

- return specialized versions of assertEquals(byte[], byte[])

bazhenov · 2017-08-01T03:13:02Z

Maybe we also should add specialized versions of assertEquals() for int[], long[], short[], boolean[] and char[]. Or it would be overkill? What do you think?

juherr · 2017-08-01T04:21:01Z

You can add them if you want.

bazhenov · 2017-08-01T04:23:55Z

I think it will be more consistent if TestNG provide assert-methods for all possible primitive types. I'll add them.

juherr added the perf/enhancement label Mar 13, 2017

bazhenov added a commit to bazhenov/testng that referenced this issue Aug 1, 2017

Issue testng-team#1384: Huge performance issue between 6.5.2 and 6.11

7743e84

- return specialized versions of assertEquals(byte[], byte[])

bazhenov mentioned this issue Aug 1, 2017

Issue 1384: Huge performance issue between 6.5.2 and 6.11 #1495

Merged

2 tasks

cbeust closed this as completed in #1495 Aug 7, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Huge performance issue between 6.5.2 and 6.11 #1384

Huge performance issue between 6.5.2 and 6.11 #1384

juherr commented Mar 13, 2017

cbeust commented Mar 14, 2017

juherr commented Mar 14, 2017

krmahadevan commented Mar 14, 2017

krmahadevan commented Mar 14, 2017

juherr commented Mar 14, 2017

krmahadevan commented Mar 14, 2017

juherr commented Mar 14, 2017

juherr commented Mar 14, 2017

bazhenov commented Jun 28, 2017 •

edited

Loading

bazhenov commented Jun 29, 2017

juherr commented Jun 29, 2017 •

edited

Loading

bazhenov commented Jun 29, 2017 •

edited

Loading

juherr commented Jun 29, 2017

krmahadevan commented Jul 6, 2017

bazhenov commented Jul 6, 2017

juherr commented Jul 7, 2017

krmahadevan commented Jul 22, 2017

bazhenov commented Jul 25, 2017

bazhenov commented Aug 1, 2017

juherr commented Aug 1, 2017

bazhenov commented Aug 1, 2017

Huge performance issue between 6.5.2 and 6.11 #1384

Huge performance issue between 6.5.2 and 6.11 #1384

Comments

juherr commented Mar 13, 2017

Expected behavior

Actual behavior

Is the issue reproductible on runner?

Test case sample

cbeust commented Mar 14, 2017

juherr commented Mar 14, 2017

krmahadevan commented Mar 14, 2017

krmahadevan commented Mar 14, 2017

juherr commented Mar 14, 2017

krmahadevan commented Mar 14, 2017

juherr commented Mar 14, 2017

juherr commented Mar 14, 2017

bazhenov commented Jun 28, 2017 • edited Loading

bazhenov commented Jun 29, 2017

juherr commented Jun 29, 2017 • edited Loading

bazhenov commented Jun 29, 2017 • edited Loading

juherr commented Jun 29, 2017

krmahadevan commented Jul 6, 2017

bazhenov commented Jul 6, 2017

juherr commented Jul 7, 2017

krmahadevan commented Jul 22, 2017

bazhenov commented Jul 25, 2017

bazhenov commented Aug 1, 2017

juherr commented Aug 1, 2017

bazhenov commented Aug 1, 2017

bazhenov commented Jun 28, 2017 •

edited

Loading

juherr commented Jun 29, 2017 •

edited

Loading

bazhenov commented Jun 29, 2017 •

edited

Loading