Apex performance drops between Anonymous Apex and Trigger. Then further when using LMA login

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

Answer

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.

Attribution
Source : Link , Question Author : Daniel Ballinger , Answer Author : Community

Leave a Comment