protocols-vs-threads.clj

;; follow up to http://clj-me.cgrand.net/2010/05/08/destructuring-records-prototypes-and-named-arguments/
user=> (defrecord Foo [a b])
user.Foo
user=> (defprotocol Seq (my-seq [this]) (my-seq? [this]))
Seq
user=> (extend-protocol Seq
clojure.lang.ISeq
(my-seq [this] (.seq this))
(my-seq? [this] true)
Object
(my-seq [this] (clojure.lang.RT/seq this))
(my-seq? [this] false))
nil
;; benchmarking  fns
user=> (defn foo-dest [n] (with-out-str (let [x (Foo. 1 2)] (dotimes [_ 5] (time (dotimes [_ n] (let* [map__3838 x map__3838 (if (my-seq? map__3838) (clojure.core/apply clojure.core/hash-map map__3838) map__3838) b (:b map__3838) a (:a map__3838)] [a b])))))))
#'user/foo-dest
user=> (defn map-dest [n] (with-out-str (let [x {:a 1 :b 2}] (dotimes [_ 5] (time (dotimes [_ n] (let* [map__3838 x map__3838 (if (my-seq? map__3838) (clojure.core/apply clojure.core/hash-map map__3838) map__3838) b (:b map__3838) a (:a map__3838)] [a b])))))))
#'user/map-dest
;; for the record, non-concurrent timings
;; * datatypes ~ 1.4s
user=> (println (foo-dest 1e8))
"Elapsed time: 1473.611171 msecs"
"Elapsed time: 1457.087912 msecs"
"Elapsed time: 1458.858249 msecs"
"Elapsed time: 1481.323115 msecs"
"Elapsed time: 1461.595468 msecs"

nil
;; * array maps ~ 4.5s
user=> (println (map-dest 1e8))
"Elapsed time: 4547.932279 msecs"
"Elapsed time: 4570.094035 msecs"
"Elapsed time: 4574.920276 msecs"
"Elapsed time: 4577.704429 msecs"
"Elapsed time: 4602.040972 msecs"

nil
;; two threads performing datatype destructuring: ~1.6s instead of 1.4s
user=> (let [a (future (foo-dest 1e8)) b (future (foo-dest 1e8))] (println @a) (println @b))
"Elapsed time: 1766.657284 msecs"
"Elapsed time: 1714.443316 msecs"
"Elapsed time: 1709.158147 msecs"
"Elapsed time: 1829.157547 msecs"
"Elapsed time: 1679.124791 msecs"

"Elapsed time: 1616.249133 msecs"
"Elapsed time: 1691.059618 msecs"
"Elapsed time: 1580.639788 msecs"
"Elapsed time: 1618.993894 msecs"
"Elapsed time: 1586.112551 msecs"

nil
;; two threads performing arraymaps destructuring: ~5.3s instead of 4.6s
user=> (let [a (future (map-dest 1e8)) b (future (map-dest 1e8))] (println @a) (println @b))
"Elapsed time: 5352.87327 msecs"
"Elapsed time: 5606.322591 msecs"
"Elapsed time: 5916.193817 msecs"
"Elapsed time: 5539.506976 msecs"
"Elapsed time: 5074.207685 msecs"

"Elapsed time: 5041.718361 msecs"
"Elapsed time: 5029.104746 msecs"
"Elapsed time: 5005.710013 msecs"
"Elapsed time: 5475.130848 msecs"
"Elapsed time: 5102.93487 msecs"

nil

;; Now, the heart of the problem:
;; two threads performing different destructurings:
;; foo: ~3.3s instead of 1.4/1.6 (non-concurrent/concurrent) 
;; arraymaps 8.1s instead of 4.6/5.3
user=> (let [a (future (foo-dest 1e8)) b (future (map-dest 1e8))] (println @a) (println @b))
"Elapsed time: 3165.176929 msecs"
"Elapsed time: 3713.008916 msecs"
"Elapsed time: 3271.081939 msecs"
"Elapsed time: 3627.45307 msecs"
"Elapsed time: 3417.678853 msecs"

"Elapsed time: 8148.976337 msecs"
"Elapsed time: 8104.987714 msecs"
"Elapsed time: 4967.582612 msecs" ; non-concurrent, the 1st future is done
"Elapsed time: 4600.386293 msecs" ; non-concurrent
"Elapsed time: 4597.667302 msecs" ; non-concurrent

