JMH test failure

[khatchad]

I am seeing this failure when running the JHM tests. No results are produced from this test due to the failure:

# Run progress: 6.67% complete, ETA 00:00:43
# Fork: 3 of 10
# Warmup Iteration   1: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
<failure>

java.lang.IllegalArgumentException: Comparison method violates its general contract!
	at java.util.TimSort.mergeLo(TimSort.java:777)
	at java.util.TimSort.mergeAt(TimSort.java:514)
	at java.util.TimSort.mergeCollapse(TimSort.java:441)
	at java.util.TimSort.sort(TimSort.java:245)
	at java.util.Arrays.sort(Arrays.java:1512)
	at java.util.stream.SortedOps$SizedRefSortingSink.end(SortedOps.java:348)
	at java.util.stream.Sink$ChainedInt.end(Sink.java:290)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:545)
	at java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260)
	at java.util.stream.IntPipeline.toArray(IntPipeline.java:502)
	at org.numenta.nupic.algorithms.SpatialPooler.inhibitColumnsGlobal(SpatialPooler.java:815)
	at org.numenta.nupic.algorithms.SpatialPooler.inhibitColumns(SpatialPooler.java:786)
	at org.numenta.nupic.algorithms.SpatialPooler.compute(SpatialPooler.java:206)
	at org.numenta.nupic.benchmarks.SpatialPoolerGlobalInhibitionBenchmark.measureAvgCompute_7_Times(SpatialPoolerGlobalInhibitionBenchmark.java:62)
	at org.numenta.nupic.benchmarks.generated.SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.measureAvgCompute_7_Times_avgt_jmhStub(SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.java:221)
	at org.numenta.nupic.benchmarks.generated.SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.measureAvgCompute_7_Times_AverageTime(SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.java:164)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:198)
	at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:180)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

[rhyolight]

How are you running tests? I'm running with gradle -Pskipbench check and it's BUILD SUCCESSFUL for me.

[khatchad]

I'm also running that way and it's also successful but if you look at the final results you won't see anything for this particular test (only 2/3 tests are shown).

[cogmission]

Hi Guys! (@rhyolight @khatchad)

I'm also running that way and it's also successful but if you look at the final results you won't see anything for this particular test (only 2/3 tests are shown).

