Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.3
    • Fix Version/s: 1.5
    • Component/s: Build
    • Labels:
      None
    • Environment:
      Operating System: Linux
      Platform: Other

      Description

      I am using Velocity in a J2EE application. I had problems with my application
      leaking memory. I have traced this back to Velocity. I have made a little simple
      JUnit test, which demonstrates this memory leak. It seems that every time you
      instantiate a Velocity Engine with a resource loader it leaks about 1.5 Kb of
      heap memory. If I do not include the setup of the resource loader from
      properties, there is no leak.
      I found this in Velocity 1.3, but I have tried the same test with a cvs checkout
      of Velocity from 4th of marts 2003, and it showed the same problem. If I let the
      test run with a max heap size of 64Mb, it will fail with OutOfMemoryError
      exception after about 34.000 iterations.
      I have attached the JUnit.

      Cheers, Kim Madsen

      Below follows my unit test
      ________________________________________________________________________
      package com.inceptor.rt;

      import com.inceptor.base.ExceptionBase;
      import com.inceptor.service.DiagnosticsFact;
      import com.inceptor.service.DiagnosticsIf;
      import com.inceptor.util.Test;
      import com.inceptor.util.TestSuite;
      import com.inceptor.util.TestCaseJUnit;
      import com.inceptor.util.Various;

      import java.io.StringWriter;
      import java.util.Properties;

      import org.apache.velocity.VelocityContext;
      import org.apache.velocity.Template;
      import org.apache.velocity.app.VelocityEngine;

      /** Servlet used to test <code>rt/Servlet</code> functionality.
      *

      • @version $Id: VelocityMemorySimple.java,v 1.3 2003/02/28 17:28:52 kim Exp $
        */
        public class VelocityMemorySimple
        extends TestCaseJUnit {

      private static final DiagnosticsIf diag =
      DiagnosticsFact.instance(VelocityMemorySimple.class);

      private static final int ROWS_BETWEEN_DISPLAY = 1000;
      private static final int ROWS_TO_ITERATE = 50000 * ROWS_BETWEEN_DISPLAY;

      private static long lastTime = -1;

      public VelocityMemorySimple(String name) throws ExceptionBase

      { super(name); }

      ///////////////////////////////////////////////////////////////////

      private void showInfo(long rowsInserted)
      throws Exception {

      if (rowsInserted==0)

      { System.gc(); lastTime = System.currentTimeMillis(); }

      if (rowsInserted%ROWS_BETWEEN_DISPLAY == 0)

      { long nowTime = System.currentTimeMillis(); System.gc(); diag.info("Ite=" + rowsInserted + " Mem free =" + java.lang.Runtime.getRuntime().freeMemory() + " Mem total=" + java.lang.Runtime.getRuntime().totalMemory() + " Ite/sec.=" + ((double) 1000*ROWS_BETWEEN_DISPLAY)/(nowTime-lastTime) ); lastTime = nowTime; }

      }

      public void testMemory()
      throws Exception {

      try {
      Properties p = new Properties();

      p.setProperty("runtime.log.logsystem.class",
      "org.apache.velocity.runtime.log.SimpleLog4JLogSystem");
      p.setProperty("runtime.log.logsystem.log4j.category", "VELOCITY");

      p.setProperty("resource.manager.logwhenfound", "true");

      p.setProperty("velocimacro.library", "");

      p.setProperty("resource.loader",
      "datasourceglobal, datasourcecustom");

      p.setProperty("datasourceglobal.resource.description",
      "Load Templates From java:ExcediaDB Global Resources");
      p.setProperty("datasourceglobal.resource.loader.class",
      "org.apache.velocity.runtime.resource.loader.DataSourceResourceLoader");
      p.setProperty("datasourceglobal.resource.loader.resource.datasource",
      "java:ExcediaDB");
      p.setProperty("datasourceglobal.resource.loader.resource.table",
      "RESOURCEGLOBALS");
      p.setProperty("datasourceglobal.resource.loader.resource.keycolumn",
      "NAMESTR");
      p.setProperty("datasourceglobal.resource.loader.resource.templatecolumn",
      "CONTENTCHARACTER");
      p.setProperty("datasourceglobal.resource.loader.resource.timestampcolumn",
      "MODIFICATIONTIME");
      p.setProperty("datasourceglobal.resource.loader.resource.cache",
      "true");
      p.setProperty("datasourceglobal.resource.loader.resource",
      "6");

      p.setProperty("datasourcecustom.resource.description",
      "Load Templates From java:ExcediaDB Custom Resources");
      p.setProperty("datasourcecustom.resource.loader.class",
      "org.apache.velocity.runtime.resource.loader.DataSourceResourceLoader");
      p.setProperty("datasourcecustom.resource.loader.resource.datasource",
      "java:ExcediaDB");
      p.setProperty("datasourcecustom.resource.loader.resource.table",
      "RESOURCECUSTOMS");
      p.setProperty("datasourcecustom.resource.loader.resource.keycolumn",
      "NAMESTR");
      p.setProperty("datasourcecustom.resource.loader.resource.templatecolumn",
      "CONTENTCHARACTER");
      p.setProperty("datasourcecustom.resource.loader.resource.timestampcolumn",
      "MODIFICATIONTIME");
      p.setProperty("datasourcecustom.resource.loader.resource.cache",
      "true");
      p.setProperty("datasourcecustom.resource.loader.resource",
      "6");
      VelocityContext context = null;
      StringWriter sw = null;
      VelocityEngine ve = null;

      for (int i=0; i<=ROWS_TO_ITERATE; i++)

      { showInfo(i); ve = new VelocityEngine(); ve.init(p); }

      } catch (OutOfMemoryError e)

      { diag.error(e); throw e; }

      }

      public static Test suite() throws Exception

      { diag.debug("Setup test suite"); TestSuite suite = new TestSuite(); suite.addTest(new VelocityMemorySimple("testMemory")); return suite; }

      }

      1. ASF.LICENSE.NOT.GRANTED--VelocityMemorySimple.java
        5 kB
        Will Glass-Husain
      2. ASF.LICENSE.NOT.GRANTED--results.txt
        4 kB
        Will Glass-Husain
      3. ASF.LICENSE.NOT.GRANTED--results.xls
        19 kB
        Will Glass-Husain
      4. ASF.LICENSE.NOT.GRANTED--DataSource.patch
        3 kB
        Will Glass-Husain

        Activity

        Hide
        Will Glass-Husain added a comment -

        Could this be fixed with the new code in CVS head? Previously, the cached
        resources had no limit and could accumulate, but now are limited by default.
        I suggest you try running the test code again.

        Show
        Will Glass-Husain added a comment - Could this be fixed with the new code in CVS head? Previously, the cached resources had no limit and could accumulate, but now are limited by default. I suggest you try running the test code again.
        Hide
        Geir Magnusson Jr added a comment -

        No, the new code should have nothing to do with it. If you read what he wrote, all he has to do is
        instantiate a VelocityEngine. He doesn't need to do any resources. All I can think of is that the
        classloader is holding onto a singleton somewhere, but that's just a quick quess.

        Show
        Geir Magnusson Jr added a comment - No, the new code should have nothing to do with it. If you read what he wrote, all he has to do is instantiate a VelocityEngine. He doesn't need to do any resources. All I can think of is that the classloader is holding onto a singleton somewhere, but that's just a quick quess.
        Hide
        Will Glass-Husain added a comment -

        Tested this with sample code provided (slightly modified to avoid proprietary
        dependencies). The free memory jumps all over the place (vagaries of garbage
        collection), but over 50,000 iterations there's a clear downward trends (737
        bytes/iteration according to my linear regression). Definitely a problem for
        high-volume sites. Not yet clear if this applies to other resource loaders,or
        just the DataResourceLoader.

        I'll attach the source code I used so that this can be tested again. I tested
        on Win XP/JDK 1.4.1/Velocity 1.5-dev (with cache improvement). For the
        record, it took an hour to run before it hit the 64MB memory limit.

        Show
        Will Glass-Husain added a comment - Tested this with sample code provided (slightly modified to avoid proprietary dependencies). The free memory jumps all over the place (vagaries of garbage collection), but over 50,000 iterations there's a clear downward trends (737 bytes/iteration according to my linear regression). Definitely a problem for high-volume sites. Not yet clear if this applies to other resource loaders,or just the DataResourceLoader. I'll attach the source code I used so that this can be tested again. I tested on Win XP/JDK 1.4.1/Velocity 1.5-dev (with cache improvement). For the record, it took an hour to run before it hit the 64MB memory limit.
        Hide
        Will Glass-Husain added a comment -

        Created an attachment (id=8742)
        modified test case (uses JUnit, no proprietary dependencies)

        Show
        Will Glass-Husain added a comment - Created an attachment (id=8742) modified test case (uses JUnit, no proprietary dependencies)
        Hide
        Will Glass-Husain added a comment -

        Created an attachment (id=8743)
        results of running test case (out of memory in 45,000 iterations)

        Show
        Will Glass-Husain added a comment - Created an attachment (id=8743) results of running test case (out of memory in 45,000 iterations)
        Hide
        Will Glass-Husain added a comment -

        Created an attachment (id=8744)
        results Excel spreadsheet (showing regression and graph)

        Show
        Will Glass-Husain added a comment - Created an attachment (id=8744) results Excel spreadsheet (showing regression and graph)
        Hide
        Will Glass-Husain added a comment -

        Found the problem. Patch to follow. (Committers, please take note).

        ResourceLoader was calling the singleton Runtime for logging instead of the
        instance rsvc. Checked the rest of the source code for the same problem
        elsewhere, didn't see it. Running Kim's test code shows there are no further
        leaks.

        [java] Ite=0 Mem free =1856528 Mem total=2031616 Ite/sec.=Infinity
        [java] log4j:WARN No appenders could be found for logger (VELOCITY).
        [java] log4j:WARN Please initialize the log4j system properly.
        [java] Ite=1000 Mem free =40474704 Mem total=44871680
        Ite/sec.=32.7075292732387
        [java] Ite=2000 Mem free =39729152 Mem total=66650112
        Ite/sec.=35.4735721887194
        [java] Ite=3000 Mem free =41777648 Mem total=66650112
        Ite/sec.=34.75601279021271
        [java] Ite=4000 Mem free =41777648 Mem total=66650112
        Ite/sec.=36.685131516196485
        [java] Ite=5000 Mem free =41777648 Mem total=66650112
        Ite/sec.=38.09814081072844
        [java] Ite=6000 Mem free =41777648 Mem total=66650112
        Ite/sec.=37.98237617745366

        Show
        Will Glass-Husain added a comment - Found the problem. Patch to follow. (Committers, please take note). ResourceLoader was calling the singleton Runtime for logging instead of the instance rsvc. Checked the rest of the source code for the same problem elsewhere, didn't see it. Running Kim's test code shows there are no further leaks. [java] Ite=0 Mem free =1856528 Mem total=2031616 Ite/sec.=Infinity [java] log4j:WARN No appenders could be found for logger (VELOCITY). [java] log4j:WARN Please initialize the log4j system properly. [java] Ite=1000 Mem free =40474704 Mem total=44871680 Ite/sec.=32.7075292732387 [java] Ite=2000 Mem free =39729152 Mem total=66650112 Ite/sec.=35.4735721887194 [java] Ite=3000 Mem free =41777648 Mem total=66650112 Ite/sec.=34.75601279021271 [java] Ite=4000 Mem free =41777648 Mem total=66650112 Ite/sec.=36.685131516196485 [java] Ite=5000 Mem free =41777648 Mem total=66650112 Ite/sec.=38.09814081072844 [java] Ite=6000 Mem free =41777648 Mem total=66650112 Ite/sec.=37.98237617745366
        Hide
        Will Glass-Husain added a comment -

        Created an attachment (id=8745)
        DataSourceResourceLoader.java patch (changes Runtime log calls to rsvc)

        Show
        Will Glass-Husain added a comment - Created an attachment (id=8745) DataSourceResourceLoader.java patch (changes Runtime log calls to rsvc)
        Hide
        Geir Magnusson Jr added a comment -

        Thought it would be a singleton. Nice job. That's definitely it, and I can't find any other uses of
        Runtime in the codebase. This one escaped attention because the DataResourceLoader is not built
        as part of the standard build due to the j2ee.jar dependency. (And I remember the argument Jason
        and I had over whether to keep this - I thought it would be a maintenace issue....)

        It's fixed now, and closing this.

        Note to interested reader :

        This does not mean that your usage of Velocity is leaking. This was only the
        DataSourceResourceLoader, and only if you instantiated many many instances of the
        VelocityEngine.

        If you don't use the DatasourceResourceLoader, you won't be affected, and if you do, but use
        Velocity in the canonical way of having one instance for use during the lifetime of your program,
        you did use up an extra few hundred bytes, and only once.

        Show
        Geir Magnusson Jr added a comment - Thought it would be a singleton. Nice job. That's definitely it, and I can't find any other uses of Runtime in the codebase. This one escaped attention because the DataResourceLoader is not built as part of the standard build due to the j2ee.jar dependency. (And I remember the argument Jason and I had over whether to keep this - I thought it would be a maintenace issue....) It's fixed now, and closing this. Note to interested reader : This does not mean that your usage of Velocity is leaking. This was only the DataSourceResourceLoader, and only if you instantiated many many instances of the VelocityEngine. If you don't use the DatasourceResourceLoader, you won't be affected, and if you do, but use Velocity in the canonical way of having one instance for use during the lifetime of your program, you did use up an extra few hundred bytes, and only once.

          People

          • Assignee:
            Unassigned
            Reporter:
            Kim Madsen
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development