Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Thread contention during deserialization #4506

Closed
fridgebuzz opened this issue Jan 29, 2015 · 14 comments

Comments

Projects
None yet
10 participants
@fridgebuzz
Copy link

commented Jan 29, 2015

Profiling a Hazelcast app reveals thread contention in SpringManagedContext on java.lang.Class.getAnnotation(). That calls a synchronized method called java.lang.Class.initAnnotationsIfNecessary(). Stack trace is:

java.lang.Class.initAnnotationsIfNecessary()
   java.lang.Class.getAnnotation(Class)
      com.hazelcast.spring.context.SpringManagedContext.initializeIfSpringAwareIsPresent(Object)
         com.hazelcast.spring.context.SpringManagedContext.initialize(Object)
            com.hazelcast.instance.HazelcastManagedContext.initialize(Object)
               com.hazelcast.nio.serialization.SerializationServiceImpl.toObject(Object)
                  com.hazelcast.map.operation.QueryOperation$PartitionCallable.call()
                     com.hazelcast.map.operation.QueryOperation$PartitionCallable.call()
                        java.util.concurrent.FutureTask.run()
                           com.hazelcast.util.executor.CompletableFutureTask.run()
                              com.hazelcast.util.executor.CachedExecutorServiceDelegate$Worker.run()
                                 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker)
                                    java.util.concurrent.ThreadPoolExecutor$Worker.run()
                                       java.lang.Thread.run()
                                          com.hazelcast.util.executor.PoolExecutorThreadFactory$ManagedThread.run()

A way of preventing this is to cache the results of getAnnotation, so that it is only called once per class. Instead, it's called on every object deserialization (along with other places.) Performance could be improved.

@pveentjer

This comment has been minimized.

Copy link
Member

commented Jan 30, 2015

Can you create a test that reproduces the contention? This makes it (a lot) easier for us to come up with a fix. If it can be improved with simple caching, than it looks like something we can quickly do.

@noctarius

This comment has been minimized.

Copy link
Contributor

commented Jan 30, 2015

Please remember it has to be weak reference caching since classloaders are meant to be reloaded in application containers :)

@gurbuzali gurbuzali added the PENDING label Jan 30, 2015

@fridgebuzz

This comment has been minimized.

Copy link
Author

commented Jan 31, 2015

Realistically, it would probably take me a significant investment of time and effort to create a test application and associated load test that would demonstrate this. I couldn't do it at work, it would have to be on my own time.

I got the data I have from ongoing performance tests of our product under heavy load. In fact, this is a perf bug filed by our testing department.

It would be much faster and more practical for me to send you a patch that fixes it, if necessary. I'd have a better chance of justifying that effort (it doesn't appear very difficult.)

@pveentjer

This comment has been minimized.

Copy link
Member

commented Jan 31, 2015

Hi Fridgebuss,

a simple main would do the trick. I don't think that a full blown 'distributed' test is needed in this case, but I just need to see it in action. So just a very basis example using Spring that shows the overhead of the continuous annotation access.

The problem is that this performance issue currently doesn't have priority for us; so if you want to get it through quickly, you need to help me out as well. Setting up a test that exactly reproduces the issue, often is the biggest time consumer. Sending in the patch would be helpful, but I still need to create a test to verify that there actually is an improvement.

@fridgebuzz

This comment has been minimized.

Copy link
Author

commented Feb 3, 2015

This is a trivial test, but it proves the point. Please bear in mind that in a real app the results are considerably worse.

Spring app context (hazelcast-context.xml):

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xmlns:hz="http://www.hazelcast.com/schema/spring"
       xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-4.0.xsd
        http://www.hazelcast.com/schema/spring http://www.hazelcast.com/schema/spring/hazelcast-spring-3.2.xsd">


    <hz:hazelcast id="testInstance">

        <hz:config>
            <hz:group name="test-grid" password="password" />
            <hz:network port="5701" port-auto-increment="true">
                <hz:join>
                    <hz:multicast enabled="false" />
                    <hz:tcp-ip enabled="true">
                        <hz:member>localhost:5701</hz:member>
                        <hz:member>localhost:5801</hz:member>
                    </hz:tcp-ip>
                </hz:join>
                <hz:interfaces enabled="false" />
            </hz:network>

            <hz:map name="testMap" backup-count="1" read-backup-data="true"
                    merge-policy="com.hazelcast.map.merge.PassThroughMergePolicy" />

        </hz:config>

    </hz:hazelcast>

    <hz:map id="testMap" instance-ref="testInstance" name="testMap" />

</beans>

Main test class:

package ca.thoughtwire.hazelcasttest;

import com.hazelcast.core.HazelcastInstance;
import com.hazelcast.nio.ObjectDataInput;
import com.hazelcast.nio.ObjectDataOutput;
import com.hazelcast.nio.serialization.DataSerializable;
import org.springframework.context.ApplicationContext;
import org.springframework.context.support.ClassPathXmlApplicationContext;

import java.io.IOException;
import java.util.Collection;
import java.util.Random;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;


public class SpringClassThreadContentionTest {

    private final HazelcastInstance hazelcastInstance;
    private final ExecutorService executorService;

    public static void main(String[] args)
    {
        SpringClassThreadContentionTest instance = new SpringClassThreadContentionTest(args[0]);
        instance.go();
    }

    public SpringClassThreadContentionTest(String pathToHzContext) {

        ApplicationContext context = new ClassPathXmlApplicationContext(pathToHzContext);
        this.hazelcastInstance = (HazelcastInstance) context.getBean("testInstance");
        this.executorService = Executors.newFixedThreadPool(30);
    }

    public void go()
    {
        // fill the map with entries
        ConcurrentMap<Integer, GridEntry> testMap = hazelcastInstance.getMap("testMap");
        Random random = new Random(System.currentTimeMillis());
        for (int i=0; i<2000; i++)
        {
            testMap.put(i, new GridEntry(random.nextInt(), random.nextInt(), random.nextInt()));
        }

        // make multiple threads constantly deserialize the map
        for (int i=0; i<30; i++)
        {
            executorService.execute(new MapPounder(testMap));
        }
    }

    public static class GridEntry implements DataSerializable
    {
        private Integer arg1;
        private Integer arg2;
        private Integer arg3;

        public GridEntry() {}

        public GridEntry(Integer arg1, Integer arg2, Integer arg3)
        {
            this.arg1 = arg1;
            this.arg2 = arg2;
            this.arg3 = arg3;
        }

        public Integer getArg1() { return arg1; }

        public void setArg1(Integer arg1) { this.arg1 = arg1; }

        public Integer getArg2() { return arg2; }

        public void setArg2(Integer arg2) { this.arg2 = arg2; }

        public Integer getArg3() { return arg3; }

        public void setArg3(Integer arg3) { this.arg3 = arg3; }

        public void writeData(ObjectDataOutput out) throws IOException {
            out.writeInt(arg1);
            out.writeInt(arg2);
            out.writeInt(arg3);
        }

        public void readData(ObjectDataInput in) throws IOException {
            arg1 = in.readInt();
            arg2 = in.readInt();
            arg3 = in.readInt();
        }
    }

    public static class MapPounder implements Runnable
    {
        private final ConcurrentMap<Integer, GridEntry> map;

        public MapPounder(ConcurrentMap<Integer, GridEntry> map) {
            this.map = map;
        }

        @Override
        public void run() {

            while(!Thread.currentThread().isInterrupted()) {
                    Collection<GridEntry> mapEntries = map.values();
                try {
                    Thread.sleep(1);
                } catch (InterruptedException e) {
                    System.out.println("Thread interrupted. Exiting.");
                    Thread.currentThread().interrupt();
                }
            }
        }
    }
}

