12

Short version using approximate Apex CPU timings.

  • Anonymous Apex can run a loop over 200 opportunities in ~10ms.
  • The same loop in a trigger takes ~80ms.
  • If you use an LMA login the trigger loop rises to ~140ms.
  • A trigger in a managed package takes ~2,500 ms to run the same loop.

Why is my managed package loop performance so bad?


I'm currently debugging a performance problem with a trigger in my managed package.

The first part of the trigger is reasonably basic and is used to validate that certain fields have the expected value. (Long story around why Apex is used rather than Validation Rules)

The following is a basic version of the managed package trigger that I duplicated into the subscribers sandbox. The trigger in question would also usually occur on a before insert, but in this case I'm only interested in the update scenario.

trigger TempOppUpdateTestTrigger on Opportunity (before update) {
    TempOppUpdateTest helper = new TempOppUpdateTest();
    if(trigger.isBefore) {
        helper.validateOpportunities(trigger.new, trigger.oldMap, trigger.isInsert);
    }
}

The TempOppUpdateTest helper examines 11 different custom fields to see if they are either set when inserting or changed when updating.

public class TempOppUpdateTest {

    public void validateOpportunities(List<Opportunity> triggerNew, Map<Id,Opportunity> oldMap, boolean isInsert) {

        Map<Id,Set<Opportunity>> accountIdToOpportunityMap = new Map<Id,Set<Opportunity>> ();
        Map<Id,Set<Opportunity>> contactsForOpportunitiesMap = new Map<Id,Set<Opportunity>> ();
        Map<Id,Set<Opportunity>> repsForOpportunitiesMap = new Map<Id,Set<Opportunity>> ();

        integer cpuTimeStart = Limits.getCpuTime();

        for (Opportunity opp: triggerNew) {
            Opportunity oldOpp = null;
            if (!isInsert) {
                oldOpp = oldMap.get(opp.Id);
            }

            if (opp.NSP__SP_Agency__c != null &&
                (
                    isInsert ||
                    (!isInsert && opp.NSP__SP_Agency__c != oldOpp.NSP__SP_Agency__c) ||
                    (!isInsert && opp.NSP__SPBillTo__c == 'Agency' && opp.NSP__SPBillTo__c != oldOpp.NSP__SPBillTo__c)
                )
            ) {

                queueId(accountIdToOpportunityMap, opp.NSP__SP_Agency__c, opp);
            }

            if ((isInsert && opp.NSP__SPAgencyContact__c != null) ||
                (!isInsert && opp.NSP__SPAgencyContact__c != oldOpp.NSP__SPAgencyContact__c)) {

                queueId(contactsForOpportunitiesMap, opp.NSP__SPAgencyContact__c, opp);
            }


            if ((isInsert && opp.NSP__SPBillingContact__c != null) ||
                (!isInsert && opp.NSP__SPBillingContact__c != oldOpp.NSP__SPBillingContact__c)) {

                queueId(contactsForOpportunitiesMap, opp.NSP__SPBillingContact__c, opp);
            }

            if ((isInsert && opp.NSP__SPClientContact__c != null) ||
                (!isInsert && opp.NSP__SPClientContact__c != oldOpp.NSP__SPClientContact__c)) {

                queueId(contactsForOpportunitiesMap, opp.NSP__SPClientContact__c, opp);
            }

            if ((isInsert && opp.NSP__SPMaterialsContact__c != null) ||
                (!isInsert && opp.NSP__SPMaterialsContact__c != oldOpp.NSP__SPMaterialsContact__c)) {

                queueId(contactsForOpportunitiesMap, opp.NSP__SPMaterialsContact__c, opp);
            }

            if ((isInsert && opp.NSP__Operations_Rep__c != null) ||
                (!isInsert && opp.NSP__Operations_Rep__c != oldOpp.NSP__Operations_Rep__c)) {

                queueId(repsForOpportunitiesMap, opp.NSP__Operations_Rep__c, opp);
            }

            if ((isInsert && opp.NSP__Sales_Rep1__c != null) ||
                (!isInsert && opp.NSP__Sales_Rep1__c != oldOpp.NSP__Sales_Rep1__c)) {

                queueId(repsForOpportunitiesMap, opp.NSP__Sales_Rep1__c, opp);
            }

            if ((isInsert && opp.NSP__Sales_Rep2__c != null) ||
                (!isInsert && opp.NSP__Sales_Rep2__c != oldOpp.NSP__Sales_Rep2__c)) {

                queueId(repsForOpportunitiesMap, opp.NSP__Sales_Rep2__c, opp);
            }

            if ((isInsert && opp.NSP__Sales_Rep3__c != null) ||
                (!isInsert && opp.NSP__Sales_Rep3__c != oldOpp.NSP__Sales_Rep3__c)) {

                queueId(repsForOpportunitiesMap, opp.NSP__Sales_Rep3__c, opp);
            }

            if ((isInsert && opp.NSP__Sales_Rep4__c != null) ||
                (!isInsert && opp.NSP__Sales_Rep4__c != oldOpp.NSP__Sales_Rep4__c)) {

                queueId(repsForOpportunitiesMap, opp.NSP__Sales_Rep4__c, opp);
            }

            if ((isInsert && opp.NSP__Sales_Rep5__c != null) ||
                (!isInsert && opp.NSP__Sales_Rep5__c != oldOpp.NSP__Sales_Rep5__c)) {

                queueId(repsForOpportunitiesMap, opp.NSP__Sales_Rep5__c, opp);
            }
        }

        integer cpuTimeFinish = Limits.getCpuTime();

        System.debug(LoggingLevel.Debug, 'Processed ' + triggerNew.size() + ' records.' +
        '\n Start CPU: ' + cpuTimeStart + '/' + Limits.getLimitCpuTime() +
        '\n End CPU: ' + cpuTimeFinish + '/' + Limits.getLimitCpuTime() +
        '\n CPU usage ' + (cpuTimeFinish - cpuTimeStart));

        // ... Further processing with the contents of the Maps
    }

