having trouble modifying guix-daemon

having trouble modifying guix-daemon

[Robert Vollmert]

Hi,

I’m trying to investigate why guix-daemon appears to spend
a lot of time locking store directories. (It’s possible that
it’s doing useful work and just the debug output is useless.)

To do this, I’ve tried adding some debug statements to the
C++ files in guix/nix/…. I’m having trouble getting those
changes live. My understanding is that committing those
changes to my configured guix channel, then running

$ guix pull

should rebuild the guix client tools from that repository.
That seems to work.

Next,

$ sudo guix system reconfigure

should rebuild the system using that same repository, and
thus pull in the updated guix daemon. That does not seem to
be the case, not even after

$ sudo herd restart guix-daemon

Any hints?

(Relatedly, two areas where it feels the Guix System feels
needlessly confusing:
- root guix vs. user guix (and apparently there’s even a
  system guix in /var/guix/profiles/system/profile/bin/guix:
  does that even get used?
  I’d be tempted to simplify this by going for a rootless
  setup (i.e., you can’t log in to root account, root has no
  home and no profile). Reasons against?
- opaque system status: it’s very hard to figure out what
  configuration and what versions of programs are current. My
  current best attempt is to grep through the output of ps
  and then look at those paths in /gnu/store. This is made
  worse due to the lack of timestamps in /gnu/store, as I
  can’t tell which of the many versions of some package is
  the newest just from looking in /gnu/store. Then, the
  shepherd configuration is very opaque: I have to follow
  through a chain of illegible scheme modules to figure
  out what the current configuration is (and then how do
  I know I’m even looking at the right shepherd config?).)

Robert

Re: having trouble modifying guix-daemon

[Ludovic Courtès]

Hi,

Robert Vollmert <rob@vllmrt.net> skribis:

> I’m trying to investigate why guix-daemon appears to spend
> a lot of time locking store directories. (It’s possible that
> it’s doing useful work and just the debug output is useless.)

Note that there are already quite a few debugging statements that you
can view by running something like:

  guix build --debug=5 …

> To do this, I’ve tried adding some debug statements to the
> C++ files in guix/nix/…. I’m having trouble getting those
> changes live. My understanding is that committing those
> changes to my configured guix channel, then running
>
> $ guix pull
>
> should rebuild the guix client tools from that repository.

Unfortunately no.  The ‘guix’ channel is built using (guix self).  That
module has code to build everything, except the daemon itself; for the
daemon, it resorts to the ‘guix-daemon’ package of (gnu packages
package-management).  Thus, changes to the C++ code base do not
propagate until we update the ‘guix’ and thus the ‘guix-daemon’ package.

It’s usually not a problem, but it does mean that your use case is not
supported.

I would suggest simply building it from a checkout and running it
directly from there:

  sudo herd stop guix-daemon
  sudo -E ./pre-inst-env guix-daemon --build-users-group=guixbuild

> (Relatedly, two areas where it feels the Guix System feels
> needlessly confusing:
> - root guix vs. user guix (and apparently there’s even a
>   system guix in /var/guix/profiles/system/profile/bin/guix:
>   does that even get used?
>   I’d be tempted to simplify this by going for a rootless
>   setup (i.e., you can’t log in to root account, root has no
>   home and no profile). Reasons against?

No, that’s actually what we recommend now—that is, not running ‘guix
pull’ as root.

> - opaque system status: it’s very hard to figure out what
>   configuration and what versions of programs are current. My
>   current best attempt is to grep through the output of ps
>   and then look at those paths in /gnu/store. This is made
>   worse due to the lack of timestamps in /gnu/store, as I
>   can’t tell which of the many versions of some package is
>   the newest just from looking in /gnu/store. Then, the
>   shepherd configuration is very opaque: I have to follow
>   through a chain of illegible scheme modules to figure
>   out what the current configuration is (and then how do
>   I know I’m even looking at the right shepherd config?).)

Are you talking about the status of system services specifically?
For those, my trick is usually to simply look up the command line of
the service, like so:

--8<---------------cut here---------------start------------->8---
$ sudo herd status ssh-daemon
Status of ssh-daemon:
  It is started.
  Running value is 528.
  It is enabled.
  Provides (ssh-daemon).
  Requires (syslogd loopback).
  Conflicts with ().
  Will be respawned.
$ sudo cat /proc/528/cmdline |xargs -0 echo
/gnu/store/qpvxwh0l5l2vs7m6dnaclb5y5vll0mlg-openssh-8.0p1/sbin/sshd -D -f /gnu/store/0h0lap06j58acndz9agdzf10cj1gqnr8-sshd_config
--8<---------------cut here---------------end--------------->8---

For the global profile, you can of course just run:

  guix package -p /run/current-system/profile -I

There’s also ‘guix system list-generations’, which prints useful info.

Last, there’s a trick to embed the OS config file directly in
/run/current-system, for those who want it.

That said, we could have a command like:

  guix system status /etc/config.scm

It would print, for the kernel, profile, and services, which are current
and which differ.  It usually won’t be able to tell much beyond that one
bit: current or not.

Thoughts?

Ludo’.

Re: having trouble modifying guix-daemon

[Robert Vollmert]

Hi,

thanks for the detailed reply.

On 27. Jun 2019, at 17:34, Ludovic Courtès <ludo@gnu.org> wrote:
> Robert Vollmert <rob@vllmrt.net> skribis:
> 
>> I’m trying to investigate why guix-daemon appears to spend
>> a lot of time locking store directories. (It’s possible that
>> it’s doing useful work and just the debug output is useless.)
> 
> Note that there are already quite a few debugging statements that you
> can view by running something like:
> 
>  guix build --debug=5 …

Yes I found that, and the output is not very helpful (yet). I get hundreds
of repetitive

  acquiring write lock on `<dir>'
  downgrading to read lock on `<dir>'

at the start. By modifying that debug statement, I can now see that at least
these are calls to add roots for different parts — I assume by now that
these are client calls to add-temp-root.

I’d like to improve the debug output here more generally: At (high enough)
debug level, it seems to make sense to log every operation. What I’m unclear
on here is whether it’s better to do that client or server side, what do you
think? The spots would be

(a) nix/nix-daemon/nix-daemon.cc:performOp (inside each start/stopWork pair)
(b) guix/store.scm:operation (next to record-operation)

I have a slight preference for (b) since it avoids the sending data back
and forth.

>> To do this, I’ve tried adding some debug statements to the
>> C++ files in guix/nix/…. I’m having trouble getting those
>> changes live. My understanding is that committing those
>> changes to my configured guix channel, then running
>> 
>> $ guix pull
>> 
>> should rebuild the guix client tools from that repository.
> 
> Unfortunately no.  The ‘guix’ channel is built using (guix self).  That
> module has code to build everything, except the daemon itself; for the
> daemon, it resorts to the ‘guix-daemon’ package of (gnu packages
> package-management).  Thus, changes to the C++ code base do not
> propagate until we update the ‘guix’ and thus the ‘guix-daemon’ package.
> 
> It’s usually not a problem, but it does mean that your use case is not
> supported.
> 
> I would suggest simply building it from a checkout and running it
> directly from there:
> 
>  sudo herd stop guix-daemon
>  sudo -E ./pre-inst-env guix-daemon --build-users-group=guixbuild

Thank you, that works!

>> (Relatedly, two areas where it feels the Guix System feels
>> needlessly confusing:
>> - root guix vs. user guix (and apparently there’s even a
>>  system guix in /var/guix/profiles/system/profile/bin/guix:
>>  does that even get used?
>>  I’d be tempted to simplify this by going for a rootless
>>  setup (i.e., you can’t log in to root account, root has no
>>  home and no profile). Reasons against?
> 
> No, that’s actually what we recommend now—that is, not running ‘guix
> pull’ as root.

Alright. I’ll see if I can figure out how to set up the system without
login-able root account, and might send a patch if successful.

>> - opaque system status: it’s very hard to figure out what
>>  configuration and what versions of programs are current. My
>>  current best attempt is to grep through the output of ps
>>  and then look at those paths in /gnu/store. This is made
>>  worse due to the lack of timestamps in /gnu/store, as I
>>  can’t tell which of the many versions of some package is
>>  the newest just from looking in /gnu/store. Then, the
>>  shepherd configuration is very opaque: I have to follow
>>  through a chain of illegible scheme modules to figure
>>  out what the current configuration is (and then how do
>>  I know I’m even looking at the right shepherd config?).)
> 
> Are you talking about the status of system services specifically?
> For those, my trick is usually to simply look up the command line of
> the service, like so:
> 
> --8<---------------cut here---------------start------------->8---
> $ sudo herd status ssh-daemon
> Status of ssh-daemon:
>  It is started.
>  Running value is 528.
>  It is enabled.
>  Provides (ssh-daemon).
>  Requires (syslogd loopback).
>  Conflicts with ().
>  Will be respawned.
> $ sudo cat /proc/528/cmdline |xargs -0 echo
> /gnu/store/qpvxwh0l5l2vs7m6dnaclb5y5vll0mlg-openssh-8.0p1/sbin/sshd -D -f /gnu/store/0h0lap06j58acndz9agdzf10cj1gqnr8-sshd_config
> --8<---------------cut here---------------end--------------->8---
> 

That’s a bit more precise than what I was doing, thanks. It would be
quite helpful for `herd status` to do that work itself, what do you
think? Also maybe to optionally show the service definition?

(I do still think that having the system configuration stored in a
rather opaque database and only queryable via tools is a disadvantage.
Sort of like how systemd’s binary logging has disadvantages compared to
plain text logfiles in /var/log.)

> For the global profile, you can of course just run:
> 
>  guix package -p /run/current-system/profile -I
> 
> There’s also ‘guix system list-generations’, which prints useful info.

Thanks, interesting. Following the output of these commands, here are two
questions I didn’t manage to answer (1 would help answer 2):

1. Where is the current version and configuration of shepherd defined?
2. Which nginx version is part of the current system, with which configuration?

(One point where querying shepherd or guix about what’s current breaks down
is when debugging the system. It’s really helpful to have some redundancy
there, where I can compare the input, some files, and what guix/shepherd
think to see which is at odds. That’s not necessarily debugging the system
btw, might also be debugging my understanding. :) )

> Last, there’s a trick to embed the OS config file directly in
> /run/current-system, for those who want it.
> 
> That said, we could have a command like:
> 
>  guix system status /etc/config.scm
> 
> It would print, for the kernel, profile, and services, which are current
> and which differ.  It usually won’t be able to tell much beyond that one
> bit: current or not.

Couldn’t `guix system status` even be useful without the config.scm argument?
Showing the kernel that’s part of the system configuration compared to the
running kernel, and services that are part of the system configuration compared
to what’s running.

Robert

Re: having trouble modifying guix-daemon

[Ludovic Courtès]

Hello,

Robert Vollmert <rob@vllmrt.net> skribis:

> I’d like to improve the debug output here more generally: At (high enough)
> debug level, it seems to make sense to log every operation. What I’m unclear
> on here is whether it’s better to do that client or server side, what do you
> think? The spots would be
>
> (a) nix/nix-daemon/nix-daemon.cc:performOp (inside each start/stopWork pair)
> (b) guix/store.scm:operation (next to record-operation)
>
> I have a slight preference for (b) since it avoids the sending data back
> and forth.

In my experience I rarely need to log every operation (e.g., every RPC),
and when I do, I add a well-placed ‘pk’.  :-)  If you have a specific
example in mind, we can discuss it, but my feeling is that it’s often
better to just go ahead and add the debugging statement that precisely
shows what you want rather than add “generic” debugging statements.

Also, there’s GUIX_PROFILING for general statistics; that is pretty
useful IMO.

>> For those, my trick is usually to simply look up the command line of
>> the service, like so:
>> 
>> --8<---------------cut here---------------start------------->8---
>> $ sudo herd status ssh-daemon
>> Status of ssh-daemon:
>>  It is started.
>>  Running value is 528.
>>  It is enabled.
>>  Provides (ssh-daemon).
>>  Requires (syslogd loopback).
>>  Conflicts with ().
>>  Will be respawned.
>> $ sudo cat /proc/528/cmdline |xargs -0 echo
>> /gnu/store/qpvxwh0l5l2vs7m6dnaclb5y5vll0mlg-openssh-8.0p1/sbin/sshd -D -f /gnu/store/0h0lap06j58acndz9agdzf10cj1gqnr8-sshd_config
>> --8<---------------cut here---------------end--------------->8---
>> 
>
> That’s a bit more precise than what I was doing, thanks. It would be
> quite helpful for `herd status` to do that work itself, what do you
> think? Also maybe to optionally show the service definition?

The problem is that, with its current API, the Shepherd doesn’t see
processes with a command; it just sees <service> classes with a ‘start’
method.

That said, when the “running value” is a number, it’s must be a PID; so
in this case, ‘herd status’ could definitely write the output of
/proc/PID/cmdline for you.  Would you like to give it a try?

The service definition cannot really be shown, at least not in a
meaningful way, but it could show source location information, which
would already be an improvement.  We just need to add a ‘location’ field
to <service>, I guess.

> (I do still think that having the system configuration stored in a
> rather opaque database and only queryable via tools is a disadvantage.
> Sort of like how systemd’s binary logging has disadvantages compared to
> plain text logfiles in /var/log.)

I see what you mean, but I also think is a matter of perspective: after
all, Guix allows you to view your OS config as a regular object in
Scheme, you can traverse it to view its services, etc.  This expressive
power can hardly be achieved at the command line.

> Thanks, interesting. Following the output of these commands, here are two
> questions I didn’t manage to answer (1 would help answer 2):
>
> 1. Where is the current version and configuration of shepherd defined?

cat /proc/1/cmdline :-)

