[hibernate-issues] [Hibernate-JIRA] Updated: (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:all-tabpanel ]

Paul Cowan updated HHH-2645:
----------------------------

    Attachment: maptest.patch

Attached is a very rough-and-ready, cobbled-together test which very approximately demonstrates the problem and is fairly adjustable to show different alternatives for the different 'real-world' scenarios people might be encountering. The patch should apply cleanly to the 3.2.4sp1 codebase, which is what we're running; not sure how cleanly it will apply elsewhere but it's extremely simple. It consists of 2 parts:

1) It changes EntityModeToTuplizerMapping to (optionally) take a Map implementation in the constructor, defaulting to the current implementation (synchronized map wrapped around a SequencedHashMap).

2) A simple test (not JUnit, just a main() method) which performs a very simple timing test. It does 2 runs, one of which is thrown away and is just used to try and get the VM up to speed with JITting etc. so as to produce a (slightly) more accurate result. The main emphasis of the test is to create a number of threads, each of which will perform a particular number of iterations. In each iteration, a certain number of guessEntityMode()s and a certain number of getTuplizerOrNull()s will be performed against a very simple dummy subclass of EntityModeToTuplizerMapping which in turn uses a simple dummied-out Tuplizer implementation. The test is performed once using the current synchronised version, once with FastHashMap, once with Doug Lea's ConcurrentHashMap, and once with his ConcurrentReaderHashMap (obviously this requires the concurrent library to be on the classpath).

It cuts a lot of corners, but it at least gives us something to work from. The behaviour can be adjusted by modifying the values of the 6 constants at the top of the file. Running 20 threads, with a 20:1 getTuplizerOrNull():guessEntityMode() ratio (which is a very rough attempt to recreate what we see in our system, in that we flush extremely frequently and I gather this triggers the getTuplizerOrNull(); as far as I can tell guessEntityMode() is most likely to be used in finding-by-example, which is rare in our application) on the Server VM I get the following results:

Map class: class java.util.Collections$SynchronizedMap: 1510ms
Map class: class org.hibernate.util.FastHashMap: 292ms (x0.19337748344370861)
Map class: class EDU.oswego.cs.dl.util.concurrent.ConcurrentHashMap: 787ms (x0.5211920529801325)
Map class: class EDU.oswego.cs.dl.util.concurrent.ConcurrentReaderHashMap: 532ms (x0.352317880794702)

which shows a ~3x speedup with ConcurrentReaderHashMap and a ~5x speedup with FastHashMap.

If you play with the ratios, you'll see that the higher the ratio of tuplizer gets:entity mode guesses, the bigger the problem is and the bigger improvements can be gained. If you eliminate the guessEntityMode() calls completely (this is actually probably closer to the real-world figure we get, though I don't have exact counts to hand) the speedup is ~ 17x with FastHashMap.

>From this, I would draw a few conclusions:
* Given that update frequency is (as far as I can observe) close to zero -- I think these mappings are largely set up once and forgotten? I may be wrong though -- FastHashMap is probably more than sufficient, particularly given it's in the codebase already
* It may be worth considering changing FastHashMap into a more generic FastMap, which takes in some sort of MapFactory. The default implementation could use HashMap, but the TuplizerMapping could use SequencedHashMap to preserve existing behaviour (if this is important).

I'd encourage people to calculate what loading makes this test (very roughly) reflect any results they see in their application to check that our figures are not 'outliers' and we're operating off accurate data.

> 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: 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