Friday, 6 June 2014

CFML: Follow-up on custom tag performance

G'day:
Yesterday I looked at memory leaks (or lack thereof) in custom tag usage: "Do CFML custom tags have an intrinsic memory leak issue?". There was no memory leakage, but what there was was pretty poor performance.

My suspicion was that it was down to there being a lot of string handling going on, as I had a custom tag around quite a lot of text, and text-handling is not a great performer.



I've just put this to the test, by getting rid of the main tag I was using, and just testing one of the smaller ones:

<!--- testWithTagsWithoutPageTag.cfm --->
<link rel="stylesheet" href="lib/css/styles.css">
<cfimport taglib="lib/tags" prefix="doc">
<p>
<dl>
<dt>one</dt><dd><doc:translate>one</doc:translate></dd>
<dt>two</dt><dd><doc:translate>two</doc:translate></dd>
<dt>three</dt><dd><doc:translate>three</doc:translate></dd>
<dt>four</dt><dd><doc:translate>four</doc:translate></dd>
<dt>five</dt><dd><doc:translate>five</doc:translate></dd>
<dt>six</dt><dd><doc:translate>six</doc:translate></dd>
<dt>seven</dt><dd><doc:translate>seven</doc:translate></dd>
<dt>eight</dt><dd><doc:translate>eight</doc:translate></dd>
<dt>nine</dt><dd><doc:translate>nine</doc:translate></dd>
<dt>ten</dt><dd><doc:translate>ten</doc:translate></dd>
</dl>
</p>

And the non-tag equivalent:

<!--- testWithoutTagsWithoutPageStuff.cfm --->
<link rel="stylesheet" href="lib/css/styles.css">
<cfoutput>
<dl>
<dt>one</dt><dd>#application.translationService.translate("one")#</dd>
<dt>two</dt><dd>#application.translationService.translate("two")#</dd>
<dt>three</dt><dd>#application.translationService.translate("three")#</dd>
<dt>four</dt><dd>#application.translationService.translate("four")#</dd>
<dt>five</dt><dd>#application.translationService.translate("five")#</dd>
<dt>six</dt><dd>#application.translationService.translate("six")#</dd>
<dt>seven</dt><dd>#application.translationService.translate("seven")#</dd>
<dt>eight</dt><dd>#application.translationService.translate("eight")#</dd>
<dt>nine</dt><dd>#application.translationService.translate("nine")#</dd>
<dt>ten</dt><dd>#application.translationService.translate("ten")#</dd>
</dl>
</p>
</cfoutput>

So here we're manipulating strings, but the tag version is not manipulating great swathes of them. Hopefully analogous. But here's the results:

Using tags:

"Information","catalina-exec-21","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","121;129"
"Information","catalina-exec-16","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","283;129"
"Information","catalina-exec-10","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","238;129"
"Information","catalina-exec-24","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","133;128"
"Information","catalina-exec-18","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","183;128"
"Information","catalina-exec-15","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","178;127"
"Information","catalina-exec-8","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","226;127"
"Information","catalina-exec-9","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","203;127"
"Information","catalina-exec-23","06/06/14","09:47:41","TESTWITHTAGSWITHOUTPAGETAG.CFM_10_02","183;127"

Without tags:
"Information","catalina-exec-2","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","31;152"
"Information","catalina-exec-11","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","20;152"
"Information","catalina-exec-18","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","74;152"
"Information","catalina-exec-13","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","88;152"
"Information","catalina-exec-20","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","63;206"
"Information","catalina-exec-16","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","44;206"
"Information","catalina-exec-8","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","64;206"
"Information","catalina-exec-6","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","85;206"
"Information","catalina-exec-7","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","69;206"
"Information","catalina-exec-24","06/06/14","09:48:39","TESTWITHOUTTAGSWITHOUTPAGESTUFF.CFM_10_02","42;206"

So using tags, we're getting about 100-300ms running that test (well: the test calls in those templates ten times each... so 100 tag or function calls, for the respective tests), and using method calls instead... 30-100ms.

There's definitely a performance consideration there: tags are 3-4 times slower. And I also think the load I'm putting this lot under is not unreasonable: I'm only running 20 threads simulatenously, and this is only 100 translations per request. I showed these results to one of our lead devs and he screwed up his nose and went "100ms diff? Hmmm...". We need to think a bit more about this before we make a call on it.

Anyway, that's that. I just wanted to do the follow-up to yesterday's article.

Back to Scotch on the Rocks.

--
Adam