First, this Logger error is (should be) a non-sequitur. As SLF4J allows each user to specify a log module to handle log output - when it isn't specified, this message is printed and a default logger is used. This is a setting inside of the JMH Benchmarking lib which I believe would have to specify this somehow... But this doesn't (shouldn't) affect the execution.

Secondly I'm kind of confused as to what you might be expecting? When running with the "-Pskipbench" flag, the benchmarks won't run and you won't see any bench mark reports created in build/reports/jmh/* ? So that is the expected behavior. If you run with gradle check the benchmarks are then run and you should see output in the directory previously mentioned?

I'm also not clear on what test you say is missing? (i.e. what is the "this test" you say is missing)

Also, how are you both "causing" the above exception, and where are you seeing it?

[khatchad]

Ah, sorry, I am not using -Pskipbench because that skips the benchmark testing! I am simply using gradle check. Let me gather more detailed data.

[khatchad]

Hi @cogmission,

First, this Logger error is (should be) a non-sequitur.

Actually, what I was trying to bring attention to was the IllegalArgumentException since it causes one of the benchmark tests not to execute. Yes, I agree that it shouldn't affect the execution.

Secondly I'm kind of confused as to what you might be expecting? When running with the "-Pskipbench" flag, the benchmarks won't run and you won't see any bench mark reports created in build/reports/jmh/* ? So that is the expected behavior.

Yes, agreed. Sorry about that. I was not using that flag as explained above. What I meant to say that my build was also showing BUILD SUCCESSFUL despite one of the tests throwing the exception.

If you run with gradle check the benchmarks are then run and you should see output in the directory previously mentioned?

Yes, I do see it.

I'm also not clear on what test you say is missing? (i.e. what is the "this test" you say is missing)

I mean to say that the benchmark org.numenta.nupic.benchmarks.SpatialPoolerGlobalInhibitionBenchmark.measureAvgCompute_7_Times has no data associated with it in the results.txt file:

Benchmark	Mode	Threads	Samples	Score	Score Error (99.9%)	Unit
org.numenta.nupic.benchmarks.SpatialPoolerLocalInhibitionBenchmark.measureAvgCompute_7_Times	avgt	1	5	1010.7619305000001	101.06559550281271	ms/op
org.numenta.nupic.benchmarks.TemporalMemoryBenchmark.measureAvgCompute_7_Times	avgt	1	5	1.2745183063550178	0.4644973486792368	ms/op

Also, how are you both "causing" the above exception, and where are you seeing it?

$ ./gradlew check
Downloading https://services.gradle.org/distributions/gradle-2.2-bin.zip
..................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
Unzipping /home/rk1424/.gradle/wrapper/dists/gradle-2.2-bin/ca0flae0itb57he40lyj6fhpp/gradle-2.2-bin.zip to /home/rk1424/.gradle/wrapper/dists/gradle-2.2-bin/ca0flae0itb57he40lyj6fhpp
Set executable permissions for: /home/rk1424/.gradle/wrapper/dists/gradle-2.2-bin/ca0flae0itb57he40lyj6fhpp/gradle-2.2/bin/gradle
Download https://jcenter.bintray.com/me/champeau/gradle/jmh-gradle-plugin/0.1.3/jmh-gradle-plugin-0.1.3.pom
Download https://jcenter.bintray.com/com/github/jengelman/gradle/plugins/shadow/1.2.3/shadow-1.2.3.pom
Download https://jcenter.bintray.com/org/openjdk/jmh/jmh-generator-annprocess/1.5.2/jmh-generator-annprocess-1.5.2.pom
Download https://jcenter.bintray.com/org/openjdk/jmh/jmh-parent/1.5.2/jmh-parent-1.5.2.pom
Download https://jcenter.bintray.com/org/openjdk/jmh/jmh-core/1.5.2/jmh-core-1.5.2.pom
Download https://jcenter.bintray.com/me/champeau/gradle/jmh-gradle-plugin/0.1.3/jmh-gradle-plugin-0.1.3.jar
Download https://jcenter.bintray.com/org/openjdk/jmh/jmh-generator-annprocess/1.5.2/jmh-generator-annprocess-1.5.2.jar
Download https://jcenter.bintray.com/org/openjdk/jmh/jmh-core/1.5.2/jmh-core-1.5.2.jar
returning from has Property false
:compileJava
Note: Some input files use unchecked or unsafe operations.
Note: Recompile with -Xlint:unchecked for details.
:processResources
:classes
:compileTestJava
:processTestResources
:testClasses
:test
:check
Download https://repo1.maven.org/maven2/org/openjdk/jmh/jmh-core/1.1.1/jmh-core-1.1.1.pom
Download https://repo1.maven.org/maven2/org/openjdk/jmh/jmh-parent/1.1.1/jmh-parent-1.1.1.pom
Download https://repo1.maven.org/maven2/org/openjdk/jmh/jmh-generator-annprocess/1.1.1/jmh-generator-annprocess-1.1.1.pom
Download https://repo1.maven.org/maven2/org/openjdk/jmh/jmh-core/1.1.1/jmh-core-1.1.1.jar
Download https://repo1.maven.org/maven2/org/openjdk/jmh/jmh-generator-annprocess/1.1.1/jmh-generator-annprocess-1.1.1.jar
warning: Supported source version 'RELEASE_6' from annotation processor 'org.openjdk.jmh.generators.BenchmarkProcessor' less than -source '1.8'
Note: Some input files use unchecked or unsafe operations.
Note: Recompile with -Xlint:unchecked for details.
1 warning
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
>SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

BUILD SUCCESSFUL

Total time: 2 mins 27.037 secs

$ head -n 42 build/reports/jmh/human.txt
# VM invoker: /usr/lib/jvm/java-8-oracle/jre/bin/java
# VM options: -Dfile.encoding=UTF-8 -Duser.country=US -Duser.language=en -Duser.variant
# Warmup: 5 iterations, 1 s each
# Measurement: 5 iterations, 1 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: org.numenta.nupic.benchmarks.SpatialPoolerGlobalInhibitionBenchmark.measureAvgCompute_7_Times

# Run progress: 0.00% complete, ETA 00:00:30
# Fork: 1 of 1
# Warmup Iteration   1: <failure>

java.lang.IllegalArgumentException: Comparison method violates its general contract!
	at java.util.TimSort.mergeLo(TimSort.java:777)
	at java.util.TimSort.mergeAt(TimSort.java:514)
	at java.util.TimSort.mergeCollapse(TimSort.java:441)
	at java.util.TimSort.sort(TimSort.java:245)
	at java.util.Arrays.sort(Arrays.java:1512)
	at java.util.stream.SortedOps$SizedRefSortingSink.end(SortedOps.java:348)
	at java.util.stream.Sink$ChainedInt.end(Sink.java:290)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:545)
	at java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:260)
	at java.util.stream.IntPipeline.toArray(IntPipeline.java:502)
	at org.numenta.nupic.algorithms.SpatialPooler.inhibitColumnsGlobal(SpatialPooler.java:815)
	at org.numenta.nupic.algorithms.SpatialPooler.inhibitColumns(SpatialPooler.java:786)
	at org.numenta.nupic.algorithms.SpatialPooler.compute(SpatialPooler.java:206)
	at org.numenta.nupic.benchmarks.SpatialPoolerGlobalInhibitionBenchmark.measureAvgCompute_7_Times(SpatialPoolerGlobalInhibitionBenchmark.java:62)
	at org.numenta.nupic.benchmarks.generated.SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.measureAvgCompute_7_Times_avgt_jmhStub(SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.java:221)
	at org.numenta.nupic.benchmarks.generated.SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.measureAvgCompute_7_Times_AverageTime(SpatialPoolerGlobalInhibitionBenchmark_measureAvgCompute_7_Times.java:164)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:198)
	at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:180)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

