bug#47283: Performance regression in narinfo fetching

[Christopher Baines <mail@cbaines.net>]

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


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

> As reported on guix-devel, ‘guix weather’ has become extremely slow.
> Specifically, in the narinfo-fetching phase, it runs at 100% CPU, even
> though that part should be network-bound (pipelined HTTP GETs).
>
> A profile of the ‘report-server-coverage’ call would show this:
>
> --8<---------------cut here---------------start------------->8---
> %     cumulative   self             
> time   seconds     seconds  procedure
>  62.50      1.06      1.06  fluid-ref*
>   6.25      0.11      0.11  regexp-exec
>   3.13      0.05      0.05  ice-9/boot-9.scm:1738:4:throw
>   2.08      0.04      0.04  string-index
>   2.08      0.04      0.04  write
>   1.04    568.08      0.02  ice-9/boot-9.scm:1673:4:with-exception-handler
>   1.04      0.02      0.02  %read-line
>   1.04      0.02      0.02  guix/ci.scm:78:0:json->build
>   1.04      0.02      0.02  string-append
> --8<---------------cut here---------------end--------------->8---
>
> More than half of the time spent in ‘fluid-ref*’—sounds fishy.
>
> Where does that that call come from?  There seems to be a single caller,
> in boot-9.scm:
>
>     (define* (raise-exception exn #:key (continuable? #f))
>       (define (capture-current-exception-handlers)
>         ;; FIXME: This is quadratic.
>         (let lp ((depth 0))
>           (let ((h (fluid-ref* %exception-handler depth)))
>             (if h
>                 (cons h (lp (1+ depth)))
>                 (list fallback-exception-handler)))))
>       ;; …
>       )
>
> We must be abusing exceptions somewhere…
>
> Indeed, there’s one place on the hot path where we install exception
> handlers: in ‘http-multiple-get’ (from commit
> 205833b72c5517915a47a50dbe28e7024dc74e57).  I don’t think it’s needed,
> is it?  (But if it is, let’s find another approach, this one is
> prohibitively expensive.)

I think the exception handling has moved around, but I guess the
exceptions that could be caught in http-multiple-get could happen,
right? I am really just guessing here, as Guile doesn't help tell you
about possible exceptions, and I haven't spent enough time to read all
the possible code involved to find out if these are definitely possible.

> A simple performance test is:
>
>   rm -rf ~/.cache/guix/substitute/
>   time ./pre-inst-env guix weather $(guix package -A|head -500| cut -f1)
>
> After removing this ‘catch’ in ‘http-multiple-get’, the profile is
> flatter:
>
> --8<---------------cut here---------------start------------->8---
> %     cumulative   self
> time   seconds     seconds  procedure
>   8.33      0.07      0.07  string-index
>   8.33      0.07      0.07  regexp-exec
>   5.56      0.05      0.05  anon #x154af88
>   5.56      0.05      0.05  write
>   5.56      0.05      0.05  string-tokenize
>   5.56      0.05      0.05  read-char
>   5.56      0.05      0.05  set-certificate-credentials-x509-trust-data!
>   5.56      0.05      0.05  %read-line
> --8<---------------cut here---------------end--------------->8---
>
> There’s also this ‘call-with-connection-error-handling’ call in (guix
> substitute), around an ‘http-multiple-get’ call, that may not be
> justified.
>
> Attached is a diff of the tweaks I made to test this.
>
> WDYT, Chris?

I haven't looked in to this yet, but maybe it would be possible to
adjust the code so that it doesn't perform so badly, but still tries to
handle possible exceptions.

The two ideas I have is to rewrite the (let ...) bit in terms of a fold,
maybe that would perform better, or stop using let for iteration and
setup the exception handling, then process each request, using set! to
update the state. I haven't tested either of these.

It's good to know that Guile exception handling can be excessively
expensive though, I wouldn't have expected it to beat out anything over
the network in terms of the performance penalty.

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