> 2. Which nginx version is part of the current system, with which configuration?

You can do things like:

  guix gc -R $(readlink -f /run/current-system) | grep nginx

or again ‘herd status nginx’ as discussed before.

I agree that we should work on better UIs here.

>> Last, there’s a trick to embed the OS config file directly in
>> /run/current-system, for those who want it.
>> 
>> That said, we could have a command like:
>> 
>>  guix system status /etc/config.scm
>> 
>> It would print, for the kernel, profile, and services, which are current
>> and which differ.  It usually won’t be able to tell much beyond that one
>> bit: current or not.
>
> Couldn’t `guix system status` even be useful without the config.scm argument?

That would compare /run/booted-system to /run/current-system, right?
That could work, I guess.

Thanks,
Ludo’.

Re: having trouble modifying guix-daemon

[Robert Vollmert]

> On 1. Jul 2019, at 12:28, Ludovic Courtès <ludo@gnu.org> wrote:
> 
> Hello,
> 
> Robert Vollmert <rob@vllmrt.net> skribis:
> 
>> I’d like to improve the debug output here more generally: At (high enough)
>> debug level, it seems to make sense to log every operation. What I’m unclear
>> on here is whether it’s better to do that client or server side, what do you
>> think? The spots would be
>> 
>> (a) nix/nix-daemon/nix-daemon.cc:performOp (inside each start/stopWork pair)
>> (b) guix/store.scm:operation (next to record-operation)
>> 
>> I have a slight preference for (b) since it avoids the sending data back
>> and forth.
> 
> In my experience I rarely need to log every operation (e.g., every RPC),
> and when I do, I add a well-placed ‘pk’.  :-)