[cogmission]

Hi @khatchad,

Thank you, now I think I understand what the issue is to which you're bringing attention. Let me take a look at it. Also, thank you very much for hanging in there and explaining things to me!

Cheers,
David

[khatchad]

No problem, @cogmission. Sorry I wasn't originally clear.

[khatchad]

I actually somehow fixed this problem by increasing the data size that the tests run on but I don't think you'd want that here. It seems to me that the intent of this test is a quick performance test. I'll post a pull request soon that will show this test passing (but taking much longer overall).

[khatchad]

#539 has a patch where the test does not fail.

[cogmission]

Hi @khatchad,

Ok I've found the actual problem. It has to do with the transitivity of the comparator used for Global Inhibition in the SpatialPooler.

https://github.com/numenta/htm.java/blob/master/src/main/java/org/numenta/nupic/model/Connections.java#L236

There was an issue written up about this on StackOverflow...

I set the comparator to: (to eliminate the rounding of values whose difference was < 0.000000001) and there is no error. I'm thinking about inserting this Comparator only in the AbstractAlgorithmBenchmark class so that it is inserted for this test only.

(p1, p2) -> { 
            double p1val = p1.getSecond();
            double p2val = p2.getSecond();
            
            return p1val == p2val ? 0 : p2val > p1val ? -1 : 1;
        };

...as opposed to the normal way...

(p1, p2) -> { 
            int p1key = p1.getFirst();
            int p2key = p2.getFirst();
            double p1val = p1.getSecond();
            double p2val = p2.getSecond();
            if(Math.abs(p2val - p1val) < 0.000000001) {
                return Math.abs(p2key - p1key) < 0.000000001 ? 0 : p2key > p1key ? -1 : 1;
            } else {
                return p2val > p1val ? -1 : 1;
            }
        };

I will take a look at submitting this as a pull request. I saw your pull request which increases the test size, and I really appreciate your effort on this, but I think inserting this will be a more "wholistic" solution?

Here is a Gist with the class file to replace. Replace the AbstractAlgorithmBenchmark.java file found in src/jmh/java in the org.numenta.nupic.benchmarks package...

[khatchad]

Hi @cogmission,

I saw your pull request which increases the test size, and I really appreciate your effort on this, but I think inserting this will be a more "wholistic" solution?

The increase of the test size in #539 is just to exploit more parallelism to show how the refactoring can optimize the code. So, yes, I agree with you that if changing the comparator solves the problem, it should be the solution given that this JMH test is supposed to be fast.