Search code examples
javaconcurrenthashmapjmhjava-threads

JMH iterations go from >300,000 ops/sec to < 1 op/sec

My main class contains the data structure to be used by multiple threads. In my original program, I also start the threads here. 

public class JDKSolution {

public static final ConcurrentHashMap<Long, Book> books = new ConcurrentHashMap<>();
public static void main(String[] args) throws RunnerException{
    Options opt = new OptionsBuilder()
        .include(JDKSolutionThread.class.getSimpleName())
        .forks(1)
        .jvmArgsAppend("-XX:MaxInlineLevel=12")
        .verbosity(VerboseMode.EXTRA)
        .build();

    new Runner(opt).run();              
}
}

Book is simply

public class Book {
  static long count  = 0;
  long id;
  Book(){
    synchronized(this){
      id = count;
      count++;
    }
  }

  long getID(){
    return id;
  }
}

I have another class which extends thread; in here are the methods to be analyzed. 

@State(Scope.Benchmark)
public class JDKSolutionThread extends Thread{

@Benchmark 
    public void addBook(){
        Book b = new Book();
        books.put(b.getID(), b);
    }
}

The output looks like this

# Warmup Iteration  15: 329731.671 ops/s
# Warmup Iteration  16: 23160.167 ops/s
# Warmup Iteration  17: 55316.913 ops/s
# Warmup Iteration  18: 30454.814 ops/s
# Warmup Iteration  19: 0.316 ops/s
# Warmup Iteration  20: 0.880 ops/s
Iteration   1: 0.085 ops/s
Iteration   2: 1.349 ops/s
...
Iteration  20: 4.508 ops/s
<JMH had finished, but forked VM did not exit, are there stray running threads? Waiting 24 seconds more...>
Thread[DestroyJavaVM,5,main]
  at java.lang.Object.wait(Native Method)
  at java.lang.Thread.join(Thread.java:1245)
  at java.lang.Thread.join(Thread.java:1319)
  at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:106)
  at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
  at java.lang.Shutdown.runHooks(Shutdown.java:123)
  at java.lang.Shutdown.sequence(Shutdown.java:167)
  at java.lang.Shutdown.shutdown(Shutdown.java:234)

Thread[Thread-0,5,main]
  at java.lang.StringCoding.deref(StringCoding.java:63)
  at java.lang.StringCoding.encode(StringCoding.java:330)
  at java.lang.String.getBytes(String.java:918)
  at java.io.UnixFileSystem.getBooleanAttributes0(Native Method)
  at java.io.UnixFileSystem.getBooleanAttributes(UnixFileSystem.java:242)
  at java.io.File.exists(File.java:819)
  at sun.misc.URLClassPath$FileLoader.getResource(URLClassPath.java:1245)
  at sun.misc.URLClassPath.getResource(URLClassPath.java:212)
  at java.net.URLClassLoader$1.run(URLClassLoader.java:365)
  at java.net.URLClassLoader$1.run(URLClassLoader.java:362)
  at java.security.AccessController.doPrivileged(Native Method)
  at java.net.URLClassLoader.findClass(URLClassLoader.java:361)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
  at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:331)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
  at org.openjdk.jmh.runner.link.BinaryLinkClient.close(BinaryLinkClient.java:141)
  at org.openjdk.jmh.runner.ForkedMain.hangup(ForkedMain.java:136)
  at org.openjdk.jmh.runner.ForkedMain$HangupThread.run(ForkedMain.java:157)

<shutdown timeout of 30 seconds expired, forcing forked VM to exit>

The operations per second should be in the range of ~300000 each iteration. What would cause as little as 1 operation?

Solution

  • In most benchmarking modes, JMH calls @Benchmark over and over again.

    Assuming books is a collection, what does happen is you saturate the collection, and each put call adds to a larger and larger collection. You have to either clear the collection after some size is reached, or remove some other Book after put to maintain constant size, or mock the collection to "skip" the addition, etc. All these measures would have implication on experimental design and the data you get from the experiment, and so it's your responsibility to choose and face the consequences.