Java profiling: java.lang.Object.hashCode takes half of the CPU time but never explictly called

Question

I have been benchmarked my multihreaded program using -agentlib:hprof=cpu=samples and was surprised to find the following line in the results:

rank   self  accum   count trace method
   1 52.88% 52.88%    8486 300050 java.lang.Object.hashCode

I never explicitly call hashCode() in my program. What can be the reason for this? How can I understand the source for this time "waste" and whether it is normal or not?

Thanks, David

Answer 1

Most likely you're using very intensively a Map such as a HashMap.

HashMap used the hashCode to distribute the objects. If you're using many objects with this data structure, is very important your .equals and your .hashCode method are properly implemented.

See: Effective Java Item 8: Always override hashCode when you override equals

Answer 2

One thing you should do is to check out matching stack trace to see who is calling it; changes are it is indeed HashMap.

But beyond this, I have noticed that hprof tends to vasty overestimate calls to hashCode(); and I really would like to know how and why. This is based on actually knowing rough performance profile of code; and I have seen 50% percent cpu use (by sampling), where it is all but certain that it absolutely will not take that long. Implementation of hashCode() just returns an int field, and method is final (on final object). So it is basically a profiler artifact of some sort... just no idea how or why, or how to get rid of it.