TRANSFER.SOFTREFERENCEHANDLER_1: Element AFTERCREATEOBSERVERCOLLECTION is undefined

[Jaime Metcher]

Hi,

Running Transfer 1.0 on CF8 standard with the default JVM 1.6, IIS 6, Windows Server 2003, SQL Server 2000.  We're getting a bunch of errors in the SoftReferenceHandler.  Not sure yet whether this is a problem, but it is evident that the memory usage is greater, and we haven't yet seen it drop.  With 0.6.3 on CF7 we would see memory go up in busy times, then fall again later.

We did in fact see these errors with 0.6.3 on CF8, and went to 1.0 to try to resolve them.  We have restarted CF, but have not rebooted the box.

Below are a couple of samples.  We saw similar things for AFTERDISCARDOBSERVERCOLLECTION, CACHEMANAGER, AFTERDELETEOBSERVERCOLLECTION, AFTERUPDATEOBSERVERCOLLECTION on 0.6.3, but since upgrading have seen only these two.

We run two instances of transfer, one with an application scoped cache, the other with a request scoped cache.  My wild guess is that the request scope is vanishing (due to completion of the parent page) while the reaper thread is still running, in which case the error is probably harmless, but that doesn't explain the dramatic change in memory usage.

Finally, I know the paths in the stack trace say CFMX7, but this really is CF8.

Jaime


"Error","cfthread-10","06/11/08","10:28:42",,"TRANSFER.SOFTREFERENCEHANDLER_1: Element AFTERCREATEOBSERVERCOLLECTION is undefined in a CFML structure referenced as part of an expression. "
coldfusion.runtime.UndefinedElementException: Element AFTERCREATEOBSERVERCOLLECTION is undefined in a CFML structure referenced as part of an expression.
    at coldfusion.runtime.CfJspPage._resolve(CfJspPage.java:1477)
    at coldfusion.runtime.CfJspPage._resolveAndAutoscalarize(CfJspPage.java:1700)
    at coldfusion.runtime.CfJspPage._resolveAndAutoscalarize(CfJspPage.java:1692)
    at cfAbstractBaseFacade2ecfc995706692$funcGETAFTERCREATEOBSERVERCOLLECTION.runFunction(C:\CFusionMX7\CustomTags\transfer\com\facade\AbstractBaseFacade.cfc:61)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:360)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:448)
    at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:308)
    at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2260)
    at cfSoftReferenceHandler2ecfc1880139728$funcHANDLEREAP.runFunction(C:\CFusionMX7\CustomTags\transfer\com\cache\SoftReferenceHandler.cfc:158)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:360)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2464)
    at cfSoftReferenceHandler2ecfc1880139728$funcSYNCRONOUSREAP.runFunction(C:\CFusionMX7\CustomTags\transfer\com\cache\SoftReferenceHandler.cfc:118)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:360)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2464)
    at cfSoftReferenceHandler2ecfc813003929$func_CFFUNCCFTHREAD_CFSOFTREFERENCEHANDLER2ECFC8130039291.runFunction(C:\CFusionMX7\CustomTags\transfer\com\cache\cf8\SoftReferenceHandler.cfc:65)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.UDFMethod.invokeCFThread(UDFMethod.java:174)
    at coldfusion.thread.Task.invokeFunction(Task.java:237)
    at coldfusion.thread.Task.run(Task.java:140)
    at coldfusion.scheduling.ThreadPool.run(ThreadPool.java:201)
    at coldfusion.scheduling.WorkerThread.run(WorkerThread.java:71)


