9 Replies Latest reply on Nov 24, 2009 8:19 AM by Bart Vanhulle

    Repeated Call to CFC function is much slower than UDF version

    Bart Vanhulle

      For a project we were confronted with an unexpected behaviour from a CFC. Without going to much into the details of the project it comes down to the following: when we run through a set of records, let's say 100, and apply a formatting function on it, the overhead is 4-5 extra seconds when we call it from an instantiated component (only once) compared to when we hardcode it as a UDF. Since our application can process several thousands of records in 1 pass the overhead quickly goes over 100 seconds compared to the UDF.

       

      I was wondering if there's any logical explanation to this behaviour. From what I understood a function called from a component shouldn't add any noticeable overhead after the component has been instantiated.

       

      Our setup is a Coldfusion 8 Jrun installation running on Linux. We couldn't really find anything on the web documenting this (or what we found told us there shouldn't be any extra overhead). We could change the function call to a UDF call but we prefer to keep it in a CFC as there's more going on behind the scenes than just formatting the data.

       

      B.

        • 1. Re: Repeated Call to CFC function is much slower than UDF version
          ilssac Level 5

          It shouldn't unless the way you coded the CFC causes it to do so.

           

          It would depend on how you instainate the CFC, what scope you instinate the CFC in, and what the CFC does with memory every time it is called.

          • 2. Re: Repeated Call to CFC function is much slower than UDF version
            Bart Vanhulle Level 1

            Thank you for the reply. The CFC is instantiated using CFScript, before the loop starts. It's stored in the Variables scope for usage in a component. A quick version of the script would look like this:

             

            Variables.MyCFC = CreateObject("component","MyCFC");

             

            function test(arr) {

             

            for ( i = 1; i < ArrayLen(arr); i++) {

            x = Variables.MyCFC.format(arr[i]);

            }

             

            }

             

            The format function we tested with in the MyCFC component looks like this:

             

            function format(s) {

                return s;

            }

             

            This is a very basic test case we used to validate the problem. If the format function is in the same page as where the loop is, every 100 records it's 4 seconds faster than when it's invoked from the CFC (the 'real' overhead with the UDF being less than 100ms). Pulling it out of the Variables scope didn't make a difference either.

             

            Perhaps we missed something related to memory consumption, but we figured this is the correct way to do what we had in mind. We doubt it's the extra methods and data in the CFC as we noticed similar processing result times with just the format function in the component.

             

            B.

            • 3. Re: Repeated Call to CFC function is much slower than UDF version
              BKBK Adobe Community Professional & MVP
              we call it from an instantiated component (only once)

              Check to make sure this doesn't happen in a loop. If it does, you will be instantiating the component once, a thousand times.

              • 4. Re: Repeated Call to CFC function is much slower than UDF version
                Bart Vanhulle Level 1

                The loop was the first thing we checked. We're certain the component(s) are only instantiated once.

                 

                B.

                • 5. Re: Repeated Call to CFC function is much slower than UDF version
                  Adam Cameron. Level 5

                  I ran a test with the following code:

                   

                  // MyCFC.cfc

                  component {

                   

                      function format(s) {
                          return s;
                      }

                   

                  }

                   

                  <!--- runCfc.cfm --->

                  <cfscript>
                  // make an array to test with
                  a = [];
                  for (i=1; i <= 10000; i++){
                      a[i] = repeatString(chr(randRange(65, 90)), 100);
                  }

                   


                  Variables.MyCFC = CreateObject("component","MyCFC");

                   

                  function test(arr) {
                      for ( i = 1; i < ArrayLen(arr); i++) {
                          x = Variables.MyCFC.format(arr[i]);
                      }
                  }

                   

                  iStart = getTickCount();
                  test(a);
                  writeOutput("Runtime: #getTickCount()-iStart#");
                  </cfscript>

                   

                   

                  <!--- runUdf.cfm --->

                  <cfscript>
                  // make an array to test with
                  a = [];
                  for (i=1; i <= 10000; i++){
                      a[i] = repeatString(chr(randRange(65, 90)), 100);
                  }

                   


                  function format(s) {
                      return s;
                  }
                     
                  function test(arr) {
                      for ( i = 1; i < ArrayLen(arr); i++) {
                          x = format(arr[i]);
                      }
                  }

                   

                  iStart = getTickCount();
                  test(a);
                  writeOutput("Runtime: #getTickCount()-iStart#");
                  </cfscript>

                   

                   

                  The only real difference between runCfc.cfm and runUdf.cfm being the former uses the CFC method, the latter a UDF (same function though).

                   


                  My results were that over multiple passes, the CFC version averaged around 180ms, and the UDF version 140ms.  Over 10000 iterations, that difference only really registers as "trivial" to me.

                   

                   

                  I'm concerned that you are seeing a 4sec difference over 100 iterations.  4sec is huge.

                   

                   

                  Can you pls create a stand-alone, self-contained, completely functional bit of code that demonstrates this (along the lines of what I've posted above)?  I think there's something else to it.

                   

                  --

                  Adam

                  • 6. Re: Repeated Call to CFC function is much slower than UDF version
                    Bart Vanhulle Level 1

                    Thank you for your input. I have used your example before building further on our code to check if the difference applies to it as well.

                     

                    The results are:

                     

                    CFC output:

                     

                    Runtime: ~3500 - 5000

                     

                    UDF output:

                     

                    Runtime: ~50 - 75

                     

                    So even with this very basic example the difference is extreme. I did not modify anything in your code, just copy / pasted and ran it from 2 separate CF files (several times, results were always around the mentionned range). We're running CF8 at the moment, could this have anything to do with it?

                     

                    B.

                    • 7. Re: Repeated Call to CFC function is much slower than UDF version
                      Bart Vanhulle Level 1

                      I ran the test now from 3 different servers, 2 Linux servers (fully licensed) and 1 windows server (developer edition) and the results are the same. All 3 servers run CF8. The UDF version is 40 times faster than the CFC version. The CFC on the windows server is slightly faster than on the Linux servers, but it's still 30 times slower than the UDF.

                       

                      We don't have a CF9 installation so can't test on that.

                       

                      B.

                      • 8. Re: Repeated Call to CFC function is much slower than UDF version
                        ilssac Level 5

                        HA!  Cool!!!! I Think I solved something, I feel so proud.

                         

                         

                        I run Adam's code and the first time I ran it I was getting results similar to Biebel3.  But it was curious, I had debug output showing it it was not showing where the time was being spent.  It would show nearly 2 full seconds to generate the CFC page, but the components broken down in the debugging table only added up to about 50 milliseconds.

                         

                        I first tired putting a <cfsetting showdebugoutput="no"> on the top of the CFC page, but that did not change the results.  Because even if you don't show the results, ColdFusion still complies the debugging output.  So I went into the Administrator and actually turned off the debugging feature.

                         

                        Viola, I started getting the results posted by Adam.

                         

                        It looks like this is an issue where it takes a lot of overhead for ColdFusion to compile a debugging record for each and every CFC call in that large loop.

                         

                        The good news, this is a darn easy fix for a production system!

                        • 9. Re: Repeated Call to CFC function is much slower than UDF version
                          Bart Vanhulle Level 1

                          That's it, the debugger was turned on but we never noticed as there's a <cfsetting showdebugoutput="no"> at the top of the application. On our development server we have it always turned on and never thought of that.

                          Turning it off in the CFIDE now produces much faster processing times for the CFC function invoking.

                           

                          Many thanks for clearing this up and investing time trying to figure it out.

                           

                          B.