Performance regression in corba serialization in migration glassfish 4.0 -> payara-4.1.151

[matthiasblaesing]

When upgrading our internal servers we decided to upgrade from glassfish 4.0 to payara 4.1 as we plan to aquire support for the application support and so glassfish is not an option anymore.

The upgrade was very smooth but now a collegue is facing an issue, that shows in very slow Inter-Application access times. The interface he accesses is available as a webservice and via EJB-Remote Interface. The webservice returned the requested results in about two seconds, while the EJB-Remote interface request took about two minutes!

I investigated further and it turns out, that it can be traced back into the corba serialization. For now we replaced the glassfish-corba-orb.jar in payara 4.1 with the one from glassfish 4.0, this works and brings back the performance, but my plan was to use payara because in the past I already had to patch glassfish and wanted to reduce this.

Analysis

Analysis with jvisual VM show high runtime for a call of a method called duplicateIndirectionOffset called from com.sun.corba.ee.impl.misc.CacheTable#put_table. This is part of the deserialization of the datastream resulting from the EJB call.
That call (duplicateIndirectionOffset) is defined in: https://java.net/projects/glassfish-corba/sources/hg/content/orbmain/src/main/java/com/sun/corba/ee/spi/logging/ORBUtilSystemException.java (line 1271):

@Log( level=LogLevel.FINE, id=75 )
@Message( "Old entry in serialization indirection table has a "
 + "different value than the value being added with the same key" )
INTERNAL duplicateIndirectionOffset(  ) ;

The call is done from:

https://java.net/projects/glassfish-corba/sources/hg/content/orbmain/src/main/java/com/sun/corba/ee/impl/misc/CacheTable.java?rev=957

line 178. The comment there is interesting:

// duplicateIndirectionOffset error here is not an error:
// A serializable/externalizable class that defines
// a readResolve method that creates a canonical representation
// of a value can legally have the same key occuring at
// multiple values.  This is GlassFish issue 1605.
// Note: we store this anyway, so that getVal can find the key.
wrapper.duplicateIndirectionOffset();

The problem is, that the method call results in creating a stack trace, that is the expensive operation in this case an even more later discarded.

The stackTrace is generated in:

https://hg.java.net/hg/gmbal~pfl/file/812cb7dfaf52/pfl-basic/src/main/java/org/glassfish/pfl/basic/logex/WrapperGenerator.java

line 513.

From my point of view this call is totally useless, as the return value is discarded and logging in handleFullLogging is commented out.

The problem seems to only affects deserializing primitive-boxed-Types with explizitly allocated values. I asume(!) that the empty String "" is no contained multiple times in the datastream from the EJB reaching the CacheTable put_table method and causing hashCollisions when deseralizing.

Demonstration

To demonstate the problem (and the gravity) I created a producer and a consumer of an EJB-Interface, that serializes

a) a class only containing explizitly allocated primitive boxed types (DemoData.java) and
b) a class with the same structure but using primitives

The demo (see below) is deployed into a fresh payara 4.1.151 installation and run.

I did two runs: One with the glassfish-corba-orb.jar from the distribution above and one where I replace the orb with the one from glassfish 4.0.

Results with payara 4.1 orb: https://github.com/matthiasblaesing/payara-corba-serialisierung-slow/blob/master/additional_data/output-bad-orb.txt
Results with glassfish 4.0 orb: https://github.com/matthiasblaesing/payara-corba-serialisierung-slow/blob/master/additional_data/output-good-orb.txt

You see, that deserialzing the boxed types is 400(!) time slower than the primitives and the sampler profile clearly indicates the call to the stacktrace generator as the problem.

To reproduce:

1. Install a clean payara 4.1.151 and start it
2. Build the Demo-Producer and deploy it into the payara installation
3. Build the Demo-Consumer and deploy it into the payara installation
4. Launch the consumer (this is the "bad" run)
5. Shutdown the payara installation
6. Clean the glassfish/domains/domain1/generated and glassfish/domain/domain1/osgi-cache directories
7. Remove glassfish-corba-orb.jar from glassfish/modules
8. Copy the glassfish 4.0 orb into glassfish/modules (see below for source)
9. Start payara again
10. Launch consumer

Reference material

Repository: https://github.com/matthiasblaesing/payara-corba-serialisierung-slow
Profiler-Snapshot (sampled): https://github.com/matthiasblaesing/payara-corba-serialisierung-slow/blob/master/additional_data/sampler-profile-bad-orb.nps

Demo-Producer: https://github.com/matthiasblaesing/payara-corba-serialisierung-slow/tree/master/corbaserialisierung2-provider
Demo-Consumer: https://github.com/matthiasblaesing/payara-corba-serialisierung-slow/tree/master/crobaserialisierung-consumer

