3

A client has recently come to me with a performance issue with my managed package. He is running a test operation which causes a trigger in my package to run but when it does, the maximum CPU time consistently jumps up by at least 3000ms each time, which is causing him concern.

The code for the trigger is simple; it runs on before update, loads all the old records from the DB and loops over them to work out if specific fields have changed. In my client's tests, we have confirmed that none of the fields the trigger is looking for have changed on any of the records, so the trigger should not alter anything or cause any side effects.

After spending quite a bit of time optimising the trigger to no significant effect, I noticed something strange about the debug log my client had given me. The first thing that the trigger does is to run a SOQL query to load the old records, but the debug log was showing a 3s time difference between entering the managed package and running the SOQL query, which is almost exactly the same amount of time that is being added on to the maximum CPU time.

Does anyone know what could be causing such a large time difference between Apex entering my managed package and actually running the trigger?

... // three seconds between entering package (first line) and SOQL query (second line)
13:10:36.153 (8153597148)|ENTERING_MANAGED_PKG|MyPackage
13:10:39.372 (11372876733)|SOQL_EXECUTE_BEGIN|[39]|Aggregations:0|SELECT Id, Website, MyPackage__ReportID__c, MyPackage__ReportIsRunning__c FROM Account WHERE Id IN :tmpVar1
13:10:39.372 (11399440552)|SOQL_EXECUTE_END|[39]|Rows:199
13:10:39.418 (11418181642)|CUMULATIVE_LIMIT_USAGE
...

Below is the result of the Query Plan for the SOQL query (as requested in the comments). It is important to note that the query plan was run on my company's organisation, not my client's organisation where the debug log came from:

Query plan of the SOQL query that is the first line of code in the trigger

The query used to generate that plan is:

SELECT Id, Website, Haystack__HaystackReportID__c, Haystack__HaystackReportIsRunning__c FROM Account WHERE Id IN ('0012000001MNUbRAAX', '0012000001NJc89AAD', '0012000001NJjoVAAT', '0012000001NJjkfAAD', '0012000001NJjokAAD', '0012000001Nx2xYAAR', '0012000001NK2N2AAL', '0012000001NwSrbAAF', '0012000001NJc9WAAT', '0012000001NJd3wAAD', '0012000001NJk1JAAT', '0012000001NJjfiAAD', '0012000001NJjyUAAT', '0012000001NKgvfAAD', '0012000001NKSQVAA5', '0012000001NKBWjAAP', '0012000001NKElnAAH', '0012000001NJjh0AAD', '0012000001NJjjQAAT', '0012000001NJjjaAAD', '0012000001NJjytAAD', '0012000001NKgs1AAD', '0012000001NJjqCAAT', '0012000001NJk0fAAD', '0012000001NwWTUAA3', '0012000001NJjjLAAT', '0012000001NJjo6AAD', '0012000001NxwfbAAB', '0012000001NKIyEAAX', '0012000001NyPMrAAN', '0012000001NxzUJAAZ', '0012000001Nx1CrAAJ', '0012000001Nxt7RAAR', '0012000001NyIVrAAN', '0012000001NyGiSAAV', '0012000001NyPK8AAN', '0012000001OoedfAAB', '0012000001NyPNBAA3', '0012000001Nxr8wAAB', '0012000001Ny1fDAAR', '0012000001OoYuVAAV', '0012000001OoYwaAAF', '0012000001Nyrc0AAB', '0012000001Ny1iWAAR', '0012000001OofDFAAZ', '0012000001OolxfAAB', '0012000001OoeduAAB', '0012000001NyiBEAAZ', '0012000001QSS65AAH', '0012000001NyNshAAF', '0012000001Nz1kOAAR', '0012000001NyPLnAAN', '0012000001NzjdkAAB', '0012000001NyNXOAA3', '0012000001NyNZIAA3', '0012000001NJjjzAAD', '0012000001NJjxbAAD', '0012000001NK2ZDAA1', '0012000001NJjirAAD', '0012000001NJjgbAAD', '0012000001NJjvCAAT', '0012000001NJjqSAAT', '0012000001NJjuEAAT', '0012000001NJmrrAAD', '0012000001NJjozAAD', '0012000001NJjpOAAT', '0012000001NJz0IAAT', '0012000001NK2OeAAL', '0012000001NK2e8AAD', '0012000001Nx19VAAR', '0012000001Nx1DGAAZ', '0012000001NJzJJAA1', '0012000001NJjpTAAT', '0012000001NzOYIAA3', '0012000001NyTSnAAN', '0012000001PZgy0AAD', '0012000001NyiCuAAJ', '0012000001Nz0siAAB', '0012000001Nz9iFAAR', '0012000001OocmIAAR', '0012000001NzjNjAAJ', '0012000001Nz9vHAAR', '0012000001Pc8X7AAJ', '0012000001QSc1vAAD', '0012000001Nz9RoAAJ', '0012000001PbNZkAAN', '0012000001QS67vAAD', '0012000001PcahHAAR', '0012000001QSH5OAAX', '0012000001QS67bAAD', '0012000001PbNxCAAV', '0012000001QSHbxAAH', '0012000001PZrxZAAT', '0012000001PbODPAA3', '0012000001QSGu2AAH', '0012000001QSHFZAA5', '0012000001QSHHHAA5', '0012000001QSGwoAAH', '0012000001QS6AIAA1', '0012000001R4ahiAAB', '0012000001R5Jy0AAF', '0012000001QSHgDAAX', '0012000001Rl8Y9AAJ', '0012000001R4NUPAA3', '0012000001R4aiWAAR', '00120000018eELTAA2', '001200000183OzMAAU', '001200000183OzNAAU', '00120000018grL9AAI', '00120000018fDZEAA2', '00120000018fOr2AAE', '00120000018fVeUAAU', '00120000019RjsSAAS', '0012000001OmrXyAAJ', '0012000001OmsYYAAZ', '0012000001On2poAAB', '0012000001OmJjdAAF', '0012000001OmrX0AAJ', '0012000001OmHgSAAV', '0012000001OmsXfAAJ', '0012000001On2TXAAZ', '0012000001OmpTwAAJ', '0012000001OmrGeAAJ', '0012000001On2dtAAB', '0012000001OmrymAAB', '0012000001On3JVAAZ', '0012000001KMQsYAAX', '0012000001KMEioAAH', '0012000001KMUPzAAP', '0012000001KOhyFAAT', '0012000001KMPJ4AAP', '0012000001KPU6nAAH', '0012000001LKTzOAAX', '0012000001LKTwAAAX', '0012000001LOSVcAAP', '00120000018eED2AAM', '0012000001LXcOHAA1')

In the trigger, the where clause is WHERE Id IN :Trigger.New, but you can't create a query plan from that.

UPDATE

I managed to replace the SOQL query with Trigger.oldMap but while the time difference in the logs is now gone, the problem has not gone away.

All the trigger does now is loop over the changed records, find the corresponding old record and make 2 checks to see if certain fields have changed. In my client's case, all checks return false so no side effects are happening nor anything else that is obviously processor intensive, yet they're still seeing an abnormally large CPU limit increase.

The trigger code is as follows:

trigger AccountTrigger on Account (before update, after update) {

    // check if website has been updated
    Map<Id, Account> oldAccounts = Trigger.oldMap;

    for (Account account:Trigger.New) {
        // find the original account data for this account
        Account oldAccount = oldAccounts.get(account.Id);
        if (oldAccount == null) {
            continue;
        }

        Boolean hasChanged = false; // for debugging

        // if the report ID went from empty to being set, then mark the report as finished
        if (
            oldAccount.ReportIsRunning__c == true &&
            String.isEmpty(oldAccount.ReportId__c) &&
            !String.isEmpty(account.ReportId__c)
        ) {
            System.debug('Report finished, setting report is running flag to false for ' + account.Id);
            account.ReportIsRunning__c = false;
            hasChanged = true;
        }

        if (oldAccount.Website != account.Website) {
            System.debug('Website has changed, removing all report data for ' + account.Id);
            TriggerUtil.populateAccountFields(account, null);
            hasChanged = true;
        }

        if (!hasChanged) {
            System.debug('No update for ' + account.Id);
        }

    }

}
  • In full copy sandbox try uninstalling the managed package and check if it affects performance ,if it does this simply means you will need to contact package owner for this and it might be bad code in the package code – Mohith Shrivastava Jul 22 '16 at 12:18
  • I don't think you've understood the question. This is my package that is having the problem. As such I can say that it is not due to bad code; I have been following best practice and have optimised this trigger to death. – Danny Smart Jul 22 '16 at 13:55
  • Can we get to see the code ? – Mohith Shrivastava Jul 22 '16 at 14:07
  • 1
    My client potentially has thousands of Accounts, and I'm not sure what effect that would have on the query plan, but selecting 200 records from a table by ID surely can't take that much time to plan? If there is any inefficiency, I'd expect it to be in the running of the query, rather than at the planing step – Danny Smart Jul 22 '16 at 16:07
  • 1
    The query used to generate the plan has been added to the question. But again, the execution time of the query isn't included in the CPU time limit, so I'm not sure we're looking in the right direction here – Danny Smart Jul 22 '16 at 16:56
1

As a long shot, try adding a checkbox hierarchy custom setting to your managed package. Use it as the first line in the trigger to determine if the trigger should be bypassed or not. Then you can have a specific user or profile in the customers org setup to completely skip your trigger. If it is still slow with the bypass active then you might need to contact support.


Based on your trigger implementation, it might not be bulkified. How is TriggerUtil.populateAccountFields(account, null); implemented? In the ideal world it would take a collection of accounts to operate on. That way if 200 Accounts were passed into the trigger and had a change to the Website field they would all be processed in a single method call. If there is any SOQL or other expensive operations (nested for loops) in that method it could drastically increase the processing time.


You mention that you are running a SOQL query on Account in your trigger to figure out what fields have changed. Assuming that your before update trigger is on Account, then there is no need to run an additional SOQL query to detect which fields have changed.

You can use the oldMap trigger context variable to find this out directly.

E.g.

trigger accTrigger on Account (before update) {
    for (Account acc : trigger.new) {
        Account oldAcc = Trigger.oldMap.get(acc.Id);
        if(acc.Website != oldAcc.Website) {
            // Website has changed
        }
    }
}

As a guess about what might be causing the delay before the SOQL query is executed, how are you building up the dynamic SOQL query? Are you doing a lot of string concatenation for all the IDs? That could certainly slow things down with all the heap allocation required.

| improve this answer | |
  • Yeah, I found oldMap shortly after posting this question. Unfortunately, removing the SOQL query has not solved the problem; my client is still reporting a massive (+4000) increase in CPU time. – Danny Smart Jul 28 '16 at 8:48
  • For the record, I was using WHERE Id IN Trigger.New in the query – Danny Smart Jul 28 '16 at 8:48
  • Can you add the trigger body to the question? It might provide some clues. Looking for things like System.debug, looping structures and bulkificaiton. Are there other triggers or workflow rules being applied? – Daniel Ballinger Jul 28 '16 at 8:53
  • I've added the code. I do use System.debug() but the rest should be pretty optimal (does System.debug add overhead in a managed package?). My client does have several other triggers running from other packages, but none of those see the kind of CPU time increases that mine does – Danny Smart Jul 28 '16 at 9:13
  • @DannySmart Try adding a custom setting to allow the trigger to be bypassed with minimal processing. Debug statements do increase processing time, but the 3 that you should shouldn't cause a significant blow out. – Daniel Ballinger Jul 28 '16 at 21:30

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.