Wednesday, June 23, 2004

Collecting Your Garbage in CFMX

I came up with a handy little trick the other day, while working on a Dreaded Import Job. I wouldn't recommend relying on it, but it's a nifty last-ditch "kludge" if the pressure is on and the deadline is tight.

I was looping round a few hundred records from database X to import them into database Y. Each time round the loop, depending on the data, it was grabbing lots of related records from DB X, and performing all sorts of checks on existing records in DB Y via CFC calls.

The issue was that every time it ran, it would slow to a crawl after a couple of hundred records. A little investigation showed that it was hogging server RAM at a quite frightening rate - maybe two or three MB every second - and never releasing it until the job finished. As the available RAM decreased, the rate of processing got slower and slower, and a hasty back-of-an-envelope calculation showed that it was extremely unlikely to finish the job in finite time.

Hmmm....

A bit more digging uncovered that the problem was most probably due to some less-than-optimal memory usage inside the CFCs. For instance, the "view" method, to retrieve a record from the DB and return an instance of the CFC with the properties populated, was following a process something like this -

- Get the record from the DB
- Create a new instance of the CFC
- Populate the fields
- Return it.

Hands up who spots whats wrong with that? Anyone? What happens to the new instance of the CFC? When does it get destroyed? Ah-hah....!

--- ASIDE -----
Variable scoping, memory management and the lifetimes of objects are critical issues in a "proper" object-oriented language like Java or (particularly) C++. In fact, one of the main motivations behind the development of Java in the first place was to provide a way to free devlopers from the headaches of manual memory management in C++.

Having written a few fairly complex apps in both languages, I can testify that having to manually allocate AND free the exact number of bytes that you need, in C/C++ is both a curse AND a blessing - it's very easy to write code that will allocate memory and never release it, and often very difficult to track down the cause of the problem when it happens. The upside of it is that it forces you to be very aware of what the code you write is actually doing on a very low level. As a result, variable-scoping is very well defined and documented in C++ - it HAS to be.

Java, on the other hand, uses a different approach. Because a Java app runs in a virtual machine, it allows the use of a Garbage Collector. Developers can happily create new instances of objects with abandon, knowing that every so often the system's garbage collector will check for objects that have gone out of scope, or have no remaining valid references to them, and destroy those instances and free the memory they were occupying back to the heap. This gives developers a lot more freedom, at the cost of losing the hands-on control that you get with C/C++. And sometimes, when things aren't quite working as they should, you can really miss that low-level control.

As CFMX is now a 100% Java application, and CF code is actually compiled into Java classes for execution, this means that intensive, long-run-time code needs to rely on the garbage collector to free resources, but the lifetime of CFC instances and the point where they go out of scope is extremely difficult to pin down - it doesn't seem to be clearly documented anywhere that I've found in a couple of hours of solid Googling.

--- /ASIDE ---


When the above method is called hundreds of times in a loop, it looks to be creating hundreds of instances of CFCs that never seem to die. As stated above, it's very very difficult to find any documentation on this, so all I have to go on is educated guesswork, and hunches.

My hunch is that CF doesn't explicitly run the garbage collector until the end of a request. It's a fairly reasonable way to have designed it, given that 99% of all CF requests are intended to display stuff to a browser within a short amount of time. It's not a language that's really designed for long back-end tasks.

What the view method above should really have been doing was more like -

- Get the record from the DB
- Populate the properties of THIS INSTANCE
- Return this

It's quite a subtle difference in approach - object-oriented versus procedural - and with CFCs still being a pretty new advance in ColdFusion, it's not something you'd be likely to spot without having developed object-oriented code in other languages, and come across similar issues.

When faced with a situation like this, the "correct" thing to do is to re-develop the CFCs to do it properly. However, that takes a lot of time for re-coding and retesting the whole application. That's the downside of centralised, modular code - when you change a bit of modularised code that gets called from all over the place, you have to re-test all over the place!
The deadline, unfortunately, was very tight, so a quick "kludge" had to be found. And here it is -

We can use the fact that CFMX is 100% Java to our advantage here, by FORCING the garbage collector to run. It's actually quite simple:


<cfscript>
// NOTE: I'm typing this code from memory, on a laptop with
// no access to the code, so apologies for any thing that
// may not be 100% correct. The aim here is to illustrate
// the principle, rather than give a copy-and-paste solution

// Create a java System object
objSystem = CreateObject( "java", "java.lang.System" );

// How often do we want it to run?
if( NOT isDefined( "attributes.forceGCEveryNLoops" ) ){
attributes.forceGCEveryNLoops = 25;
}
</cfscript>

<!--- get import data --->
<cfquery name="qryImportData" datasource="whatever"&gt;

</cfquery>

<cfset intLoopCount = 1>

<!--- start of big loop --->
<cfloop query="qryImportData">

<!--- do lots of complicated stuff here --->

<!--- do we need to run the GC? --->
<cfscript>
if( intLoopCount GT attributes.forceGCEveryNLoops ){
// run the GC
System.gc();
intLoopCount = 1;
} else {
intLoopCount = intLoopCount + 1;
}
</cfscript>
</cfloop>



And that's it! Yes, it's a kludge, it's a cheap-and-nasty workaround to cover over fundamental flaws in the code. But on deadline day, it might just save your skin until you get time to re-do those pesky CFC's properly.


4 comments:

Anonymous said...

Whilst I believe you that you hit this problem, I must say I'm very surprised! The JVM should be able to run the garbage collector whenever it wants and it is going to be totally independent of ColdFusion and "requests". In general, in Java, forcing the GC to run is very bad practice and can cause all sorts of weird performance glitches. I'm fascinated that it seems to fix the performance problems with the code you're working on...

I'm also surprised by the "holding onto memory" problem you were seeing. I'd love to see the original CFC code.

Sean A Corfield
seancorfield at gmail.com

Anonymous said...

I encountered a similar problem, but I wasn't using CFC's at all... just strings.

I had a CF template that did close to 1 million INSERTs using a simple CFQUERY inside a simple CFLOOP like this:

CFLOOP 1 to 1,000,000
Do a CFQUERY insert
/CFLOOP

Each insert used a slightly different SQL string (it included the loop iteration number in the SQL text).

It'd start out very fast (5,000 inserts/sec), then eventually get slower, and slower, until it was crawling (1 insert/sec).

Apparently my problem was similar, but it was *strings* (the text of the INSERT queries) and not CFC's, that were being created and apparently never destroyed by the garbage collector.

Java *never* destroys strings and can't even modify them... it simply makes new ones. So if you set myvar to "foo" and then set myvar to "bar", both values are still taking up memory, but only "var" is referenced. The memory used by "foo" will continue to be unavailable for use until the garbage collector gets around to killing that now-unreferenced string.

So in my case, every time I did a CFQUERY insert with a slightly different SQL string (different numbers in it, etc.), I was making a brand new string... nearly a million times. I was expecting the Java gc to intelligently pause and clear all unused ones when memory usage reached 90% or some other reasonable value, and then continue afresh. But it doesn't seem to work that way.

Apparently the gc never runs until the template finishes, or else it's doing some weird tiny incremental runs constantly, which only clear a small number of unreferenced strings on each run and take awhile on each run, which explains why my template eventually slows to a crawl.

I don't know if that lousy gc behavior is CF's fault, the JVM's fault, or what, but it's a big problem. Not just with CFC's, but even with sufficiently high numbers of simple variables like strings... even if they're all assigned to the exact same variable name!

This is making me miss C/C++ where I could allocate a little block of memory big enough to hold one SQL statement and then *REUSE* it on each loop iteration... problem completely solved. It frustrates me that Java can't seem to do this simple task. It'd be okay if it at least used gc intelligently, though! Grrr.

Anybody know how to fix this? I'm not asking for much... I just want Java to do its job and pause for a full gc when the memory gets sufficiently large. Shouldn't that be automatic, for Pete's sake?

Thanks, hope this helped someone!

Alistair Davidson said...

Hi there,

just a quick question - you said you had a "slightly different" SQL statement every time round the loop.... are there any differences in SQL structure *apart from* parameters you're passing in?

If not, then you ARE using CFQUERYPARAM tags, aren't you?

Al

Anonymous said...

thanks for this post..
im trying to get the hang of things at the 'garbage collection arena' of CFMX. and as u said, the topic isn't clearly documented so I could use as much first-hand info as i can.
thanks again.

-=kat=-