Orb from payara 4.1.151: https://github.com/matthiasblaesing/payara-corba-serialisierung-slow/blob/master/additional_data/glassfish-corba-orb-bad.jar
Orb from glassfish 4.0: https://github.com/matthiasblaesing/payara-corba-serialisierung-slow/blob/master/additional_data/glassfish-corba-orb-good.jar

If you need further information, please feel free to contact me.

[smillidge]

Thanks Matthias,

Does the same delay occur on standard GlassFish 4.1 as I don't believe we have changed any code in this area from GlassFish 4.1?

We will definitely investigate and get a fix out there.

[matthiasblaesing]

Hello Steve,

thank you for your quick reply! Your feeling was correct, the same problem can be observed with glassfish 4.1. And the fix is also working the same way (so stock glassfish 4.1 is bad, glassfish 4.1 with glassfish-corba-orb.jar from 4.0 is good).

From a potential fix viewpoint I would check whether the call:

wrapper.duplicateIndirectionOffset();

has any wanted side effects and if not just drop the call from put_table. The comments seems to indicate, that the situation is expected and so this worst case call is inappropriate. But this is just the perspective from a "user" of glassfish.

[smillidge]

Regression has been made between versions 4.0.0-b007 and 4.0.0-b008

GlassFish 4.0 Corba version
<glassfish-corba.version>4.0.0-b007</glassfish-corba.version>

6th Jan 2014 0c72b57#diff-1a0ff1b907622b750405cad68426242d Changes Corba version 4.0.0-b008

5530420#diff-1a0ff1b907622b750405cad68426242d Upgrades to 4.0.1

Regression must have occurred between b07 and b08

[smillidge]

Reproduced on current Payara 4.1.152 build

[smillidge]

Offending stack trace

"http-listener-1(3)" #37 daemon prio=5 os_prio=0 tid=0x00007f48e0151800 nid=0x31f6 runnable [0x00007f490df58000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.Throwable.getStackTraceDepth(Native Method)
    at java.lang.Throwable.getOurStackTrace(Throwable.java:824)
    - locked <0x00000000f7c0eef0> (a org.omg.CORBA.INTERNAL)
    at java.lang.Throwable.getStackTrace(Throwable.java:816)
    at org.glassfish.pfl.basic.logex.WrapperGenerator.trimStackTrace(WrapperGenerator.java:421)
    at org.glassfish.pfl.basic.logex.WrapperGenerator.handleFullLogging(WrapperGenerator.java:514)
    at org.glassfish.pfl.basic.logex.WrapperGenerator$2.invoke(WrapperGenerator.java:656)
    at org.glassfish.pfl.basic.proxy.CompositeInvocationHandlerImpl.invoke(CompositeInvocationHandlerImpl.java:114)
    at com.sun.proxy.$Proxy162.duplicateIndirectionOffset(Unknown Source)
    at com.sun.corba.ee.impl.misc.CacheTable.put_table(CacheTable.java:178)
    at com.sun.corba.ee.impl.misc.CacheTable.put(CacheTable.java:157)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:1016)
    at com.sun.corba.ee.impl.encoding.CDRInputObject.read_value(CDRInputObject.java:518)
    at com.sun.corba.ee.impl.io.IIOPInputStream.inputObjectField(IIOPInputStream.java:2160)
    at com.sun.corba.ee.impl.io.IIOPInputStream.inputClassFields(IIOPInputStream.java:2402)
    at com.sun.corba.ee.impl.io.IIOPInputStream.inputObject(IIOPInputStream.java:1222)
    at com.sun.corba.ee.impl.io.IIOPInputStream.simpleReadObject(IIOPInputStream.java:423)
    at com.sun.corba.ee.impl.io.ValueHandlerImpl.readValueInternal(ValueHandlerImpl.java:307)
    at com.sun.corba.ee.impl.io.ValueHandlerImpl.readValue(ValueHandlerImpl.java:273)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.readRMIIIOPValueType(CDRInputStream_1_0.java:893)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:995)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:813)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_abstract_interface(CDRInputStream_1_0.java:806)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_abstract_interface(CDRInputStream_1_0.java:796)
    at com.sun.corba.ee.impl.encoding.CDRInputObject.read_abstract_interface(CDRInputObject.java:544)
    at com.sun.corba.ee.impl.io.IIOPInputStream.readObjectDelegate(IIOPInputStream.java:389)
    at com.sun.corba.ee.impl.io.IIOPInputStream.readObjectOverride(IIOPInputStream.java:542)
    at java.io.ObjectInputStream.readObject(ObjectInputStream.java:365)
    at java.util.ArrayList.readObject(ArrayList.java:791)
    at sun.reflect.GeneratedMethodAccessor93.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at com.sun.corba.ee.impl.io.IIOPInputStream.invokeObjectReader(IIOPInputStream.java:1830)
    at com.sun.corba.ee.impl.io.IIOPInputStream.inputObject(IIOPInputStream.java:1212)
    at com.sun.corba.ee.impl.io.IIOPInputStream.simpleReadObject(IIOPInputStream.java:423)
    at com.sun.corba.ee.impl.io.ValueHandlerImpl.readValueInternal(ValueHandlerImpl.java:307)
    at com.sun.corba.ee.impl.io.ValueHandlerImpl.readValue(ValueHandlerImpl.java:273)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.readRMIIIOPValueType(CDRInputStream_1_0.java:893)
    at com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:995)
    at com.sun.corba.ee.impl.encoding.CDRInputObject.read_value(CDRInputObject.java:518)
    at com.sun.corba.ee.impl.presentation.rmi.DynamicMethodMarshallerImpl$14.read(DynamicMethodMarshallerImpl.java:383)
    at com.sun.corba.ee.impl.presentation.rmi.DynamicMethodMarshallerImpl.readResult(DynamicMethodMarshallerImpl.java:482)
    at com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.privateInvoke(StubInvocationHandlerImpl.java:201)
    at com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.invoke(StubInvocationHandlerImpl.java:150)
    at com.sun.corba.ee.impl.presentation.rmi.codegen.CodegenStubBase.invoke(CodegenStubBase.java:226)
    at de.persona.dev.blaesing.spielplatz.corbaserialisierung.__DemoIface_Remote_DynamicStub.createData(de/persona/dev/blaesing/spielplatz/corbaserialisierung/__DemoIface_Remote_DynamicStub.java)
    at de.persona.dev.blaesing.spielplatz.corbaserialisierung._DemoIface_Wrapper.createData(de/persona/dev/blaesing/spielplatz/corbaserialisierung/_DemoIface_Wrapper.java)
    at de.persona.dev.blaesing.spielplatz.crobaserialisierung.consumer.Reproducer.processRequest(Reproducer.java:43)
    at de.persona.dev.blaesing.spielplatz.crobaserialisierung.consumer.Reproducer.doGet(Reproducer.java:66)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:318)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
    at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
    at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
    at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:99)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:174)
    at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:415)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:282)
    at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
    at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
    at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:204)
    at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:178)
    at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
    at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:283)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:132)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:111)
    at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
    at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:536)
    at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:565)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:545)
    at java.lang.Thread.run(Thread.java:745)

[smillidge]

For the record the diff from glassfish-corba-orb 4.0.1 is;

diff -r 5541165fd78e orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_0.java
--- a/orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_0.java  Fri Mar 20 09:34:40 2015 -0400
+++ b/orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_0.java  Sat Apr 18 08:28:48 2015 +0100
@@ -144,7 +144,6 @@
     private static final OMGSystemException omgWrapper = OMGSystemException.self;
     private static final String K_READ_METHOD = "read";
     private static final int MAX_BLOCK_LENGTH = 0x7fffff00;
-    protected static final String EMPTY_STRING = "";

     protected BufferManagerRead bufferManagerRead;
     protected ByteBuffer byteBuffer;
@@ -497,7 +496,7 @@
         // zero to mean empty string.
         //
         if (len == 0) {
-            return EMPTY_STRING;
+            return new String("");
         }

         char[] result = getConvertedChars(len - 1, getCharConverter());
@@ -516,8 +515,8 @@
         // zero to mean empty string.
         //
         if (len == 0) {
-            return EMPTY_STRING;
-        }
+            return new String("");
+       }

         len--;
         char[] c = new char[len];
@@ -567,7 +566,7 @@
         // zero to mean empty string.
         //
         if (len == 0) {
-            return EMPTY_STRING;
+            return new String("");
         }

         checkForNegativeLength(len);
diff -r 5541165fd78e orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_1.java
--- a/orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_1.java  Fri Mar 20 09:34:40 2015 -0400
+++ b/orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_1.java  Sat Apr 18 08:28:48 2015 +0100
@@ -184,7 +184,7 @@
         // zero to mean empty string.
         //
         if (len == 0)
-            return EMPTY_STRING;
+            return new String("");

         checkForNegativeLength(len);

diff -r 5541165fd78e orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_2.java
--- a/orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_2.java  Fri Mar 20 09:34:40 2015 -0400
+++ b/orbmain/src/main/java/com/sun/corba/ee/impl/encoding/CDRInputStream_1_2.java  Sat Apr 18 08:28:48 2015 +0100
@@ -160,7 +160,7 @@
         int len = read_long();

         if (len == 0)
-            return EMPTY_STRING;
+            return new String("");

         checkForNegativeLength(len);

[smillidge]

Thanks for comprehensive issue report. It made the issue very easy to track down.

[smillidge]

Please download the latest prerelease to check the problem is fixed.

http://www.payara.fish/upstream_builds

[matthiasblaesing]

That was fast. And I can verify the fix. I setup our failing application in a testinstallation of the 1.4.152-pre-release. I reduced that also to a simple timing test (though using the business logic) and got:

payara 4.1.151: 188926 ms
payara 4.1.152-prerelease: 2574 ms

Good work!