"Error","cfthread-11","06/11/08","09:45:01",,"TRANSFER.SOFTREFERENCEHANDLER_7: Element transfer is undefined in a Java object of type class coldfusion.runtime.RequestScope. "
coldfusion.runtime.UndefinedElementException: Element transfer is undefined in a Java object of type class coldfusion.runtime.RequestScope.
    at coldfusion.runtime.CfJspPage.ArrayGetAt(CfJspPage.java:908)
    at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:919)
    at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:914)
    at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:744)
    at coldfusion.runtime.CfJspPage._arrayGetAt(CfJspPage.java:728)
    at cfAbstractBaseFacade2ecfc995706692$funcGETSCOPEPLACE.runFunction(C:\CFusionMX7\CustomTags\transfer\com\facade\AbstractBaseFacade.cfc:218)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:360)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2464)
    at cfAbstractBaseFacade2ecfc995706692$funcGETAFTERCREATEOBSERVERCOLLECTION.runFunction(C:\CFusionMX7\CustomTags\transfer\com\facade\AbstractBaseFacade.cfc:61)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:360)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:448)
    at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:308)
    at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2260)
    at cfSoftReferenceHandler2ecfc1880139728$funcHANDLEREAP.runFunction(C:\CFusionMX7\CustomTags\transfer\com\cache\SoftReferenceHandler.cfc:158)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:360)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2464)
    at cfSoftReferenceHandler2ecfc1880139728$funcSYNCRONOUSREAP.runFunction(C:\CFusionMX7\CustomTags\transfer\com\cache\SoftReferenceHandler.cfc:118)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)
    at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:360)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2464)
    at cfSoftReferenceHandler2ecfc813003929$func_CFFUNCCFTHREAD_CFSOFTREFERENCEHANDLER2ECFC8130039291.runFunction(C:\CFusionMX7\CustomTags\transfer\com\cache\cf8\SoftReferenceHandler.cfc:65)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:418)
    at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:324)
    at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:56)
    at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:277)
    at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:192)
    at coldfusion.runtime.UDFMethod.invokeCFThread(UDFMethod.java:174)
    at coldfusion.thread.Task.invokeFunction(Task.java:237)
    at coldfusion.thread.Task.run(Task.java:140)
    at coldfusion.scheduling.ThreadPool.run(ThreadPool.java:201)
    at coldfusion.scheduling.WorkerThread.run(WorkerThread.java:71)

[Mark Mandel]

Jaime,

Yup, that looks like a annoying bug with request scope caching, not
entirely sure what to do with that, I'll have to look into it.

That may actually explain some of your memory issues, (Is the memory
issue on the request one, or the instance one?), as cleanup may not
happen properly.

Also, have you done any cache tuning on the Transfer cache settings?

It has been found (by various people, myself included), that by
tweaking the maxminutestimeout and various other cache params, that
you can actually increase performance by finding that 'sweet spot' in
cache memory usage, and allowing enough memory to be able to be used.

After webDU, I plan on writing an article on the wiki about cache tuning.

Mark

--
E: mark....@gmail.com
W: www.compoundtheory.com

[Jaime Metcher]

Mark,

Thanks for the reply.  I have no detailed insight into the memory thing- just the JVM as a whole is using more memory since we went to CF8, starting low and climbing pretty continuously - very much like it did in CF7 before Transfer 0.6.3.  It's only early days yet, so we don't know whether it will level out or not. 

Re cache tuning - none so far.  Should hardly be an issue with the request scope cache, and Transfer 0.6.3 under CF7 was releasing cache so aggressively that we never bothered tuning the application scope cache.

As for the bug - if you just never called the reaper for the request scope, surely the GC would clean up?  Or does that not work with soft references?

Jaime

[Mark Mandel]

Jaime,

The memory could be a gazillion things, 1.0 and 0.6.3 work quite
differently for starters, as well as your switch of JVMs and CFML
versions.

I would highly recommend some Cache tuning.

I tend to start with a global timeout of about half an hour, and work
from there.... but it really depends on your application, and what you
need.

Mark

[Mark Mandel]

Jaime,

I believe I have a fix locally for this issue,
http://tracker.transfer-orm.com/issue.cfm?p=89977683-A728-9CD3-ABD9545A91734422&i=7A4955A1-E51E-AD41-B56E9698CF1B14BF

I need to do some testing for this, which may take me a short amount
of time, trying to wrap it around webDU ;o)

I'll let you know when it's in SVN.

Mark

[Jaime Metcher]

Cool.  Probably no big rush, as I'd think this is just a "cosmetic" bug - if the scope has gone then there's nothing to clean up anyway, right?

Jaime

On Thu, Jun 12, 2008 at 3:44 PM, Mark Mandel <mark....@gmail.com> wrote:

Jaime,

[Mark Mandel]

Jaime,

I just committed a fix for this into SVN, can you have a run with it,
let me know if you hit any errors.

Cheers,

Mark

--
E: mark....@gmail.com
W: www.compoundtheory.com

[Jaime Metcher]

Thanks, Mark.  Will do - might take a couple of days.

Jaime

[Mark Mandel]

No problem.

Mark

[Jaime Metcher]

Haven't seen the error since Saturday AM.  Thanks again :)

Jaime

[Mark Mandel]

Wonderful.

Mark