That’s hardly something you’d expect a guix system user to do that’s trying
to understand why guix pull is taking forever though, is it? Compare the
log file of a guix pull run here: http://sprunge.us/jiz2Yl:

00:00:03 acquiring write lock on `/var/guix/temproots/28553'
00:00:03 downgrading to read lock on `/var/guix/temproots/28553'
00:00:03 acquiring write lock on `/var/guix/temproots/28553'
00:00:03 downgrading to read lock on `/var/guix/temproots/28553'
00:00:03 acquiring write lock on `/var/guix/temproots/28553'
00:00:03 downgrading to read lock on `/var/guix/temproots/28553'
00:00:03 acquiring write lock on `/var/guix/temproots/28553'
00:00:03 downgrading to read lock on `/var/guix/temproots/28553'
[…]

Those pages and pages of identical store locking debug messages are worse
than useless. Adding some higher level debug logs in between that show what’s
actually being worked on would help a lot there.

Cheers
Robert

Re: having trouble modifying guix-daemon

[Ludovic Courtès]

Hi Robert,

Robert Vollmert <rob@vllmrt.net> skribis:

>> On 1. Jul 2019, at 12:28, Ludovic Courtès <ludo@gnu.org> wrote:
>> 
>> Hello,
>> 
>> Robert Vollmert <rob@vllmrt.net> skribis:
>> 
>>> I’d like to improve the debug output here more generally: At (high enough)
>>> debug level, it seems to make sense to log every operation. What I’m unclear
>>> on here is whether it’s better to do that client or server side, what do you
>>> think? The spots would be
>>> 
>>> (a) nix/nix-daemon/nix-daemon.cc:performOp (inside each start/stopWork pair)
>>> (b) guix/store.scm:operation (next to record-operation)
>>> 
>>> I have a slight preference for (b) since it avoids the sending data back
>>> and forth.
>> 
>> In my experience I rarely need to log every operation (e.g., every RPC),
>> and when I do, I add a well-placed ‘pk’.  :-)
>
> That’s hardly something you’d expect a guix system user to do that’s trying
> to understand why guix pull is taking forever though, is it?