Run this with the following things in your classpath:

  • hazelcast.jar (I used 3.2, but I don't think it matters)
  • hazelcast-spring.jar (again, 3.2 but it doesn't matter)
  • spring-context-4.0.3.RELEASE.jar
  • spring-core-4.0.3.RELEASE.jar
  • spring-beans-4.0.3.RELEASE.jar
  • com.springsource.org.apache.commons.logging-1.1.1.jar
  • spring-expression-4.0.3.RELEASE.jar

This is infinitely easier using Maven, just add

  • hazelcast
  • hazelcast-spring
  • spring-core
  • spring-context
  • spring-beans
  • spring-expression
    to your pom.xml.

Add the following JVM args to your command-line:

-XX:+UnlockCommercialFeatures -XX:+FlightRecorder

Give the program the hazelcast-context.xml as a program argument.

Run Flight Recorder for a couple of minutes:

jcmd [pid] JFR.start duration=120s name="AnnotationThreadContention" filename=~/Flight1.jfr settings=profile

Open the file in Mission Control navigate to Threads-->Contention-->Top Blocking Locks and observe:

screen shot 2015-02-03 at 5 27 16 pm

@pveentjer

This comment has been minimized.

Copy link
Member

commented Feb 4, 2015

Thanks! This saves a lot of time on my side.

@bwzhang2011

This comment has been minimized.

Copy link

commented Feb 9, 2015

@fridgebuzz, did you run such around hazelcast3.4, for hz3.4 changed a lot since 3.2.

@fridgebuzz

This comment has been minimized.

Copy link
Author

commented Feb 10, 2015

@bwzhang2011 The code for the affected class (SpringManagedContext) is unchanged, so the problem exists in all versions 3.2+ (and probably earlier ones as well, though there's no profit in verifying that.)

@bwzhang2011

This comment has been minimized.

Copy link

commented Feb 10, 2015

@fridgebuzz , thanks for feed back. In my app, I set up the hazelcast cluster through hazelcast-spring similar as you referred. but I didn't use that way for IMap as you did above. maybe you could setup the mancenter for monitoring the change of the IMap. if the SpringManagedContext were the problem, hz team should take it into consideration and find the proper way to fix that.

@mesutcelik mesutcelik added this to the 3.4.3 milestone May 12, 2015

@mesutcelik mesutcelik modified the milestones: 3.5.1, 3.4.3 May 27, 2015

@bwzhang2011

This comment has been minimized.

Copy link

commented Jul 24, 2015

@fridgebuzz, any update with the issue ?

@enesakar enesakar modified the milestones: 3.5.1, 3.5.2 Jul 25, 2015

@fridgebuzz

This comment has been minimized.

Copy link
Author

commented Jul 29, 2015

@bwzhang2011 you have to ask @pveentjer.

@pveentjer

This comment has been minimized.

Copy link
Member

commented Jul 29, 2015

Could you switch to Java 8 and see what happens. In Java 7 there is:

  public <A extends Annotation> A getAnnotation(Class<A> var1) {
        if(var1 == null) {
            throw new NullPointerException();
        } else {
            this.initAnnotationsIfNecessary();
            return (Annotation)this.annotations.get(var1);
        }
    }

    private synchronized void initAnnotationsIfNecessary() {
          ....
    }

So there is always a synchronized method being called. But in Java 8 this has changed to an optimistic locking based version.

@fridgebuzz

This comment has been minimized.

Copy link
Author

commented Jul 30, 2015

As far as I can tell, the same test described above, but using JDK 1.8, does not display any contention. I'd consider it closed. Thanks.

@degerhz degerhz modified the milestones: 3.5.3, 3.5.2 Sep 8, 2015

@degerhz degerhz modified the milestones: 3.5.4, 3.5.3 Oct 6, 2015

@mesutcelik mesutcelik modified the milestones: 3.5.4, 3.7 Oct 27, 2015

@mdogan mdogan removed the PENDING label Nov 2, 2015

@emrahkocaman

This comment has been minimized.

Copy link
Contributor

commented Jan 20, 2016

I'm closing this issue then, thanks @fridgebuzz

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.