2

I am trying to benchmark an expression using the Criterium library. The expression is

(vec (range 10000000))

To benchmark it i type

 (criterium.core/bench (vec (range 10000000)))

and after a while i get 

 OutOfMemoryError GC overhead limit exceeded  java.lang.Long.valueOf (Long.java:840)

As i have seen here this means that the maximum size of the heap (1 GB) is not enough for the data to fit and the garbage collector tries to free space but is unable to do so. However, microbenchmarking the expression like below doesn't produce this error

(dotimes [i 60] (time (vec (range 10000000))))

By the way, i set it to 60 times because i have seen here that the bench macro does 60 executions by default.

The question is why is this happening when using Criterium.

Edit: When starting a fresh repl the code below

{:max (.maxMemory (Runtime/getRuntime)), :total (.totalMemory (Runtime/getRuntime))}

outputs

{:max 922746880, :total 212860928}

After i run (dotimes [i 60] (time (vec (range 10000000)))) or (criterium.core/bench (vec (range 10000000)))

it outputs

{:max 922746880, :total 922746880}
Chris
  • 23
  • 4
  • This will be easier for answerers to reproduce if they know how big a heap you have when you run this code. What is the result of evaluating `{:max (.maxMemory (Runtime/getRuntime)), :total (.totalMemory (Runtime/getRuntime))}`? – amalloy Aug 21 '17 at 01:26
  • @amalloy Thank you, i have edited the question to include it. – Chris Aug 21 '17 at 07:44

1 Answers1

2

I was able to reproduce the behavior by using this test:

;project.clj
:profiles {:test    {:jvm-opts ["-Xms1024m" "-Xmx1024m"]}}

(:require [clojure.test :refer :all]
          [criterium.core :as ben])

(deftest ^:focused ben-test
  (is (ben/with-progress-reporting
        (ben/bench (vec (range 10000000))))))

The stack trace looks like this:

Estimating sampling overhead                                         
Warming up for JIT optimisations 10000000000 ...                     
compilation occurred before 377618 iterations                      
...

Estimating execution count ...
Sampling ...
Final GC...
Checking GC...
Finding outliers ...
Bootstrapping ...
Checking outlier significance
Warming up for JIT optimisations 10000000000 ...
compilation occurred before 1 iterations

criterium.core$execute_expr_core_timed_part$fn__40395.invoke (core.clj:370)                                                                                                                                                                                                        
criterium.core$execute_expr_core_timed_part.invokeStatic (core.clj:366)                                                                                                                                                                                                            
criterium.core$execute_expr_core_timed_part.invoke (core.clj:345)                                                                                                                                                                                                                  
criterium.core$execute_expr.invokeStatic (core.clj:378)                                                                                                                                                                                                                            
criterium.core$execute_expr.invoke (core.clj:374)                                                                                                                                                                                                                                  
criterium.core$warmup_for_jit.invokeStatic (core.clj:428)                                                                                                                                                                                                                          
criterium.core$warmup_for_jit.invoke (core.clj:396)                                                                                                                                                                                                                                
criterium.core$run_benchmark.invokeStatic (core.clj:479)                                                                                                                                                                                                                           
criterium.core$run_benchmark.invoke (core.clj:470)                                                                                                                                                                                                                                 
criterium.core$benchmark_STAR_.invokeStatic (core.clj:826)                                                                                                                                                                                                                         
criterium.core$benchmark_STAR_.invoke (core.clj:812)

We can see here that the error occurs in the JIT-Warning-Up step. The interesting point is the function execute-expr-core-timed-part (core.clj:345). This functions performs the expression (vec (range 10000000)) n times and saves the returned value every time to a so-called mutable place. My hypothesis it that we have the memory leak here. 

(time-body
  (loop [i (long (dec n))
      v (f)]
==> (set-place mutable-place v**)
    (if (pos? i)
     (recur (unchecked-dec i) (f))
     v)))
Minh Tuan Nguyen
  • 1,026
  • 8
  • 13
  • Thank you, as it seems this behavior caused the error. I wrapped the expression inside a `(do nil)` and it was benchmarked without problems. – Chris Aug 21 '17 at 08:28
  • Be careful with that, though: criterium stores its results in a heap object for a reason. The JVM may observe that you always throw away the result of `(f)` after computing it, and if it can prove that `f` has no side effects it may optimize out the code you are trying to benchmark. – amalloy Aug 21 '17 at 09:29
  • @amalloy I was counting on [this](https://github.com/hugoduncan/criterium/blob/develop/src/criterium/core.clj#L354) to leave the calls to 'f' unoptimized, but i understand that i have to find a better way of doing it – Chris Aug 21 '17 at 12:34
  • 1
    The comment you linked to explains that the point of the function is to force the calls to `f` to be unoptimized. That is accomplished by saving their results. By throwing away the results *inside of `f`*, you remove that protection: the optimizer can now, when optimizing `f` itself, decide to compile it to a no-op. That's usually fine, because the JVM doesn't generally notice it can optimize this stuff out in my experience. But my point is you can't count on the comment if you circumvent its features. – amalloy Aug 21 '17 at 18:34