Recently I helped someone who reported a rapid memory leak in ColdFusion MX 6.1 server where memory for the jrun.exe process grew from 300 MB upon startup to 1200 MB within about 15 minutes, followed by a JVM crash.

A thread dump was obtained from when the memory was peaking and reviewed along with the ColdFusion and JRun log files.

The thread dump showed several jrpp threads where the individual stack for a jrpp was hundreds and hundreds of lines, composed primarily of a repeating sequence. The repeating sequence appeared to be a type of long or infinite loop where cfm A called cfm B which called cfm C which called cfm A again. The sequence repeated until it used the maximum heap available to the JVM, 1.2GB, and then crashed the server.

This is one example of how coding logic can induce uncontrolled memory growth in the JVM under the CF server. The application running on the server was one of the popular Content Management Software applications built in ColdFusion, but references to the CMS name is removed from this blog entry.

While the thread dumps were the first clue to the problem, the ColdFusion runtime default-out.log contained a great record of the crash, shown below.

In particular, the EXCEPTION_ACCESS_VIOLATION was logged with the current thread it was running, the dlls loaded, and the heap at VM abort. The current thread running showed the same type of stack trace with infinite loop, and the Heap information showed that the PSYoungGen has 99% of the eden space used, the PSOldGen had 100% used, and the PSPermGen had 99% used. So that's a pretty open and shut case.

Here's the crash information from the default-out.log:

Server default ready (startup time: 9 seconds)

Unexpected Signal : EXCEPTION_ACCESS_VIOLATION (0xc0000005) occurred at PC=0x80DAF8C
Function=java_lang_Throwable::get_stack_trace_depth+0x4C
Library=C:CFusionMX untimejreinserverjvm.dll
Source file = D:/BUILD_AREA2/jdk1.4.2/hotspotsrcsharevmmemoryjavaClasses.cpp : 785


Current Java thread:
at java.lang.Throwable.getStackTraceDepth(Native Method)
at java.lang.Throwable.getOurStackTrace(Throwable.java:588)
- locked <0x1320e050> (a java.lang.Exception)
at java.lang.Throwable.printStackTrace(Throwable.java:510)
- locked <0x1320ef80> (a java.io.PrintWriter)
at coldfusion.runtime.ExceptionInformation.(ExceptionInformation.java:46)
at coldfusion.debug.CFMLDebugger.template(CFMLDebugger.java:373)
at coldfusion.debug.CFMLDebugger.template(CFMLDebugger.java:354)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:403)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1876)
at cfverify2dstub2ddata2ecfm469275655.runPage(D:webrootcmsapputilitiesvstub-data.cfm.cfm:36)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:60)
at coldfusion.tagext.lang.ModuleTag.doStartTag(ModuleTag.java:256)
at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:1886)
at cfmaster2ecfm532680640._factor3(D:webrootcmsappmaster.cfm:130)
at cfmaster2ecfm532680640._factor14(D:webrootcmsappmaster.cfm:113)
at cfmaster2ecfm532680640._factor16(D:webrootcmsappmaster.cfm:36)
at cfmaster2ecfm532680640.runPage(D:webrootcmsappmaster.cfm:1)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:357)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1876)
at cftextblock2ecfm522855857.runPage(D:webrootchapters extblock.cfm.cfm:3)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:60)
at coldfusion.tagext.lang.ModuleTag.doStartTag(ModuleTag.java:256)
at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:1886)
at cfwrite2dstub2ecfm1697960716.runPage(D:webrootcmsapputilitieswrite-stub.cfm:45)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:357)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1876)
at cfverify2dstub2ddata2ecfm469275655.runPage(D:webrootcmsapputilitiesvstub-data.cfm.cfm:37)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:60)
at coldfusion.tagext.lang.ModuleTag.doStartTag(ModuleTag.java:256)
at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:1886)
at cfmaster2ecfm532680640._factor3(D:webrootcmsappmaster.cfm:130)
at cfmaster2ecfm532680640._factor14(D:webrootcmsappmaster.cfm:113)
at cfmaster2ecfm532680640._factor16(D:webrootcmsappmaster.cfm:36)
at cfmaster2ecfm532680640.runPage(D:webrootcmsappmaster.cfm:1)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:357)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1876)
at cftextblock2ecfm522855857.runPage(D:webrootchapters extblock.cfm.cfm:3)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:60)
at coldfusion.tagext.lang.ModuleTag.doStartTag(ModuleTag.java:256)
at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:1886)
at cfwrite2dstub2ecfm1697960716.runPage(D:webrootcmsapputilitieswrite-stub.cfm:45)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:357)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1876)
at cfverify2dstub2ddata2ecfm469275655.runPage(D:webrootcmsapputilitiesvstub-data.cfm.cfm:37)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:60)
at coldfusion.tagext.lang.ModuleTag.doStartTag(ModuleTag.java:256)
at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:1886)
at cfmaster2ecfm532680640._factor3(D:webrootcmsappmaster.cfm:130)
at cfmaster2ecfm532680640._factor14(D:webrootcmsappmaster.cfm:113)
at cfmaster2ecfm532680640._factor16(D:webrootcmsappmaster.cfm:36)
at cfmaster2ecfm532680640.runPage(D:webrootcmsappmaster.cfm:1)

