Why XmiCasSerializer is slow

["greg@holmberg.name" <ho...@comcast.net>]

I had previously described that when I used XmiCasSerializer with many (10) concurrent AnalysisEngines, my throughput dropped to about half, and wasn't scaling up.

I did some profiling of my code using JProbe, and I think I've found the problem.

I discovered that my application spent 64% of its elapsed time in XmiCasSerializer and it's child methods.  Within that, one method rose to the top: 72% of elapsed time was spent in TypeSystemImpl.ll_isValidTypeCode().  In fact, this exceeded the time spent in XmiCasSerializer (114%).

This in turn was almost all in SymbolTable.getSymbol().  This was called over 17 million times in my application, which spent 72% of its elapsed time in this one method.  99.9% of its time was spent in itself, and not it's children (Vector.get(int) was the highest child, at 0.1%).

I'm not exactly sure why this method takes so long.  I suspect it's a concurrency issue.  I see a synchronized block in the set() method, so that would be something to look into.  Given that some of my AnalysisEngines may be inserting annotations while others are executing XmiCasSerializer, I can see potential for conflict.

Hopefully, these clues will be enough for someone familiar with the code to figure it out.


Greg Holmberg

Re: Why XmiCasSerializer is slow

[Thilo Goetz <tw...@gmx.de>]

Adam Lally wrote:
[...]
> 
> Very Interesting...
> 
> Vectors are internally synchronized.  All the CASes in the CAS Pool
> share the same instance of the TypeSystemImpl, so they will all
> synchronize when calling ll_isValidTypeCode().  I wonder if switching
> the Vector to an ArrayList would help.  (Thilo, would that be safe?
> If set() is itself synchronized, and if nothing else modifies the
> table, then it seems like it would be.

Looking at the code, I think it should be safe.  Believe it or not,
this code is actually from a time when there were no ArrayLists, it's
that old :-)

--Thilo

Re: Why XmiCasSerializer is slow

[Marshall Schor <ms...@schor.com>]

Adam Lally wrote:
> On 7/10/07, greg@holmberg.name <ho...@comcast.net> wrote:
>> I had previously described that when I used XmiCasSerializer with 
>> many (10) concurrent AnalysisEngines, my throughput dropped to about 
>> half, and wasn't scaling up.
>>
>> I did some profiling of my code using JProbe, and I think I've found 
>> the problem.
>>
>> I discovered that my application spent 64% of its elapsed time in 
>> XmiCasSerializer and it's child methods.  Within that, one method 
>> rose to the top: 72% of elapsed time was spent in 
>> TypeSystemImpl.ll_isValidTypeCode().  In fact, this exceeded the time 
>> spent in XmiCasSerializer (114%).
>>
>> This in turn was almost all in SymbolTable.getSymbol().  This was 
>> called over 17 million times in my application, which spent 72% of 
>> its elapsed time in this one method.  99.9% of its time was spent in 
>> itself, and not it's children (Vector.get(int) was the highest child, 
>> at 0.1%).
>>
>> I'm not exactly sure why this method takes so long.  I suspect it's a 
>> concurrency issue.  I see a synchronized block in the set() method, 
>> so that would be something to look into.  Given that some of my 
>> AnalysisEngines may be inserting annotations while others are 
>> executing XmiCasSerializer, I can see potential for conflict.
>>
>> Hopefully, these clues will be enough for someone familiar with the 
>> code to figure it out.
>>
>
> Very Interesting...
>
> Vectors are internally synchronized.  All the CASes in the CAS Pool
> share the same instance of the TypeSystemImpl, so they will all
> synchronize when calling ll_isValidTypeCode().  I wonder if switching
> the Vector to an ArrayList would help.  (Thilo, would that be safe?
> If set() is itself synchronized, and if nothing else modifies the
> table, then it seems like it would be.

Or maybe not... due to Java memory model - gets need to be synch'd to see
updates that "set" did.

The overall design of having Type System Impl shared by CASes in the CAS
pool was based on the premise that the Type System was set up once for
all CASes in the pool, and is then, read-only.  However, the 
implementation of
arrays of FeatureStructures adds these kinds of types to the type system 
impl,
after the type system is "committed" and more-or-less locked against 
further
updates.  These updates might require synchronization.  A bit of 
research might
turn up other kinds of updates that can happen after type system commit. 
(or not)

I'm also not clear on how CAS Pools interact with "complete" 
deserialization - where
the type system is re-created for the CAS.  I think, in this case, the 
new type system is
not shared by other CASes.
>
> Also perhaps we can drastically reduce the number of times the
> serializer calls this method.  Among other places, it looks like it is
> called by Type.isArray, which is in turn called by
> TypeSystem.subsumes.  I'd have to run a test with the XmiCasSerializer
> to see what the real call stack looks like.
>
> -Adam
>
>

Re: Why XmiCasSerializer is slow

[Adam Lally <al...@alum.rpi.edu>]

On 7/10/07, greg@holmberg.name <ho...@comcast.net> wrote:
> I had previously described that when I used XmiCasSerializer with many (10) concurrent AnalysisEngines, my throughput dropped to about half, and wasn't scaling up.
>
> I did some profiling of my code using JProbe, and I think I've found the problem.
>
> I discovered that my application spent 64% of its elapsed time in XmiCasSerializer and it's child methods.  Within that, one method rose to the top: 72% of elapsed time was spent in TypeSystemImpl.ll_isValidTypeCode().  In fact, this exceeded the time spent in XmiCasSerializer (114%).
>
> This in turn was almost all in SymbolTable.getSymbol().  This was called over 17 million times in my application, which spent 72% of its elapsed time in this one method.  99.9% of its time was spent in itself, and not it's children (Vector.get(int) was the highest child, at 0.1%).
>
> I'm not exactly sure why this method takes so long.  I suspect it's a concurrency issue.  I see a synchronized block in the set() method, so that would be something to look into.  Given that some of my AnalysisEngines may be inserting annotations while others are executing XmiCasSerializer, I can see potential for conflict.
>
> Hopefully, these clues will be enough for someone familiar with the code to figure it out.
>

Very Interesting...

Vectors are internally synchronized.  All the CASes in the CAS Pool
share the same instance of the TypeSystemImpl, so they will all
synchronize when calling ll_isValidTypeCode().  I wonder if switching
the Vector to an ArrayList would help.  (Thilo, would that be safe?
If set() is itself synchronized, and if nothing else modifies the
table, then it seems like it would be.

Also perhaps we can drastically reduce the number of times the
serializer calls this method.  Among other places, it looks like it is
called by Type.isArray, which is in turn called by
TypeSystem.subsumes.  I'd have to run a test with the XmiCasSerializer
to see what the real call stack looks like.

-Adam

Re: Why XmiCasSerializer is slow

[Eddie Epstein <ea...@gmail.com>]

Hi Greg,

Any chance this recent post from Lev Kozakov applies to your situation?

Problem analysis:
The setUimaClassPath.bat script creates UIMA_CLASSPATH by adding UIMA
resources to the default system CLASSPATH, which may already include
3rd party JARs (like eglbatchgen.jar in WebSphere products) containing
their own implementation of org.xml.sax packages. Such JAR files may
conflict with standard JDK runtime JARs and slow down XCAS related
operations. If I manually modify the documentAnalyzer.bat script to
use 'clear' UIMA CLASSPATH, w/o default system CLASSPATH, my XMI file
opens reasonably fast (< 2 sec).

Regards,
Eddie