[hibernate-issues] [Hibernate-JIRA] Commented: (HHH-2645) Synchronization bottleneck in EntityModeToTuplizerMapping

[Paul Cowan (JIRA)]

    [ http://opensource.atlassian.com/projects/hibernate/browse/HHH-2645?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#action_28849 ] 

Paul Cowan commented on HHH-2645:
---------------------------------

Thanks Steve -- those results ARE extremely confusing, as I can reproduce your results on my machine, but running MY version produces basically the same results as before. This, to put not too fine a point on it, confused the @#$! out of me. After spending WAY too long incrementally refactoring my code towards yours, though, continually running mine until I got results like yours, I worked it out. There IS one subtle difference between our codebases.

You have:

	Map fastMap = new org.apache.commons.collections.FastHashMap();

where I had:

	liveRun(new FastHashMap(), base);
with (drumroll):
	import org.hibernate.util.FastHashMap;

org.hibernate.util.FastHashMap != org.apache.commons.collections.FastHashMap. D'oh! Can't believe it took me that long to work it out. :)

If I amend your code to add:
		Map fastMapHibernate = new org.hibernate.util.FastHashMap();
		fastMapHibernate.put( EntityMode.DOM4J, tuplizer1 );
		fastMapHibernate.put( EntityMode.POJO, tuplizer2 );
and the according dry + live runs, I get:

baseline : 2815 ms
FastHashMap (Apache) : 2576 ms (ratio=0.9150977)
FastHashMap (Hibernate) : 380 ms (ratio=0.13499112)
ConcurrentHashMap (jdk) : 473 ms (ratio=0.16802841)
ConcurrentHashMap (dl) : 1740 ms (ratio=0.6181172)
ConcurrentReaderHashMap (dl) : 1060 ms (ratio=0.37655416)

which neatly encapsulates the difference we got (again, this is with the server VM, the proportions differ somewhat with the client VM but they're in the ballpark).

Why is this the case? Well, change the code to call .setFast(true) on the Apache map and suddenly the figure drops to ~ the org.hibernate version. If the Apache one isn't in fast mode, it's effectively fully synchronised (which explains why the performance is close to the Collections.synchronizedMap wrapper).

So that explains that. Phew! Hopefully that gets us all on the same page.

2 other things:

1) Minor thing but, if you're thinking of landing this test in the codebase, check the classname: 'Acess' -> 'Access'. 
2) I don't know where the 'open the floodgates' latch-based concurrent test idiom came from, to be honest. Been using it for a while; either stumbled upon it myself one day or absorbed it by osmosis from a colleague, not sure. It's damn handy though!

> Synchronization bottleneck in EntityModeToTuplizerMapping
> ---------------------------------------------------------
>
>                 Key: HHH-2645
>                 URL: http://opensource.atlassian.com/projects/hibernate/browse/HHH-2645
>             Project: Hibernate3
>          Issue Type: Patch
>          Components: core
>    Affects Versions: 3.2.3, 3.2.4, 3.2.4.sp1
>         Environment: Hibernate 3.2.3 (and later), Sun's JDK 1.4.2_12 (server VM) on SunOS 5.10, Oracle 10g R2
>            Reporter: Erik Bergersjö
>            Assignee: Gail Badner
>            Priority: Minor
>         Attachments: ConcurrentMapAcessPerformanceTest.java, concurrentreader.patch, maptest.patch
>
>
> We have had a major performance bottleneck in EntityModeToTuplizerMapping with Hibernate version 3.2.3 and the code for that class in 3.2.4sp1 is unchanged. We have found a solution that solves the issue and would like to get it into the real version. I submitted to the user forum first and was asked to create a JIRA issue.
> The problematic line is:
> private final Map tuplizers = Collections.synchronizedMap( new SequencedHashMap() );
> We have changed it to (using util.concurrent):
> private final Map tuplizers = new EDU.oswego.cs.dl.util.concurrent.ConcurrentReaderHashMap();
> This change alone makes our use cases six times faster. The difference is that ConcurrentReaderHashMap handles concurrent readers much better, they don't have to wait for each other.
> The problem occurs when a high number of threads try to initialize sets (see mapping below). A thread dump showed a high number of threads waiting for the same monitor, see partial stack trace below.
> The code runs on Sun's JDK 1.4.2_12 (server VM) on SunOS 5.10 and the kernel spends a lot of time handling mutexes with the original implementation. That time disappears from the radar screen with the fixed version.
> Example mapping for set:
> [code]
> <set name="lines" lazy="true"  inverse="true" cascade="all-delete-orphan">
>   <key>
>       <column name="col1" not-null="true" />
>       <column name="col2" not-null="true" />
>    </key>
>    <one-to-many class="LineClass" />
> </set>
> [/code]
> Stack trace (partial):
> "Thread-108" prio=5 tid=0x05852e90 nid=0x103 waiting for monitor entry [0x3ed7e000..0x3ed7fc28]
>         at java.util.Collections$SynchronizedMap.get(Collections.java:1942)
>         - waiting to lock <0x89d30788> (a java.util.Collections$SynchronizedMap)
>         at org.hibernate.tuple.EntityModeToTuplizerMapping.getTuplizerOrNull(EntityModeToTuplizerMapping.java:53)
>         at org.hibernate.tuple.EntityModeToTuplizerMapping.getTuplizer(EntityModeToTuplizerMapping.java:66)
>         at org.hibernate.type.ComponentType.getPropertyValues(ComponentType.java:353)
>         at org.hibernate.type.ComponentType.isEqual(ComponentType.java:141)
>         at org.hibernate.engine.CollectionKey.equals(CollectionKey.java:50)
>         at java.util.HashMap.eq(HashMap.java:274)
>         at java.util.HashMap.get(HashMap.java:323)
>         at org.hibernate.engine.loading.CollectionLoadContext.getLocalLoadingCollectionEntry(CollectionLoadContext.java:163)
>         at org.hibernate.engine.loading.CollectionLoadContext.locateLoadingCollectionEntry(CollectionLoadContext.java:150)
>         at org.hibernate.engine.loading.CollectionLoadContext.getLoadingCollection(CollectionLoadContext.java:92)
>         at org.hibernate.loader.Loader.readCollectionElement(Loader.java:1003)
>         at org.hibernate.loader.Loader.readCollectionElements(Loader.java:646)
>         at org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:591)
>         at org.hibernate.loader.Loader.doQuery(Loader.java:701)
>         at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
>         at org.hibernate.loader.Loader.loadCollection(Loader.java:1994)
>         at org.hibernate.loader.collection.CollectionLoader.initialize(CollectionLoader.java:36)
>         at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:565)
>         at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:60)
>         at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1716)
>         at org.hibernate.collection.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:344)
>         at org.hibernate.collection.AbstractPersistentCollection.read(AbstractPersistentCollection.java:86)
>         at org.hibernate.collection.PersistentSet.iterator(PersistentSet.java:163)
>  

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://opensource.atlassian.com/projects/hibernate/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira