Compilation time with Guile 3.0.3-to-be

Compilation time with Guile 3.0.3-to-be

[Ludovic Courtès]

Hello!

Here’s a followup to Andy’s great blog post about the new “baseline
compiler” that’ll be in Guile 3.0.3:

  https://wingolog.org/archives/2020/06/03/a-baseline-compiler-for-guile

With the attached patch I’ve run ‘make as-derivation’ (equivalent to
‘guix pull’) and timed the builds of guix-packages-base.drv (279 files)
and guix-packages.drv (217 files) on my 4-core i7 laptop:

  • guix-packages-base.drv: 1m30s (was 4m)

  • guix-packages.drv: 30s (was 1m8s)

So this part is ~2.5 times faster than before, yay!  Thank you, Andy!
This is quite an achievement, especially given that, before compiling,
there’s an initial phase during which we load all the files, and that
phase is sequential and takes the same amount of time in both cases.

For the record, the optimizations currently used in (guix build compile)
are between the new -O0 and -O1:

  (cond ((or (string-contains file "gnu/packages/")
             (string-contains file "gnu/tests/"))
         ;; Level 0 is good enough but partial evaluation helps preserve the
         ;; "macro writer's bill of rights".
         (override-option #:partial-eval? #t
                          (optimizations-for-level 0)))
        ((string-contains file "gnu/services/")
         ;; '-O2 -Ono-letrectify' compiles about ~20% faster than '-O2' for
         ;; large files like gnu/services/mail.scm.
         (override-option #:letrectify? #f
                          (optimizations-for-level 2)))
        (else
         (optimizations-for-level 3)))

With the new -O1, the scheme->tree-il conversion (mostly macro
expansion) accounts for half of the build time on large files:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,use(system base optimize)
scheme@(guile-user)> ,time (compile-file "gnu/packages/python-xyz.scm" #:opts (optimizations-for-level 1))
$1 = "/data/src/guile-3.0/cache/guile/ccache/3.0-LE-8-4.3/home/ludo/src/guix/gnu/packages/python-xyz.scm.go"
;; 4.154311s real time, 5.604945s run time.  2.538106s spent in GC.
--8<---------------cut here---------------end--------------->8---

vs.:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,use(system base compile)
scheme@(guile-user)> ,time (define t (call-with-input-file  "gnu/packages/python-xyz.scm" (lambda (port) (read-and-compile port #:to 'tree-il))))
;; 2.206563s real time, 3.057369s run time.  1.339261s spent in GC.
--8<---------------cut here---------------end--------------->8---

The profile looks like this:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,pr (define t (call-with-input-file  "gnu/packages/python-xyz.scm" (lambda (port) (read-and-compile port #:to 'tree-il))))
%     cumulative   self             
time   seconds     seconds  procedure
 13.16      0.45      0.40  anon #x1136458
 10.53      0.35      0.32  ice-9/popen.scm:168:0:reap-pipes
  7.89      0.24      0.24  anon #x1132af8
  6.14      0.35      0.19  ice-9/boot-9.scm:3128:0:module-gensym
  5.26      0.21      0.16  ice-9/boot-9.scm:2201:0:%load-announce
  4.39      0.19      0.13  ice-9/psyntax.scm:749:8:search
  3.51      0.69      0.11  ice-9/psyntax.scm:2964:6:match*
  3.51      0.11      0.11  anon #x11334e8
  3.51      0.11      0.11  anon #x1136428
  2.63      0.08      0.08  anon #x113a258
  1.75      0.05      0.05  ice-9/psyntax.scm:3017:12:$sc-dispatch
  1.75      0.05      0.05  anon #x1139e68
  0.88    277.30      0.03  ice-9/boot-9.scm:220:5:map1
--8<---------------cut here---------------end--------------->8---

It’d be great to waive the anonymity of that first lambda.  :-)
I was wondering what fraction of that time was spent running Guix macros
(‘package’, ‘base32’, and so on), but it’s difficult to answer that
question here.  Probably something to investigate so we can make further
progress!

Ludo’.

Re: Compilation time with Guile 3.0.3-to-be

[Christopher Baines]

[-- Attachment #1: Type: text/plain, Size: 705 bytes --]


Ludovic Courtès <ludo@gnu.org> writes:

> Hello!
>
> Here’s a followup to Andy’s great blog post about the new “baseline
> compiler” that’ll be in Guile 3.0.3:
>
>   https://wingolog.org/archives/2020/06/03/a-baseline-compiler-for-guile
>
> With the attached patch I’ve run ‘make as-derivation’ (equivalent to
> ‘guix pull’) and timed the builds of guix-packages-base.drv (279 files)
> and guix-packages.drv (217 files) on my 4-core i7 laptop:
>
>   • guix-packages-base.drv: 1m30s (was 4m)
>
>   • guix-packages.drv: 30s (was 1m8s)
>
> So this part is ~2.5 times faster than before, yay!  Thank you, Andy!

Indeed, thanks Andy! That's an amazing speedup :D

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 962 bytes --]

Re: Compilation time with Guile 3.0.3-to-be

[Andy Wingo]

Hi :)

On Thu 04 Jun 2020 09:50, Ludovic Courtès <ludo@gnu.org> writes:

> With the attached patch I’ve run ‘make as-derivation’ (equivalent to
> ‘guix pull’) and timed the builds of guix-packages-base.drv (279 files)
> and guix-packages.drv (217 files) on my 4-core i7 laptop:
>
>   • guix-packages-base.drv: 1m30s (was 4m)
>
>   • guix-packages.drv: 30s (was 1m8s)

Nice!!  Thanks for testing :-)

> For the record, the optimizations currently used in (guix build compile)
> are between the new -O0 and -O1:
>
>   (cond ((or (string-contains file "gnu/packages/")
>              (string-contains file "gnu/tests/"))
>          ;; Level 0 is good enough but partial evaluation helps preserve the
>          ;; "macro writer's bill of rights".
>          (override-option #:partial-eval? #t
>                           (optimizations-for-level 0)))

Here fwiw I would use -O1.  It is basically the same as -O0 except that
it adds partial evaluation and it inlines primcalls.  If you are willing
to do partial evaluation, you are probably willing to inline primcalls
too; I think it typically leads to less code and the compilation time is
similar to -O0.

>         ((string-contains file "gnu/services/")
>          ;; '-O2 -Ono-letrectify' compiles about ~20% faster than '-O2' for
>          ;; large files like gnu/services/mail.scm.
>          (override-option #:letrectify? #f
>                           (optimizations-for-level 2)))

Interesting.  I think this is probably a bug of some sort that we'll
have to keep working on.

> With the new -O1, the scheme->tree-il conversion (mostly macro
> expansion) accounts for half of the build time on large files:
>
> scheme@(guile-user)> ,use(system base optimize)
> scheme@(guile-user)> ,time (compile-file "gnu/packages/python-xyz.scm" #:opts (optimizations-for-level 1))
> $1 = "/data/src/guile-3.0/cache/guile/ccache/3.0-LE-8-4.3/home/ludo/src/guix/gnu/packages/python-xyz.scm.go"
> ;; 4.154311s real time, 5.604945s run time.  2.538106s spent in GC.

Interesting data :)

Note that in 3.0.3 there is also a new phase called "lowering".  Before
a compiler from Tree-IL to language X is called, the tree-IL program is
"lowered" -- meaning canonicalized and optionally optimized.

(define (lower-exp exp env optimization-level opts)
  (let ((make-lowerer (language-lowerer (lookup-language 'tree-il))))
    ((make-lowerer optimization-level opts) exp env)))

Similarly there is an analysis pass for warnings, which runs before
lowering:

(define (analyze-exp exp env warning-level warnings)
  (let ((make-analyzer (language-analyzer (lookup-language 'tree-il))))
    ((make-analyzer warning-level warnings) exp env)))

These can be interesting to test different phases of the tree-il ->
bytecode path.

> The profile looks like this:
>
> scheme@(guile-user)> ,pr (define t (call-with-input-file  "gnu/packages/python-xyz.scm" (lambda (port) (read-and-compile port #:to 'tree-il))))
> %     cumulative   self             
> time   seconds     seconds  procedure
>  13.16      0.45      0.40  anon #x1136458
>  10.53      0.35      0.32  ice-9/popen.scm:168:0:reap-pipes
>   7.89      0.24      0.24  anon #x1132af8
>   6.14      0.35      0.19  ice-9/boot-9.scm:3128:0:module-gensym
>   5.26      0.21      0.16  ice-9/boot-9.scm:2201:0:%load-announce
>   4.39      0.19      0.13  ice-9/psyntax.scm:749:8:search
>   3.51      0.69      0.11  ice-9/psyntax.scm:2964:6:match*
>   3.51      0.11      0.11  anon #x11334e8
>   3.51      0.11      0.11  anon #x1136428
>   2.63      0.08      0.08  anon #x113a258
>   1.75      0.05      0.05  ice-9/psyntax.scm:3017:12:$sc-dispatch
>   1.75      0.05      0.05  anon #x1139e68
>   0.88    277.30      0.03  ice-9/boot-9.scm:220:5:map1
>
> It’d be great to waive the anonymity of that first lambda.  :-)

I think I just fixed it :)

> I was wondering what fraction of that time was spent running Guix macros
> (‘package’, ‘base32’, and so on), but it’s difficult to answer that
> question here.  Probably something to investigate so we can make further
> progress!

I think the reap-pipes call is a pretty bad sign, incidentally!

Cheers,

Andy

Re: Compilation time with Guile 3.0.3-to-be

[Katherine Cox-Buday]

Ludovic Courtès <ludo@gnu.org> writes:

> So this part is ~2.5 times faster than before, yay!  Thank you, Andy!

I find a sense of peace working on and with Guix. It seems to me that
Guix has the fundamentals correct, and so change feels like progress and
not churn. We seem to have the right people, working on the right
things, with empathy.

Also, Andy, I appreciated the addendum in your blog post. Thanks for
your efforts towards Guile too!

-- 
Katherine

Re: Compilation time with Guile 3.0.3-to-be

[Ludovic Courtès]

[-- Attachment #1: Type: text/plain, Size: 314 bytes --]

Ludovic Courtès <ludo@gnu.org> skribis:

> With the attached patch I’ve run ‘make as-derivation’ (equivalent to
> ‘guix pull’) and timed the builds of guix-packages-base.drv (279 files)
> and guix-packages.drv (217 files) on my 4-core i7 laptop:

Oh, here comes the attached patch.

Ludo’.


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 2585 bytes --]

diff --git a/gnu/packages/guile.scm b/gnu/packages/guile.scm
index c2dc7f6d5f..2c9a9825e4 100644
--- a/gnu/packages/guile.scm
+++ b/gnu/packages/guile.scm
@@ -322,6 +322,41 @@ without requiring the source code to be rewritten.")
       `(("bdw-gc" ,libgc-7)
         ,@(srfi-1:alist-delete "bdw-gc" (package-propagated-inputs guile-3.0)))))))
 
+(define-public guile-devel
+  (let ((commit "e2066d2e639ecc81078e83fcd7acd8b75faf27a3")
+        (revision "0"))
+   (package
+     (inherit guile-3.0)
+     (version (git-version (package-version guile-3.0)
+                           revision commit))
+     (source (origin
+               (method git-fetch)
+               (uri (git-reference
+                     (url "https://git.savannah.gnu.org/git/guile.git")
+                     (commit commit)))
+               (file-name (git-file-name "guile" version))
+               (sha256
+                (base32
+                 "1qipc4j2wbc2h22qsqp7n81ykclmnw8zxay06gqyaijk3nyf0bbn"))))
+     (arguments
+      (substitute-keyword-arguments (package-arguments guile-3.0)
+        ((#:phases phases '%standard-phases)
+         `(modify-phases ,phases
+            (add-before 'check 'skip-failing-tests
+              (lambda _
+                (setenv "XFAIL_TESTS" "test-out-of-memory")
+                (delete-file "test-suite/tests/version.test")
+                #t))))))
+     (native-inputs
+      `(("autoconf" ,autoconf)
+        ("automake" ,automake)
+        ("libtool" ,libtool)
+        ("flex" ,flex)
+        ("gettext" ,gnu-gettext)
+        ("texinfo" ,texinfo)
+        ("util-linux" ,util-linux)              ;for 'rev', used in popen.test
+        ,@(package-native-inputs guile-3.0))))))
+
 (define-public guile-3.0/fixed
   ;; A package of Guile that's rarely changed.  It is the one used in the
   ;; `base' module, and thus changing it entails a full rebuild.
@@ -776,3 +811,4 @@ manipulate repositories of the Git version control system.")
 
 ;;; guile.scm ends here
 
+
diff --git a/guix/self.scm b/guix/self.scm
index 60fe6e6b01..7449406dc5 100644
--- a/guix/self.scm
+++ b/guix/self.scm
@@ -48,7 +48,7 @@
   (let ((ref (lambda (module variable)
                (module-ref (resolve-interface module) variable))))
     (match-lambda
-      ("guile"      (ref '(gnu packages guile) 'guile-3.0/libgc-7))
+      ("guile"      (ref '(gnu packages guile) 'guile-devel))
       ("guile-json" (ref '(gnu packages guile) 'guile-json-3))
       ("guile-ssh"  (ref '(gnu packages ssh)   'guile-ssh))
       ("guile-git"  (ref '(gnu packages guile) 'guile-git))

Re: Compilation time with Guile 3.0.3-to-be

[Ludovic Courtès]

Hello!

Andy Wingo <wingo@igalia.com> skribis:

> On Thu 04 Jun 2020 09:50, Ludovic Courtès <ludo@gnu.org> writes:

[...]

>> For the record, the optimizations currently used in (guix build compile)
>> are between the new -O0 and -O1:
>>
>>   (cond ((or (string-contains file "gnu/packages/")
>>              (string-contains file "gnu/tests/"))
>>          ;; Level 0 is good enough but partial evaluation helps preserve the
>>          ;; "macro writer's bill of rights".
>>          (override-option #:partial-eval? #t
>>                           (optimizations-for-level 0)))
>
> Here fwiw I would use -O1.  It is basically the same as -O0 except that
> it adds partial evaluation and it inlines primcalls.  If you are willing
> to do partial evaluation, you are probably willing to inline primcalls
> too; I think it typically leads to less code and the compilation time is
> similar to -O0.

Alright, let’s do that.

>>         ((string-contains file "gnu/services/")
>>          ;; '-O2 -Ono-letrectify' compiles about ~20% faster than '-O2' for
>>          ;; large files like gnu/services/mail.scm.
>>          (override-option #:letrectify? #f
>>                           (optimizations-for-level 2)))
>
> Interesting.  I think this is probably a bug of some sort that we'll
> have to keep working on.

Yeah I think memory consumption increases noticeably with
letrectification, which in turns means more GC activity.

> Note that in 3.0.3 there is also a new phase called "lowering".  Before
> a compiler from Tree-IL to language X is called, the tree-IL program is
> "lowered" -- meaning canonicalized and optionally optimized.
>
> (define (lower-exp exp env optimization-level opts)
>   (let ((make-lowerer (language-lowerer (lookup-language 'tree-il))))
>     ((make-lowerer optimization-level opts) exp env)))
>
> Similarly there is an analysis pass for warnings, which runs before
> lowering:
>
> (define (analyze-exp exp env warning-level warnings)
>   (let ((make-analyzer (language-analyzer (lookup-language 'tree-il))))
>     ((make-analyzer warning-level warnings) exp env)))
>
> These can be interesting to test different phases of the tree-il ->
> bytecode path.

OK, I’ll take a look.

>> The profile looks like this:
>>
>> scheme@(guile-user)> ,pr (define t (call-with-input-file  "gnu/packages/python-xyz.scm" (lambda (port) (read-and-compile port #:to 'tree-il))))
>> %     cumulative   self             
>> time   seconds     seconds  procedure
>>  13.16      0.45      0.40  anon #x1136458

[...]

>> It’d be great to waive the anonymity of that first lambda.  :-)
>
> I think I just fixed it :)

Yay, thank you, it’s much nicer now!

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,use(system base compile)
scheme@(guile-user)> ,pr (define t (call-with-input-file  "gnu/packages/python-xyz.scm" (lambda (port) (read-and-compile port #:to 'tree-il))))
%     cumulative   self             
time   seconds     seconds  procedure
 16.24      0.52      0.49  set-source-properties!
 12.82      0.47      0.39  ice-9/boot-9.scm:3128:0:module-gensym
  4.27      0.13      0.13  ice-9/popen.scm:168:0:reap-pipes
  4.27      0.13      0.13  ice-9/psyntax.scm:749:8:search
  3.42      0.13      0.10  ice-9/boot-9.scm:2201:0:%load-announce
  3.42      0.10      0.10  ice-9/boot-9.scm:3434:11:b
  3.42      0.10      0.10  read
  3.42      0.10      0.10  source-properties
  2.56     50.34      0.08  ice-9/threads.scm:388:4
  2.56     12.56      0.08  ice-9/psyntax.scm:1611:10:parse
  2.56      0.08      0.08  module-variable
  2.56      0.08      0.08  memoize-expression
  2.56      0.08      0.08  ice-9/psyntax.scm:668:4:make-binding-wrap
  1.71      0.08      0.05  ice-9/boot-9.scm:2790:0:module-ref-submodule
  1.71      0.05      0.05  number->string
  1.71      0.05      0.05  ice-9/boot-9.scm:1396:0:symbol-append
  1.71      0.05      0.05  append
  1.71      0.05      0.05  string-append
  0.85    270.25      0.03  ice-9/boot-9.scm:220:5:map1
--8<---------------cut here---------------end--------------->8---

Nowadays I freak out every time I see those weak hash tables show up.  ;-)
Well, given the size of the file, it’s no surprise that
‘set-source-properties!’ is called a lot, but it’s still worrying that
it’s #1.  (Perhaps an issue similar to <https://bugs.gnu.org/40194>?)

> I think the reap-pipes call is a pretty bad sign, incidentally!

Yeah, it was discussed recently and I can’t explain it:

  https://lists.gnu.org/archive/html/guile-devel/2020-05/msg00019.html

Thanks for your feedback!

Ludo’.