Why does runtime count increase when aborted thread count also increases?

Question

I am asking this question, to find out why my runtime count increases.

I have a simple program that has a vector of references to numbers and a bunch of threads simultaneously trying to write to one of the numbers in the vector.

By modifying the size of the vector (its called histogram in the program) I can reduce the number of aborted transactions because the write-sets don't conflict for larger vector sizes. The size is called "histsize" in the program.

However, when I reduce the number of aborted transactions, the run-time goes UP! On my system, when I reduce the number of aborted transactions from 2500 to 300, the run-time goes up from 460 milliseconds to 620 milliseconds. Clearly, there is something else at play but I just can't seem to figure out what it is.

This makes absolutely no sense to me. Here's the code...can anyone tell me what is going on?

(def histsize 5000)
(def histogram (vec (take histsize (repeatedly #(ref 0)))))
(def abort-counter (atom 0))

(defn inc_alter []
  (loop [counter 10000]
     (if (zero? counter)
        nil
     (do
       (dosync
         (try
           (let [index (mod counter histsize)]
             (ref-set (histogram index) (inc @(histogram index))))
           (catch Throwable t 
             (do
               (swap! abort-counter inc) 
               (throw t)))))
       (recur (dec counter))))))

(defn run-histo []
  (let [threads (for [x (range 0 20)] (Thread. #(inc_alter)))]
    (do
      (time
        (do (doall (map #(.start %) threads))
            (doall (map #(.join %) threads))))
      (println "total aborts: " @abort-counter) )))

(run-histo)

Answer 1

Maybe it's just the matter of JVM runtime optimization. The first run may take longer, but have your tried consecutive runs? I increased the size of histogram vector from 5000 to 50000, and for 10 consecutive runs got this result:

; 5000
("Elapsed time: 1221.597 msecs" total aborts:  203
 "Elapsed time: 466.733 msecs" total aborts:  64
 "Elapsed time: 484.87 msecs" total aborts:  127
 "Elapsed time: 730.735 msecs" total aborts:  127
 "Elapsed time: 461.475 msecs" total aborts:  97
 "Elapsed time: 488.735 msecs" total aborts:  178
 "Elapsed time: 484.342 msecs" total aborts:  42
 "Elapsed time: 447.577 msecs" total aborts:  96
 "Elapsed time: 478.22 msecs" total aborts:  178
 "Elapsed time: 402.598 msecs" total aborts: 125
 nil nil nil nil nil nil nil nil nil nil)


; 50000
("Elapsed time: 21.374 msecs" total aborts:  20
 "Elapsed time: 48.55 msecs" total aborts:  20
 "Elapsed time: 16.818 msecs" total aborts:  20
 "Elapsed time: 13.407 msecs" total aborts:  20
 "Elapsed time: 14.546 msecs" total aborts:  20
 "Elapsed time: 16.687 msecs" total aborts:  20
 "Elapsed time: 12.22 msecs" total aborts:  20
 "Elapsed time: 13.491 msecs" total aborts:  20
 "Elapsed time: 11.616 msecs" total aborts:  20
 "Elapsed time: 11.896 msecs" total aborts:  20
 nil nil nil nil nil nil nil nil nil nil)

The modified run-histo:

(defn run-histo []
  (for [x (range 10)]  
   (let [threads (for [x (range 0 20)] (Thread. #(inc_alter)))]
     (do
       (reset! abort-counter 0)
       (time
        (do (doall (map #(.start %) threads))
            (doall (map #(.join %) threads))))
       (println "total aborts: " @abort-counter) ))))

How does this work out on your machine?