From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.org!not-for-mail From: Luca Saiu Newsgroups: gmane.lisp.guile.bugs Subject: High run time variance Date: Mon, 29 Mar 2010 18:09:11 +0200 Message-ID: <4BB0D0A7.7080505@gnu.org> NNTP-Posting-Host: lo.gmane.org Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit X-Trace: dough.gmane.org 1269880345 941 80.91.229.12 (29 Mar 2010 16:32:25 GMT) X-Complaints-To: usenet@dough.gmane.org NNTP-Posting-Date: Mon, 29 Mar 2010 16:32:25 +0000 (UTC) To: bug-guile@gnu.org Original-X-From: bug-guile-bounces+guile-bugs=m.gmane.org@gnu.org Mon Mar 29 18:32:21 2010 Return-path: Envelope-to: guile-bugs@m.gmane.org Original-Received: from lists.gnu.org ([199.232.76.165]) by lo.gmane.org with esmtp (Exim 4.69) (envelope-from ) id 1NwHsw-00079D-5J for guile-bugs@m.gmane.org; Mon, 29 Mar 2010 18:32:18 +0200 Original-Received: from localhost ([127.0.0.1]:35435 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.43) id 1NwHlP-0001rl-Qw for guile-bugs@m.gmane.org; Mon, 29 Mar 2010 12:24:31 -0400 Original-Received: from mailman by lists.gnu.org with tmda-scanned (Exim 4.43) id 1NwHg6-0004bq-St for bug-guile@gnu.org; Mon, 29 Mar 2010 12:19:02 -0400 Original-Received: from [140.186.70.92] (port=53944 helo=eggs.gnu.org) by lists.gnu.org with esmtp (Exim 4.43) id 1NwHb5-00032o-Hn for bug-guile@gnu.org; Mon, 29 Mar 2010 12:19:02 -0400 Original-Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.69) (envelope-from ) id 1NwHai-00051u-SN for bug-guile@gnu.org; Mon, 29 Mar 2010 12:13:31 -0400 Original-Received: from mail.lipn.univ-paris13.fr ([194.254.163.24]:37015) by eggs.gnu.org with esmtp (Exim 4.69) (envelope-from ) id 1NwHai-00051k-6b for bug-guile@gnu.org; Mon, 29 Mar 2010 12:13:28 -0400 Original-Received: from [10.10.0.234] (optimum.lipn.univ-paris13.fr [10.10.0.234]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) (Authenticated sender: saiu@lipn.univ-paris13.fr) by mail.lipn.univ-paris13.fr (sendmail 8.9.3/8.9.2) with ESMTP id 61CA422E02; Mon, 29 Mar 2010 18:13:27 +0200 (CEST) User-Agent: Mozilla-Thunderbird 2.0.0.22 (X11/20091109) X-Enigmail-Version: 0.95.0 OpenPGP: id=26C5D286; url=http://www-lipn.univ-paris13.fr/~saiu/lucasaiu.asc X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.6 (newer, 3) X-BeenThere: bug-guile@gnu.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: "Bug reports for GUILE, GNU's Ubiquitous Extension Language" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Original-Sender: bug-guile-bounces+guile-bugs=m.gmane.org@gnu.org Errors-To: bug-guile-bounces+guile-bugs=m.gmane.org@gnu.org Xref: news.gmane.org gmane.lisp.guile.bugs:4538 Archived-At: -----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): [luca@optimum ~/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: [luca@optimum ~/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: [luca@optimum ~/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: [luca@optimum ~/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: [luca@factotum /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: [luca@factotum /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: [luca@factotum /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-----