    private void queueId(Map<Id, Set<Opportunity>> recordMap, Id recordId, Opportunity opp) {
        if(recordId == null) {
            System.assert(false, 'queueId() recordId is null');
        }
        else if (recordMap.containsKey(recordId)) {
            Set<Opportunity> opps = recordMap.get(recordId);
            if (!opps.contains(opp)) {
                opps.add(opp);
            }
        } else {
            Set<Opportunity> opps = new Set <Opportunity> ();
            opps.add(opp);
            recordMap.put(recordId, opps);
        }
    }
}

I'm finding a large variance in how much Apex CPU time it takes to run that loop.

I made a basic method to test spinning over the loop from anonymous Apex.

public void bulkCompare(integer size) {
    List<Id> oppIds = new List<ID> {
        '006a000001FkZ4pAAF',
        // ... 400 odd IDs for testing
        '006a000001FkW4aAAF'        
    };

    List<Opportunity> opps = [Select Id, IsDeleted, AccountId, RecordTypeId,
        IsPrivate, Name, Description, StageName, Amount, Probability, 
        // All 391 fields on Opportunity
        from Opportunity
        where ID in: oppIds
        limit :size
    ];

    boolean isInsert = false;

    Map<Id,Opportunity> oldMap = new Map<Id,Opportunity>();
    for (Opportunity opp: opps) {
        oldMap.put(opp.Id, opp.Clone());
    }

    validateOpportunities(opps, oldMap, isInsert);

} 

Then tested it with anonymous Apex:

TempOppUpdateTest tempTest = new TempOppUpdateTest();
tempTest.bulkCompare(200);

Debug output from anonymous Apex for that local trigger.

Processed 200 records.
Start CPU: 991/10000
End CPU: 1002/10000
CPU usage 11

I've got another method that updates an unrelated field on another 200 related records. So the difference here is that it is running via the trigger context.

Processed 200 records.
Start CPU: 3074/10000
End CPU: 3144/10000
CPU usage 70

Then I logged into the same subscriber org as the same user and ran the same anonymous Apex to test the trigger.

Processed 200 records.
Start CPU: 3228/10000
End CPU: 3369/10000
CPU usage 141

The Logging levels were consistent across all the tests:

APEX_CODE,DEBUG;APEX_PROFILING,INFO;CALLOUT,INFO;DB,INFO;SYSTEM,INFO;VALIDATION,NONE;VISUALFORCE,INFO;WAVE,NONE;WORKFLOW,ERROR

There are no Class or Trigger Trace Overrides.

Where this gets particularly problematic for me is the trigger doing the same thing in the managed package. At the start of the validateOpportunities helper method the CPU limit is at 211. Then, just after the same loop and conditionals it's at 2779. So 2,568 CPU ms to do the same thing with the same records.

Summary:

  • Anon Apex in Subscriber org: 12ms
  • Anon Apex in Subscriber org with LMA login: 11ms
  • Direct Trigger in Subscriber org: 70ms
  • Direct Trigger in Subscriber org with LMA login: 141ms
  • Managed package Trigger in Subscriber org with LMA login: 2,568ms

These figures can vary a bit from run to run, but the general ratios are consistent.

It appears that the triggers are much slower than the anonymous apex. Using the LMA sign in makes the trigger slower again (but oddly not the anon apex). And using the LMA to check the managed package shows it is exceptionally slow.

Getting the timing out of the managed package without using the LMA is difficult. It appears from the ENTERING_MANAGED_PKG lines that there is significant time going into that before update trigger. The elapsed ticks between the first and last ENTERING_MANAGED_PKG show 3548 ms (including what should be some quick processing after the loop). Needless to say, using a quarter of the CPU limit to run what should be a quick look is causing all sorts of problems with integrations bulk loading data.

Why can't I get my managed package trigger time anywhere near the anonymous apex timing?


With debug logging off and just an assertion that fails and reports the loop timing:

  • Anon Apex in Subscriber org: 7ms
  • Anon Apex in Subscriber org with LMA login: 6ms
  • Direct Trigger in Subscriber org: 64ms
  • Direct Trigger in Subscriber org with LMA login: 127ms
  • Managed package Trigger in Subscriber org with LMA login: Unknown as the assertion isn't part of the package.

Also raised as Support Case #16098663

  • 1
    Might be a smaller difference if you turned off logging completely? – Adrian Larson Mar 28 '17 at 20:47
  • @AdrianLarson, maybe, but it is difficult for me to get any timing out without any logging. Or do I need to investigate your Apex Profiling project? :) – Daniel Ballinger Mar 28 '17 at 20:52
  • @AdrianLarson Doh, I'll just turn all the logging off and add an assertion that will dump the elapsed time. – Daniel Ballinger Mar 28 '17 at 20:54
  • 2
    @AdrianLarson The logging off timing is faster, but still shows the same general pattern. Admittedly, I haven't got the timing out of the managed package yet. It would take me some time to create a new version of the package to get that number out. – Daniel Ballinger Mar 28 '17 at 21:09
  • 1
    @Eric. LMA session definitely seems to have an overhead. I started looking at this trigger as the ENTERING_MANAGED_PKG entries immediately after the DML_BEGIN point to it as a huge time sink. It's spending 3646 ms of a 3901 ms transaction in the managed package section. Just after the loop in the MP it runs a SOQL query. I can see the timing of these events in the log. It certainly looks like the performance of the MP loop has gone through the floor. – Daniel Ballinger Mar 28 '17 at 22:08
1

Answer that came out of the support case #16098663.

Known Issues - Accessing null fields in trigger context consumes more CPU time

Summary

When an apex method is called via trigger (trigger context) , and the method accesses trigger.new or trigger.old record fields, it needs to do access checks. Thus, consumption of more CPU in trigger context as compared to calling the method directly with same data as access check adds some overhead to CPU. This extra CPU time is working as designed.

However, if the values in the records' fields is null, apex spends more than expected time in accessing the fields when invoked via trigger, which is unexpected.

This may or may not be related to the time blowout when using an LMA based login. I'll seek clarification on that.

Also note that the subscriber org where the problem was manifesting itself has 330 custom fields on Opportunity. It's likely that the vast majority of these were null when the before and after values were compared.

  • Within the provided link, you're instantiating String s within the double for loops. I'm curious if the CPU time changes much if you set the String s; outside the for loops and then just assigned s = acc.myTextField__c; – Brian Miller Mar 25 at 9:00

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.