Uploaded image for project: 'Lucee Development'
  1. LDEV-1623

Intermediate values used in function not released until function is finished

    Details

    • Type: Bug
    • Status: Deployed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 5.2.4.37, 5.2.6.29
    • Fix Version/s: 5.2.6.36
    • Labels:
      None
    • Sprint:

      Description

      I have been running into memory issues trying to solve this year's Advent of Code programming puzzles in CFML.

      It seems to me as if Lucee holds on to all intermediate values used in a function until the function is finished.

      Steps to reproduce

      bug.cfm
      <cfsetting requesttimeout="120" />
      <cffunction name="loop" output="false">
      	<cfargument name="loopFrom" required="true" />
      	<cfargument name="loopTo" required="true" />
      	<cfargument name="totalLoops" required="true" />
      	<cfset var i = '' />
      	<cfloop from="#arguments.loopFrom#" to="#arguments.loopTo#" index="i">
      		<cfif i % 2000000 eq 0>
      			<cflog file="bug" text="#Round(i / arguments.totalLoops * 100)#% done" />
      		</cfif>
      	</cfloop>
      </cffunction>
      <cfset loop(loopFrom = 1, loopTo = 200000000, totalLoops = 200000000) />
      

      Actual result

      Using the latest lucee/lucee52 docker image (5.2.4.37) with "LUCEE_JAVA_OPTS=-Xms256m -Xmx512m -Xloggc:/opt/lucee/web/logs/GC.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps":

      bug.log
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:21","","1% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:22","","2% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:22","","3% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:22","","4% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:23","","5% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:23","","6% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:24","","7% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:24","","8% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:25","","9% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:25","","10% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:25","","11% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:26","","12% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:27","","13% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:27","","14% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:28","","15% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:29","","16% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:30","","17% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:32","","18% done"
      "INFO","http-apr-8888-exec-1","12/17/2017","09:29:35","","19% done"
      

      And then nothing more. I see in GC.log that the JVM performs 1-2 full GCs every second and that it manages to free very little memory.

      I have also tested to upgrade to 5.2.6.29-SNAPSHOT inside the container but that made no difference.

      On Adobe ColdFusion 2016.0.0.298074 the script completes without issues and the time between every percentage of completion is fairly constant all the time.

      Expected result

      The request should complete without issues. At any point in time the function is referencing very little data so the JVM should be able to GC the intermediate values.

      Workaround

      Split up the work:

      workaround.cfm
      <cfsetting requesttimeout="120" />
      <cffunction name="loop" output="false">
      	<cfargument name="loopFrom" required="true" />
      	<cfargument name="loopTo" required="true" />
      	<cfargument name="totalLoops" required="true" />
      	<cfset var i = '' />
      	<cfloop from="#arguments.loopFrom#" to="#arguments.loopTo#" index="i">
      		<cfif i % 2000000 eq 0>
      			<cflog file="bug" text="#Round(i / arguments.totalLoops * 100)#% done" />
      		</cfif>
      	</cfloop>
      </cffunction>
      <cfset loop(loopFrom =         1, loopTo =  20000000, totalLoops = 200000000) />
      <cfset loop(loopFrom =  20000001, loopTo =  40000000, totalLoops = 200000000) />
      <cfset loop(loopFrom =  40000001, loopTo =  60000000, totalLoops = 200000000) />
      <cfset loop(loopFrom =  60000001, loopTo =  80000000, totalLoops = 200000000) />
      <cfset loop(loopFrom =  80000001, loopTo = 100000000, totalLoops = 200000000) />
      <cfset loop(loopFrom = 100000001, loopTo = 120000000, totalLoops = 200000000) />
      <cfset loop(loopFrom = 120000001, loopTo = 140000000, totalLoops = 200000000) />
      <cfset loop(loopFrom = 140000001, loopTo = 160000000, totalLoops = 200000000) />
      <cfset loop(loopFrom = 160000001, loopTo = 180000000, totalLoops = 200000000) />
      <cfset loop(loopFrom = 180000001, loopTo = 200000000, totalLoops = 200000000) />
      

        Attachments

        1. ACF11.log
          7 kB
        2. bug-bufferOutputFalse.log
          7 kB
        3. GC.log
          32 kB
        4. LDEV1623.cfm
          0.5 kB
        5. Lucee-bug.log
          0.9 kB

          Issue links

            Activity

              People

              • Assignee:
                michaeloffner Michael Offner
                Reporter:
                jonas Jonas Meller
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: