High run time variance

[Luca Saiu]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hello guilers.

I've come across a curious issue with Guile; I had already casually
spotted it before, but today I've run a somewhat more comprehensive
test, and I think the results are interesting. As usual, please forgive
me for the noise if you're already aware of what I say.

Let's say we have to perform a CPU-intensive computation several times;
in this distilled test case I will use the traditional recursive,
exponential-complexity definition of the Fibonacci sequence. Let's apply
the function to the same argument three time in a row in the same script
run, measuring the completion time of each computation.

Here comes the content of my script q.scm:
================================================================
(define-macro (benchmark . body)
  ;; Yes, I know that this is ugly and non-hygienic.  That's
  ;; not the problem.
  `(let* ((t0 (array-ref (times) 0))
          (result (begin ,@body))
          (t1 (array-ref (times) 0)))
     (format #t
             "~a returned ~a in ~a seconds.\n"
             '(begin ,@body)
             result
             (/ (- t1 t0) 100.0))
     result))

(define-macro (thrice . body)
  `(begin
     ,@body
     ,@body
     ,@body))

(define (fibo n)
  (if (< n 2)
      n
      (+ (fibo (- n 1))
         (fibo (- n 2)))))

(define n 35)
(thrice (benchmark (fibo n)))
================================================================

Here's what I get when running the script ten times on 1.9.9 with my
office machine (a fast x86_64 machine with eight 3GHz cores, very
lightly loaded):

address@hidden ~/tmp]$ rm -rf ~/.cache/guile/; for i in `seq 10`; do
guile --autocompile q.scm; echo; done
;;; note: autocompilation is enabled, set GUILE_AUTO_COMPILE=0
;;;       or pass the --no-autocompile argument to disable.
;;; compiling q.scm
;;; compiled
/home/luca/.cache/guile/ccache/2.0-0.P-LE-8/home/luca/tmp/q.scm.go
(begin (fibo n)) returned 9227465 in 2.75 seconds.
(begin (fibo n)) returned 9227465 in 2.74 seconds.
(begin (fibo n)) returned 9227465 in 2.75 seconds.

(begin (fibo n)) returned 9227465 in 2.63 seconds.
(begin (fibo n)) returned 9227465 in 2.62 seconds.
(begin (fibo n)) returned 9227465 in 2.63 seconds.

(begin (fibo n)) returned 9227465 in 3.07 seconds.
(begin (fibo n)) returned 9227465 in 3.07 seconds.
(begin (fibo n)) returned 9227465 in 3.08 seconds.

(begin (fibo n)) returned 9227465 in 2.87 seconds.
(begin (fibo n)) returned 9227465 in 2.87 seconds.
(begin (fibo n)) returned 9227465 in 2.87 seconds.

(begin (fibo n)) returned 9227465 in 2.93 seconds.
(begin (fibo n)) returned 9227465 in 2.93 seconds.
(begin (fibo n)) returned 9227465 in 2.93 seconds.

(begin (fibo n)) returned 9227465 in 2.6 seconds.
(begin (fibo n)) returned 9227465 in 2.6 seconds.
(begin (fibo n)) returned 9227465 in 2.59 seconds.

(begin (fibo n)) returned 9227465 in 2.88 seconds.
(begin (fibo n)) returned 9227465 in 2.88 seconds.
(begin (fibo n)) returned 9227465 in 2.88 seconds.

(begin (fibo n)) returned 9227465 in 2.67 seconds.
(begin (fibo n)) returned 9227465 in 2.67 seconds.
(begin (fibo n)) returned 9227465 in 2.67 seconds.

(begin (fibo n)) returned 9227465 in 2.76 seconds.
(begin (fibo n)) returned 9227465 in 2.75 seconds.
(begin (fibo n)) returned 9227465 in 2.75 seconds.

(begin (fibo n)) returned 9227465 in 3.23 seconds.
(begin (fibo n)) returned 9227465 in 3.23 seconds.
(begin (fibo n)) returned 9227465 in 3.23 seconds.

