Significant elapsed time differences when calling sort() on different Comparable implementations

Question

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

Answer 1

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.)

Answer 2

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;
}