nil

;; with a non-volatile MethodImplCache.mre
;; foo: ~3s instead of 3.3s (volatile)
;; arraymaps: 6.7s instead of 8.1 (volatile)
user=> (let [a (future (foo-dest 1e8)) b (future (map-dest 1e8))] (println @a) (println @b))
"Elapsed time: 3023.324193 msecs"
"Elapsed time: 3262.466947 msecs"
"Elapsed time: 2876.130974 msecs"
"Elapsed time: 2840.484196 msecs"
"Elapsed time: 2854.192362 msecs"

"Elapsed time: 6623.254701 msecs"
"Elapsed time: 6822.179216 msecs"
"Elapsed time: 5437.200399 msecs"
"Elapsed time: 5131.609534 msecs"
"Elapsed time: 5098.58718 msecs"

nil

;; for reference, without MethodImplCache.mre:
;; foo: 2.2s instead of 3/3.3s (non-volatile/volatile)
;; arraymaps: 6.8s instead of 6.7/8.1 (non-volatile/volatile)
user=> (let [a (future (foo-dest 1e8)) b (future (map-dest 1e8))] (println @a) (println @b))
"Elapsed time: 2216.960326 msecs"
"Elapsed time: 2255.31967 msecs"
"Elapsed time: 2185.348906 msecs"
"Elapsed time: 2144.08577 msecs"
"Elapsed time: 2153.637194 msecs"

"Elapsed time: 6823.892003 msecs"
"Elapsed time: 5730.888423 msecs"
"Elapsed time: 5363.689938 msecs"
"Elapsed time: 5300.091701 msecs"
"Elapsed time: 5366.968567 msecs"


;;;;;;;;;;;; Send more cores!
;; same code, run on a 32-threads T2000 http://www.sun.com/servers/coolthreads/t2000/index.xml

ser=> (println (foo-dest 1e6))
"Elapsed time: 454.260381 msecs"
"Elapsed time: 526.503864 msecs"
"Elapsed time: 611.366579 msecs"
"Elapsed time: 454.24793 msecs"
"Elapsed time: 454.177124 msecs"

nil
user=> (println (map-dest 1e6))
"Elapsed time: 630.115303 msecs"
"Elapsed time: 630.016759 msecs"
"Elapsed time: 674.0532 msecs"
"Elapsed time: 629.943333 msecs"
"Elapsed time: 629.958103 msecs"

