ColdFusion Memory Tracking: Real World Performance Example

It is widely known that the built-in ColdFusion Server Monitor can in many cases cause a CF server to become entirely unresponsive if Memory Tracking is enabled. I've experienced this myself when I previously consulted with customers, and I was able to save many clients that engaged me to resolve performance problems by identifying that they had inadvertently enabled Memory Tracking in production. I've written about this before, as have others.

A Test
However, as I am currently working on a Performance Testing project for an enormously large web application, I took this opportunity to observe and measure the impact of enabling Memory Tracking on performance. I was not at all surprised by what happened (the server became entirely unresponsive in very little time), but I was pleased that I was able to document the exact impact in a more empirical manner.

This experiment took place in a staging environment with 3 machines: One to host ColdFusion, another to host IIS, and a third to host JMeter. A performance test was created in JMeter to moderately exercise the application. It was run as a stress test by applying 100 Virtual Users indefinitely with 0 think time (no delay between a HTTP Response and the next HTTP Request). This means that at any given moment JMeter is making 100 simultaneous Requests to the CF server. The CF server is a virtualized instance with a max heap size set to about 12GB, sitting on Windows 7 with 25 GB RAM and 4 x 2.4GHz processors.

Let'r Rip!
The JMeter Test Plan was started and left to run for several hours, all the while pounding ColdFusion. During this period Monitoring was enabled in Server Monitor, but neither Profiling nor Memory Tracking were enabled. The CF Server's throughput was measured in Server Montitor to be steady at about 20 Requests per Second +/- 4 requests (steady range of 16-24). Memory Used by the JVM was a steady 3.9 GB at the peak followed by troughs of about 1.2 GB, with Garbage Collection happening once a minute. This created the typical sawtooth pattern when using the -XX:UseParallelGC JVM GC option. The CPU was typically in the range of 8-12% usage (across the 4 CPUs). The total throughput and memory utilization held steady for the several hours of testing. The app was performing beautifully, with 0 errors logged.

The Death Spiral
Before terminating the JMeter Test Plan execution, I enabled Memory Tracking in the Server Monitor. The JVM memory used began to quickly rise at the rate of about +700 MB per minute. The memory used jumped from a steady 4GB up to 8GB in just 6 minutes before the Server Monitor Interface stopped updating completely. Attempts to disable Memory Tracking were futile as button clicks did not respond. I could only watch the Task Manager on the CF server to continue observing memory and CPU. During the several hours of testing, total System Memory in Task Manager showed about 7.4 GB used, but after Memory Tracking was enabled and Server Monitor became unresponsive, I observed the total System Memory to be 13.7 GB, an increase of about 6 GB. The JVM was at or very close to being at the max heap allowed of 12 GB and was not able to reclaim any memory via GC. At this point I decided to kill the process tree of jrunsvc.exe (which also killed it's child process of jrun.exe, the main server instance). I stopped JMeter and then started ColdFusion again, making sure to disable Memory Tracking before running my next performance test run.

Caveat Emptor
This was a great example to see how Memory Tracking can bring a server to its knees. Often reported and well understood anecdotally, but I thought some actual screenshots of it in action would help illustrate how dangerous this setting can be. Memory Tracking can be used effectively in development and QA for debugging or troubleshooting performance issues, but only when used under small load. I should point out that sometimes Profiling is known to similarly bring down a server, but I was not able to observe any impact of the Profiling setting on this particular application as performance seemed normal when enabled during a stress test.

Server Monitor during Test
ColdFusion Server Monitor: Memory Tracking Performance Impact


Could not find ColdFusion component or interface Query

My best blogging years were when I worked in ColdFusion Technical Support, from Allaire and right on thru Macromedia then Adobe. Constantly fielding customer questions provided an endless source of fodder to investigate and blog about when a solution or workaround was found. It feels a little like old times again now that my QA team is expanding and I've been helping others come up to speed with our ColdFusion driven Automated Test Suite. Although my colleagues are experienced web professionals, I'm happy there is room for mentoring in ColdFusion, and that provides me with more fodder to share here.

After helping someone install ColdFusion 9.0 and apply the 9.01 updater, they reported the updater failed to complete. We cleaned things up a bit, confirmed installers, and tried again. Success. Shortly after, we continued setting up the test suite environment they reported a very unusual error that I'd never seen before, Could not find the ColdFusion component or interface Query. With a bit of Googling, I found that there were only 2 hits, and one was in a comment on Ben Nadel's blog where he provided the winning hint. The other hit was a tweet about it when someone else encountered this issue.

Per Ben's hint, I had my colleague check the CF Admin's Custom Tag mappings, and the source of the problem was immediately evident. The core mapping for "C:ColdFusion9CustomTags" was missing. Prior to then, I thought this mapping was immutable by the end user of the CF Admin. Perhaps it was due to the initial failed 9.01 updater, I'm not really sure how that mapping got wiped out, but as soon as we restored it, everything worked.

The mapping is needed because some parts of the Core CFML language are implemented as custom tags stored in that core location. This includes the query.cfc tag, which implements the script-based version of CFQuery. Without that mapping, there will be several language areas that won't work.


JVM Memory Management and ColdFusion Log Analysis

The following is a document I wrote for knowledge sharing with some peers, but I feel that it might have some value to other ColdFusion Devs, Testers, and Admins out there. The purpose was to illustrate how I went about analyzing CF's performance during a prior troubleshooting session. I'm re-purposing the content here after scrubbing some private information. Hopefully it still makes sense, although slightly out of context.

These are some technical notes on what to look for when analyzing ColdFusion server performance history. It includes concepts and techniques to assess what performance related problems might exist, emphasizing memory usage issues first. This is a somewhat simplified explanation about how the JVM manages memory and its relation to CF applications, and about how I went about analyzing them. There are many similar resources on the web, but I found many of them are quite technical, so this article is written with more of a layman's approach to make it more digistible to those not as familiar with troubleshooting ColdFusion or Java apps.

The ColdFusion Application Server runs inside (is "contained" in) a higher level JRun J2EE server. The J2EE server (and therefore the CF server) run on top a JVM (Java Virtual Machine). To analyze the ColdFusion and JVM performance, I take a forensic approach. I start by collecting the ColdFusion and JRun server logs. I also colelct the JVM Garbage Collection (GC) log that has been manually enabled to log information regarding how the JVM is cleaning up the memory that is has used. The JVM is configured with an algorithm that tells it what approach to take when cleaning up and freeing memory. The application's Java objects (like queries, session variables, local variables, cfc instances, etc) are held in the JVM's memory. Objects are said to hold "references" in memory, meaning that something in the application is potentially using that object. When the application no longer has a need for an object, its memory is dereferenced. That dereferenced memory can be released by the JVM and then reused by other objects that require it.


Starting ColdFusion9 Solr: Using cfsolr in same directory

The cfsolr script for Mac, Linux, and Unix is written such that you must be in the ColdFusion9/solr/ directory when running the script. The script refers to the start.jar file without providing the full path.

The problem is that if you are not in the solr/ directory under the ColdFusion root directory, the cfsolr script echos that Solr has been started or stopped, even though it has not.

Since the standard error is redirected to the standard out with "2>&1" the problem is swallowed and the person performing the operation is led to believe that the operation has been carried out as expected.

Here's a snippet from the ColdFusion9/solr/cfsolr script showing that start.jar is referenced without a full path:

view plain print about
1SOLRSTART='nohup java $JVMARGS -jar start.jar > $SOLR/logs/start.log 2>&1 &'
2SOLRSTOP='nohup java $JVMARGS -jar start.jar --stop > $SOLR/logs/start.log 2>&1'

Looking at the logs, I see that the problem was quietly recorded in a solr log file:

view plain print about
1QAs-iMac:logs QA$ pwd
3QAs-iMac:logs QA$ cat start.log
4Unable to access jarfile start.jar

The script already has a variable defining the Solr directory path:

view plain print about

To fix the bug, prefix the reference to start.jar with ${SOLR}/start.jar like this:

view plain print about
1SOLRSTART='nohup java $JVMARGS -jar ${SOLR}/start.jar > $SOLR/logs/start.log 2>&1 &'
2SOLRSTOP='nohup java $JVMARGS -jar ${SOLR}/start.jar --stop > $SOLR/logs/start.log 2>&1'

With that fix, the cfsolr script can be called from any directory outside the solr directory.

Here is an examle of how the script falsely echos that the solr server has stopped or started when it has not (determined by grepping for the process):

view plain print about
1QAs-iMac:opt QA$ pwd
3QAs-iMac:opt QA$ ./ColdFusion9/bin/coldfusion stop
4Stopping ColdFusion 9, please wait
5Stopping coldfusion server.stopped
6ColdFusion 9 has been stopped
7QAs-iMac:opt QA$ ps -ef | grep solr
8 501 73310 1 0 0:00.25 ?? 0:02.64 /usr/bin/java -XX:+AggressiveOpts -XX:+ScavengeBeforeFullGC -XX:-UseParallelGC -Xmx256m -Dsolr.solr.home=multicore -DSTOP.PORT=8079 -DSTOP.KEY=cfsolrstop -jar start.jar

view plain print about
1QAs-iMac:opt QA$ ./ColdFusion9/solr/cfsolr start
2Starting ColdFusion Solr Server...
3ColdFusion Solr Server is starting up and will be available shortly.
4QAs-iMac:opt QA$ ps -ef | grep solr
5 501 78371 62961 0 0:00.00 ttys000 0:00.00 grep solr
6QAs-iMac:opt QA$ ps -ef | grep solr
7 501 78373 62961 0 0:00.00 ttys000 0:00.00 grep solr
8QAs-iMac:opt QA$ ps -ef | grep solr

Recent Tweets for Fri Oct 2, 2009

Follow me on Twitter!

Fri Oct 02 7:26 PM
Ghosts of ColdFusion Past
Fri Oct 02 4:40 PM
@john_mason_ Thanks. Indeed, the server was under high load.
Fri Oct 02 4:21 PM
Ditto that! RT @awest: Working at home really blows. Not.
Fri Oct 02 3:44 PM
@charliegriefer Enjoy! Twitter is gonna have a melt down. #adobeMAX
Fri Oct 02 3:12 PM
Have you ever launched the ColdFusion Server Monitor and seen the buttons for Monitoring, Profiling, and Memory just not show up at the top?


Recent Tweets for Fri August 28, 2009

Follow me on Twitter!

Fri Aug 28 8:52 PM
Why is it that ColdFusion must be started by a privileged user on every operating system but Mac? Hmph!
Fri Aug 28 8:43 PM
@shutupdanielle Could be worse, you could be in Bolton. 2 pizza shops, that's it. Nary a chicken wing in sight (really).
Fri Aug 28 8:36 PM
@mobarger Big city turn me loose, set me free, somewhere in the middle of Montana
Fri Aug 28 8:08 PM
@styggiti Outside temp last night was 52F here, but not sure which is better lower temps or lower humidity.
Fri Aug 28 5:43 PM
ColdFusion 9 (& ColdFusion 8.01) bug for CF Multiserver's bin/ file. Please vote:
Fri Aug 28 4:56 PM
Yep, verified the 3 issues with the Solaris part of the boot script installer for ColdFusion 9. Oh, bugtracker.....


ColdFusion Request Tuning Settings in Depth

Undoubtedly, the ColdFusion Administrator settings for Request Tuning are critical to performance of Web applications running in the server. While reading the recent Adobe article on Performance Tuning for ColdFusion Applications I was surprised to find the content on this topic to be a little light. With that in mind, I set out to expand on the topic of the Request Tuning settings.

Foundations of ColdFusion Request Settings

To begin, let’s look at how the ColdFusion settings were configured in earlier versions of application server. With the release of ColdFusion MX 6.0 through versions 6.1 and 7, all editions of the ColdFusion server had one setting for Request Limits. This was referred to as the “Simultaneous Requests” setting. This single setting throttled the number of running requests to be processed concurrently. Should the running pool be fully occupied by requests that are processing but haven’t yet completed, the J2EE server underlying ColdFusion will hold requests in a queued request thread pool that are to be fed to the running request pool.


Recent Tweets for Sat July 25, 2009

Follow me on Twitter!

Fri Jul 24 9:13 PM
Thorough video tutorial for the special requirements of photographing actor headshots @LayersMagazine #photog
Fri Jul 24 8:49 PM
@jeffcrossphoto Yeah, @GuyWithCamera he kills me. Gonna tweet him for next week's #photog #FF
Fri Jul 24 8:39 PM
@jeffcrossphoto Yes, but how many #photogs are actually just #gwcam (guy with camera) (@GuyWithCamera)
Fri Jul 24 6:33 PM
@jshapiro1109 Thanks for the hint. I can't help myself from deconstructing things. :D #AdobeWave
Fri Jul 24 6:30 PM
The company that laidoff my wife in March just went bankrupt and laid the rest off, but severance checks are bouncing now. #whew #epix #pharmaceuticals


Recent Tweets for Friday July 17, 2009

Follow me on Twitter!

Fri Jul 17 1:15 AM
@scouten Fascinating! BTW, if u ever need LR3 beta testers, sign me up. (I won the Adobe contest for most bugs logged against PS Express)
Fri Jul 17 12:59 AM
@ashumittal Feeling a lot like Thursday night here! ;-)
Fri Jul 17 12:52 AM
@scouten Yikes! Didn't know that. A 4 year dev cycle must have been grueling (but finally rewarding)
Fri Jul 17 12:43 AM
@scouten Wasn't Lightroom 1 released Feb 2007? Macr/Adobe deal closed Dec 2005. Well, as Flex dev, my fingers are crossed for MXML in LR3
Fri Jul 17 12:37 AM
@scouten What got me thinking was PatchPanel which enables Flex developers to write plugins for CS4. WIshing could do that with Lightroom.
Fri Jul 17 12:33 AM
Passing the night by watching @benforta videos on ColdFusion 9 (again)


Recent Tweets for Wed July 01, 2009

Recent Tweets for Wed July 01, 2009

Wed Jul 01 2:59 PM
Thx @fuzzyorange . Looks like a known condition with its own JVM flag -XX:-UseGCOverheadLimit
Wed Jul 01 2:56 PM
@dfgrumpy Thx. Its the "GC overhead limit exceeded" part I've never seen before. Researching now. Might be a new verbiage, nothing more.
Wed Jul 01 2:50 PM
First time I've ever seen this in ColdFusion: java.lang.OutOfMemoryError: GC overhead limit exceeded
Wed Jul 01 2:48 PM
@awest @cfaddict minus ~30% in taxes of course.
Wed Jul 01 2:37 PM
@mvanleest Linux, CF80 RedHat 5. I'm thinking its a large cf.registry file for client storage since cf startup pauses at "Starting client"


More Entries