<< many repetitive lines removed here >>

at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:357)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1876)
at cftextblock2ecfm522855857.runPage(D:webrootchapters extblock.cfm.cfm:3)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:60)
at coldfusion.tagext.lang.ModuleTag.doStartTag(ModuleTag.java:256)
at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:1886)
at cfwrite2dstub2ecfm1697960716.runPage(D:webrootcmsapputilitieswrite-stub.cfm:45)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:357)
at coldfusion.runtime.CfJspPage._emptyTag(CfJspPage.java:1876)
at cfverify2dstub2ddata2ecfm469275655.runPage(D:webrootcmsapputilitiesvstub-data.cfm.cfm:37)
at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:147)
at coldfusion.filter.CFVariablesScopeFilter.invoke(CFVariablesScopeFilter.java:60)
at coldfusion.tagext.lang.ModuleTag.doStartTag(ModuleTag.java:256)
at coldfusion.runtime.CfJspPage._emptyTcfTag(CfJspPage.java:1886)
at cfmaster2ecfm532680640._factor3(D:webrootcmsappmaster.cfm:130)
at cfmaster2ecfm532680640._factor14(D:webrootcmsappmaster.cfm:113)
at cfmaster2ecfm532680640._factor16(D:webrootcmsappmaster.cfm:36)

Dynamic libraries:
0x00400000 - 0x0040F000 C:CFusionMX untimeinjrun.exe
0x77F80000 - 0x77FFD000 C:WINNTsystem32 tdll.dll
0x7C570000 - 0x7C623000 C:WINNTsystem32KERNEL32.dll
0x7C2D0000 - 0x7C332000 C:WINNTsystem32ADVAPI32.dll
0x77D30000 - 0x77DA1000 C:WINNTsystem32RPCRT4.DLL
0x78000000 - 0x78045000 C:WINNTsystem32MSVCRT.dll
0x08000000 - 0x082A7000 C:CFusionMX untimejreinserverjvm.dll
0x77E10000 - 0x77E6F000 C:WINNTsystem32USER32.dll
0x77F40000 - 0x77F7B000 C:WINNTsystem32GDI32.dll
0x77570000 - 0x775A0000 C:WINNTsystem32WINMM.dll
0x10000000 - 0x10007000 C:CFusionMX untimejreinhpi.dll
0x00770000 - 0x0077E000 C:CFusionMX untimejreinverify.dll
0x00780000 - 0x00798000 C:CFusionMX untimejreinjava.dll
0x007A0000 - 0x007AD000 C:CFusionMX untimejreinzip.dll
0x76750000 - 0x7675F000 C:CFusionMX untimejrein et.dll
0x76760000 - 0x76774000 C:WINNTsystem32WS2_32.dll
0x76780000 - 0x76788000 C:WINNTsystem32WS2HELP.DLL
<< many more loaded dlls removed here >>

Heap at VM Abort:
Heap
PSYoungGen total 103616K, used 51199K [0x10010000, 0x19610000, 0x19610000)
eden space 51200K, 99% used [0x10010000,0x1320fff0,0x13210000)
from space 52416K, 0% used [0x13210000,0x13210000,0x16540000)
to space 49984K, 0% used [0x16540000,0x16540000,0x19610000)
PSOldGen total 1228800K, used 1228800K [0x19610000, 0x64610000, 0x64610000)
object space 1228800K, 100% used [0x19610000,0x64610000,0x64610000)
PSPermGen total 41216K, used 41109K [0x64610000, 0x66e50000, 0x74610000)
object space 41216K, 99% used [0x64610000,0x66e357a0,0x66e50000)

Local Time = Wed Feb 02 23:32:50 2005
Elapsed Time = 9286
#
# HotSpot Virtual Machine Error : EXCEPTION_ACCESS_VIOLATION
# Error ID : 4A415641234C41535345530E4350500311
# Please report this error at
# http://java.sun.com/cgi-bin/bugreport.cgi
#
# Java VM: Java HotSpot(TM) Server VM (1.4.2-b28 mixed mode)
#
space 51200K, 99% used space 52416K, 0% used space 49984K, 0% used space 1228800K, 100% used space 41216K, 99% used
# An error report file has been saved as hs_err_pid792.log.
# Please refer to the file for further information.