Notice the wide variance among runs (from 2.6 to 3.23 seconds); however
within each single run the three computations always take roughly the
same time -- This will remain consistent in all the following
experiments, and it is the "anomaly" I am concerned about in this
message. If I had to bet about the cause, I'd say it's an alignment
issue (determined at startup time); if the alignment were always optimal
we would get the best time in all runs.
  Notice that there is no consing (at least with the VM), so false
pointers are not an issue.

Is the effect also observable with the interpreter? Just to be sure:

address@hidden ~/tmp]$ rm -rf ~/.cache/guile/; for i in `seq 10`; do
guile --no-autocompile q.scm; echo; done
(begin (fibo n)) returned 9227465 in 169.99 seconds.
(begin (fibo n)) returned 9227465 in 170.1 seconds.
(begin (fibo n)) returned 9227465 in 169.09 seconds.

(begin (fibo n)) returned 9227465 in 168.65 seconds.
(begin (fibo n)) returned 9227465 in 168.53 seconds.
(begin (fibo n)) returned 9227465 in 168.78 seconds.

(begin (fibo n)) returned 9227465 in 172.49 seconds.
(begin (fibo n)) returned 9227465 in 172.63 seconds.
(begin (fibo n)) returned 9227465 in 172.71 seconds.

(begin (fibo n)) returned 9227465 in 179.91 seconds.
(begin (fibo n)) returned 9227465 in 179.89 seconds.
(begin (fibo n)) returned 9227465 in 181.18 seconds.

(begin (fibo n)) returned 9227465 in 166.11 seconds.
(begin (fibo n)) returned 9227465 in 166.06 seconds.
(begin (fibo n)) returned 9227465 in 166.16 seconds.

(begin (fibo n)) returned 9227465 in 166.09 seconds.
(begin (fibo n)) returned 9227465 in 166.12 seconds.
(begin (fibo n)) returned 9227465 in 166.27 seconds.

(begin (fibo n)) returned 9227465 in 165.64 seconds.
(begin (fibo n)) returned 9227465 in 165.48 seconds.
(begin (fibo n)) returned 9227465 in 166.27 seconds.

(begin (fibo n)) returned 9227465 in 172.14 seconds.
(begin (fibo n)) returned 9227465 in 172.94 seconds.
(begin (fibo n)) returned 9227465 in 173.33 seconds.

(begin (fibo n)) returned 9227465 in 164.26 seconds.
(begin (fibo n)) returned 9227465 in 164.28 seconds.
(begin (fibo n)) returned 9227465 in 162.94 seconds.

(begin (fibo n)) returned 9227465 in 175.57 seconds.
(begin (fibo n)) returned 9227465 in 175.45 seconds.
(begin (fibo n)) returned 9227465 in 175.22 seconds.

- From 164 to 180 seconds. Less pronounced than before, but the effect is
still visible.

Now let's define n as 42:

address@hidden ~/tmp]$ rm -rf ~/.cache/guile/; for i in `seq 10`; do
guile --autocompile q2.scm; echo; done
;;; note: autocompilation is enabled, set GUILE_AUTO_COMPILE=0
;;;       or pass the --no-autocompile argument to disable.
;;; compiling q2.scm
;;; compiled
/home/luca/.cache/guile/ccache/2.0-0.P-LE-8/home/luca/tmp/q2.scm.go
(begin (fibo n)) returned 267914296 in 84.44 seconds.
(begin (fibo n)) returned 267914296 in 84.45 seconds.
(begin (fibo n)) returned 267914296 in 84.44 seconds.

(begin (fibo n)) returned 267914296 in 78.83 seconds.
(begin (fibo n)) returned 267914296 in 78.71 seconds.
(begin (fibo n)) returned 267914296 in 78.73 seconds.

(begin (fibo n)) returned 267914296 in 93.8 seconds.
(begin (fibo n)) returned 267914296 in 93.81 seconds.
(begin (fibo n)) returned 267914296 in 93.8 seconds.

(begin (fibo n)) returned 267914296 in 79.27 seconds.
(begin (fibo n)) returned 267914296 in 79.27 seconds.
(begin (fibo n)) returned 267914296 in 79.27 seconds.

(begin (fibo n)) returned 267914296 in 91.31 seconds.
(begin (fibo n)) returned 267914296 in 91.31 seconds.
(begin (fibo n)) returned 267914296 in 91.3 seconds.

(begin (fibo n)) returned 267914296 in 87.23 seconds.
(begin (fibo n)) returned 267914296 in 87.13 seconds.
(begin (fibo n)) returned 267914296 in 87.12 seconds.

(begin (fibo n)) returned 267914296 in 79.6 seconds.
(begin (fibo n)) returned 267914296 in 79.6 seconds.
(begin (fibo n)) returned 267914296 in 79.59 seconds.

(begin (fibo n)) returned 267914296 in 84.9 seconds.
(begin (fibo n)) returned 267914296 in 84.88 seconds.
(begin (fibo n)) returned 267914296 in 84.88 seconds.

(begin (fibo n)) returned 267914296 in 98.91 seconds.
(begin (fibo n)) returned 267914296 in 98.9 seconds.
(begin (fibo n)) returned 267914296 in 98.9 seconds.

(begin (fibo n)) returned 267914296 in 73.83 seconds.
(begin (fibo n)) returned 267914296 in 73.82 seconds.
(begin (fibo n)) returned 267914296 in 73.83 seconds.

The variance is quite high: from 73.8 to 98.9.

Let's define n as 43:

address@hidden ~/tmp]$ rm -rf ~/.cache/guile/; for i in `seq 10`; do
guile --autocompile q3.scm; echo; done
;;; note: autocompilation is enabled, set GUILE_AUTO_COMPILE=0
;;;       or pass the --no-autocompile argument to disable.
;;; compiling q3.scm
;;; compiled
/home/luca/.cache/guile/ccache/2.0-0.P-LE-8/home/luca/tmp/q3.scm.go
(begin (fibo n)) returned 433494437 in 136.97 seconds.
(begin (fibo n)) returned 433494437 in 136.97 seconds.
(begin (fibo n)) returned 433494437 in 136.96 seconds.

(begin (fibo n)) returned 433494437 in 119.29 seconds.
(begin (fibo n)) returned 433494437 in 119.32 seconds.
(begin (fibo n)) returned 433494437 in 119.38 seconds.

(begin (fibo n)) returned 433494437 in 135.42 seconds.
(begin (fibo n)) returned 433494437 in 135.47 seconds.
(begin (fibo n)) returned 433494437 in 135.45 seconds.

(begin (fibo n)) returned 433494437 in 150.63 seconds.
(begin (fibo n)) returned 433494437 in 149.82 seconds.
(begin (fibo n)) returned 433494437 in 149.68 seconds.

(begin (fibo n)) returned 433494437 in 121.13 seconds.
(begin (fibo n)) returned 433494437 in 121.19 seconds.
(begin (fibo n)) returned 433494437 in 121.15 seconds.

(begin (fibo n)) returned 433494437 in 119.39 seconds.
(begin (fibo n)) returned 433494437 in 119.36 seconds.
(begin (fibo n)) returned 433494437 in 119.39 seconds.

(begin (fibo n)) returned 433494437 in 137.46 seconds.
(begin (fibo n)) returned 433494437 in 137.44 seconds.
(begin (fibo n)) returned 433494437 in 137.41 seconds.

(begin (fibo n)) returned 433494437 in 123.83 seconds.
(begin (fibo n)) returned 433494437 in 123.85 seconds.
(begin (fibo n)) returned 433494437 in 123.78 seconds.

(begin (fibo n)) returned 433494437 in 136.3 seconds.
(begin (fibo n)) returned 433494437 in 136.26 seconds.
(begin (fibo n)) returned 433494437 in 136.26 seconds.

(begin (fibo n)) returned 433494437 in 118.75 seconds.
(begin (fibo n)) returned 433494437 in 118.73 seconds.
(begin (fibo n)) returned 433494437 in 118.75 seconds.

- From 118.7 to 150 seconds.

Now, did this happen also in 1.8? I had 1.8.7 already installed on
another machine (it's nearly identical to mine, it just has 2GHz instead
of 3GHz cores; this should not be relevant), so I used that:

With n = 35:
address@hidden /tmp]$ for i in `seq 10`; do guile q.scm; echo; done
(begin (fibo n)) returned 9227465 in 9.69 seconds.
(begin (fibo n)) returned 9227465 in 9.69 seconds.
(begin (fibo n)) returned 9227465 in 9.7 seconds.

(begin (fibo n)) returned 9227465 in 9.81 seconds.
(begin (fibo n)) returned 9227465 in 9.8 seconds.
(begin (fibo n)) returned 9227465 in 9.88 seconds.

(begin (fibo n)) returned 9227465 in 9.56 seconds.
(begin (fibo n)) returned 9227465 in 9.55 seconds.
(begin (fibo n)) returned 9227465 in 9.55 seconds.

(begin (fibo n)) returned 9227465 in 9.61 seconds.
(begin (fibo n)) returned 9227465 in 9.59 seconds.
(begin (fibo n)) returned 9227465 in 9.58 seconds.

(begin (fibo n)) returned 9227465 in 9.69 seconds.
(begin (fibo n)) returned 9227465 in 9.76 seconds.
(begin (fibo n)) returned 9227465 in 9.69 seconds.

(begin (fibo n)) returned 9227465 in 9.78 seconds.
(begin (fibo n)) returned 9227465 in 9.77 seconds.
(begin (fibo n)) returned 9227465 in 9.82 seconds.

(begin (fibo n)) returned 9227465 in 9.7 seconds.
(begin (fibo n)) returned 9227465 in 9.67 seconds.
(begin (fibo n)) returned 9227465 in 9.68 seconds.

(begin (fibo n)) returned 9227465 in 9.69 seconds.
(begin (fibo n)) returned 9227465 in 9.69 seconds.
(begin (fibo n)) returned 9227465 in 9.71 seconds.

(begin (fibo n)) returned 9227465 in 9.69 seconds.
(begin (fibo n)) returned 9227465 in 9.68 seconds.
(begin (fibo n)) returned 9227465 in 9.66 seconds.

(begin (fibo n)) returned 9227465 in 9.76 seconds.
(begin (fibo n)) returned 9227465 in 9.74 seconds.
(begin (fibo n)) returned 9227465 in 9.71 seconds.

I'd say that the "anomaly" was there also in 1.8, even if it was much
less pronounced.

Let's also try with higher values of n:

n=38:
address@hidden /tmp]$ for i in `seq 10`; do guile q2.scm; echo; done
(begin (fibo n)) returned 39088169 in 40.76 seconds.
(begin (fibo n)) returned 39088169 in 40.85 seconds.
(begin (fibo n)) returned 39088169 in 40.76 seconds.

(begin (fibo n)) returned 39088169 in 40.78 seconds.
(begin (fibo n)) returned 39088169 in 40.91 seconds.
(begin (fibo n)) returned 39088169 in 40.89 seconds.

(begin (fibo n)) returned 39088169 in 41.08 seconds.
(begin (fibo n)) returned 39088169 in 41.49 seconds.
(begin (fibo n)) returned 39088169 in 41.33 seconds.

(begin (fibo n)) returned 39088169 in 41.52 seconds.
(begin (fibo n)) returned 39088169 in 41.59 seconds.
(begin (fibo n)) returned 39088169 in 41.41 seconds.

(begin (fibo n)) returned 39088169 in 41.17 seconds.
(begin (fibo n)) returned 39088169 in 41.3 seconds.
(begin (fibo n)) returned 39088169 in 41.33 seconds.

(begin (fibo n)) returned 39088169 in 40.98 seconds.
(begin (fibo n)) returned 39088169 in 41.06 seconds.
(begin (fibo n)) returned 39088169 in 41.09 seconds.

