Unexpected results when using a custom class as key in Map

Question

I thought I understood how maps are supposed to work. So, I thought I would try to be clever and use a custom class as the key in a map in Apex. The results, however have been unexpected.

It's so fundamental that I must be missing something stupid, but I can't see it yet. In the actual application, the custom class I'm using as a key is a bit like an XPath specifier, identifying an object in a tree by the path to that object.

Below, I've distilled it right down to something you can run as anonymous Apex, and still get results that baffle me:

Integer nCallsToEquals = 0;

public class HashingTest {
    private String s;

    public HashingTest(HashingTest ht) {
        this.s = ht.s;
    }

    public HashingTest(String s) {
        this.s = s;
    }

    public Integer hashCode() {
        return s.hashCode();
    }

    public Boolean equals(Object o) {
        ++nCallsToEquals;
        if(o instanceof HashingTest) {
            return s == ((HashingTest)o).s;
        } else {
            return false;
        }
    }

}

HashingTest k1 = new HashingTest('a');
HashingTest k2 = new HashingTest('b');

System.debug('k1.hashCode(): ' + k1.hashCode());
System.debug('k2.hashCode(): ' + k2.hashCode());

Map<HashingTest, Integer> aMap = new Map<HashingTest, Integer>();

aMap.put(k1, 1);
aMap.put(k2, 2);

nCallsToEquals = 0;
aMap.get(k1);
System.debug('nCallsToEquals: ' + nCallsToEquals);
System.assertEquals(1, nCallsToEquals);
nCallsToEquals = 0;
aMap.get(k2);
System.debug('nCallsToEquals: ' + nCallsToEquals);
System.assertEquals(1, nCallsToEquals);

System.debug('aMap: ' + aMap);
System.debug('calling keySet()');
aMap.keySet();
System.debug('aMap: ' + aMap);

nCallsToEquals = 0;
aMap.get(k1);
System.debug('nCallsToEquals: ' + nCallsToEquals);
System.assertEquals(1, nCallsToEquals);
nCallsToEquals = 0;
aMap.get(k2);
System.debug('nCallsToEquals: ' + nCallsToEquals);
System.assertEquals(1, nCallsToEquals);

In my code, HashingTest is suitable for use as a key because it specifies implementations for hashCode() and equals() (they just delegate to String).

And I have a counter to see how many times equals() gets called. This allows us to count the number of collisions in the hashmap implementation.

After populating the map, I output the hashcodes for the keys to make sure they are different (they are).

Then, I get the values back out of the map using the keys. I reset the counter before each get(), so that I can see how many times equals() is called.

The first time, equals() is called once for getting k1 and once for k2. Then, after I call keyset(), it is called once for k1 and twice for k2. As if k1 and k2 are now in the same bucket in the hashmap.

This seems like a triviality, but the numbers explode very quickly. I came to this because I have map with 185 entries where I need to access key-value pairs. I was iterating over the keyset and calling get() on each key. Due to this behaviour, it takes 1 + 2 + 3 + ... + 185 = 17,020 calls to equals() to achieve this.

Here's the debug output in its entirety:

15:48:47.1 (3318843)|USER_DEBUG|[32]|DEBUG|k1.hashCode(): 97
15:48:47.1 (3513197)|USER_DEBUG|[33]|DEBUG|k2.hashCode(): 98
15:48:47.1 (4144662)|USER_DEBUG|[42]|DEBUG|nCallsToEquals: 1
15:48:47.1 (4386196)|USER_DEBUG|[45]|DEBUG|nCallsToEquals: 1
15:48:47.1 (4749309)|USER_DEBUG|[47]|DEBUG|aMap: {HashingTest:[s=a]=1, HashingTest:[s=b]=2}
15:48:47.1 (4792183)|USER_DEBUG|[48]|DEBUG|calling keySet()
15:48:47.1 (5045209)|USER_DEBUG|[50]|DEBUG|aMap: {HashingTest:[s=a]=1, HashingTest:[s=b]=2}
15:48:47.1 (5180286)|USER_DEBUG|[54]|DEBUG|nCallsToEquals: 1
15:48:47.1 (5333300)|USER_DEBUG|[57]|DEBUG|nCallsToEquals: 2

A couple of updates:

1. I tried using System.hashCode(s) instead of s.hashCode() but it made no difference
2. This problem certainly looks related to hashCode() is never called when adding to Maps and Sets (as @keith-c answered below), but I don't believe it is entirely down to the same Known Issue (https://success.salesforce.com/issues_view?id=a1p30000000eMoeAAE). I've rerun the code with all logging flags set to NONE, and put in assertions to check the value of nCallsToEquals. It then fails on the final assertion (getting k2 after calling keySet()) and generates no debug log at all. If I set the logging flags to FINEST, then it fails on the second assertion (the first time we get k2, before calling keySet()), which is what I would expect after reading the Known Issue. To me, this looks like there ought to be a separate bug filed with SF for a call to keySet() changing the underlying representation of a map.

Answer 1

Aidan has already linked to the post that describes what I think is the likely cause: hashCode() is never called when adding to Maps and Sets.

Running with the debug level turned down would confirm.

A key point from that:

2) Once a Map is marshaled, the other representation is used.In this representation, in the put() method call, we traverse all objects in a Map and linearly check uniqueness of keys using the equals() method if a user defined key is used.That's why you don't see the hashCode() method calls but see the equals() method calls in your testcase. (In your org, the Map object is marshaled when trying to generate a debug message for local variable assignments.)

with the supporting comment:

However, the latter representation does not violate the Map contract. Any method call defined in the Map class works as per doc.

I guess the view is that reasonable performance is not an explicit part of the contract...