Adam Cameron's Dev Blog: Do CFML custom tags have an intrinsic memory leak issue?

G'day:
Betteridge's Law is very much in play with that headline. I guess that's a spoiler. But read on anyhow...

Situation

My previous article - I hope - out to bed the idea that there's a real-world performance consideration when it comes to using transient objects in CFML: "Hanging on to outdated knowledge: don't". This article will give the same treatment to the notion that CFML-based custom tags have an innate issue in that they cause memory leaks. TBH I have only ever heard this from one source, having researched thoroughly and polled the community could not turn up any corroborating evidence, and my own testing here will show: there doesn't seem to be a basis for it.

What I have heard is that back in the days of Spectra - which relies heavily on custom tags - people had performance and stability issues with Spectra-based sites. However as far as I can tell this had always been caused by one or more of the following sort of issues:

sub-optimally-written code;
trying too do too much with too little kit: under-provisioned hardware.

This sort of thing used to happen all the time with all sorts of CFML applications, and was not solely the domain of custom tag usage.

Another consideration is perhaps that this was back on old C++ -written versions of ColdFusion (pre 6.0), and those had intrinsic "idiosyncrasies" with memory handling.

So this is probably a case of throwing the baby out with the bath water.

Custom tags

You could well be thinking "why are you still interested in custom tags?", and indeed I've had a bit of that from the community whilst researching this article. People seem to think that they're dead technology now that we have CFCs and functions and OO practices coming our our ears. I understand why people are seeing this, but it's mostly because things missing the intent off custom tags, I think. And also based on historical misappropriation of them to emulate functions (we had little choice prior to CFMX6.0, that said).

Most custom tag usage I have encountered is along these lines:

<!--- add.cfm --->
<cfset caller[attributes.result] = attributes.addend1 + attributes.addend2>

<!--- oldSchoolExample.cfm --->
<cf_add addend1="13" addend2="17" result="sum">
<cfoutput>#sum#</cfoutput>

Here we take some inputs, process 'em, and "return" some output. It's being used as a function. So... fair enough... if you actually want a function, a custom tag is a bad solution: use a function.

However this was always a misuse of custom tags, and unfortunately it became so widespread, this is - I think - what people think a custom tag is: a pretend function.

The intent of a custom tag, however, is not this. A custom tag is intended to be used in view files, to blend CFML functionality "transparently" in with the view's mark-up.

For the purposes of this article, I've knocked-together a few custom tags and put them together in a test rig (as is my wont with these articles).

Firstly I've created a footnote tag, which when used in conjunction with a page tag, shows one to easily create footnote references in the body of some text, and have the footnotes created at the bottom of the page:

<cfscript>
    // footnote.cfm
    if (!thistag.hasEndtag){
        throw(type="UnmatchedStartTagException" message="Context validation error for the footnote tag" detail="The start tag must have a matching end tag.");
    }
    if (listGetAt(getBasetagList(),2) != "cf_page"){
        throw(type="InvalidTagNestingException" message="Context validation error for the footer tag" detail="The tag must be nested inside a page tag.");
    }
 
   if (thistag.executionMode != "end"){
        exit;
    }
    include "udfs.cfm";
    associate(basetag="cf_page", datacollection="footnoteCollection");
    pageTagData = getBaseTagData("cf_page");
    param pageTagData.footnotes = [];

    thisFootnote = {};
    if (structKeyExists(attributes, "href")){
        thisFootnote.href = attributes.href;
    }
    param attributes.title = thisTag.generatedContent;
    thisFootnote.title = attributes.title;
    arrayAppend(pageTagData.footnotes, thisFootnote);

    thisFootnoteIndex = arrayLen(pageTagData.footnotes);
    thisTag.generatedContent = '<a href="##footNote#thisFootnoteIndex#" class="footnoteLink"><span class="footnote">#thisTag.generatedContent#</span>&nbsp;<sup>#thisFootnoteIndex#</sup></a>';
</cfscript>

The code here is pretty straight fwd, but here's a summary:

validate the usage of the tag, and fail if it's wrong;
interconnect this footnote tag instance with its parent page tag;
grab the details of the footnote from the tag call (its attributes and its text content);
and add that info to the array of footnotes the page tag is tracking;
finally replace the content within the tag pair with some formatting and a link to the footnote

footnote.cfm is a child tag of page.cfm, which is what's used to render the footnotes at the bottom of the page:

<cfscript>
    if (!thistag.hasEndtag){
        throw(type="UnmatchedStartTagException" message="Context validation error for the page tag" detail="The start tag must have a matching end tag.");
    }

    if (thistag.executionMode != "end"){
        exit;
    }

    if (structKeyExists(thisTag, "footnoteCollection") && arrayLen(thisTag.footnoteCollection)){
        writeOutput("<hr><ol>");

        for (i=1; i <= arrayLen(thisTag.footnoteCollection); i++){
            footnote = thisTag.footnoteCollection[i];
            writeOutput('<li id="footNote#i#">');
            textToDisplay = footnote.title;
            if (structKeyExists(footnote, "href")){
                textToDisplay = '<a href="#footnote.href#">#textToDisplay#</a>';
            }
            writeOutput('#textToDisplay#</li>');
        }
        writeOutput("</ol>");
    }
</cfscript>

This is straight forward too:

validate the tag usage (same as for footer);
at the bottom of the page tagset, outputs the array of footnotes.

This was basically an exercise in demonstrating a sensible (?) use of nested tags. Here's an example of it in action:

<link rel="stylesheet" href="lib/css/styles.css">
<cfimport taglib="lib/tags" prefix="doc">
<doc:page>
This is <doc:footnote title="Title of footnote" href="##aLinkForFootnote">text cross referenced with a footnote</doc:footnote>
</doc:page>

This outputs:

This is text cross referenced with a footnote ¹

Title of footnote

That's marginally useful, I guess.

More realistic for my own situation is a translator tag: this one takes an inline key and outputs the translation for it (given a fairly contrived translator in this example, but the concept is sound). We have a multi-lingual site, and currently have to output variables holding the translations when we implement our views. This is much cleaner:

<cfscript>
    // translate.cfm
    if (!thistag.hasEndtag){
        throw(type="UnmatchedStartTagException" message="Context validation error for the translate tag" detail="The start tag must have a matching end tag.");
    }
    if (thistag.executionMode != "end"){
        exit;
    }
    thistag.generatedcontent = application.translationService.translate(thistag.generatedcontent);
</cfscript>

This is really straight forward: it just wraps up a call to a translate method, and replaces the translation key with its translation. This makes for very elegant code in the view file:

<!--- translateExample.cfm --->
<link rel="stylesheet" href="lib/css/styles.css">
<cfimport taglib="lib/tags" prefix="doc">
<p>This is a demo of the translator:
<dl>
<cfloop array="#['one','two','three','four']#" index="number">
    <cfoutput><dt>#number#</dt><dd><doc:translate>#number#</doc:translate></dd></cfoutput>
</cfloop>
<dt>five</dt><dd><doc:translate>five</doc:translate></dd>
</dl>
</p>

Output:
This is a demo of the translator:

one: tahi
two: rua
three: toru
four: wha
five: rima

Finally I've got some util tags which simply output some content and some padding to round out the doc:

<cfscript>
    // filler.cfm
    if (thistag.hasEndtag){
        throw(type="IllegalEndTagException" message="Context validation error for the filler tag" detail="The filler tag must not have a matching end tag.");
    }
    param attributes.paragraphs=0;
    if (!attributes.paragraphs){
        exit;
    }
    for (i=1; i <= attributes.paragraphs; i++){
        writeOutput("<p>#application.textUtilsService.fillerText[i]#</p>");
    }
</cfscript>

The filler tag simply outputs paragraphs of lorem ipsum text, eg:

<!--- fillerExample.cfm --->
<cfimport taglib="lib/tags" prefix="doc">
<doc:filler paragraphs="3">

