Re: RPC pipelining

[Ludovic Courtès]

Ricardo Wurmus  skribis:

>> Why does Guix need Shepherd?  And if it needs the (charting)
>> module, why isn't guile-charting already an input?
>
> Guile Charting is optional.  The error is misleadingly alarming.

Yes, same for Shepherd (both are mere warnings, but I agree they can be
misleading.)

Does “make dist” eventually fail?

Thanks,
Ludo’.

Re: RPC pipelining

[Ricardo Wurmus]

> Why does Guix need Shepherd?  And if it needs the (charting)
> module, why isn't guile-charting already an input?

Guile Charting is optional.  The error is misleadingly alarming.

-- 
Ricardo

GPG: BCA6 89B6 3655 3801 C3C6  2150 197A 5888 235F ACAC
https://elephly.net

Re: RPC pipelining

[Roel Janssen]

Ludovic Courtès writes:

> Hi Roel,
>
> Roel Janssen  skribis:
>
>> substitute: guix substitute: warning: ACL for archive imports seems to be 
>> uninitialized, substitutes may be unavailable
>> substitute: ;;; Failed to autoload make-session in (gnutls):
>> substitute: ;;; ERROR: missing interface for module (gnutls)
>> substitute: Backtrace:
>> substitute:1 (primitive-load 
>> "/gnu/repositories/guix/scripts/guix")
>> substitute: In guix/ui.scm:
>> substitute:   1352:12  0 (run-guix-command _ . _)
>> substitute: 
>> substitute: guix/ui.scm:1352:12: In procedure run-guix-command:
>> substitute: guix/ui.scm:1352:12: In procedure module-lookup: Unbound 
>> variable: make-session
>> guix environment: error: build failed: writing to file: Broken pipe
>
> This is because ‘guix substitute’, called by ‘guix-daemon’, doesn’t find
> (gnutls) in its GUILE_LOAD_PATH.
>
> Use either “sudo -E ./pre-inst-env guix-daemon …” so that guix-daemon
> inherits GUILE_LOAD_PATH and GUILE_LOAD_COMPILED_PATH, or
> --no-substitutes.
>
> Thanks for testing!
>
> Ludo’.

Thanks for the pointer.  I think it was a bad idea to try it with the
pre-inst-env, because before it even got to this point I had to modify
the location of guile in the header of scripts/guix.

So, maybe I shouldn't be using the pre-inst-env at all and just
properly install the patched version.  I can always --roll-back anyway.

So I applied the patch, and ran:
make dist

Which produced a tarball.
I then modified the guix recipe to use the tarball instead of a git
checkout.  But unfortunately, building it is again troublesome:

...
  GUILEC   guix/scripts/import/gem.go
  GUILEC   guix/scripts/import/pypi.go
  GUILEC   guix/scripts/import/stackage.go
  GUILEC   guix/ssh.go
  GUILEC   guix/scripts/copy.go
  GUILEC   guix/store/ssh.go
  GUILEC   guix/scripts/offload.go
  GUILEC   guix/config.go
  GUILEC   guix/tests.go
  GUILEC   guix/tests/http.go
;;; Failed to autoload make-page-map in (charting):
;;; ERROR: missing interface for module (charting)
;;; Failed to autoload make-page-map in (charting):
;;; ERROR: missing interface for module (charting)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload exec-command in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
random seed for tests: 1499856249
;;; Failed to autoload make-page-map in (charting):
;;; ERROR: missing interface for module (charting)
;;; Failed to autoload make-page-map in (charting):
;;; ERROR: missing interface for module (charting)
;;; Failed to autoload make-page-map in (charting):
;;; ERROR: missing interface for module (charting)
guix/scripts/size.scm:211:2: warning: possibly unbound variable `make-page-map'
;;; Failed to autoload make-page-map in (charting):
;;; ERROR: missing interface for module (charting)
;;; Failed to autoload make-page-map in (charting):
;;; ERROR: missing interface for module (charting)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload exec-command in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload exec-command in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
gnu/build/shepherd.scm:98:13: warning: possibly unbound variable `read-pid-file'
gnu/build/shepherd.scm:159:32: warning: possibly unbound variable `exec-command'
gnu/build/shepherd.scm:170:14: warning: possibly unbound variable 
`read-pid-file'
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload exec-command in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload exec-command in (shepherd service):
;;; ERROR: missing interface for module (shepherd service)
;;; Failed to autoload read-pid-file in (shepherd service):
;;; ERROR: 

