[SalesForce] How to you benchmark Apex code to determine what operations consume the most CPU time

There are multiple reasons why I'm asking this question, and I realize that it doesn't have an easy answer – accurately benchmarking code is difficult. I’m hoping I can craft this post in such a way that it can be helpful to everyone now and in the future and not be considered too broad.

With new releases coming out from Salesforce three times a year, what was once a CPU-intensive method may be improved in future versions and conversely, new operations could be introduced that blow your limits out of the water. So please note that any mentions of what operations in Apex are CPU-intensive should be re-confirmed regularly.

My goals from this question are as follows:

  1. While there are many questions out there around CPU timeout exceptions, I don't see anything asking about what to specifically avoid doing before a problem actually happens. (Maybe I didn't search hard enough?)

  2. I'm in the process of writing performance rules into the PMD engine and ApexMetrics projects (see pmd and codeclimate-apexmetrics on GitHub), and I'd like to gather feedback on what I should include as a rule. It would be great if some others were able to do their own benchmarking and give me ideas for what I should include.

  3. Dan Appleman and I presented this topic at DF16 and gave some guidance on how to do your own testing. I’d like to share that knowledge here (in case you missed the session), and I'm interested to know if there have been any additional findings that I'm not already aware of.

Best Answer

Benchmarking Code

With a small amount of code you can do some testing to figure out what is eating up that precious CPU limit. (Check out How does SF calculate the CPU time? for reference on what Salesforce counts towards this limit.)

To help get started, I would recommend installing the LimitsProfiler package that Adrian Larson has developed. By using the code provided in this unmanaged package, you no longer need to deal with setting the appropriate logging levels when debugging. In fact, you don’t need to use debug logs at all. (Note that this unmanaged package contains several classes, pages, a custom object, and a custom settings object, and should never be installed into a production environment.)

Next, create a class that extends LimitsProfiler. The implementation below contains code to benchmark static versus dynamic variable assignment.

public with sharing class LimitsTesting {
    public class AssignmentProfiler extends LimitsProfiler {
        Contact ct;
        ID sourceid;
        ID actid;

        public override void setup() {
            // Query a contact - change this to something that will find a match in your org
            ct = [SELECT ID, AccountID FROM Contact WHERE LastName LIKE 'testcontact%' LIMIT 1];
            sourceid = ct.AccountID;
        }

        public override void execute() {
            // Test #1: Put what you are measuring in here, for example:
            actid = sourceid;

            // Test #2: Keep test #1 uncommented. After you get your baseline measurements, uncomment this block to add in ten more and test again:

            /*
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            actid = sourceid;
            */


            // Test #3: Comment out test #2 and test a static field assignment:


            /*
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            actid = ct.AccountID;
            */

            // Test #4: Comment out tests #2 and #3, adjust the loop iteration to 100000, and test a dynamic apex assignment:

            /*
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            actid = (Id)ct.get('AccountID');
            */
        }
    }
}

After saving the class, navigate to /apex/LimitsProfiler and click the "Configure" button to configure a new test run. The Profiler Type should be set to LimitsTesting.AssignmentProfiler and Iterations should be set to 1,000,000. Only the Display CPU Time? checkbox needs to be checked. Saving the configuration will take you back to the main page.

From the main page, take five or more measurements and then calculate the average CPU time across the tests. Record the calculated average, and if you wish, save your results. (Saving the results stores them in a custom object that you can reference in a report later, if you need them.)

You will then perform three more tests, following the directions in the comments of the above class. (For the fourth test, you will likely need to drop the number of iterations down to 100,000 or 10,000.) When calculating the CPU time for tests #2-4, remember to subtract the average CPU time from the first test. We subtract this number when calculating the results of the other tests because we want to know the CPU time for a single variable assignment, not the CPU time for a variable assignment in a for loop.

Benchmarking Results

Test #1: 1,000,000 iterations - 1 variable assignment (baseline test)

939ms average CPU time

Test #2: 1,000,000 iterations - baseline test + 10 variable assignments

2852ms average CPU time

2852-939ms = 1913ms / 10 assignments = 191.3ms / 1,000,000 iterations = .19 microseconds per assignment

Test #3: 1,000,000 iterations - baseline test + 10 static field assignments

9167ms average CPU time

9167-939ms = 8228ms / 10 assignments = 822.8ms / 1,000,000 iterations = .8 microseconds per assignment

Test #4: 100,000 iterations - baseline test + 10 dynamic field assignments

8547ms average CPU time

8547-93.9ms = 8453.1ms / 10 assignments = 845.31ms / 100,000 iterations = 8.5 microseconds per assignment

Note: We should only subtract 93.9ms from the average in test #4 since we are only performing 100,000 instead of 1,000,000 iterations.

What if I don't want to install an unmanaged package to benchmark CPU time?

More details around benchmarking Apex can be found in the DF16 presentation: The Dark Art of CPU Benchmarking and examples found on my DF16 Github repo. The BenchmarkTests.cls class can be used as a guide if you wish to perform CPU benchmarking without using the LimitsProfiler. One of the most important things to remember when benchmarking CPU time is to make sure that all of your logging levels are turned off except where absolutely necessary.

What are the most CPU intensive operations?

We learned a lot when preparing for our DF ‘16 talk on benchmarking. Here are some of the highlights from what we’ve discovered:

  • Calling Schema.getGlobalDescribe() is a big one. While Salesforce does its own caching, it actually isn't very good at caching. Calling Schema.getGlobalDescribe() eats up precious milliseconds of CPU time even on subsequent calls.

  • Using doubles instead of decimals is 200 times faster (half a microsecond vs 100 microseconds) - though make sure you understand the difference when choosing one or the other (Decimal or double?)

  • Serializing data can be CPU intensive depending on the amount of data being serialized.

  • Dynamic assignment uses 8+ microseconds of CPU time, whereas a simple assignment or static assignment can be done in far less than a microsecond. Again, this is really only going to be an issue if you’re iterating over a large list.

    List<Account> account = [SELECT Id FROM Account WHERE Id = '001someidhere']; 
    if (account.size() == 0) return;
    Id accountId = account[0].Id;
    for (Contact contact : contacts) {
        contact.AccountId = accountId; // Do this
        contact.AccountId = (Id)account[0].get('Id'); // Avoid doing this
    }
    

What else am I missing here? What else should we avoid?

Related Topic