And this outputs some filler text (I'll spare you).

<cfscript>
    // spacer.cfm
    if (thistag.hasEndtag){
        throw(type="IllegalEndTagException" message="Context validation error for the spacer tag" detail="The spacer tag must not have a matching end tag.");
    }
    param attributes.lines=0;
    if (!attributes.lines){
        exit;
    }

    for (i=1; i <= attributes.lines; i++){
        writeOutput("<br>");
    }
</cfscript>

You get the idea.

I've put all this together to create a mock-up test doc for me to load test:

<!--- test.cfm --->
<link rel="stylesheet" href="lib/css/styles.css">
<cfimport taglib="lib/tags" prefix="doc">
<doc:page>
<p>
This is a test of the footnotes. This is the <doc:footnote>first footnote, and it does not have an href</doc:footnote>.
And now we have a second footnote: <doc:footnote title="specific title for second one">second footnote has a different title</doc:footnote>.
Continuing on we demonstrate giving the footnote an href to another doc: <doc:footnote href="someUrl">third footnote has an href</doc:footnote>,
and finally we've got one with both a <doc:footnote href="someUrl" title="this is the footnote title for the fourth footnote">separate title for the footnote text and has an href too</doc:footnote>.
That's enough testing.</p>
<p>This is a demo of the translator:
<dl>
<cfloop array="#['one','two','three','four']#" index="number">
    <cfoutput><dt>#number#</dt><dd><doc:translate>#number#</doc:translate></dd></cfoutput>
</cfloop>
<dt>five</dt><dd><doc:translate>five</doc:translate></dd>
</dl>
</p>
Some filler text:<br>
<doc:filler paragraphs="10">
And some whitespace:<br>
<doc:spacer lines="5">
</doc:page>

And this outputs:

Notice in test.cfm there's a bunch of CFML processing going on in this view, but stuff-all actual CFML code. Basically we need the <cfimport> tag to make the custom tags work; and then my <cfloop> to demo the translator. If I'd put more effort into it, I could have used a repeater tag for that too.

I showed my colleague this code so as to sanity-check how I was testing, and he commented "it's like you've written a DSL here". Well: precisely! (I concede I had not thought of it in these terms before, but it does sit nicely with me).

Let's have a look at how that test.cfm file might look if I did it all with inline CFML instead:

<!--- testWithoutTags.cfm --->
<cfset footnoteCollection = new services.FootnoteCollection()>
<link rel="stylesheet" href="lib/css/styles.css">
<cfoutput>
<p>
This is a test of the footnotes. This is the #footnoteCollection.addFootnote(text="first footnote, and it does not have an href")#.
And now we have a second footnote: #footnoteCollection.addFootnote(text="second footnote has a different title", title="specific title for second one")#.
Continuing on we demonstrate giving the footnote an href to another doc: #footnoteCollection.addFootnote(text="third footnote has an href", href="someUrl")#,
and finally we've got one with both a #footnoteCollection.addFootnote(text="separate title for the footnote text and has an href too", href="someUrl", title="this is the footnote title for the fourth footnote")#.
That's enough testing.</p>
<p>This is a demo of the translator:
<dl>
    <cfloop array="#['one','two','three','four']#" index="number">
        <dt>#number#</dt><dd>#application.translationService.translate(number)#</dd>
    </cfloop>
    <dt>five</dt><dd>#application.translationService.translate("five")#</dd>

</dl>
</p>
Some filler text:<br>
#application.textUtilsService.getFiller(10)#
And some whitespace:<br>
#application.textUtilsService.getSpacer(5)#
#footnoteCollection.renderFootnotes()#
</cfoutput>

I think it's clear that this:

<doc:footnote>first footnote, and it does not have an href</doc:footnote>

Is much more elegant code that this:

#footnoteCollection.addFootnote(text="first footnote, and it does not have an href")#

Yes? So that's how we should be using custom tags.

Testing

This is all well and good in a one-off situation, but - just like ask simple scenarios when testing unlikely performance issues - single requests will not tell us much. So I've contrived an amplification of this using JMeter to both repeat the test, as well as apply load. It's very much the same as the test I did in the last article, and it's perhaps best just to look at it with JMeter. It's in Github: load.jmx.

I set this to run over 10000 iterations using 50 threads, and calling-in test.cfm 20 times per request. And it ran and ran and ran, without hitch, for at least 80000 requests before I had to switch it off (because I was leaving the office, and wanted to shut down the computer). The general pattern was that request times were uniform, some memory was consumed each request, but when a GC occurred it was all released fine. And this continued predictably for five hours without a single glitch. Here's a few log entries:

"Information","catalina-exec-47","06/04/14","11:13:49","CUSTOMTAGPERF04","1005;162"
"Information","catalina-exec-10","06/04/14","11:13:49","CUSTOMTAGPERF04","1046;165"
"Information","catalina-exec-12","06/04/14","11:13:49","CUSTOMTAGPERF04","1031;169"
"Information","catalina-exec-20","06/04/14","11:13:49","CUSTOMTAGPERF04","1067;151"
"Information","catalina-exec-36","06/04/14","11:13:49","CUSTOMTAGPERF04","894;150"
"Information","catalina-exec-19","06/04/14","11:13:49","CUSTOMTAGPERF04","922;149"
"Information","catalina-exec-40","06/04/14","11:13:49","CUSTOMTAGPERF04","876;143"
"Information","catalina-exec-35","06/04/14","11:13:49","CUSTOMTAGPERF04","975;138"
"Information","catalina-exec-37","06/04/14","11:13:49","CUSTOMTAGPERF04","1032;129"
"Information","catalina-exec-53","06/04/14","11:13:49","CUSTOMTAGPERF04","1038;125"
"Information","catalina-exec-16","06/04/14","11:13:49","CUSTOMTAGPERF04","1008;117"
"Information","catalina-exec-52","06/04/14","11:13:49","CUSTOMTAGPERF04","1062;100"
"Information","catalina-exec-3","06/04/14","11:13:49","CUSTOMTAGPERF04","1102;94"
"Information","catalina-exec-49","06/04/14","11:13:49","CUSTOMTAGPERF04","980;173"
"Information","catalina-exec-15","06/04/14","11:13:49","CUSTOMTAGPERF04","1056;170"
"Information","catalina-exec-9","06/04/14","11:13:50","CUSTOMTAGPERF04","910;161"
"Information","catalina-exec-21","06/04/14","11:13:50","CUSTOMTAGPERF04","1041;154"
"Information","catalina-exec-32","06/04/14","11:13:50","CUSTOMTAGPERF04","1095;146"
"Information","catalina-exec-8","06/04/14","11:13:50","CUSTOMTAGPERF04","1035;144"
"Information","catalina-exec-42","06/04/14","11:13:50","CUSTOMTAGPERF04","1116;133"
"Information","catalina-exec-13","06/04/14","11:13:50","CUSTOMTAGPERF04","1017;129"
"Information","catalina-exec-29","06/04/14","11:13:50","CUSTOMTAGPERF04","1070;123"
"Information","catalina-exec-2","06/04/14","11:13:50","CUSTOMTAGPERF04","1131;112"
"Information","catalina-exec-7","06/04/14","11:13:50","CUSTOMTAGPERF04","1135;106"
"Information","catalina-exec-25","06/04/14","11:13:50","CUSTOMTAGPERF04","965;98"
"Information","catalina-exec-33","06/04/14","11:13:50","CUSTOMTAGPERF04","989;94"
"Information","catalina-exec-54","06/04/14","11:13:50","CUSTOMTAGPERF04","968;88"
"Information","catalina-exec-38","06/04/14","11:13:50","CUSTOMTAGPERF04","1005;171"
"Information","catalina-exec-28","06/04/14","11:13:50","CUSTOMTAGPERF04","937;169"
"Information","catalina-exec-27","06/04/14","11:13:50","CUSTOMTAGPERF04","1047;162"
"Information","catalina-exec-51","06/04/14","11:13:50","CUSTOMTAGPERF04","1128;161"
"Information","catalina-exec-31","06/04/14","11:13:50","CUSTOMTAGPERF04","1155;155"
"Information","catalina-exec-22","06/04/14","11:13:50","CUSTOMTAGPERF04","1161;139"
"Information","catalina-exec-48","06/04/14","11:13:50","CUSTOMTAGPERF04","1041;131"
"Information","catalina-exec-39","06/04/14","11:13:50","CUSTOMTAGPERF04","1116;128"
"Information","catalina-exec-43","06/04/14","11:13:50","CUSTOMTAGPERF04","1163;124"
"Information","catalina-exec-11","06/04/14","11:13:50","CUSTOMTAGPERF04","1012;117"
"Information","catalina-exec-30","06/04/14","11:13:50","CUSTOMTAGPERF04","1002;111"
"Information","catalina-exec-18","06/04/14","11:13:50","CUSTOMTAGPERF04","895;108"
"Information","catalina-exec-45","06/04/14","11:13:50","CUSTOMTAGPERF04","978;106"
"Information","catalina-exec-17","06/04/14","11:13:50","CUSTOMTAGPERF04","898;98"
"Information","catalina-exec-5","06/04/14","11:13:51","CUSTOMTAGPERF04","1132;167"
"Information","catalina-exec-46","06/04/14","11:13:51","CUSTOMTAGPERF04","996;165"

Pretty dry reading. The first column is the execution time of the request, and the second column is how much free memory is available. If you scan down that second column, you see that memory is being consumed, fine, but there's a GC every now and then, and all the memory is released again. Like I said, I ran this for six hours, and the performance pattern was the same throughout.

No memory leak. But we're not done yet...

Oh, btw, the Application.cfc for this is thus:

// Application.cfc
component {
    this.name                = "customTagPerf21";
    this.applicationTimeout    = createTimespan(0,0,0,30);

    function onApplicationStart(){
        application.runtime                = createObject("java","java.lang.Runtime").getRuntime();
        application.translationService    = new services.TranslationService();
        application.textUtilsService    = new services.TextUtilsService();
    }

    function onRequest(){
        var startTime        = getTickCount();
        include arguments[1];
        var executionTime    = getTickCount()-startTime;

        writeLog(file="#this.name#", text="#executionTime#;#getFreeAllocatedMemory()#");
    }

    function getFreeAllocatedMemory(){
        return int(application.runtime.freeMemory() / 1024^2);
    }

}

Control

That's all well and good, but how does the memory usage, request time, and GC interval compare if using object methods instead of custom tags? As a control, I used that testWithoutTags.cfm file, and load tested that as well. This is interesting. Here's an extract from the logs:

"Information","catalina-exec-46","06/05/14","16:30:31","CUSTOMTAGPERF21","83;183"
"Information","catalina-exec-5","06/05/14","16:30:31","CUSTOMTAGPERF21","73;181"
"Information","catalina-exec-10","06/05/14","16:30:31","CUSTOMTAGPERF21","108;164"
"Information","catalina-exec-29","06/05/14","16:30:31","CUSTOMTAGPERF21","116;163"
"Information","catalina-exec-15","06/05/14","16:30:31","CUSTOMTAGPERF21","139;157"
"Information","catalina-exec-20","06/05/14","16:30:31","CUSTOMTAGPERF21","138;148"
"Information","catalina-exec-51","06/05/14","16:30:31","CUSTOMTAGPERF21","100;148"
"Information","catalina-exec-13","06/05/14","16:30:31","CUSTOMTAGPERF21","97;144"
"Information","catalina-exec-54","06/05/14","16:30:31","CUSTOMTAGPERF21","168;136"
"Information","catalina-exec-34","06/05/14","16:30:31","CUSTOMTAGPERF21","137;132"
"Information","catalina-exec-22","06/05/14","16:30:31","CUSTOMTAGPERF21","137;127"
"Information","catalina-exec-50","06/05/14","16:30:31","CUSTOMTAGPERF21","111;127"
"Information","catalina-exec-18","06/05/14","16:30:31","CUSTOMTAGPERF21","157;124"
"Information","catalina-exec-9","06/05/14","16:30:31","CUSTOMTAGPERF21","194;109"
"Information","catalina-exec-41","06/05/14","16:30:31","CUSTOMTAGPERF21","186;106"
"Information","catalina-exec-27","06/05/14","16:30:31","CUSTOMTAGPERF21","200;104"
"Information","catalina-exec-14","06/05/14","16:30:31","CUSTOMTAGPERF21","194;100"
"Information","catalina-exec-42","06/05/14","16:30:31","CUSTOMTAGPERF21","236;93"
"Information","catalina-exec-30","06/05/14","16:30:31","CUSTOMTAGPERF21","151;87"
"Information","catalina-exec-35","06/05/14","16:30:31","CUSTOMTAGPERF21","180;86"
"Information","catalina-exec-19","06/05/14","16:30:31","CUSTOMTAGPERF21","229;82"
"Information","catalina-exec-2","06/05/14","16:30:31","CUSTOMTAGPERF21","175;82"
"Information","catalina-exec-11","06/05/14","16:30:31","CUSTOMTAGPERF21","118;77"
"Information","catalina-exec-33","06/05/14","16:30:31","CUSTOMTAGPERF21","275;76"
"Information","catalina-exec-37","06/05/14","16:30:31","CUSTOMTAGPERF21","231;73"
"Information","catalina-exec-36","06/05/14","16:30:31","CUSTOMTAGPERF21","162;72"
"Information","catalina-exec-47","06/05/14","16:30:31","CUSTOMTAGPERF21","277;71"
"Information","catalina-exec-16","06/05/14","16:30:31","CUSTOMTAGPERF21","319;57"
"Information","catalina-exec-28","06/05/14","16:30:31","CUSTOMTAGPERF21","302;54"
"Information","catalina-exec-40","06/05/14","16:30:31","CUSTOMTAGPERF21","297;184"
"Information","catalina-exec-39","06/05/14","16:30:31","CUSTOMTAGPERF21","335;183"
"Information","catalina-exec-21","06/05/14","16:30:31","CUSTOMTAGPERF21","242;177"
"Information","catalina-exec-12","06/05/14","16:30:31","CUSTOMTAGPERF21","152;174"
"Information","catalina-exec-4","06/05/14","16:30:31","CUSTOMTAGPERF21","203;172"
"Information","catalina-exec-8","06/05/14","16:30:31","CUSTOMTAGPERF21","227;166"
"Information","catalina-exec-45","06/05/14","16:30:31","CUSTOMTAGPERF21","347;161"
"Information","catalina-exec-52","06/05/14","16:30:32","CUSTOMTAGPERF21","280;149"
"Information","catalina-exec-49","06/05/14","16:30:32","CUSTOMTAGPERF21","290;145"
"Information","catalina-exec-26","06/05/14","16:30:32","CUSTOMTAGPERF21","331;143"
"Information","catalina-exec-32","06/05/14","16:30:32","CUSTOMTAGPERF21","227;142"
"Information","catalina-exec-3","06/05/14","16:30:32","CUSTOMTAGPERF21","266;131"
"Information","catalina-exec-25","06/05/14","16:30:32","CUSTOMTAGPERF21","175;129"
"Information","catalina-exec-38","06/05/14","16:30:32","CUSTOMTAGPERF21","194;128"
"Information","catalina-exec-23","06/05/14","16:30:32","CUSTOMTAGPERF21","227;126"
"Information","catalina-exec-5","06/05/14","16:30:32","CUSTOMTAGPERF21","196;122"
"Information","catalina-exec-51","06/05/14","16:30:32","CUSTOMTAGPERF21","119;122"
"Information","catalina-exec-29","06/05/14","16:30:32","CUSTOMTAGPERF21","171;117"
"Information","catalina-exec-48","06/05/14","16:30:32","CUSTOMTAGPERF21","249;111"
"Information","catalina-exec-44","06/05/14","16:30:32","CUSTOMTAGPERF21","294;109"
"Information","catalina-exec-10","06/05/14","16:30:32","CUSTOMTAGPERF21","189;106"
"Information","catalina-exec-24","06/05/14","16:30:32","CUSTOMTAGPERF21","276;107"
"Information","catalina-exec-54","06/05/14","16:30:32","CUSTOMTAGPERF21","151;108"
"Information","catalina-exec-17","06/05/14","16:30:32","CUSTOMTAGPERF21","263;109"
"Information","catalina-exec-20","06/05/14","16:30:32","CUSTOMTAGPERF21","175;103"
"Information","catalina-exec-31","06/05/14","16:30:32","CUSTOMTAGPERF21","191;94"
"Information","catalina-exec-1","06/05/14","16:30:32","CUSTOMTAGPERF21","296;90"
"Information","catalina-exec-22","06/05/14","16:30:32","CUSTOMTAGPERF21","130;89"
"Information","catalina-exec-53","06/05/14","16:30:32","CUSTOMTAGPERF21","295;86"
"Information","catalina-exec-34","06/05/14","16:30:32","CUSTOMTAGPERF21","209;78"
"Information","catalina-exec-6","06/05/14","16:30:32","CUSTOMTAGPERF21","308;75"
"Information","catalina-exec-15","06/05/14","16:30:32","CUSTOMTAGPERF21","252;71"
"Information","catalina-exec-41","06/05/14","16:30:32","CUSTOMTAGPERF21","189;63"
"Information","catalina-exec-46","06/05/14","16:30:32","CUSTOMTAGPERF21","213;181"
"Information","catalina-exec-19","06/05/14","16:30:32","CUSTOMTAGPERF21","137;180"
"Information","catalina-exec-50","06/05/14","16:30:32","CUSTOMTAGPERF21","246;179"
"Information","catalina-exec-13","06/05/14","16:30:32","CUSTOMTAGPERF21","232;173"
"Information","catalina-exec-35","06/05/14","16:30:32","CUSTOMTAGPERF21","221;168"
"Information","catalina-exec-2","06/05/14","16:30:32","CUSTOMTAGPERF21","201;167"
"Information","catalina-exec-30","06/05/14","16:30:32","CUSTOMTAGPERF21","225;163"
"Information","catalina-exec-9","06/05/14","16:30:32","CUSTOMTAGPERF21","254;161"
"Information","catalina-exec-39","06/05/14","16:30:32","CUSTOMTAGPERF21","174;160"
"Information","catalina-exec-7","06/05/14","16:30:32","CUSTOMTAGPERF21","299;159"
"Information","catalina-exec-18","06/05/14","16:30:32","CUSTOMTAGPERF21","289;147"
"Information","catalina-exec-45","06/05/14","16:30:32","CUSTOMTAGPERF21","155;146"
"Information","catalina-exec-27","06/05/14","16:30:32","CUSTOMTAGPERF21","259;142"
"Information","catalina-exec-28","06/05/14","16:30:32","CUSTOMTAGPERF21","209;141"
"Information","catalina-exec-8","06/05/14","16:30:32","CUSTOMTAGPERF21","183;138"
"Information","catalina-exec-47","06/05/14","16:30:32","CUSTOMTAGPERF21","244;138"
"Information","catalina-exec-37","06/05/14","16:30:32","CUSTOMTAGPERF21","221;134"
"Information","catalina-exec-16","06/05/14","16:30:32","CUSTOMTAGPERF21","262;130"
"Information","catalina-exec-33","06/05/14","16:30:32","CUSTOMTAGPERF21","247;125"
"Information","catalina-exec-36","06/05/14","16:30:32","CUSTOMTAGPERF21","293;120"
"Information","catalina-exec-14","06/05/14","16:30:32","CUSTOMTAGPERF21","345;118"
"Information","catalina-exec-4","06/05/14","16:30:32","CUSTOMTAGPERF21","232;114"
"Information","catalina-exec-40","06/05/14","16:30:32","CUSTOMTAGPERF21","254;112"
"Information","catalina-exec-43","06/05/14","16:30:32","CUSTOMTAGPERF21","152;106"
"Information","catalina-exec-26","06/05/14","16:30:32","CUSTOMTAGPERF21","189;104"
"Information","catalina-exec-21","06/05/14","16:30:32","CUSTOMTAGPERF21","258;103"
"Information","catalina-exec-49","06/05/14","16:30:32","CUSTOMTAGPERF21","196;101"
"Information","catalina-exec-38","06/05/14","16:30:32","CUSTOMTAGPERF21","181;94"
"Information","catalina-exec-32","06/05/14","16:30:32","CUSTOMTAGPERF21","256;93"
"Information","catalina-exec-48","06/05/14","16:30:32","CUSTOMTAGPERF21","135;92"
"Information","catalina-exec-3","06/05/14","16:30:32","CUSTOMTAGPERF21","207;83"
"Information","catalina-exec-52","06/05/14","16:30:32","CUSTOMTAGPERF21","249;77"
"Information","catalina-exec-5","06/05/14","16:30:32","CUSTOMTAGPERF21","228;68"
"Information","catalina-exec-25","06/05/14","16:30:32","CUSTOMTAGPERF21","207;64"
"Information","catalina-exec-17","06/05/14","16:30:32","CUSTOMTAGPERF21","184;63"
"Information","catalina-exec-24","06/05/14","16:30:32","CUSTOMTAGPERF21","170;60"
"Information","catalina-exec-11","06/05/14","16:30:32","CUSTOMTAGPERF21","255;48"
"Information","catalina-exec-34","06/05/14","16:30:32","CUSTOMTAGPERF21","159;182"

Here we've got the same two columns: the code's execution time; and the free memory at the end of the request. We see the memory running down and being GCed here too, but the cycle is a lot longer: about 40 requests, as opposed to about 20 for the custom tag version. Also note how much faster the requests are here... a coupla hundred milliseconds per request, as opposed to around a second or so... five times slower on the custom tags version.

I suspect this is because the custom tag version has the <doc:page> tag around the whole thing, and there's an overhead doing the large amount of string handling involved in passing the generatedContent variable about the place.

So I have got to the end of this article and am happy to say "there's no memory leak", but I have some more work to do to check this performance thing out. But I'll do that later... I'm towards the end of the last presentation on day one of Scotch on the Rocks, and the bar is beckoning.

Any thoughts?

--
Adam

Thursday, 5 June 2014

Do CFML custom tags have an intrinsic memory leak issue?

Situation

Custom tags

Testing

Control