10 Replies Latest reply on Dec 8, 2009 1:59 PM by dward

    Performance Improvement Prop: Cache PortReference.extendedTo

    dward

      As part of the work in ActionProcessingPipeline.processPipeline(),
      ...esb.message.format.xml.HeaderImpl.toString() is called, which calls
      ...esb.addressing.Call.toString(), which calls
      ...esb.addressing.eprs.InVMEpr.toString(), which calls
      ...esb.addressing.PortReference.extendedToString().

      PortReference.extendedToString() does a substantial amount of StringBuilder appending, which surprisingly accounted for 10% of the total testing time [1].

      The proposed fix is to cache the extendedToString() value, being very careful to clear the cached value if any of the fields which build that value get mutated. So change this:

      public void setAddress(String address) {
       _address = address;
       }
       public void addExtension(PortReference.Extension extension) {
       _extensions.add(extension);
       }
       public void removeExtension (String tag, String value) {
       _extensions.remove(new Extension(tag, XMLUtil.JBOSSESB_PREFIX, XMLUtil.JBOSSESB_NAMESPACE_URI, value));
       }
       public void addExtension(String tag, String prefix, String uri, String value) {
       _extensions.add(new Extension(tag, prefix, uri, value, Extension.REFERENCE_PROPERTIES));
       }
       public void addExtension(String tag, String prefix, String uri, String value, int parent) {
       _extensions.add(new Extension(tag, prefix, uri, value, parent));
       }
       public void addExtensions(final List<Extension> extensions) {
       _extensions.addAll(extensions);
       }
       public List<Extension> getAllExtensions() {
       return _extensions;
       }
       public void clearExtensions() {
       _extensions.clear();
       }
       public String extendedToString() {
       StringBuilder addr = new StringBuilder("PortReference < ").append("<").append(XMLUtil.WSA_PREFIX).append(":Address ").append(_address + "/>");
       Iterator extensions = getExtensions();
       while (extensions.hasNext()) {
       Extension ext = (Extension) extensions.next();
       addr.append(", <").append(XMLUtil.WSA_PREFIX).append(":")
       .append(XMLUtil.REFERENCE_PROPERTIES_TAG).append(" ").append(ext.getPrefix())
       .append(":").append(ext.getTag()).append(" : ").append(ext.getValue()).append("/>");
       }
       return addr.append(" >").toString();
       }


      to this:

      public void setAddress(String address) {
       synchronized (_extendedToString_LOCK) {
       _address = address;
       _extendedToString_CACHE = null;
       }
       }
       public void addExtension(PortReference.Extension extension) {
       synchronized (_extendedToString_LOCK) {
       _extensions.add(extension);
       _extendedToString_CACHE = null;
       }
       }
       public void removeExtension (String tag, String value) {
       synchronized (_extendedToString_LOCK) {
       _extensions.remove(new Extension(tag, XMLUtil.JBOSSESB_PREFIX, XMLUtil.JBOSSESB_NAMESPACE_URI, value));
       _extendedToString_CACHE = null;
       }
       }
       public void addExtension(String tag, String prefix, String uri, String value) {
       synchronized (_extendedToString_LOCK) {
       _extensions.add(new Extension(tag, prefix, uri, value, Extension.REFERENCE_PROPERTIES));
       _extendedToString_CACHE = null;
       }
       }
       public void addExtension(String tag, String prefix, String uri, String value, int parent) {
       synchronized (_extendedToString_LOCK) {
       _extensions.add(new Extension(tag, prefix, uri, value, parent));
       _extendedToString_CACHE = null;
       }
       }
       public void addExtensions(final List<Extension> extensions) {
       synchronized (_extendedToString_LOCK) {
       _extensions.addAll(extensions);
       _extendedToString_CACHE = null;
       }
       }
       public List<Extension> getAllExtensions() {
       return Collections.unmodifiableList(_extensions);
       }
       public void clearExtensions() {
       synchronized (_extendedToString_LOCK) {
       _extensions.clear();
       _extendedToString_CACHE = null;
       }
       }
       public String extendedToString() {
       synchronized (_extendedToString_LOCK) {
       if (_extendedToString_CACHE == null) {
       StringBuilder addr = new StringBuilder("PortReference < ").append("<").append(XMLUtil.WSA_PREFIX).append(":Address ").append(_address + "/>");
       Iterator extensions = getExtensions();
       while (extensions.hasNext()) {
       Extension ext = (Extension) extensions.next();
       addr.append(", <").append(XMLUtil.WSA_PREFIX).append(":")
       .append(XMLUtil.REFERENCE_PROPERTIES_TAG).append(" ").append(ext.getPrefix())
       .append(":").append(ext.getTag()).append(" : ").append(ext.getValue()).append("/>");
       }
       _extendedToString_CACHE = addr.append(" >").toString();
       }
       return _extendedToString_CACHE;
       }
       }
       private final Object _extendedToString_LOCK = new Object();
       private String _extendedToString_CACHE = null;


      Two things worth nothing:
      1. We don't have to keep track of changes to each Extension object, as the only fields used in PortReference's extendedToString method are immutable.
      2. synchronizing on a monitor object (_extendedToString_LOCK) is done rather than synchronizing the methods so we can be selective rather than locking the entire PortReference object.
      3. Notice how getAllExtensions() protects changes to the _extensions list by now returning an unmodifiableList. I checked to make sure callers of this method never try to change the list.

      JProfiler proved this hotspot was reduced from 10% of the total testing time to 1.4% of the total testing time once the fix was applied.

      [1]
      Test Details:
      - Web Service requests through new HttpGateway to a single-action chain calling the XsltAction.
      - 50 client threads
      - each Message size is <1k
      Server Environment:
      - Sun JDK 1.5.0_22
      - Fedora 11 (Linux 2.6.30.9-99.fc11.i686.PAE)
      - 4 gigs RAM, dual-core CPU
      - JBoss ESB 4.7
      Client Environment:
      - Sun JDK 1.6.0_17
      - Fedora 11 (Linux 2.6.30.9-99.fc11.i686.PAE)
      - 2 gigs RAM, dual-core CPU
      - soapUI 3.0.1

        • 1. Re: Performance Improvement Prop: Cache PortReference.extend
          dward

          Once again, the Subject of this post was chopped. It was supposed to read "Performance Improvement Prop: Cache PortReference.extendedToString()"

          • 2. Re: Performance Improvement Prop: Cache PortReference.extend
            kconner

            It looks like the real issue is in the ActionProcessingPipeline rather than the extendedToString.

            Looks like there are a number of debug statements being invoked without guards, are they the source of this? If so, a better fix is to add the guards so that they are never invoked unless debugging is enabled (in which case the impact is not so important).

            Do you have a list of the invocation points within the pipeline?

            Kev

            • 3. Re: Performance Improvement Prop: Cache PortReference.extend
              dward

              There were indeed a couple debug statements in ActionProcessingPipeline that ended up causing extendedToString being called because they weren't surrounded in a isDebugEnabled(). I've fixed those.

              What threw me is that after fixing those, I still saw extendedToString being called (7 times for just 1 web service request!). After looking at the call stack, the debug statements were still being invoked. I looked at the jboss-log4j.xml file, and I had to uncomment out the section that limits org.jboss to INFO. Any reason why the log4j level isn't INFO by default? I think we might need to change jboss-log4j.xml in jbossesb-server-base.zip.

              • 4. Re: Performance Improvement Prop: Cache PortReference.extend
                dward

                BTW, after changing ActionProcessingPipeline (and the log4j file - haha), this bottleneck fell off JProfiler's radar. If you want I can tweak the log4j file in the zip. I'll wait for what you wanna do before I commit to the performance workspace + 4.7 CP branch.

                • 5. Re: Performance Improvement Prop: Cache PortReference.extend
                  kconner

                  So DEBUG is still enabled, and being invoked, but not being logged? Eeek.

                  I'll create an issue for the debugs and commit it, will also cache in the pipeline for when debug is not really disabled.

                  Kev

                  • 6. Re: Performance Improvement Prop: Cache PortReference.extend
                    kconner

                    On second thoughts, logging the header so many times in DEBUG is not useful (and noisy) so I will change it so that it is only logged once in DEBUG.

                    Kev

                    • 7. Re: Performance Improvement Prop: Cache PortReference.extend
                      kconner

                      David, I have created https://jira.jboss.org/jira/browse/JBESB-3044 and assigned it to you rather than commit the changes.

                      There is a diff attached with my suggestions, can you run them through your performance tests and see if that helps?

                      I have not touched the error invocations within messageTo as I feel those are separate and need tidying up independently.

                      Kev

                      • 8. Re: Performance Improvement Prop: Cache PortReference.extend
                        dward

                         

                        "Kevin.Conner@jboss.com" wrote:
                        So DEBUG is still enabled, and being invoked, but not being logged? Eeek.


                        Out-of-the-box, the (.org ESB) default profile's jboss-log4j.xml is configured such that the FILE appender will output DEBUG statements to server.log. This can be changed if you add a non-DEBUG Threshold to the FILE appender (it currently doesn't have a Threshold set)
                        <param name="Threshold" value="INFO"/>

                        , or you can just remove the FILE appender completely.

                        The CONSOLE appender is set with a Threshold of INFO, so you don't see any DEBUG output, however debug statements are still called (logger.isDebugEnabled() still returns true) unless you uncomment this section:
                        <!-- Limit JBoss categories
                        <category name="org.jboss">
                         <priority value="INFO"/>
                        </category>
                        -->

                        to set the log level of that logger. So, in summary, log events are still being created (which means unecessary debug code like String-building is still occurring), even if the Threshold of the Appender is filtering them out. We need to stop the events from being fired in the first place, which means setting a priority/level on the right logger categories.

                        Can I change this along with JBESB-3044, or should it be it's own Jira issue?

                        • 9. Re: Performance Improvement Prop: Cache PortReference.extend
                          kconner

                          No, logging is not within our remit. If people want to run with debugging enable then that is their choice and is the norm within the project releases, the platform releases take a different view though.

                          The patch I have suggested should reduce the number of invocations to one during each message processing, which is all that is really required. Having it included for every processor was overkill.

                          Kev

                          • 10. Re: Performance Improvement Prop: Cache PortReference.extend
                            dward