Re: RPC pipelining

[Ludovic Courtès]

Hi Roel,

Roel Janssen  skribis:

> substitute: guix substitute: warning: ACL for archive imports seems to be 
> uninitialized, substitutes may be unavailable
> substitute: ;;; Failed to autoload make-session in (gnutls):
> substitute: ;;; ERROR: missing interface for module (gnutls)
> substitute: Backtrace:
> substitute:1 (primitive-load 
> "/gnu/repositories/guix/scripts/guix")
> substitute: In guix/ui.scm:
> substitute:   1352:12  0 (run-guix-command _ . _)
> substitute: 
> substitute: guix/ui.scm:1352:12: In procedure run-guix-command:
> substitute: guix/ui.scm:1352:12: In procedure module-lookup: Unbound 
> variable: make-session
> guix environment: error: build failed: writing to file: Broken pipe

This is because ‘guix substitute’, called by ‘guix-daemon’, doesn’t find
(gnutls) in its GUILE_LOAD_PATH.

Use either “sudo -E ./pre-inst-env guix-daemon …” so that guix-daemon
inherits GUILE_LOAD_PATH and GUILE_LOAD_COMPILED_PATH, or
--no-substitutes.

Thanks for testing!

Ludo’.

Re: RPC pipelining

[Roel Janssen]

Hello Ludo’!

Thanks for working so hard on this.
I run into trouble with my test setup..

[roel@hpcguix ~]$ time ./guixr environment --ad-hoc coreutils -- true

;;; (flush-pending-rpcs 170)

;;; (flush-pending-rpcs 4)
substitute: guix substitute: warning: ACL for archive imports seems to be 
uninitialized, substitutes may be unavailable
substitute: ;;; Failed to autoload make-session in (gnutls):
substitute: ;;; ERROR: missing interface for module (gnutls)
substitute: Backtrace:
substitute:1 (primitive-load "/gnu/repositories/guix/scripts/guix")
substitute: In guix/ui.scm:
substitute:   1352:12  0 (run-guix-command _ . _)
substitute: 
substitute: guix/ui.scm:1352:12: In procedure run-guix-command:
substitute: guix/ui.scm:1352:12: In procedure module-lookup: Unbound variable: 
make-session
guix environment: error: build failed: writing to file: Broken pipe

real0m8.679s
user0m1.199s
sys 0m0.202s


But FWIW, I think the time between no output and the "substitute: ..."
output is dramatically shorter.

I'll report back when I have a better testing environment ready.

Kind regards,
Roel Janssen


Ludovic Courtès writes:

> Hello Guix!
>
> One of the main sources of slowness when talking to a remote daemon, as
> with GUIX_DAEMON_SOCKET=guix://…, is the many RPCs that translate in
> lots of network round trips:
>
> --8<---cut here---start->8---
> $ GUIX_PROFILING=rpc ./pre-inst-env guix build inkscape -d --no-grafts
> /gnu/store/iymxyy5sn0qrkivppl6fn0javnmr3nss-inkscape-0.92.1.drv
> Remote procedure call summary: 1006 RPCs
>   built-in-builders  ... 1
>   add-to-store   ...   136
>   add-text-to-store  ...   869
> --8<---cut here---end--->8---
>
> In this example we’re making ~1,000 round trips; not good!
>
> Before changing the protocol, an idea that came to mind is to do “RPC
> pipelining”: send as many RPC requests at once, then read all the
> corresponding responses.
>
> It turns out to necessitate a small change in the daemon, though, but
> the attached patch demonstrates it: the client buffers all
> ‘add-text-to-store’ RPCs, and writes them all at once when another RPC
> is made (because other RPCs, which are not buffered, might depend on the
> effect of those ‘add-text-to-store’ RPCs) or when the connection is
> closed.  In practice, on the example above, it manages to buffer all 869
> RPCs and send them all at once.
>
> To estimate the effectiveness of this approach, I introduced delay on
> the loopback device with tc-netem(8) and measured execution time (the
> first run uses pipelining, the second doesn’t):
>
> --8<---cut here---start->8---
> $ sudo tc qdisc add dev lo root netem delay 150ms
> $ time GUIX_DAEMON_SOCKET=guix://localhost ./pre-inst-env guix build inkscape 
> -d --no-grafts
> accepted connection from 127.0.0.1
> /gnu/store/iymxyy5sn0qrkivppl6fn0javnmr3nss-inkscape-0.92.1.drv
>
> ;;; (flush-pending-rpcs 869)
>
> real  0m47.796s
> user  0m1.307s
> sys   0m0.056s
> $ time GUIX_DAEMON_SOCKET=guix://localhost guix build inkscape -d --no-grafts
> accepted connection from 127.0.0.1
> /gnu/store/iymxyy5sn0qrkivppl6fn0javnmr3nss-inkscape-0.92.1.drv
>
> real  5m7.226s
> user  0m1.392s
> sys   0m0.056s
> $ sudo tc qdisc del dev lo root
> --8<---cut here---end--->8---
>
> So the wall-clock time is divided by 6 thanks to ‘add-text-to-store’
> pipelining, but it’s still pretty high due to the 136 ‘add-to-store’
> RPCs which are still *not* pipelined.
>
> It’s less clear what to do with these.  Buffering them would require
> clients to compute the store file name of the files that are passed to
> ‘add-to-store’, which involves computing the hash of the files itself,
> which can be quite costly and redundant with what the daemon will do
> eventually anyway.  The CPU cost might be compensated for when latency
> is high, but not when latency is low.
>
> Anyway, food for thought!
>
> For now, if those using Guix on clusters are willing to test the patch
> below (notice that you need to run the patched guix-daemon as well), I’d
> be interested in seeing how representative the above test is!
>
> Ludo’.
>
> diff --git a/guix/store.scm b/guix/store.scm
> index b15da5485..1ba22cf2d 100644
> --- a/guix/store.scm
> +++ b/guix/store.scm
> @@ -40,6 +40,7 @@
>#:use-module (ice-9 regex)
>#:use-module (ice-9 vlist)
>#:use-module (ice-9 popen)
> +  #:use-module (ice-9 format)
>#:use-module (web uri)
>#:export (%daemon-socket-uri
>  %gc-roots-directory
> @@ -322,7 +323,7 @@
&g

RPC pipelining

[Ludovic Courtès]

Hello Guix!

One of the main sources of slowness when talking to a remote daemon, as
with GUIX_DAEMON_SOCKET=guix://…, is the many RPCs that translate in
lots of network round trips:

--8<---cut here---start->8---
$ GUIX_PROFILING=rpc ./pre-inst-env guix build inkscape -d --no-grafts
/gnu/store/iymxyy5sn0qrkivppl6fn0javnmr3nss-inkscape-0.92.1.drv
Remote procedure call summary: 1006 RPCs
  built-in-builders  ... 1
  add-to-store   ...   136
  add-text-to-store  ...   869
--8<---cut here---end--->8---

In this example we’re making ~1,000 round trips; not good!

Before changing the protocol, an idea that came to mind is to do “RPC
pipelining”: send as many RPC requests at once, then read all the
corresponding responses.

