7

Before I dive into a bit of code, a summary of my question is: does anybody know what Salesforce does internally when calling .sort() on a List of custom classes?

Scenario: I have a wrapper class that contains an Account record and a variable that will be used to sort the list of wrapper objects. My goal here is to sort accounts in a specific way, via some calculation that can't happen in a trigger, formula, validation rule, etc because it relies on user input. For the purpose of this question, my code below just assigns an auto incremented number.

I initially tested this sorting on 3,000 account records. For 3,000 records, the .sort() method was taking around ~3 seconds to run (although the overall CPU time usage was calculated at ~1.5 seconds - my guess here is that the .sort() method is not counted in the CPU time limit)

Well, that seemed unacceptable to me. What could I do that would decrease this number? I decided to replace the Account object with an Account ID - if I need to query for more account information later, I'll do it in whatever class needs that information. This makes sense to me - instead of storing an entire Account object in the wrapper class, I'll just store the ID. I doubt this would have much impact on the sorting, but I wanted to see if it made any difference anyway.

Replacing the Account object with an ID tripled the sort time - on average, it's taking ~9 seconds to now sort the same list of wrapper objects.

I don't really know why this would be, so any insight here would be appreciated.

I took this a step further and decided to add more properties to the wrapper. It increased the sort time, but only slightly.

Code

AccountWrapper.cls:

public with sharing class AccountWrapper implements Comparable {
public Account Acct { get; private set; }
public Decimal Score { get; private set; }

public AccountWrapper(Account account, Decimal score) {
    this.Acct = account;
    this.Score = score;
}

public Integer compareTo(Object compareTo) {
    AccountWrapper compareToAccount = (AccountWrapper)compareTo;

    // Reversed the standard logic - I want to order descending
    if (Score < compareToAccount.Score) return 1;
    if (Score > compareToAccount.Score) return -1;
    return 0;
}
}

AccountIdWrapper.cls:

public with sharing class AccountIdWrapper implements Comparable {
public Id AccountId { get; private set; }
public Decimal Score { get; private set; }

public AccountIdWrapper(Id accountId, Decimal score) {
    this.AccountId = accountId;
    this.Score = score;
}

public Integer compareTo(Object compareTo) {
    AccountIdWrapper compareToAccount = (AccountIdWrapper)compareTo;

    // Reversed the standard logic - I want to order descending
    if (Score < compareToAccount.Score) return 1;
    if (Score > compareToAccount.Score) return -1;
    return 0;
}
}

BigWrapper.cls:

public with sharing class BigWrapper implements Comparable {
public Id AccountId { get; private set; }
public Id ContactId { get; private set; }
public Id CampaignMemberId { get; private set; }
public Account Acct { get; private set; }
public Decimal Score { get; private set; }

public BigWrapper(Id accountId, Id contactId, Id campaignMemberId, Account account, Decimal score) {
    this.AccountId = accountId;
    this.ContactId = contactId;
    this.CampaignMemberId = campaignMemberId;
    this.Acct = account;
    this.Score = score;
}

public Integer compareTo(Object compareTo) {
    BigWrapper compareToAccount = (BigWrapper)compareTo;

    // Reversed the standard logic - I want to order descending
    if (Score < compareToAccount.Score) return 1;
    if (Score > compareToAccount.Score) return -1;
    return 0;
}
}

WrapperTest.cls - I was calling the methods in this class from the dev console for testing:

public with sharing class WrapperTest {
public void accountWrapperTest() {
    List<AccountWrapper> accountsToSort = new List<AccountWrapper>();
    List<Account> accounts = [SELECT Id FROM Account];
    for (Integer i = 0, j = accounts.size(); i < j; i++) {
        accountsToSort.add(new AccountWrapper(accounts[i], i));
    }

    Long startTime = DateTime.now().getTime();
    accountsToSort.sort();
    Long stopTime = DateTime.now().getTime();
    System.debug('Elapsed time = ' + (stopTime - startTime));
}

public void accountIdWrapperTest() {
    List<AccountIdWrapper> accountsToSort = new List<AccountIdWrapper>();
    List<Account> accounts = [SELECT Id FROM Account];
    for (Integer i = 0, j = accounts.size(); i < j; i++) {
        accountsToSort.add(new AccountIdWrapper(accounts[i].Id, i));
    }

    Long startTime = DateTime.now().getTime();
    accountsToSort.sort();
    Long stopTime = DateTime.now().getTime();
    System.debug('Elapsed time = ' + (stopTime - startTime));
}

public void bigWrapperTest() {
    List<BigWrapper> accountsToSort = new List<BigWrapper>();
    List<Account> accounts = [SELECT Id FROM Account];
    for (Integer i = 0, j = accounts.size(); i < j; i++) {
        accountsToSort.add(new BigWrapper(accounts[i].Id, null, null, accounts[i], i));
    }

    Long startTime = DateTime.now().getTime();
    accountsToSort.sort();
    Long stopTime = DateTime.now().getTime();
    System.debug('Elapsed time = ' + (stopTime - startTime));
}
}