user=> (doseq [x (doall (map #(future (%1 1e6)) (take 2  (cycle [foo-dest map-dest]))))] (println @x))
"Elapsed time: 602.014886 msecs"
"Elapsed time: 561.789507 msecs"
"Elapsed time: 581.100227 msecs"
"Elapsed time: 562.049441 msecs"
"Elapsed time: 568.72402 msecs"

"Elapsed time: 815.004904 msecs"
"Elapsed time: 791.437008 msecs"
"Elapsed time: 771.883386 msecs"
"Elapsed time: 725.088855 msecs"
"Elapsed time: 630.199053 msecs"

nil
user=> (doseq [x (doall (map #(future (%1 1e6)) (take 8 (cycle [foo-dest map-dest]))))] (println @x))
"Elapsed time: 568.47803 msecs"
"Elapsed time: 574.64929 msecs"
"Elapsed time: 581.10607 msecs"
"Elapsed time: 628.105879 msecs"
"Elapsed time: 565.510939 msecs"

"Elapsed time: 804.853852 msecs"
"Elapsed time: 856.535258 msecs"
"Elapsed time: 838.092542 msecs"
"Elapsed time: 778.343825 msecs"
"Elapsed time: 653.002669 msecs"

"Elapsed time: 596.699713 msecs"
"Elapsed time: 578.773206 msecs"
"Elapsed time: 593.83158 msecs"
"Elapsed time: 569.1219 msecs"
"Elapsed time: 574.092617 msecs"

"Elapsed time: 847.609255 msecs"
"Elapsed time: 827.545998 msecs"
"Elapsed time: 802.144438 msecs"
"Elapsed time: 744.738493 msecs"
"Elapsed time: 653.15239 msecs"

"Elapsed time: 604.94758 msecs"
"Elapsed time: 577.90688 msecs"
"Elapsed time: 562.292653 msecs"
"Elapsed time: 582.066996 msecs"
"Elapsed time: 627.742876 msecs"

"Elapsed time: 838.770161 msecs"
"Elapsed time: 889.848045 msecs"
"Elapsed time: 868.719712 msecs"
"Elapsed time: 749.089852 msecs"
"Elapsed time: 653.09526 msecs"

"Elapsed time: 560.641304 msecs"
"Elapsed time: 597.297997 msecs"
"Elapsed time: 611.518729 msecs"
"Elapsed time: 582.094676 msecs"
"Elapsed time: 583.43079 msecs"

"Elapsed time: 810.514752 msecs"
"Elapsed time: 831.576155 msecs"
"Elapsed time: 797.832249 msecs"
"Elapsed time: 766.155765 msecs"
"Elapsed time: 653.102796 msecs"

nil
user=> (doseq [x (doall (map #(future (%1 1e6)) (take 16 (cycle [foo-dest map-dest]))))] (println @x))
"Elapsed time: 624.499687 msecs"
"Elapsed time: 612.306109 msecs"
"Elapsed time: 712.950716 msecs"
"Elapsed time: 641.636633 msecs"
"Elapsed time: 643.527369 msecs"

"Elapsed time: 926.452439 msecs"
"Elapsed time: 969.298717 msecs"
"Elapsed time: 954.970659 msecs"
"Elapsed time: 787.324562 msecs"
"Elapsed time: 734.362758 msecs"

"Elapsed time: 693.976816 msecs"
"Elapsed time: 662.849263 msecs"
"Elapsed time: 632.830093 msecs"
"Elapsed time: 667.907342 msecs"
"Elapsed time: 694.749149 msecs"

"Elapsed time: 1027.650534 msecs"
"Elapsed time: 906.343691 msecs"
"Elapsed time: 949.649984 msecs"
"Elapsed time: 814.166471 msecs"
"Elapsed time: 741.995176 msecs"

"Elapsed time: 648.176153 msecs"
"Elapsed time: 686.959439 msecs"
"Elapsed time: 736.725199 msecs"
"Elapsed time: 602.539137 msecs"
"Elapsed time: 716.575182 msecs"

"Elapsed time: 912.377662 msecs"
"Elapsed time: 999.298644 msecs"
"Elapsed time: 943.851641 msecs"
"Elapsed time: 881.015538 msecs"
"Elapsed time: 679.034486 msecs"

"Elapsed time: 637.93152 msecs"
"Elapsed time: 677.596619 msecs"
"Elapsed time: 663.694819 msecs"
"Elapsed time: 682.333879 msecs"
"Elapsed time: 680.030506 msecs"

"Elapsed time: 989.763607 msecs"
"Elapsed time: 922.930979 msecs"
"Elapsed time: 926.778337 msecs"
"Elapsed time: 797.894355 msecs"
"Elapsed time: 674.907449 msecs"

"Elapsed time: 669.474856 msecs"
"Elapsed time: 602.110893 msecs"
"Elapsed time: 686.885535 msecs"
"Elapsed time: 639.534597 msecs"
"Elapsed time: 667.370036 msecs"

"Elapsed time: 964.710501 msecs"
"Elapsed time: 969.116588 msecs"
"Elapsed time: 932.322608 msecs"
"Elapsed time: 810.787795 msecs"
"Elapsed time: 670.45373 msecs"

"Elapsed time: 685.880133 msecs"
"Elapsed time: 648.793049 msecs"
"Elapsed time: 676.644809 msecs"
"Elapsed time: 622.195416 msecs"
"Elapsed time: 673.977337 msecs"

"Elapsed time: 955.974104 msecs"
"Elapsed time: 1059.676384 msecs"
"Elapsed time: 959.19624 msecs"
"Elapsed time: 732.767576 msecs"
"Elapsed time: 696.582953 msecs"

"Elapsed time: 706.412809 msecs"
"Elapsed time: 714.123245 msecs"
"Elapsed time: 674.544866 msecs"
"Elapsed time: 605.641876 msecs"
"Elapsed time: 637.912546 msecs"

"Elapsed time: 985.828567 msecs"
"Elapsed time: 898.718562 msecs"
"Elapsed time: 960.665165 msecs"
"Elapsed time: 788.641721 msecs"
"Elapsed time: 765.799959 msecs"

"Elapsed time: 617.024127 msecs"
"Elapsed time: 722.393195 msecs"
"Elapsed time: 632.714549 msecs"
"Elapsed time: 648.07641 msecs"
"Elapsed time: 632.857239 msecs"

"Elapsed time: 993.11223 msecs"
"Elapsed time: 998.81322 msecs"
"Elapsed time: 975.445154 msecs"
"Elapsed time: 853.221202 msecs"
"Elapsed time: 762.305715 msecs"

nil
user=> (doseq [x (doall (map #(future (%1 1e6)) (take 32 (cycle [foo-dest map-dest]))))] (println @x))
"Elapsed time: 884.276009 msecs"
"Elapsed time: 922.522485 msecs"
"Elapsed time: 932.248225 msecs"
"Elapsed time: 905.184917 msecs"
"Elapsed time: 908.932031 msecs"

"Elapsed time: 1339.490166 msecs"
"Elapsed time: 1329.732952 msecs"
"Elapsed time: 1326.869076 msecs"
"Elapsed time: 1044.072053 msecs"
"Elapsed time: 861.120038 msecs"

"Elapsed time: 883.110391 msecs"
"Elapsed time: 917.631324 msecs"
"Elapsed time: 927.853067 msecs"
"Elapsed time: 904.560518 msecs"
"Elapsed time: 912.061571 msecs"

"Elapsed time: 1302.510992 msecs"
"Elapsed time: 1328.369099 msecs"
"Elapsed time: 1308.058945 msecs"
"Elapsed time: 1060.372177 msecs"
"Elapsed time: 721.51538 msecs"

"Elapsed time: 879.796135 msecs"
"Elapsed time: 919.723714 msecs"
"Elapsed time: 927.749811 msecs"
"Elapsed time: 905.510022 msecs"
"Elapsed time: 909.261568 msecs"

"Elapsed time: 1304.582479 msecs"
"Elapsed time: 1326.963786 msecs"
"Elapsed time: 1299.504032 msecs"
"Elapsed time: 1117.79296 msecs"
"Elapsed time: 838.302562 msecs"

"Elapsed time: 881.742531 msecs"
"Elapsed time: 917.570532 msecs"
"Elapsed time: 926.466868 msecs"
"Elapsed time: 908.339735 msecs"
"Elapsed time: 908.365575 msecs"

"Elapsed time: 1308.795722 msecs"
"Elapsed time: 1320.424936 msecs"
"Elapsed time: 1304.377999 msecs"
"Elapsed time: 1048.628677 msecs"
"Elapsed time: 908.137855 msecs"

"Elapsed time: 883.743718 msecs"
"Elapsed time: 918.133195 msecs"
"Elapsed time: 933.281338 msecs"
"Elapsed time: 905.155584 msecs"
"Elapsed time: 909.091611 msecs"

"Elapsed time: 1311.192695 msecs"
"Elapsed time: 1313.455989 msecs"
"Elapsed time: 1307.965638 msecs"
"Elapsed time: 1014.356757 msecs"
"Elapsed time: 830.985009 msecs"

"Elapsed time: 885.223122 msecs"
"Elapsed time: 917.873451 msecs"
"Elapsed time: 940.731608 msecs"
"Elapsed time: 903.862924 msecs"
"Elapsed time: 908.229435 msecs"

"Elapsed time: 1306.312289 msecs"
"Elapsed time: 1316.572993 msecs"
"Elapsed time: 1300.562676 msecs"
"Elapsed time: 1140.940103 msecs"
"Elapsed time: 856.534311 msecs"

"Elapsed time: 888.274048 msecs"
"Elapsed time: 918.521031 msecs"
"Elapsed time: 931.714862 msecs"
"Elapsed time: 905.05997 msecs"
"Elapsed time: 910.510698 msecs"

"Elapsed time: 1308.773226 msecs"
"Elapsed time: 1326.002046 msecs"
"Elapsed time: 1303.982889 msecs"
"Elapsed time: 1118.060063 msecs"
"Elapsed time: 861.294028 msecs"

"Elapsed time: 884.924072 msecs"
"Elapsed time: 920.224885 msecs"
"Elapsed time: 927.409608 msecs"
"Elapsed time: 904.481901 msecs"
"Elapsed time: 909.052138 msecs"

"Elapsed time: 1327.927959 msecs"
"Elapsed time: 1341.950666 msecs"
"Elapsed time: 1332.413629 msecs"
"Elapsed time: 1047.593643 msecs"
"Elapsed time: 834.447976 msecs"

"Elapsed time: 911.005335 msecs"
"Elapsed time: 930.793338 msecs"
"Elapsed time: 915.370742 msecs"
"Elapsed time: 906.614391 msecs"
"Elapsed time: 904.262415 msecs"

"Elapsed time: 1321.896338 msecs"
"Elapsed time: 1317.223209 msecs"
"Elapsed time: 1326.161155 msecs"
"Elapsed time: 1064.67881 msecs"
"Elapsed time: 788.071302 msecs"

"Elapsed time: 884.442106 msecs"
"Elapsed time: 984.054944 msecs"
"Elapsed time: 916.019788 msecs"
"Elapsed time: 909.581645 msecs"
"Elapsed time: 914.429423 msecs"

"Elapsed time: 1319.503943 msecs"
"Elapsed time: 1314.847212 msecs"
"Elapsed time: 1304.087349 msecs"
"Elapsed time: 1040.821113 msecs"
"Elapsed time: 846.497762 msecs"

"Elapsed time: 883.936718 msecs"
"Elapsed time: 921.075185 msecs"
"Elapsed time: 928.869998 msecs"
"Elapsed time: 913.553771 msecs"
"Elapsed time: 908.782518 msecs"

"Elapsed time: 1324.428912 msecs"
"Elapsed time: 1319.253839 msecs"
"Elapsed time: 1302.018412 msecs"
"Elapsed time: 1077.26618 msecs"
"Elapsed time: 808.158503 msecs"

"Elapsed time: 889.623072 msecs"
"Elapsed time: 919.460508 msecs"
"Elapsed time: 931.011364 msecs"
"Elapsed time: 907.053345 msecs"
"Elapsed time: 907.033307 msecs"

"Elapsed time: 1327.247502 msecs"
"Elapsed time: 1317.247163 msecs"
"Elapsed time: 1319.407491 msecs"
"Elapsed time: 1132.440777 msecs"
"Elapsed time: 843.202501 msecs"

"Elapsed time: 886.176812 msecs"
"Elapsed time: 922.996831 msecs"
"Elapsed time: 927.191901 msecs"
"Elapsed time: 905.171708 msecs"
"Elapsed time: 908.137898 msecs"

"Elapsed time: 1321.665172 msecs"
"Elapsed time: 1314.435979 msecs"
"Elapsed time: 1302.310838 msecs"
"Elapsed time: 1019.012534 msecs"
"Elapsed time: 867.221282 msecs"

"Elapsed time: 887.064732 msecs"
"Elapsed time: 923.136498 msecs"
"Elapsed time: 927.660281 msecs"
"Elapsed time: 904.358274 msecs"
"Elapsed time: 907.792778 msecs"

"Elapsed time: 1318.867409 msecs"
"Elapsed time: 1320.920603 msecs"
"Elapsed time: 1306.337678 msecs"
"Elapsed time: 1124.333397 msecs"
"Elapsed time: 848.887728 msecs"

"Elapsed time: 886.818132 msecs"
"Elapsed time: 920.475428 msecs"
"Elapsed time: 930.829321 msecs"
"Elapsed time: 904.271398 msecs"
"Elapsed time: 905.871801 msecs"

"Elapsed time: 1318.354475 msecs"
"Elapsed time: 1331.200776 msecs"
"Elapsed time: 1316.250609 msecs"
"Elapsed time: 1003.753835 msecs"
"Elapsed time: 832.518845 msecs"

"Elapsed time: 905.306398 msecs"
"Elapsed time: 915.433825 msecs"
"Elapsed time: 917.131664 msecs"
"Elapsed time: 910.578748 msecs"
"Elapsed time: 913.569885 msecs"

"Elapsed time: 1301.679166 msecs"
"Elapsed time: 1350.490425 msecs"
"Elapsed time: 1306.131096 msecs"
"Elapsed time: 1056.61564 msecs"
"Elapsed time: 874.079111 msecs"

nil