It turns out to necessitate a small change in the daemon, though, but
the attached patch demonstrates it: the client buffers all
‘add-text-to-store’ RPCs, and writes them all at once when another RPC
is made (because other RPCs, which are not buffered, might depend on the
effect of those ‘add-text-to-store’ RPCs) or when the connection is
closed.  In practice, on the example above, it manages to buffer all 869
RPCs and send them all at once.

To estimate the effectiveness of this approach, I introduced delay on
the loopback device with tc-netem(8) and measured execution time (the
first run uses pipelining, the second doesn’t):

--8<---cut here---start->8---
$ sudo tc qdisc add dev lo root netem delay 150ms
$ time GUIX_DAEMON_SOCKET=guix://localhost ./pre-inst-env guix build inkscape 
-d --no-grafts
accepted connection from 127.0.0.1
/gnu/store/iymxyy5sn0qrkivppl6fn0javnmr3nss-inkscape-0.92.1.drv

;;; (flush-pending-rpcs 869)

real0m47.796s
user0m1.307s
sys 0m0.056s
$ time GUIX_DAEMON_SOCKET=guix://localhost guix build inkscape -d --no-grafts
accepted connection from 127.0.0.1
/gnu/store/iymxyy5sn0qrkivppl6fn0javnmr3nss-inkscape-0.92.1.drv

real5m7.226s
user0m1.392s
sys 0m0.056s
$ sudo tc qdisc del dev lo root
--8<---cut here---end--->8---

So the wall-clock time is divided by 6 thanks to ‘add-text-to-store’
pipelining, but it’s still pretty high due to the 136 ‘add-to-store’
RPCs which are still *not* pipelined.

It’s less clear what to do with these.  Buffering them would require
clients to compute the store file name of the files that are passed to
‘add-to-store’, which involves computing the hash of the files itself,
which can be quite costly and redundant with what the daemon will do
eventually anyway.  The CPU cost might be compensated for when latency
is high, but not when latency is low.

Anyway, food for thought!

For now, if those using Guix on clusters are willing to test the patch
below (notice that you need to run the patched guix-daemon as well), I’d
be interested in seeing how representative the above test is!

Ludo’.

diff --git a/guix/store.scm b/guix/store.scm
index b15da5485..1ba22cf2d 100644
--- a/guix/store.scm
+++ b/guix/store.scm
@@ -40,6 +40,7 @@
   #:use-module (ice-9 regex)
   #:use-module (ice-9 vlist)
   #:use-module (ice-9 popen)
+  #:use-module (ice-9 format)
   #:use-module (web uri)
   #:export (%daemon-socket-uri
 %gc-roots-directory
@@ -322,7 +323,7 @@
 
 (define-record-type 
   (%make-nix-server socket major minor
-buffer flush
+buffer flush pending-rpcs
 ats-cache atts-cache)
   nix-server?
   (socket nix-server-socket)
@@ -332,6 +333,10 @@
   (buffer nix-server-output-port) ;output port
   (flush  nix-server-flush-output);thunk
 
+  ;; List of pending 'add-text-to-store' RPC arguments.
+  (pending-rpcs nix-server-pending-rpcs
+set-nix-server-pending-rpcs!)
+
   ;; Caches.  We keep them per-connection, because store paths build
   ;; during the session are temporary GC roots kept for the duration of
   ;; the session.
@@ -509,7 +514,7 @@ for this connection will be pinned.  Return a server object."
   (let ((conn (%make-nix-server port
 (protocol-major v)
 (protocol-minor v)
-output flush
+output flush '()
 (make-hash-table 100)
 (make-hash-table 100
 (let loop ((done? (process-stderr conn)))
@@ -521,8 +526,17 @@ for this connection will be pinned.  Return a server object."
   (force-output (nix-server-output-port server))
   ((nix-server-flush-output server)))
 
+(define (flush-pending-rpcs server)
+  (let ((len (length (nix-server-pending-r