GNU bug report logs - #50040
[PATCH 0/2] publish: Always render nar/narinfo during backing.

Previous Next

Full log

Message #17 received at 50040 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Mathieu Othacehe <othacehe <at> gnu.org>
Cc: 50040 <at> debbugs.gnu.org
Subject: Re: bug#50040: [PATCH 0/2] publish: Always render nar/narinfo
 during backing.
Date: Tue, 31 Aug 2021 00:31:49 +0200

Mathieu Othacehe <othacehe <at> gnu.org> skribis:

> The "narinfo-string" procedure is expensive in term of IO operations and can
> take a while under IO pressure, such a GC collecting. Defer its call to a new
> thread created in the http-write procedure.

I don’t fully understand where the performance problem comes from.

‘narinfo-string’ makes RPCs, formats a string, and computes a signature
over a few hundred bytes at most.  It does almost no I/O per se (it gets
the nar hash and size via an RPC), and does little computation.

I get this:

--8<---------------cut here---------------start------------->8---
scheme@(guix scripts publish)> (%public-key (read-file-sexp "tests/signing-key.pub"))
$8 = #f
scheme@(guix scripts publish)> (%private-key (read-file-sexp "tests/signing-key.sec"))
$9 = #f
scheme@(guix scripts publish)> ,t (narinfo-string s "/gnu/store/0ff19dxsjvhf4hjnw9ixlqpwdmwfpbyp-libreoffice-7.1.4.2")
$11 = "StorePath: /gnu/store/0ff19dxsjvhf4hjnw9ixlqpwdmwfpbyp-libreoffice-7.1.4.2\nURL: nar/0ff19dxsjvhf4hjnw9ixlqpwdmwfpbyp-libreoffice-7.1.4.2\nCompression: none\nFileSize: 441389400\n[…]"
;; 0.006714s real time, 0.006460s run time.  0.000000s spent in GC.
--8<---------------cut here---------------end--------------->8---

Off the top of my head, scenarios that can make ‘narinfo-string’ slow:

  0. The store’s big GC lock is taken so RPCs don’t complete until it’s
     over.

     GC runs at most twice a day on berlin.  Do you have logs showing at
     what time those timeouts occur?  We could see if there’s a
     correlation.

  1. Contention on the daemon database (“database is locked”) that makes
     RPCs take seconds to complete.  Right now,

       sudo guix processes|grep ^Session|wc -l

     returns 6, which is not a lot, and I suspect that’s typical.  There
     could still be contention, but that doesn’t sound very likely.

  2. It does I/O when it calls ‘read-derivation-from-file’.  Under high
     I/O load, that could be relatively expensive, though I’d expect it
     to be measured in tenths of a second at worst?

     But look, ‘read-derivation-from-file’ is called just to fill in the
     “System” field, which is not used anywhere (not a single caller of
     ‘narinfo-system’), so we could just as well remove it and see how
     it behaves.

Did you manage to come up with a way to synthetically reproduce the
problem?

Anyway, that the main thread is blocking while this happens is certainly
a problem, so this patch looks like an improvement.  That we have to use
the ‘http-write’ hack isn’t great, but I think it’s OK, unless we want
to switch to Fibers.

Ludo’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.