Optimize loading

lamah
2008-07-23
2013-05-02
  • lamah
    lamah
    2008-07-23

    Hi!

    I was wondering if you have thought about optimizing the loading of plugins even more? I do not mean the classloading, it seems fine. However, the IO operations seems to take a great deal of time. I haven't taken the time yet to look through the source, but do you unpack all the jars every time the application is launched? If you do then I would assume this could be optimized by doing the unpacking once and keeping track of the lastModified timestamp of the plugin archives. Then you could detect if a plugin has been changed and redo its unpacking when necessary.

    You could also check every IO operation to see if it is properly buffered or if it is absolutely necessary to do at startup.

    I have used/thought about:
    Latest JRE (yes the beta)
    Lazy initialization of my UI
    Turned off JPF integrity checking of plugins
    Turned off logging

    I have used JProfiler which marks some of the JPF IO stuff as hotspots at startup. (I do not have the trace right now but I could provide it...)

    regards,

    Mats

     
    • lamah
      lamah
      2008-07-25

      Here is a JProfiler hotspot trace of my application startup:

      http://rapidshare.com/files/132418052/screen.png.html

      From looking at the source it seems you unpack/create the shadow folder every time the application is launched. Is that really necessary?

       
      • Jonathan Giles
        Jonathan Giles
        2008-07-25

        Looking at your screenshot, I think you should be quite pleased - the slowdown due to using plugins is seemingly minimal. Roughly summing the three largest hotspots you're losing about 1.6 seconds at startup, which is neglible I would argue given the various benefits of plugins.

        I would argue that the largest slowdown isn't in the unpacking, but in the activation of plugins in the standardPluginManager, but from my understanding this is unlikely to be improved due to the dependence on Java security code being invoked.

        I would love to improve the JPF performance, but I think from a very quick look through the code it is already quite clean and efficient.

        Also, have you looked at the configuration options detailed on the jpf website regarding unpacking modes?

        -- Jonathan

         
    • lamah
      lamah
      2008-07-26

      For desktop applications I would argue that 1.6 seconds is quite a lot if the startup time is about 3-4 seconds like mine is now. But if I could reduce the startup time with just 400 milliseconds I would not hesitate to do it. I have now done some experiments with the JPF code and have verified some of my suspicions.

      From the JProfiler trace it seemed obvious, at least to me, that the slowdown was mainly caused by four things:
      1. The mkdirs in the unpacking
      2. The copying from the jar files to the shadow dir during unpacking
      3. The deletion of dirs and files (before copying to the shadow dir)
      4. The setlastmodified actions done on ALL zip entry files (which can be quite a lot of files...) (Why do you do this?)

      I assume that most of the JPF code is written because it is absolutely necessary to to the things that are done. Nonetheless, I started commenting out various sections of the code to see what would happen and if my application would still run. The first optimization I did was this:

      Many places in the code I found this:
      OutputStream out = new BufferedOutputStream(new FileOutputStream(entryFile, false));
      try {
          InputStream in = zipFile.getInputStream(entry);
          try {
              IoUtil.copyStream(in, out, 1024);
          } finally {
              in.close();
          }
      } finally {
          out.close();
      }

      This piece of code has a small optimization by removing the BufferedOutputStream entirely. The reason it is faster to remove it is because you are already doing buffering in the IOUtil.copyStream method. By adding the BufferedOutputStream you would in effect buffer it twice and it is not as effective. However, the benefit is not great, but every little bit counts.

      Now the big optimization is in my opinion to remove the need to unpack more than once. That is, you unpack once then every subsequent application launch will use the same unpacked files... unless something has changed in those unpacked files. This optimization would remove both the mkdirs and the copying from the jars to the shadow dirs. Additionally there would be no need to delete any files or dirs either.

      So what I (basically) did was that I:
      1. Saved permanently (using the Preference api) the "lastmodified" property for the shadow dir of each plugin after unpacking once. Then every time afterwards I check the lastmodfied property of the shadow dir against the saved version of the lastmodified property to see if the plugin should be unpacked again.
      2. I commented out the whole emptyFolder method in the IoUtil class (returning just true instead)
      3. I commented out all the setlastmodified method calls everywhere... (why are they needed?)

      The end result was:
      - Almost 1.5-2.0 seconds faster launch
      - If I replace plugins (when program in closed) it will change the lastmodified property and consequently JPF will replace the necessary files at next launch

      Everything as far as I can tell works perfectly for my relatively large application (14 plugins) using these simple changes. Now I am aware that these changes probably have various drawbacks that I am not aware of. I am assuming for instance that this would break any type of hot deployment, but I do not need hot deployment and I do not want to pay the price for it. Is it possible something similar like this could be implemented and if it just breaks hot deployment couldn't we make hot deployment configurable so that people that do not need it do not lose any performance?

      The performance gain was really quite stunning. I would be glad to help with implementing a solution for this in any way I can!
      When profiling after these changes were made the biggest hotspot was the classloading done by JPF.

      Oh.. I also used this approach with both "smart" and "always" unpacking as configured in the boot.properties

       
      • Jonathan Giles
        Jonathan Giles
        2008-07-26

        Very interesting results.

        Unfortunately, I have not heard from the project maintainer in a long time, so at this stage the JPF project may not have a maintainer that has write access to the repository. What I suggest perhaps is to try and get in touch with Dmitry again. His email address is on the JPF website, cc me if you like. If there is no response from him, it may be necessary to create a temporary fork until it is possible to remerge the code. I presume you're probably focusing your improvements only on the 1.5 branch at the moment?

        At the same time, could I ask you send your code to me via email and I can test it in my application. If it works then I believe that this, along with other improvements, should be more thoroughly pursued, either in the current JPF repository if Dmitry agrees, otherwise in a different repository.

        -- Jonathan

         
    • lamah
      lamah
      2008-07-26

      Ok, now I have looked through the source code pretty thoroughly to understand what happens. What surprised me was that he is actually doing what I suggested. That is, saving the plugins lastmodified property so you only unpack when the plugins have actually changed.

      After many hours of debugging I found a bug in his code which can also be seen by viewing the log in debug mode. This bug causes the unpacking to happen EVERY time which of course creates the performance problem. The changes I made merely duplicated what his code already should be doing and is unnecessary when this bug is fixed. Fortunately it also seems like the bug is easy to fix. However the fix might cause other regressions that I am unaware of.

      Here is what happens:

      1. For each plugin this method called to do the unpacking if necessary:
         ShadowDataController::shadowResource(final URL source, final String uid, final boolean unpack)

      2. One of the first things the shadowResource method does it to call another method that checks if the plugin really needs to be unpacked
         ShadowDataController::deepCheck(final URL source, final String uid)

      3. In the deepCheck method a check is performed to check if the source URL (the actual URL to the plugin archive) matches an URL found in the metadata manifest for this plugin. The URL in the metadata manifest should be identical if we have unpacked this plugin previously. This is where the problem happens. They should be identifical, but the source URL is constructed differently than the URL stored in the metadata manifest. They are almost identical, but the source URL ends up having a extra "jar:" prefix and a "!/" postfix. So I located the place where the source URL is constructed and just removed the prefix and postfix... I have no idea why they were added in the first place though.

      4. The code where it all happens (in deepCheck):

      URL storedSource = ShadingUtil.buildURL(shadowFolderUrl, url);
      if (!storedSource.equals(source)) {
          if (log.isDebugEnabled()) {
              log.debug("inconsistent URL found in meta-data, UID=" //$NON-NLS-1$
                         + uid + ", source=" + source //$NON-NLS-1$
                         + ", storedSource=" + storedSource); //$NON-NLS-1$
          }
          remove(uid);
          return null;
      }

      This equals check will return false and consequently the plugin is scheduled for unpacking. You can also see that if you enable debug logging you would get the "inconsistent url found" message.

      5. The solution is to change the creation of the source URL so that it matches the URL stored in the metadata manifest. This can be accomplished in the StandardPluginLocation class.
         In the StandardPluginLocation::create(final File file) method:

      //        return (manifestUrl == null) ? null
      //                : new StandardPluginLocation(new URL("jar:" //$NON-NLS-1$
      //                        + IoUtil.file2url(file).toExternalForm()
      //                        + "!/"), manifestUrl); //$NON-NLS-1$
              return (manifestUrl == null) ? null
                      : new StandardPluginLocation(IoUtil.file2url(file), manifestUrl); //$NON-NLS-1$ 

      I have commented out the original code.

      6. Download my modified code here (however it only has the simple change outlined above):
         http://rapidshare.com/files/132610261/src.zip.html

       
      • Jonathan Giles
        Jonathan Giles
        2008-07-27

        Hello,

        I have tested your code and my application didn't die a horrible death :-)

        I just thought I'd clarify my results:
        * When booting up a 'clean' install with no temp folder containing extracted zips, the deepCheck method is not called.
        * When booting with a 'dirty' install (i.e. with zips extracted), the deepCheck fails the inequality test and thus continues past the above code.

        I would say that when dirty the boot time is indeed improved, although it is of course hard to measure.

        I would say therefore that this improvement should ideally be committed back to the cvs repository, but getting hold of Dmitry may be difficult.

        If you use MSN Messenger, feel free to add me - my address is jo at jogiles.co.nz

        Cheers,
        Jonathan Giles

         
    • lamah
      lamah
      2008-07-28

      When you tested did you try to run both my version and the original version of JPF? So you did indeed verify that the original gives the "inconsistent URL found" with your plugins while mine doesn't?

      Your results seem to support my claim. Booting from a 'clean' install with no temp folder will never call deepCheck() because JPF does some "quick checks" before it reaches deepCheck to verify if there actually exists any unpacked plugins.

      When booting 'dirty' (or any boot after plugins have been unpacked to the temp dir) JPF will call deepCheck() for each plugin that is loaded to see if it has already been unpacked. In my fixed version of the code the check will work like expected and plugins that already are unpacked to the temp dir will not be unpacked again.

      How many plugins did you try to run it with? I can hardly tell the difference in boot time if I try this with just a couple of small plugins. However, as I said earlier, with 14 plugins the difference is _very_ noticeable and can be measured in seconds. Since I will be adding even more plugins this optimization is important and will be important to any decent sized project using JPF. It will actually be more important the more plugins you have :)

      I have sent Dmitry a message using the SourceForge message system. I could not find his e-mail address anywhere, do you have it? If you do send him a message telling him to read this thread.

      Now... if there was just some way to improve the classloading as well. It has surfed up to become my nr. one hotspot. 400 ms to load 300-400 classes is not fantastic, about a 1ms/class. I mean, the built in classloader is about 100x faster than that so there should be room for improvement ;)

       
      • Jonathan Giles
        Jonathan Giles
        2008-07-28

        I didn't run in debug mode, but I did insert debug statements to track what was happening and it seemed to be working properly. I didn't put debug statements in my old jpf code though.

        I have around the same number of plugins - 15 or so.

        Good luck finding further optimisations - JPF slowness has frustrated me for a long time!

        Keep me informed if you make any progress,
        Cheers,
        Jonathan

         
    • Hello,

      I'm sorry for such long salience - I have no spare time last months.

      Regarding this discussion - thank you Mats for your efforts, I'll look into ShadingPathResolver source code and try to improve it according to your changes.

      //Dmitry

       
    • I've committed changes into project CVS - could you please check how they work in your situation.

      //Dmitry

       
    • lamah
      lamah
      2008-08-01

      Excellent, I will try to to test it this weekend!

      I am curious though why you had added a extra "jar:" prefix and a "!/" postfix to the URL? Even though the fix seemed to work I still thought you might have had a good reason for doing so.

      The code fix (for reference):
      // return (manifestUrl == null) ? null
      // : new StandardPluginLocation(new URL("jar:" //$NON-NLS-1$
      // + IoUtil.file2url(file).toExternalForm()
      // + "!/"), manifestUrl); //$NON-NLS-1$
      return (manifestUrl == null) ? null
      : new StandardPluginLocation(IoUtil.file2url(file), manifestUrl); //$NON-NLS-1$

       
    • lamah
      lamah
      2008-08-03

      I have now tested the new version and it seems to work fine!
      I also profiled my application and all the IO related hotspots are now gone.
      Good job!

      You should probably also:
      1. Update the jpf module for lower versions than Java 1.5
      2. Make some new binary releases

       
  • Jethro Borsje
    Jethro Borsje
    2009-11-30

    I can not seem to find the following fix in the codebase on CVS:
    <pre><code>// return (manifestUrl == null) ? null
    // : new StandardPluginLocation(new URL("jar:" //$NON-NLS-1$
    // + IoUtil.file2url(file).toExternalForm()
    // + "!/"), manifestUrl); //$NON-NLS-1$
    return (manifestUrl == null) ? null
    : new StandardPluginLocation(IoUtil.file2url(file), manifestUrl); //$NON-NLS-1$ </code></pre>

    See: <a>http://jpf.cvs.sourceforge.net/viewvc/jpf/jpf-1.5/source/org/java/plugin/standard/StandardPluginLocation.java?view=log</a>.

    I have added this in my code and it indeed fixes the problem described in this thread. The code is now committed to the head

     
  • Richard
    Richard
    2010-10-04

    Hi everybody,
    This thread has been inactive for some while, but i've found a situation where the above mentioned solution won't work. On windows systems, applications might contain spaces like 'Program Files'. The compare in the deepcheck method uses on the one hand a safe URI (which replaces all spaces with '%20', but the meta file stores the relative url's without this change. To solve this you will need to add an extra line in the ShadingUtil.getRelativeUrl(File,File) method.
    This method should include:

     private static String getRelativeUrl(final File base, final File file)
                throws IOException {
            String result = getRelativePath(base, file);
            if (result == null) {
                return null;
            }
            result = result.replace('\\', '/');
            [b]result = result.replace(" ", "%20");[/b]
            
             if (file.isDirectory() && !result.endsWith("/")) { //$NON-NLS-1$
                result += "/"; //$NON-NLS-1$
            }
            return result;
        }
    

    which will ensure that spaces are correctly saved in the meta file.

     
  • Jethro Borsje
    Jethro Borsje
    2010-10-04

    Nicely spotted!

    Jethro