(begin (fibo n)) returned 39088169 in 41.2 seconds.
(begin (fibo n)) returned 39088169 in 41.22 seconds.
(begin (fibo n)) returned 39088169 in 41.32 seconds.

(begin (fibo n)) returned 39088169 in 40.88 seconds.
(begin (fibo n)) returned 39088169 in 41.04 seconds.
(begin (fibo n)) returned 39088169 in 41.02 seconds.

(begin (fibo n)) returned 39088169 in 40.7 seconds.
(begin (fibo n)) returned 39088169 in 40.83 seconds.
(begin (fibo n)) returned 39088169 in 40.8 seconds.

(begin (fibo n)) returned 39088169 in 41.07 seconds.
(begin (fibo n)) returned 39088169 in 41.15 seconds.
(begin (fibo n)) returned 39088169 in 40.86 seconds.

And finally n = 40:

address@hidden /tmp]$ for i in `seq 10`; do guile q3.scm; echo; done
(begin (fibo n)) returned 102334155 in 107.13 seconds.
(begin (fibo n)) returned 102334155 in 107.09 seconds.
(begin (fibo n)) returned 102334155 in 107.19 seconds.

(begin (fibo n)) returned 102334155 in 107.25 seconds.
(begin (fibo n)) returned 102334155 in 107.24 seconds.
(begin (fibo n)) returned 102334155 in 107.69 seconds.

(begin (fibo n)) returned 102334155 in 107.49 seconds.
(begin (fibo n)) returned 102334155 in 107.49 seconds.
(begin (fibo n)) returned 102334155 in 107.7 seconds.

(begin (fibo n)) returned 102334155 in 106.75 seconds.
(begin (fibo n)) returned 102334155 in 106.51 seconds.
(begin (fibo n)) returned 102334155 in 106.53 seconds.

(begin (fibo n)) returned 102334155 in 108.13 seconds.
(begin (fibo n)) returned 102334155 in 108.07 seconds.
(begin (fibo n)) returned 102334155 in 107.66 seconds.

(begin (fibo n)) returned 102334155 in 106.74 seconds.
(begin (fibo n)) returned 102334155 in 107.08 seconds.
(begin (fibo n)) returned 102334155 in 106.78 seconds.

(begin (fibo n)) returned 102334155 in 107.91 seconds.
(begin (fibo n)) returned 102334155 in 107.93 seconds.
(begin (fibo n)) returned 102334155 in 108.25 seconds.

(begin (fibo n)) returned 102334155 in 106.3 seconds.
(begin (fibo n)) returned 102334155 in 106.43 seconds.
(begin (fibo n)) returned 102334155 in 106.57 seconds.

(begin (fibo n)) returned 102334155 in 106.51 seconds.
(begin (fibo n)) returned 102334155 in 106.31 seconds.
(begin (fibo n)) returned 102334155 in 106.64 seconds.

(begin (fibo n)) returned 102334155 in 106.49 seconds.
(begin (fibo n)) returned 102334155 in 106.38 seconds.
(begin (fibo n)) returned 102334155 in 106.41 seconds.

To sum up, within each run the computation time of (fibo n) is the same,
but the time varies widely from one run to another. This anomaly seems
to have become much more accentuated in 1.9.

Is this really an alignment issue as I suspect? I don't know because I
have not tracked the problem any deeper than running these tests, but
maybe it's easy for you to see. If so, maybe it would be easy to get
some more performance by forcing the alignment to the optimum value.

Best regards,

- --
Luca Saiu
http://www-lipn.univ-paris13.fr/~saiu
GNU epsilon: http://www.gnu.org/software/epsilon
Marionnet:   http://www.marionnet.org
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkuw0KcACgkQvzOavibF0oaEWwCgksg6bNkI2BOxWnd9bEgjk99O
9EMAoJi+yadDJHEuGGs8woAmwzB6Sj9A
=018I
-----END PGP SIGNATURE-----