1 2 Previous Next 15 Replies Latest reply: Nov 17, 2009 12:20 PM by 796085 RSS

    Same Objects, Different Serialization Performance

    843790
      I am trying to find out why java objects might serialize/deserialize 10 times faster in one application than in another application.

      - Both applications use the same JRE version (1.6.0_16-b01).
      - They are both running on the same Windows 7 system.
      - They both have the same amount of memory (-Xms128m -Xmx768m -XX:PermSize=64m -XX:MaxPermSize=128m).
      - They are using the same jar files for the same data classes
      - They are acting upon exactly the same data

      Some details:
      - The data is transferred with JMS ObjectMessages (JBoss MQ).
      - I have written custom Externalization for each class used to maximize performance.
      - Looslely, the data consists of 60 container objects, each container having a list of 1000 beans, each bean having about 25 fields - Strings, ints, longs, and booleans only.
      - This is not related to my Windows 7 system AFAICT. I have similar performance, and similar disparities, when running on server blades with linux.

      I have used JProfiler to look at both systems. Here is what I see with JProfiler:

      App A: 3,511 ms - 61 inv. javax.jms.ObjectMessage.getObject
      App B: 14,333ms - 61 inv. javax.jms.ObjectMessage.getObject

      With JProfiler, the disparity is only about 4:1. Without JProfiler, I see about 550 ms vs. 5,500 ms, or about 10:1.

      I am stumped at what to begin looking at. Are there particular JVM options I should be looking at? Without knowing where specifically to look, I have had no luck so far finding anything relevant. (I checked for a -XenableSlow option. :))

      Of course, the problem could be related to the nature of the applications. One is running under JBoss, and one is running under just Tomcat. Other than that, I don't really know what could be different about them that would account for this. So I don't know what I could describe for anyone - ask specific questions, and I will answer.

      Any help would be greatly appreciated.

      I did search the sun site (and the internetz) - If this was already answered, sorry, I did not find it.

      Edited by: kmendel on Nov 10, 2009 10:22 AM
        • 1. Re: Same Objects, Different Serialization Performance
          jtahlborn
          do you know what implementation of ObjectOutputStream you are using in each application? i believe jboss has their own custom ObjectOutputStream implementation which is supposed to be faster than the vanilla java version. you should be able to determine this by looking at the class name of the ObjectOutput instance passed to your writeExternal methods.
          • 2. Re: Same Objects, Different Serialization Performance
            843790
            do you know what implementation of ObjectOutputStream you are using in each application?
            Thanks, that's a great idea!

            I have just checked. Here's what I have. They both look the same to me.

            Faster Application
            - ObjectInput is a org.jboss.mq.SpyObjectMessage$1ObjectInputStreamExt, .bin is java.io.ObjectInputStream$BlockDataInputStream
            - ObjectOutput is java.io.ObjectOutputStream, .bout is java.io.ObjectOutputStream$BlockDataOutputStream

            Slower Application:
            - ObjectInput is a org.jboss.mq.SpyObjectMessage$1ObjectInputStreamExt, .bin is ObjectInputStream$BlockDataInputStream
            - ObjectOutput is java.io.ObjectOutputStream, .bout is java.io.ObjectOutputStream$BlockDataOutputStream

            I've written custom externalization for all my data classes. This either bypasses any JBoss serialization package, or JBoss serialization is not being used. (I would hope that custom readExternal and writeExternal methods means that the JBoss serialization is not relevant.)

            P.S. so far all my efforts to make JProfiler break down what happens inside readUTF and writeUTF (as a start) have failed. I have the sources, I've changed the filters, no luck.

            Edited by: kmendel on Nov 10, 2009 12:33 PM

            Edited by: kmendel on Nov 10, 2009 12:35 PM
            • 3. Re: Same Objects, Different Serialization Performance
              jtahlborn
              I'm assuming it's not something silly like sending to a local queue vs. sending to a remote queue?

              my next question would be what stream is underneath the objectoutputstreams (where are the bytes ultimately ending up)?

              also, when you talk about speed, are you timing serialization, deserialization, or both?
              • 4. Re: Same Objects, Different Serialization Performance
                843790
                Yes, the JBoss server is the host of the JMS queue. So it would be remote from the other, slower, application.

                However, I am measuring only the serialization/deserialization time, which is rather seperate form the transmission/propogation time.

                - during the call to ObjectMessage.setMessage(), the payload is serialized
                - during the call to ObjectMessage.getMessage(), the payload is deserialized

                Or so I have surmised. I might be missing something here.

                I think I have replied above what is beneath the ObjectInputStream/ObjectOutputStream. I followed the bin and bout fields respectively. If there's additional data I can gather to help those who would help me, can you be more specific?

                I am timing the getMessage/setMessage times. In addition, using JProfiler, I can probe all the way down to (say) ObjectInput.readUTF, and ObjectOutput.writeUTF.
                JProfiler shows that these calls are more proportionally more expensive on one system than the other. (Like I said, I have been unable to get JProfiler to break down what these methods do.)

                readUTF, readBoolean, readInt, and readLong, and their writeXxx counter-parts, seem to be the major culprits here, as best as I can tell.
                • 5. Re: Same Objects, Different Serialization Performance
                  jtahlborn
                  kmendel wrote:
                  I think I have replied above what is beneath the ObjectInputStream/ObjectOutputStream. I followed the bin and bout fields respectively. If there's additional data I can gather to help those who would help me, can you be more specific?
                  no, what is under those. the BlockDataOutputStreams are just wrappers. there is something below them that is actually getting the bytes.
                  • 6. Re: Same Objects, Different Serialization Performance
                    843790
                    Thanks for the attention.
                    jtahlborn wrote:
                    no, what is under those. the BlockDataOutputStreams are just wrappers. there is something below them that is actually getting the bytes.
                    In the fast application
                    readExternal
                    in = org.jboss.mq.SpyObjectMessage$1ObjectInputStreamExt
                       + bin = java.io.ObjectInputStream$BlockDataInputStream
                          + dout = java.io.DataInputStream
                          + in = java.io.ObjectInputStream$PeakInputStream
                             + in = java.io.ByteArrayInputStream
                    
                    writeExternal
                    out = java.io.ObjectOutputStream
                       + bout = java.io.ObjectOutputStream$BlockDataOutputStream
                          + dout = java.io.DataOutputStream
                          + out = java.io.ByteArrayOutputStream               
                    In the slow application
                    readExternal
                    in = org.jboss.mq.SpyObjectMessage$1ObjectInputStreamExt
                       + bin = java.io.ObjectInputStream$BlockDataInputStream
                          + dout = java.io.DataInputStream
                          + in = java.io.ObjectInputStream$PeakInputStream
                             + in = java.io.ByteArrayInputStream
                    
                    writeExternal
                    out = java.io.ObjectOutputStream
                       + bout = java.io.ObjectOutputStream$BlockDataOutputStream
                          + dout = java.io.DataOutputStream
                          + out = java.io.ByteArrayOutputStream 
                    (No difference I can see.)

                    I cannot find anything else that seems relevant to this. Everything else is just byte[] buffers in these objects. If there's something else to look at, what?

                    Edited by: kmendel on Nov 10, 2009 2:34 PM

                    Edited by: kmendel on Nov 10, 2009 2:35 PM

                    Edited by: kmendel on Nov 10, 2009 2:46 PM
                    • 7. Re: Same Objects, Different Serialization Performance
                      jtahlborn
                      are the objects serialized of comparable size? (especially with respect to their serialized size).
                      • 8. Re: Same Objects, Different Serialization Performance
                        843790
                        First: the idea that JBoss Serialization might be in play has lead me to investigate if there are other factors, which are not specific to serialization, might be in play.

                        For example, I have discovered that object allocation in the JBoss app is 40% faster than in the non-JBoss app.

                        Also, Class.forName is approx. 13% faster.

                        Are there any other facilities that might come into play? Facilities which JBoss might have supplied their own implementation? These differences are not enough to explain the whole discrepancy, but there may be something else that is.
                        jtahlborn wrote:
                        are the objects serialized of comparable size? (especially with respect to their serialized size).
                        Yes, they are all of comparable size, but not exactly the same. I would not hesitate to say that they are all within +/- 10% of each other.

                        How does this play in?
                        • 9. Re: Same Objects, Different Serialization Performance
                          jtahlborn
                          i'm assuming both apps are running with the "-server" option, correct?

                          the next thing i would try is isolating the serialization. i'd insert some debug code into each application just before you call the setMessage method and do your own serialization into a temporary ObjectOutputStream(ByteArrayOutputStream). i would time this code by itself and record how big the resulting byte array is. this should help you determine whether the problem is truly the serialization, or something else (e.g. the app talking to a remote queue vs talking to a local queue).
                          • 10. Re: Same Objects, Different Serialization Performance
                            843790
                            jtahlborn wrote:
                            the next thing i would try is isolating the serialization. i'd insert some debug code into each application just before you call the setMessage method and do your own serialization into a temporary ObjectOutputStream(ByteArrayOutputStream). i would time this code by itself and record how big the resulting byte array is. this should help you determine whether the problem is truly the serialization, or something else (e.g. the app talking to a remote queue vs talking to a local queue).
                            I have done this. The discrepency remains.
                            JBoss App: serialize  421 ms, deserialize  496 ms
                            Other App: serialize 4662 ms, deserialize 5568 ms
                            The serialization size is identical in both cases. 19,119,317 total bytes in 61 seperate messages.
                            jtahlborn wrote:
                            i'm assuming both apps are running with the "-server" option, correct?
                            Actually, neither are.

                            So I added the -server option to both.

                            Inexplicably, the JBoss App deserialization was about twice as slow with the -server option, although still nowhere near as slow as the non-JBoss app. There was no other appreciable difference in the results.

                            Edited by: kmendel on Nov 16, 2009 8:15 AM
                            • 11. Re: Same Objects, Different Serialization Performance
                              jtahlborn
                              kmendel wrote:
                              So I added the -server option to both.

                              Inexplicably, the JBoss App deserialization was about twice as slow with the -server option, although still nowhere near as slow as the non-JBoss app. There was no other appreciable difference in the results.
                              this is most likely because the server jit takes longer to warm up (it lets the app run longer before attempting to optimize).

                              at this point, i'm out of suggestions. however, you've narrowed your problem code down to a fairly small chunk, so i would continue to try to narrow things down, try smaller objects, see if you can profile into the jdk code, try a different profiler, etc.

                              you could also try posting in the jboss forums to see if they have any ideas (assuming you haven't already).
                              • 12. Re: Same Objects, Different Serialization Performance
                                843790
                                Well, thanks for the ideas, they were good ones.

                                I am starting to think that my problem is more general than serialization. Something systemic and heretofore unnoticed.

                                We noticed in JProfiler that BlockingLinkedList.add() was significantly slower between the two programs.

                                This lead me to test the performance of ReentrantLock.lock() and .unlock(). It takes about 20 times longer in the slow app.

                                This lead me to test the performance of Thread.currentThread(). It takes almost 30 times longer in the slow app.

                                If only we could figure out why.
                                • 13. Re: Same Objects, Different Serialization Performance
                                  843790
                                  Seems I was running with -XX:enableSlow after all.

                                  Except it's spelled "-Djava.compiler=NONE".
                                  • 14. Re: Same Objects, Different Serialization Performance
                                    jtahlborn
                                    kmendel wrote:
                                    Seems I was running with -XX:enableSlow after all.

                                    Except it's spelled "-Djava.compiler=NONE".
                                    ouch.
                                    1 2 Previous Next