glassfish
  1. glassfish
  2. GLASSFISH-14077

[PERF] investigate performance bottleneck in GMS deserialization in trade2 benchmark

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.1
    • Fix Version/s: 3.1_dev
    • Labels:
      None
    • Environment:

      Operating System: All
      Platform: All

    • Issuezilla Id:
      14,077

      Description

      With availability-enabled set to true running the trade2 benchmark with
      profiling info being collected, it was identified that GMS deserialization was
      taking a substantial amount of time.

      Given the buffering of replicated data that HA is using, it is believed that the
      message size is around 80K. Given that GMS over Grizzly transport is relying on
      composite buffer (virtual buffer that spans multiple grizzly physical buffers),
      there is potential that improvements to that would assist this issue.

      Alexey will assist in improving composite buffer management. GMS team will also
      work on stats monitor so we know precisely what the usage characteristics are
      and to track where the time is going during deserialization in this benchmark.

        Issue Links

          Activity

          Hide
          Joe Fialli added a comment -

          Stack trace from trade2 that shows composite object get (ByteBuffersBuffer.get()
          ) occuring during NetworkUtility.deserialize().
          Theory is that deserialization is waiting for virtual composite object
          construction. During profiling the network latency is showing
          as part of deserialization since deserialization is occuring in virtual buffer
          (that is accumulating multiple grizzly buffers).

          GMS-GrizzlyControllerThreadPool-Group-trade2(72)" daemon prio=10
          tid=0x00002aabdca6a800 nid=0x6093 runnable [0x0000000044fc9000]
          java.lang.Thread.State: RUNNABLE
          at
          com.sun.enterprise.mgmt.transport.ByteBuffersBuffer.get(ByteBuffersBuffer.java:56)
          at
          com.sun.enterprise.mgmt.transport.BufferInputStream.read(BufferInputStream.java:70)
          at java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2266)
          at java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2279)
          at
          java.io.ObjectInputStream$BlockDataInputStream.readUTFBody(ObjectInputStream.java:3019)
          at
          java.io.ObjectInputStream$BlockDataInputStream.readUTF(ObjectInputStream.java:2820)
          at java.io.ObjectInputStream.readUTF(ObjectInputStream.java:1051)
          at java.io.ObjectStreamClass.readNonProxy(ObjectStreamClass.java:616)
          at java.io.ObjectInputStream.readClassDescriptor(ObjectInputStream.java:809)
          at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1565)
          at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1496)
          at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1316)
          at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1947)
          at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1871)
          at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1753)
          at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329)
          at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
          at
          com.sun.enterprise.mgmt.transport.NetworkUtility.deserialize(NetworkUtility.java:435)
          at
          com.sun.enterprise.mgmt.transport.MessageImpl.readMessagesInputStream(MessageImpl.java:277)
          at com.sun.enterprise.mgmt.transport.MessageImpl.parseMessage(MessageImpl.java:265)
          at
          com.sun.enterprise.mgmt.transport.grizzly.GrizzlyMessageProtocolParser.hasNextMessage(GrizzlyMessageProtocolParser.java:229)
          at
          com.sun.grizzly.filter.ParserProtocolFilter.execute(ParserProtocolFilter.java:145)
          at
          com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
          at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
          at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
          at
          com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
          at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
          at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
          at
          com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
          at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
          at java.lang.Thread.run(Thread.java:619)

          Show
          Joe Fialli added a comment - Stack trace from trade2 that shows composite object get (ByteBuffersBuffer.get() ) occuring during NetworkUtility.deserialize(). Theory is that deserialization is waiting for virtual composite object construction. During profiling the network latency is showing as part of deserialization since deserialization is occuring in virtual buffer (that is accumulating multiple grizzly buffers). GMS-GrizzlyControllerThreadPool-Group-trade2(72)" daemon prio=10 tid=0x00002aabdca6a800 nid=0x6093 runnable [0x0000000044fc9000] java.lang.Thread.State: RUNNABLE at com.sun.enterprise.mgmt.transport.ByteBuffersBuffer.get(ByteBuffersBuffer.java:56) at com.sun.enterprise.mgmt.transport.BufferInputStream.read(BufferInputStream.java:70) at java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2266) at java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2279) at java.io.ObjectInputStream$BlockDataInputStream.readUTFBody(ObjectInputStream.java:3019) at java.io.ObjectInputStream$BlockDataInputStream.readUTF(ObjectInputStream.java:2820) at java.io.ObjectInputStream.readUTF(ObjectInputStream.java:1051) at java.io.ObjectStreamClass.readNonProxy(ObjectStreamClass.java:616) at java.io.ObjectInputStream.readClassDescriptor(ObjectInputStream.java:809) at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1565) at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1496) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1316) at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1947) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1871) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1753) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351) at com.sun.enterprise.mgmt.transport.NetworkUtility.deserialize(NetworkUtility.java:435) at com.sun.enterprise.mgmt.transport.MessageImpl.readMessagesInputStream(MessageImpl.java:277) at com.sun.enterprise.mgmt.transport.MessageImpl.parseMessage(MessageImpl.java:265) at com.sun.enterprise.mgmt.transport.grizzly.GrizzlyMessageProtocolParser.hasNextMessage(GrizzlyMessageProtocolParser.java:229) at com.sun.grizzly.filter.ParserProtocolFilter.execute(ParserProtocolFilter.java:145) at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104) at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90) at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54) at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59) at com.sun.grizzly.ContextTask.run(ContextTask.java:71) at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532) at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513) at java.lang.Thread.run(Thread.java:619)
          Hide
          Joe Fialli added a comment -

          Created an attachment (id=5200)
          GMS send/receive message monitoring stats per targetcomponent for trade2

          Show
          Joe Fialli added a comment - Created an attachment (id=5200) GMS send/receive message monitoring stats per targetcomponent for trade2
          Hide
          Joe Fialli added a comment -

          Received three patches from Alexey to address this.

          First patch was to incorporate performance improvements made to
          ByteBuffersBuffer from Grizzly 2.0.

          Second patch was to ensure workbuffer resets itself properly after errors.

          Third patch ensured that when a selector fired that the ParserFilter just
          returned if it is an OP_WRITE. Alexey observed in trade2 logs that there were
          concurrernt READ and WRITES of same buffer.

          Also, I have added
          GMS monitoring stats taken periodically every 30 seconds for a 10 minute run
          show that there is no issue when not performing an interferring task (such as
          profiling). There looks to be issue with deserialization recovery to still work
          on.

          See attachment gmsstats.txt that demonstrate no bottleneck in gms send or
          receive when no heavy duty monitoring or logging is occuring.

          Show
          Joe Fialli added a comment - Received three patches from Alexey to address this. First patch was to incorporate performance improvements made to ByteBuffersBuffer from Grizzly 2.0. Second patch was to ensure workbuffer resets itself properly after errors. Third patch ensured that when a selector fired that the ParserFilter just returned if it is an OP_WRITE. Alexey observed in trade2 logs that there were concurrernt READ and WRITES of same buffer. Also, I have added GMS monitoring stats taken periodically every 30 seconds for a 10 minute run show that there is no issue when not performing an interferring task (such as profiling). There looks to be issue with deserialization recovery to still work on. See attachment gmsstats.txt that demonstrate no bottleneck in gms send or receive when no heavy duty monitoring or logging is occuring.
          Hide
          Joe Fialli added a comment -

          Fix for deserialization failure recovery when large messages are being sent is
          still being worked on.

          So in the absence of overhead caused by general java profiling, jmap heap dumps,
          excessively verbose logging level (GrizzlyMessageProtocolParser debug), we are
          not aware of a bottleneck in gms send/receive based on numbers in gmsstats.txt
          attached to this issue. Those stats were taken from a 10 minute trade2 run and
          showed no gms message send write timeouts (nor any times greater than 120 ms
          wall clock on send side.)

          Show
          Joe Fialli added a comment - Fix for deserialization failure recovery when large messages are being sent is still being worked on. So in the absence of overhead caused by general java profiling, jmap heap dumps, excessively verbose logging level (GrizzlyMessageProtocolParser debug), we are not aware of a bottleneck in gms send/receive based on numbers in gmsstats.txt attached to this issue. Those stats were taken from a 10 minute trade2 run and showed no gms message send write timeouts (nor any times greater than 120 ms wall clock on send side.)
          Hide
          Joe Fialli added a comment -

          Fix for deserialization failure recovery when large messages are being sent is
          still being worked on.

          So in the absence of overhead caused by general java profiling, jmap heap dumps,
          excessively verbose logging level (GrizzlyMessageProtocolParser debug), we are
          not aware of a bottleneck in gms send/receive based on numbers in gmsstats.txt
          attached to this issue. Those stats were taken from a 10 minute trade2 run and
          showed no gms message send write timeouts (nor any times greater than 120 ms
          wall clock on send side.)

          Show
          Joe Fialli added a comment - Fix for deserialization failure recovery when large messages are being sent is still being worked on. So in the absence of overhead caused by general java profiling, jmap heap dumps, excessively verbose logging level (GrizzlyMessageProtocolParser debug), we are not aware of a bottleneck in gms send/receive based on numbers in gmsstats.txt attached to this issue. Those stats were taken from a 10 minute trade2 run and showed no gms message send write timeouts (nor any times greater than 120 ms wall clock on send side.)
          Hide
          Joe Fialli added a comment -

          Alexey provided a grizzly/shoal-gms fix so we no longer suffer deserialization
          failures receiving gms messages nor write time outs sending gms messages when
          profiling the trade2 run.

          We performed jprofile on a trade2 run and additionally did another run taking
          jmap -histo/jstack every 2 minutes. There were no write time outs or
          deserialization failures in server.log.

          Will close this issue with next shoal integration.

          Show
          Joe Fialli added a comment - Alexey provided a grizzly/shoal-gms fix so we no longer suffer deserialization failures receiving gms messages nor write time outs sending gms messages when profiling the trade2 run. We performed jprofile on a trade2 run and additionally did another run taking jmap -histo/jstack every 2 minutes. There were no write time outs or deserialization failures in server.log. Will close this issue with next shoal integration.
          Hide
          Joe Fialli added a comment -

          there is no identified bottlenecks at this time.
          however, have been blocked in getting a successful profiling trade2 run
          by other outstanding issues.

          leaving this open but all of the previously reported issues have been addressed.
          This can be closed after a successful profiling run confirms no outstanding
          bottlenecks in gms subsystem.

          Show
          Joe Fialli added a comment - there is no identified bottlenecks at this time. however, have been blocked in getting a successful profiling trade2 run by other outstanding issues. leaving this open but all of the previously reported issues have been addressed. This can be closed after a successful profiling run confirms no outstanding bottlenecks in gms subsystem.
          Hide
          Joe Fialli added a comment -

          Closing this since the initial issue was only observable when profiling or other extra monitoring tools slowed up the system so much that GMS started timing out during writing. This resulted in stream corruption and deserialization
          WARNING messages. This is now corrected in gms over grizzly. So closing this issue for time being. It can be reopened if future profiling shows any issues with GMS deserialization.

          Show
          Joe Fialli added a comment - Closing this since the initial issue was only observable when profiling or other extra monitoring tools slowed up the system so much that GMS started timing out during writing. This resulted in stream corruption and deserialization WARNING messages. This is now corrected in gms over grizzly. So closing this issue for time being. It can be reopened if future profiling shows any issues with GMS deserialization.

            People

            • Assignee:
              Joe Fialli
              Reporter:
              Joe Fialli
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: