Re: Compilation time with Guile 3.0.3-to-be

[Andy Wingo <wingo@igalia.com>]

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