No, but I don’t expect users to profile Guix anyway.

I didn’t understand your request had to do with ‘guix pull’.  It “takes
forever” for two reasons:

  1. The “Computing Guix derivation” phases takes a bit less than 1mn on
     my laptop; it runs most of the target Guix through the interpreter,
     which is why it’s this slow.  Optimizing it is high on my list, but
     it’s not that easy.

  2. The rest is about downloading substitutes or, if you’re unlucky,
     compiling part of Guix.  As it turns out, Guile’s compiler since
     2.2 is unreasonably resource-intensive when compiling simple code
     like gnu/packages/*.scm.  Again, that needs work; if you want to
     fiddle with graph processing algorithm, this is for you.

The daemon is not responsible for the slowness here.

Thanks,
Ludo’.

Re: having trouble modifying guix-daemon

[Robert Vollmert]

On 5. Jul 2019, at 23:41, Ludovic Courtès <ludo@gnu.org> wrote:
> Robert Vollmert <rob@vllmrt.net> skribis:
> 
>>> On 1. Jul 2019, at 12:28, Ludovic Courtès <ludo@gnu.org> wrote:
>>> 
>>> Hello,
>>> 
>>> Robert Vollmert <rob@vllmrt.net> skribis:
>>> 
>>>> I’d like to improve the debug output here more generally: At (high enough)
>>>> debug level, it seems to make sense to log every operation. What I’m unclear
>>>> on here is whether it’s better to do that client or server side, what do you
>>>> think? The spots would be
>>>> 
>>>> (a) nix/nix-daemon/nix-daemon.cc:performOp (inside each start/stopWork pair)
>>>> (b) guix/store.scm:operation (next to record-operation)
>>>> 
>>>> I have a slight preference for (b) since it avoids the sending data back
>>>> and forth.
>>> 
>>> In my experience I rarely need to log every operation (e.g., every RPC),
>>> and when I do, I add a well-placed ‘pk’.  :-)
>> 
>> That’s hardly something you’d expect a guix system user to do that’s trying
>> to understand why guix pull is taking forever though, is it?
> 
> No, but I don’t expect users to profile Guix anyway.
> 
> I didn’t understand your request had to do with ‘guix pull’.  It “takes
> forever” for two reasons:

I think I didn’t really get my point across. I didn’t mean to ask about why
‘guix pull’ is slow (though I am interested, and am thankful for the explanation).

Instead, I’d like to improve on my experience, which I’m sure others would run
into:

- working with guix, doing some calls to guix pull, guix system reconfigure.
- notice that it takes quite a while, and often hangs for extended periods of
time without clear indication what it’s doing, whether it’s even doing anything
- look through the manuals to find out how to get more useful output to answer
those questions, learn about “debug” and “verbose” command line options.
- through trial and error, learn that “verbose” doesn’t seem to be helpful, but
“debug” does add some output
- but that output is mostly just pages and pages of identical locking/unlocking
the store lines

In my opinion, the debug output, if available, should help to answer the original
questions. And certainly not prompt more questions, such as “is this just spinning
on a lock?” which have an easy answer.

To that extent, I’d like to improve the output of debug level guix pull logging.
If you’d really not like adding more debug statements, I’d suggest kicking out the
existing locking statements from guix daemon.

Cheers
Robert

Re: having trouble modifying guix-daemon

[Ludovic Courtès]

Hello,

Robert Vollmert <rob@vllmrt.net> skribis:

> Instead, I’d like to improve on my experience, which I’m sure others would run
> into:
>
> - working with guix, doing some calls to guix pull, guix system reconfigure.
> - notice that it takes quite a while, and often hangs for extended periods of
> time without clear indication what it’s doing, whether it’s even doing anything
> - look through the manuals to find out how to get more useful output to answer
> those questions, learn about “debug” and “verbose” command line options.
> - through trial and error, learn that “verbose” doesn’t seem to be helpful, but
> “debug” does add some output
> - but that output is mostly just pages and pages of identical locking/unlocking
> the store lines
>
> In my opinion, the debug output, if available, should help to answer the original
> questions. And certainly not prompt more questions, such as “is this just spinning
> on a lock?” which have an easy answer.

OK, I see.

Fundamentally, we should treat “guix takes a while without printing
anything” as a bug.  I think the UI should always show a progress bar,
or a spinner, or at the very least a message indicating that some
time-consuming action is taking place.

For example, I know that an initial ‘guix pull’ takes a long time
without printing anything: that’s because it’s cloning the repo, and we
don’t have Guile-Git hooks to report on the progress of that operation.
That’s clearly something to fix in the UI.  Is this specifically the
slowness you were looking at?

‘guix system’ tends to take a bit too long to just compute the system
derivation; we should probably optimize the whole thing, but also
consider adding some sort of progress report.

These are two examples of slowness where getting debugging output from
the daemon does not help at all understand what’s going on.

> To that extent, I’d like to improve the output of debug level guix pull logging.

So, I think what I’m saying is that I’d rather improve progress
reporting in the UI, than add debugging statement.  Logging and progress
report are actually almost the same thing, except that progress report
is meant for normal human beings.  :-)

Ludo’.