Sorting Results (~3k account records)

AccountWrapper.cls - sort() time (ms) / Calculated CPU time (ms)

  1. 3333 / 1497
  2. 3019 / 1495
  3. 3030 / 1527

AccountIdWrapper.cls - sort() time (ms) / Calculated CPU time (ms) Note: These are the results that are concerning to me. Why is the sort time so high?

  1. 9856 / 1752
  2. 9057 / 2330
  3. 9989 / 1804

BigWrapper.cls - sort() time (ms) / Calculated CPU time (ms)

  1. 10524 / 1958
  2. 10540 / 1974
  3. 10827 / 2041

Apex Profiling Results

Using AccountWrapper.cls:

13:39:50.733 (3733967926)|CUMULATIVE_PROFILING_BEGIN

13:39:50.733 (3733967926)|CUMULATIVE_PROFILING|SOQL operations| Class.WrapperTest.accountWrapperTest: line 4, column 1: [SELECT Id FROM Account]: executed 1 time in 98 ms

13:39:50.733 (3733967926)|CUMULATIVE_PROFILING|No profiling information for SOSL operations

13:39:50.733 (3733967926)|CUMULATIVE_PROFILING|No profiling information for DML operations

13:39:50.733 (3733967926)|CUMULATIVE_PROFILING|method invocations| External entry point: public static void execute(): executed 1 time in 3726 ms

AnonymousBlock: line 2, column 1: public void accountWrapperTest(): executed 1 time in 3725 ms

Class.WrapperTest.accountWrapperTest: line 10, column 1: global public void sort(): executed 1 time in 2977 ms

Class.AccountWrapper.compareTo: line 14, column 1: public Decimal __sfdc_Score(): executed 64659 times in 806 ms

Class.WrapperTest.accountWrapperTest: line 6, column 1: public AccountWrapper(Account, Decimal): executed 6026 times in 438 ms

Class.AccountWrapper.: line 6, column 1: private void __sfdc_Acct(Account): executed 3013 times in 112 ms

Class.AccountWrapper.: line 7, column 1: private void __sfdc_Score(Decimal): executed 3013 times in 78 ms

AnonymousBlock: line 1, column 1: global WrapperTest(): executed 1 time in 0 ms

Class.WrapperTest.accountWrapperTest: line 3, column 1: global public List(): executed 1 time in 0 ms

Class.WrapperTest.accountWrapperTest: line 5, column 1: global public Integer size(): executed 1 time in 0 ms

Class.WrapperTest.accountWrapperTest: line 9, column 1: public static Datetime now(): executed 2 times in 0 ms

13:39:50.733 (3733967926)|CUMULATIVE_PROFILING_END

Using AccountIdWrapper.cls:

13:40:13.945 (13945594268)|CUMULATIVE_PROFILING_BEGIN

13:40:13.945 (13945594268)|CUMULATIVE_PROFILING|SOQL operations| Class.WrapperTest.accountIdWrapperTest: line 17, column 1: [SELECT Id FROM Account]: executed 1 time in 173 ms

13:40:13.945 (13945594268)|CUMULATIVE_PROFILING|No profiling information for SOSL operations

13:40:13.945 (13945594268)|CUMULATIVE_PROFILING|No profiling information for DML operations

13:40:13.945 (13945594268)|CUMULATIVE_PROFILING|method invocations| External entry point: public static void execute(): executed 1 time in 13938 ms

AnonymousBlock: line 3, column 1: public void accountIdWrapperTest(): executed 1 time in 13936 ms

Class.WrapperTest.accountIdWrapperTest: line 23, column 1: global public void sort(): executed 1 time in 12510 ms

Class.AccountIdWrapper.compareTo: line 14, column 1: public Decimal __sfdc_Score(): executed 64659 times in 3752 ms

Class.WrapperTest.accountIdWrapperTest: line 19, column 1: public AccountIdWrapper(Id, Decimal): executed 6026 times in 1000 ms

Class.AccountIdWrapper.: line 6, column 1: private void __sfdc_AccountId(Id): executed 3013 times in 357 ms

Class.AccountIdWrapper.: line 7, column 1: private void __sfdc_Score(Decimal): executed 3013 times in 251 ms

AnonymousBlock: line 1, column 1: global WrapperTest(): executed 1 time in 0 ms

Class.WrapperTest.accountIdWrapperTest: line 16, column 1: global public List(): executed 1 time in 0 ms

Class.WrapperTest.accountIdWrapperTest: line 18, column 1: global public Integer size(): executed 1 time in 0 ms

Class.WrapperTest.accountIdWrapperTest: line 22, column 1: public static Datetime now(): executed 2 times in 0 ms

13:40:13.945 (13945594268)|CUMULATIVE_PROFILING_END

  • Can you explain the discrepancy between the two posted times? I don't follow what they represent. – Adrian Larson Jun 21 '16 at 18:26
  • I highlighted the sort() elapsed times for the AccountIdWrapper.cls - these are the ones that are most concerning to me. I posted the calculated CPU times as well, but I realize now this isn't really a CPU time issue. I just don't understand how the sort() time could have jumped from 3 seconds to 9 seconds. – Robert Watson Jun 21 '16 at 18:34
  • But, what do you mean by calculated CPU time? Isn't that what the first number represents? – Adrian Larson Jun 21 '16 at 18:37
  • The first number represents the elapsed time from before and after the .sort() method call. The second number represents the total CPU time used, as reported to me by Salesforce in the debug logs. – Robert Watson Jun 21 '16 at 18:46
  • @RobertWatson Can you turn profiling on to the max and post the result of those logs? – sfdcfox Jun 21 '16 at 18:57
4

All, I'm sorry to have wrapped everyone's minds around this today. It was definitely Apex logging levels that was corrupting my results, and now I feel slightly dumb and ever slightly more educated. With very little logging enabled (just enough to debug results & profiling), results are now very consistently the same across all implementations.

Thanks to @DanielBallinger for suggesting I look at logging levels.

Lesson learned: logging levels greatly impact performance of Apex code, and in some ways more drastically than you might suspect. (The fact that execution time tripled when storing an ID vs. storing an Account record is still a bit perplexing.)

  • 1
    In that case, one possible reason that the AccountID might be slower than the account is how it appears in the logs. For accounts: 6:33:33:352 VARIABLE_ASSIGNMENT [11]|this|{"Acct":"0x741aefd6" For account ID: 16:34:25:953 VARIABLE_ASSIGNMENT [11]|compareTo|{"AccountId":"0013600000Pb5sDAAR"} – kibitzer Jun 21 '16 at 23:39
  • That totally makes sense. I once logged a defect because an update of 10 records was getting CPU timeout in an org I was in, then I realized that the debug logs were set to maximum. – sfdcfox Jun 22 '16 at 0:50
1

Salesforce (presumably) uses the standard mergesort that's in Java. This means that performance will be O(n) (roughly linear progression of execution time compared to number of elements). I did some experiments in Apex Code, and I've shown that 1000 elements sorted required 999 compareTo calls.

The problem that you have is that you're using an inefficient comparison. Each line of code that you introduce makes the system run slower. For example, you should get much better performance if you do this:

public Integer compareTo(Object compareTo) {
    return Score - ((BigWrapper)compareTo).Score;
}
  • 1
    But why would having the member be Id type instead of Account type slow it down? If anything, it seems like that should be faster. – Adrian Larson Jun 21 '16 at 18:41
  • @AdrianLarson The code I wrote that contains three elements and sorts by a number runs in ~65ms for 10k rows. I suspect that the difference has to do with the complexity of the compareTo function. The algorithm is supposed to scale linearly, and it does indeed scale linearly in all the tests I've performed. – sfdcfox Jun 21 '16 at 18:59
  • @sfdcfox If the compareTo function is the exact same in both AccountWrapper.cls and AccountIdWrapper.cls, and both lists that we're sorting are the same data, how does that make sense? – Robert Watson Jun 21 '16 at 20:28
  • @RobertWatson There's something seriously amiss, I think. I can sort 10k records in less than 1/5th of a second, so it seems odd that only 3k records would take 9 seconds. You might try raising a case with support to see if there's something wrong with your instance. I basically re-wrote your code in my org and couldn't come up with 9 seconds of execution time. – sfdcfox Jun 22 '16 at 0:48
  • @RobertWatson Just saw your answer. Looks like you found the drawback to debug logs. – sfdcfox Jun 22 '16 at 0:52

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.