Performance of computing cross derivations

[Christopher Baines]

Hey!

When asked by the data service, it seems to take Guix around 3 minutes
to compute cross derivations for all packages (to a single
target). Here's a simple script that replicates this:

  (use-modules (srfi srfi-34)
               (gnu packages)
               (guix grafts)
               (guix packages)
               (guix store)
               (statprof))
  
  (define (all-cross system target)
    (with-store store
      (%graft? #f)
      (fold-packages
       (lambda (package result)
         (with-exception-handler
             (lambda (exn)
               (unless (package-cross-build-system-error? exn)
                 (peek exn))
               result)
           (lambda ()
             (package-cross-derivation store
                                       package
                                       target
                                       system)
             (+ 1 result))
           #:unwind? #t))
       0)))
  
  (statprof
   (lambda ()
     (peek "COUNT"
           (all-cross "x86_64-linux"
                      "i586-pc-gnu")))
   #:count-calls? #t)


Here's some relevant output:

  %     cumulative   self             
  time   seconds    seconds   calls   procedure
   50.48    126.68    102.40                            
ice-9/vlist.scm:502:0:vhash-foldq*
   11.49     23.31     23.31                            hashq
    5.16     10.52     10.47                            write
    2.79     14.28      5.65                            
ice-9/vlist.scm:494:0:vhash-fold*
    2.28      4.63      4.63                            equal?
    2.14      4.35      4.35                            hash
    1.85      4.67      3.75                            
guix/packages.scm:1874:0:input=?
    1.78      3.68      3.61                            put-string
    1.77      7.16      3.59                            
guix/derivations.scm:736:0:derivation/masked-inputs
    0.93      1.90      1.90                            get-bytevector-n
    0.78      1.58      1.58                            put-char
    0.67      1.36      1.36                            search-path

  ...
  
  Total time: 202.872232073 seconds (30.927648399 seconds in GC)


Over 3 minutes seems like a long time for this, especially since it only
computes around 10000 derivations.

I don't know how to use statprof, but looking at vhash-foldq* being at
the top of the output, is this suggesting that around a third of the CPU
time is being spent looking for things in various caches?

I had a go at using the Guix profiling stuff and I did get some output,
but I couldn't figure out how to get it to show all the caching going
on.

Any ideas?

Chris

signature.asc
Description: PGP signature