<< Back to previous view

[CLJ-1000] Performance drop in PersistentHashMap.valAt(...) in v.1.4 -- Util.hasheq(...) ? Created: 21/May/12  Updated: 01/Mar/13  Resolved: 11/Dec/12

Status: Closed
Project: Clojure
Component/s: None
Affects Version/s: Release 1.4
Fix Version/s: Release 1.5

Type: Enhancement Priority: Major
Reporter: Oleksandr Shyshko Assignee: Timothy Baldridge
Resolution: Completed Votes: 1
Labels: performance
Environment:

Java(TM) SE Runtime Environment (build 1.7.0_04-b21)
Java HotSpot(TM) 64-Bit Server VM (build 23.0-b21, mixed mode)


Attachments: File caching-hasheq-v3.diff     PNG File clj_13.png     PNG File clj_14.png    
Patch: Code
Approval: Ok

 Description   

It seems there is a 30-40% performance degradation of PersistentHashMap.valAt(...) in Clojure 1.4.
Possibly due to references to new CPU-hungry implementation of Util.hasheq(...).

I have created a demo project with more details and some profiling information here:
https://github.com/oshyshko/clj-perf



 Comments   
Comment by Christophe Grand [ 27/Nov/12 8:30 AM ]

I added a patch consisting of three commits:

  • one which adds caching to seqs, sets, maps, vectors and queues
  • one that aligns the shape of Util/hasheq on the one Util/equiv (to have a consistent behavior from the JIT compiler: without that deoptimization was more penalizing for hasheq than for equiv)
  • one that fix hasheq on records (which was non consistent with its equiv impl.) – and this commit relies on a static method introduced in the "caching hasheq" commit
Comment by Timothy Baldridge [ 30/Nov/12 12:10 PM ]

In the process of screening this, I'm not seeing much of a performance difference after applying the patch.

before patch:
user=> (-main)

Version: 1.5.0-master-SNAPSHOT
"Elapsed time: 6373.752 msecs"
"Elapsed time: 6578.037 msecs"
"Elapsed time: 6476.399 msecs"

after patch:
user=> (-main)

Version: 1.5.0-master-SNAPSHOT
"Elapsed time: 6182.699 msecs"
"Elapsed time: 6548.086 msecs"
"Elapsed time: 6496.711 msecs"

clojure 1.4:
user=> (-main)

Version: 1.4.0
"Elapsed time: 6484.234 msecs"
"Elapsed time: 6243.672 msecs"
"Elapsed time: 6248.898 msecs"

clojure 1.3
user=> (-main)

Version: 1.3.0
"Elapsed time: 3584.966 msecs"
"Elapsed time: 3618.189 msecs"
"Elapsed time: 3372.979 msecs"

I blew away my local clojure repo and re-applied the patch just to make sure, but the results are the same. Does this fix not optimize the case given in the original test project?

For reference I'm running this code:

(defn -main
[& args]

(println)
(println "Version: " (clojure-version))

(def mm 10000)

(def str-keys (map str (range mm)))
(def m (zipmap str-keys (range mm)))
(time (dotimes [i mm] (doseq [k str-keys] (m k))))

(def kw-keys (map #(keyword (str %)) (range mm)))
(def m (zipmap kw-keys (range mm)))
(time (dotimes [i mm] (doseq [k kw-keys] (m k))))

(def sym-keys (map #(symbol (str %)) (range mm)))
(def m (zipmap sym-keys (range mm)))
(time (dotimes [i mm] (doseq [k sym-keys] (m k))))

(println))

Comment by Christophe Grand [ 30/Nov/12 2:10 PM ]

Sorry, I was too quick to react on the ML (someone said it was related to hasheq caching and since I had the patch almost ready: on a project I noticed too much time spent computing hasheq on vectors).
So no, my patch doesn't improve anything with kws, syms or strs as keys. However when keys are collections, it fares better.

In 1.4, for a "regular" object, it must fails two instanceof tests before calling .hashCode().
If we make keywords and symbols implement IHashEq and reverse the test order (first IHashEq, then Number) it should improve the performance of the above benchmark – except for Strings.

Comment by Timothy Baldridge [ 30/Nov/12 2:16 PM ]

Marking as incomplete, should we also delete the patch as it seems like it should be in a different ticket?

Comment by Christophe Grand [ 03/Dec/12 10:00 AM ]

In 1.3, #'hash was going through Object.hashCode and thus was simple and fast. Plus collections hashes were cached.
In 1.4 and master, #'hash goes now through two instanceof test (Number and IHasheq in this order) before trying Object.hashCode in last resort. Plus collections hashes are not cached.
As such I'm not sure Util.hasheq inherent slowness (compared to Util.hash) and hasheq caching should be separated in two issues.

The caching-hasheq-v2.diff patchset reintroduces hashes caching for collections/hasheq and reorders the instanceof tests (to test for IHashEq before Number) and makes Keyword and Symbol implement IHashEq to branch fast in Util.hasheq.

I recommend adding a collection test to the current benchmark:

(defn -main
[& args]

(println)
(println "Version: " (clojure-version))

(def mm 10000)

(def str-keys (map str (range mm)))
(def m (zipmap str-keys (range mm)))
(time (dotimes [i mm] (doseq [k str-keys] (m k))))

(def kw-keys (map #(keyword (str %)) (range mm)))
(def m (zipmap kw-keys (range mm)))
(time (dotimes [i mm] (doseq [k kw-keys] (m k))))

(def sym-keys (map #(symbol (str %)) (range mm)))
(def m (zipmap sym-keys (range mm)))
(time (dotimes [i mm] (doseq [k sym-keys] (m k))))

(def vec-keys (map (comp (juxt keyword symbol identity) str) (range mm)))
(def m (zipmap vec-keys (range mm)))
(time (dotimes [i mm] (doseq [k vec-keys] (m k))))

(println))
Comment by Timothy Baldridge [ 03/Dec/12 10:38 AM ]

For some reason I can't get v2 to build against master. It applies cleanly, but fails to build.

Comment by Christophe Grand [ 03/Dec/12 11:30 AM ]

Timothy: I inadvertently deleted a "public" modifier before commiting... fixed in caching-hasheq-v3.diff

Comment by Timothy Baldridge [ 10/Dec/12 11:00 AM ]

I now get the following results:

Version: 1.4.0
"Elapsed time: 6281.345 msecs"
"Elapsed time: 6344.321 msecs"
"Elapsed time: 6108.55 msecs"
"Elapsed time: 36172.135 msecs"

Version: 1.5.0-master-SNAPSHOT (pre-patch)
"Elapsed time: 6126.337 msecs"
"Elapsed time: 6320.857 msecs"
"Elapsed time: 6237.251 msecs"
"Elapsed time: 18167.05 msecs"

Version: 1.5.0-master-SNAPSHOT (post-patch)
"Elapsed time: 6501.929 msecs"
"Elapsed time: 3861.987 msecs"
"Elapsed time: 3871.557 msecs"
"Elapsed time: 5049.067 msecs"

Marking as screened

Comment by Oleksandr Shyshko [ 10/Dec/12 3:53 PM ]

Please, could you add as a comment the bench result using 1.3 vs 1.5-master-post-patch?

Comment by Oleksandr Shyshko [ 11/Dec/12 2:13 PM ]

The performance with 1.5-master is now very close to 1.3 for 3/4 of the benchmark.

However, this code is still showing 43% performance drop (3411 ms VS 6030 ms – 1.3 VS 1.5-master):

(def str-keys (map str (range mm)))
(def m (zipmap str-keys (range mm)))
(time (dotimes [i mm] (doseq [k str-keys] (m k))))

Version: 1.3.0
"Elapsed time: 3411.353 msecs" <---
"Elapsed time: 3459.992 msecs"
"Elapsed time: 3365.182 msecs"
"Elapsed time: 3813.637 msecs"

Version: 1.4.0
"Elapsed time: 5710.073 msecs" <---
"Elapsed time: 5817.356 msecs"
"Elapsed time: 5774.856 msecs"
"Elapsed time: 18754.482 msecs"

Version: 1.5.0-master-SNAPSHOT
"Elapsed time: 6030.247 msecs" <---
"Elapsed time: 3372.637 msecs"
"Elapsed time: 3267.481 msecs"
"Elapsed time: 3852.927 msecs"

To reproduce:
$ git clone https://github.com/clojure/clojure.git
$ cd clojure
$ mvn install -Dmaven.test.skip=true

$ cd ..

$ git clone https://github.com/oshyshko/clj-perf.git
$ cd clj-perf
$ lein run-all

Generated at Fri Dec 19 15:51:41 CST 2014 using JIRA 4.4#649-r158309.