Clojure

Performance drop in PersistentHashMap.valAt(...) in v.1.4 -- Util.hasheq(...) ?

Details

  • Type: Enhancement Enhancement
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Completed
  • Affects Version/s: Release 1.4
  • Fix Version/s: Release 1.5
  • Component/s: None
  • Labels:
  • 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)
  • 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

  1. caching-hasheq-v3.diff
    03/Dec/12 11:30 AM
    10 kB
    Christophe Grand
  1. clj_13.png
    136 kB
    21/May/12 10:06 PM
  2. clj_14.png
    140 kB
    21/May/12 10:06 PM

Activity

Hide
Oleksandr Shyshko added a comment -

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

Show
Oleksandr Shyshko added a comment - 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
Hide
Oleksandr Shyshko added a comment - - edited

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

Show
Oleksandr Shyshko added a comment - - edited Please, could you add as a comment the bench result using 1.3 vs 1.5-master-post-patch?
Hide
Timothy Baldridge added a comment -

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

Show
Timothy Baldridge added a comment - 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
Hide
Christophe Grand added a comment -

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

Show
Christophe Grand added a comment - Timothy: I inadvertently deleted a "public" modifier before commiting... fixed in caching-hasheq-v3.diff
Hide
Timothy Baldridge added a comment -

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

Show
Timothy Baldridge added a comment - For some reason I can't get v2 to build against master. It applies cleanly, but fails to build.
Hide
Christophe Grand added a comment - - edited

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))
Show
Christophe Grand added a comment - - edited 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))
Hide
Timothy Baldridge added a comment -

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

Show
Timothy Baldridge added a comment - Marking as incomplete, should we also delete the patch as it seems like it should be in a different ticket?
Hide
Christophe Grand added a comment -

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.

Show
Christophe Grand added a comment - 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.
Hide
Timothy Baldridge added a comment -

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

Show
Timothy Baldridge added a comment - 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))
Hide
Christophe Grand added a comment - - edited

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
Show
Christophe Grand added a comment - - edited 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

People

Vote (1)
Watch (2)

Dates

  • Created:
    Updated:
    Resolved: