sync-before-registering is false, possibly the cause of empty files in the store

  • Open
  • quality assurance status badge
Details
4 participants
  • Ludovic Courtès
  • Christopher Baines
  • Maxime Devos
  • zimoun
Owner
unassigned
Submitted by
Maxime Devos
Severity
normal
M
M
Maxime Devos wrote on 24 Sep 2022 03:35
(name . guix-patches@gnu.org)(address . guix-patches@gnu.org)
0530a80e-0a93-5a3a-ef98-5ba3683e810d@telenet.be
libstore/local-store.cc has the following comment:
void LocalStore::registerValidPaths(const ValidPathInfos & infos)
{
/* SQLite will fsync by default, but the new valid paths may not be
fsync-ed.
* So some may want to fsync them before registering the validity,
at the
* expense of some speed of the path registering operation. */
if (settings.syncBeforeRegistering) sync();
[...]
}
However, currently sync-before-registering is set to 'false' AFAICT. I
think this might be the cause of bugs like
https://issues.guix.gnu.org/58013 (‘Can't use "guix pull"’), and maybe
https://issues.guix.gnu.org/57838 (‘failing to boot, probably due to
guix gc’).
As such, I think we need to set it to 'true' by default instead. Or if
that turns out to be too expensive, instead do a recursive 'fsync' on
the 'paths' (store items) that are about to be registered (and maybe
some other tricks like disabling the 'fsync/sync' for most tests).
(Unverified if this solves those issues, just an idea ...)
Greetings,
Maxime.
Attachment: OpenPGP_signature
L
L
Ludovic Courtès wrote on 4 Oct 2022 09:52
(name . Maxime Devos)(address . maximedevos@telenet.be)(address . 58035@debbugs.gnu.org)
874jwkvxdt.fsf@gnu.org
Hi,

Maxime Devos <maximedevos@telenet.be> skribis:

Toggle quote (20 lines)
> libstore/local-store.cc has the following comment:
>
> void LocalStore::registerValidPaths(const ValidPathInfos & infos)
> {
> /* SQLite will fsync by default, but the new valid paths may not
> be fsync-ed.
> * So some may want to fsync them before registering the validity,
> at the
> * expense of some speed of the path registering operation. */
> if (settings.syncBeforeRegistering) sync();
>
> [...]
> }
>
> However, currently sync-before-registering is set to 'false' AFAICT.
> I think this might be the cause of bugs like
> <https://issues.guix.gnu.org/58013> (‘Can't use "guix pull"’), and
> maybe <https://issues.guix.gnu.org/57838> (‘failing to boot, probably
> due to guix gc’).

It might be a factor, combined with the fact that the file system was
not properly unmounted (power outage or similar).

However, calling sync(2) for each store item is going to be expensive.
Recursive fsync/fdatasync calls are also likely to be too expensive (see
https://issues.guix.gnu.org/55707 for a concrete example of the cost
on a spinning disk).

Thoughts?

Ludo’.
M
M
Maxime Devos wrote on 4 Oct 2022 16:04
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 58035@debbugs.gnu.org)
6bd60f0b-ffac-dcc8-5225-df4b765522c5@telenet.be
On 04-10-2022 09:52, Ludovic Courtès wrote:
Toggle quote (18 lines)
> Hi,
>
> [...]
>> However, currently sync-before-registering is set to 'false' AFAICT.
>> I think this might be the cause of bugs like
>> <https://issues.guix.gnu.org/58013> (‘Can't use "guix pull"’), and
>> maybe <https://issues.guix.gnu.org/57838> (‘failing to boot, probably
>> due to guix gc’).
>
> It might be a factor, combined with the fact that the file system was
> not properly unmounted (power outage or similar).
>
> However, calling sync(2) for each store item is going to be expensive.
> Recursive fsync/fdatasync calls are also likely to be too expensive (see
> <https://issues.guix.gnu.org/55707> for a concrete example of the cost
> on a spinning disk).
>
> Thoughts?
Debian uses fsync (going by https://wiki.debian.org/Teams/Dpkg/FAQ),and
even though that according to that FAQ dpkg can be slow, in my
experience it wasn't too bad. Also, having to investigate store
corruption and how to fix it is a form of slowness, especially when it
fails or you don't have the technical expertise and consequentially you
need to reinstall (losing old non-back-upped work).
'sync' seems relatively inexpensive to me, compared to the time required
for building a package and even more inexpensive compared to the cost of
debugging store corruption:
antipode@antipode ~$ time sync
real 0m0,230s
user 0m0,004s
sys 0m0,047s
antipode@antipode ~$
antipode@antipode ~$ time sync
real 0m0,045s
user 0m0,003s
sys 0m0,014s
antipode@antipode ~$ time sync
real 0m0,044s
user 0m0,004s
sys 0m0,012s
Or, after a download:
$ time "guix build download"
real 0m50,681s
user 0m3,856s
sys 0m0,198s
$ sync
# I forgot to properly time this one, but < 0.5 sec
# Don't have numbers on the time required for debugging corruption.
(On a SSD)
Also, the situation is unlike 55707 -- we don't need to call 'fsync' or
'sync' after building each store item or writing each line of a store
item file, we only need to do it before registering it in the database
and returning it to the user -- in some sense, the 'fsync' can be done
sort-of asynchronuously.
For example, if "guix build" asks for foo.drv is built, and it depends
on bar.drv and baz.drv, then the daemon can build bar.drv, baz.drv and
'foo.drv' (without registering or fsyncing or registering in the database).
Once all the things are built, the daemon could then fsync the things,
and after the fsyncing completes, register things in the database -- on
the speed, I would like to note that:
(*) if the store items that were made were small, then fsync'ing them
should be pretty fast, as there isn't much to sync (at least in
theory, I think I read about some limitation in the ext3
implementation where 'fsync' is essentially 'sync' or something
like that? Don't know if that's still the case, though.)
(*) if the store items were sufficiently large (say, a bunch more than
Linux is willing to buffer), then at some point Linux will have
flushed most of them anyway. I don't have a clue what heuristics
it uses though (except for 'no more than there is free RAM :p)').
(*) In theory, if a file is already written to disk (implicitly as
part of some heuristic, or by an explicit 'fsync'), 'fsync'
should be about zero cost. Also, for a reasonable implementation
of 'fsync', I would expect the OS to take the opportunity to
write some other files as well (if the disk is seeking anyways,
it might might as well write some stuff while it's moving
to the right position and such).
(This requires changes to the daemon of course).
Another difference with 55707, is that the write/fsync pattern is very
different -- in 55707, it's like
write a small line (after waiting for the previous fsync to complete)
fsync the file
repeat very often
whereas with 'recursive fsync before registering (without other
changes)', it's like
write files (number and size varies)
recursive fsync the store item (note: as written elsewhere, the cost
of a recursive fsync should in theory be a lot less than the sum of the
fsync cost of an individual file, as the kernel likely takes the
opportunity to write some other stuff anyways)
wait for fsync to complete
repeat for the next store item (much less frequent than the previous
case (*))
and with 'recursive fsync before registering, and delay the registering
where possible':
write files for a store item
repeat for other store items
fsync the new files (good chance they were flushed to disk already
when the store items are large)
wait for fsync to complete
repeat with next call to "guix build" / "guix shell" ...
-- there should be much less frequent 'fsync' than in 55707, and the
'fsyncs' that are done would be mostly batched.
(*) I'm not considering things like the 'can compute derivation' linter
-- that linter would be in theory slowed down a lot, but I don't see a
reason why that linter would need a daemon to talk too.
Summarised, the main two points are that:
* the fsync can be delayed for a while
* there's a good chance that delayed fsyncs are done automatically
by the kernel in the background (making the explicit 'fsync'
of later mostly free)
* the total time for doing multiple fsyncs should be much less
than the sum of the times of doing individual fsyncs
(This is currently all theoretical)
Greetings,
Maxime.
Attachment: OpenPGP_signature
L
L
Ludovic Courtès wrote on 4 Oct 2022 23:49
(name . Maxime Devos)(address . maximedevos@telenet.be)(address . 58035@debbugs.gnu.org)
87zgebs1h5.fsf@gnu.org
Hi,

Maxime Devos <maximedevos@telenet.be> skribis:

Toggle quote (25 lines)
> On 04-10-2022 09:52, Ludovic Courtès wrote:
>> Hi,
>> [...]
>>> However, currently sync-before-registering is set to 'false' AFAICT.
>>> I think this might be the cause of bugs like
>>> <https://issues.guix.gnu.org/58013> (‘Can't use "guix pull"’), and
>>> maybe <https://issues.guix.gnu.org/57838> (‘failing to boot, probably
>>> due to guix gc’).
>> It might be a factor, combined with the fact that the file system
>> was
>> not properly unmounted (power outage or similar).
>> However, calling sync(2) for each store item is going to be
>> expensive.
>> Recursive fsync/fdatasync calls are also likely to be too expensive (see
>> <https://issues.guix.gnu.org/55707> for a concrete example of the cost
>> on a spinning disk).
>> Thoughts?
>
> Debian uses fsync (going by https://wiki.debian.org/Teams/Dpkg/FAQ),
> and even though that according to that FAQ dpkg can be slow, in my
> experience it wasn't too bad. Also, having to investigate store
> corruption and how to fix it is a form of slowness, especially when it
> fails or you don't have the technical expertise and consequentially
> you need to reinstall (losing old non-back-upped work).

Having not experience corruption issues as in the bug you mention, I’m
tempted to minimize the problem, but it’s true that we get such reports
from time to time.

Toggle quote (4 lines)
> 'sync' seems relatively inexpensive to me, compared to the time
> required for building a package and even more inexpensive compared to
> the cost of debugging store corruption:

That’s not a fair comparison. :-) Imagine, you run reconfigure/upgrade;
that downloads tens to hundreds of store items. Calling sync(2) after
each item may be hardly noticeably on an SSD, but I bet it’s going to be
super expensive on an HDD. (In the syslogd case, each fsync(2) call—not
even sync(2)—would cause pauses of several 100s of ms.)

Maybe a good test would be to run a daemon on an “average” HDD with
sync-before-registering = true and to run ‘perf timechart record’ while
it’s fetching a large number of substitutes. That way we’d have
concrete data to talk about.

Any takers? :-)

Ludo’.
M
M
Maxime Devos wrote on 5 Oct 2022 09:58
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 58035@debbugs.gnu.org)
d5501c08-2972-c12f-ea06-f1320c84aba4@telenet.be
On 04-10-2022 23:49, Ludovic Courtès wrote:
Toggle quote (9 lines)
> Hi,
>
> Maxime Devos <maximedevos@telenet.be> skribis:
>
>> 'sync' seems relatively inexpensive to me, compared to the time
>> required for building a package and even more inexpensive compared to
>> the cost of debugging store corruption:
>
> That’s not a fair comparison. :-)
Possibly, openjdk is a bit of an extreme case.
Toggle quote (5 lines)
> Imagine, you run reconfigure/upgrade;
> that downloads tens to hundreds of store items. Calling sync(2) after
> each item may be hardly noticeably on an SSD, but I bet it’s going to be
> super expensive on an HDD. (In the syslogd case, each fsync(2) call—not
> even sync(2)—would cause pauses of several 100s of ms.)
If after some testing, this turns out to be a problem, there are some
options to avoid this (see: the delaying 'fsync' of the previous response).
Toggle quote (6 lines)
> Maybe a good test would be to run a daemon on an “average” HDD with
> sync-before-registering = true and to run ‘perf timechart record’ while
> it’s fetching a large number of substitutes. That way we’d have
> concrete data to talk about.
>
> Any takers? :-)
I don't have a HDD to test sync-before-registering=true with.
Greetings,
Maxime.
Attachment: OpenPGP_signature
Z
Z
zimoun wrote on 5 Oct 2022 13:54
Re: [bug#58035] sync-before-registering is false, possibly the cause of empty files in the store
(address . 58035@debbugs.gnu.org)
86ilkyzdsl.fsf@gmail.com
Hi,

On Tue, 04 Oct 2022 at 23:49, Ludovic Courtès <ludo@gnu.org> wrote:

Toggle quote (5 lines)
> Maybe a good test would be to run a daemon on an “average” HDD with
> sync-before-registering = true and to run ‘perf timechart record’ while
> it’s fetching a large number of substitutes. That way we’d have
> concrete data to talk about.

What is ’perf timechart record’? I can take a look if no one beats me.



Cheers,
simon
L
L
Ludovic Courtès wrote on 7 Oct 2022 11:44
(name . zimoun)(address . zimon.toutoune@gmail.com)
87o7uoc6j2.fsf@gnu.org
zimoun <zimon.toutoune@gmail.com> skribis:

Toggle quote (9 lines)
> On Tue, 04 Oct 2022 at 23:49, Ludovic Courtès <ludo@gnu.org> wrote:
>
>> Maybe a good test would be to run a daemon on an “average” HDD with
>> sync-before-registering = true and to run ‘perf timechart record’ while
>> it’s fetching a large number of substitutes. That way we’d have
>> concrete data to talk about.
>
> What is ’perf timechart record’?

It’s a tool of Linux’s ‘perf’—see ‘guix install perf’.

HTH!

Ludo’.
Z
Z
zimoun wrote on 17 Oct 2022 20:03
(address . 58035@debbugs.gnu.org)
878rlel43z.fsf@gmail.com
Hi,

3x time slower with my hardware. Closing?


On mar., 04 oct. 2022 at 23:49, Ludovic Courtès <ludo@gnu.org> wrote:

Toggle quote (5 lines)
> Maybe a good test would be to run a daemon on an “average” HDD with
> sync-before-registering = true and to run ‘perf timechart record’ while
> it’s fetching a large number of substitutes. That way we’d have
> concrete data to talk about.

+ Comparison using the manifest below.
+ guix-daemon built using fd4cbcbed7; two flavors.
+ Guix revision f43a783.
+ Before the experiment, complete ’guix gc’.

# test-58035/guix-daemon --build-users-group=guixbuild
# perf timechart record
$ time guix build -m some-packages.scm
# perf timechart --highlight guix

1/ sync-before-registering = false

real 6m24.215s
user 0m10.627s
sys 0m0.512s

[ perf record: Woken up 1984 times to write data ]
[ perf record: Captured and wrote 497.403 MB perf.data (5042727 samples)]


2/ sync-before-registering = true

real 19m46.470s
user 0m12.367s
sys 0m0.557s

[ perf record: Woken up 2625 times to write data ]
[ perf record: Captured and wrote 658.066 MB perf.data (6712342 samples) ]


Well, the charts are really big.

$ du -sh {1,2}-build-*.svg
331M 1-build-false.svg
599M 2-build-true.svg

Therefore, please find them using this link (alive for 15 days):



Cheers,
simon


Toggle snippet (18 lines)
(use-modules (guix build-system haskell)
(guix build-system julia)
(guix packages)
(guix profiles)
(gnu packages))

(manifest
(map package->manifest-entry
(fold-packages
(lambda (package result)
(if (or
;;(eq? (package-build-system package) haskell-build-system)
(eq? (package-build-system package) julia-build-system))
(cons package result)
result))
'())))

Toggle snippet (14 lines)
diff --git a/nix/libstore/globals.cc b/nix/libstore/globals.cc
index d4f9a46a74..5f8a3a3031 100644
--- a/nix/libstore/globals.cc
+++ b/nix/libstore/globals.cc
@@ -40,7 +40,7 @@ Settings::Settings()
reservedSize = 8 * 1024 * 1024;
fsyncMetadata = true;
useSQLiteWAL = true;
- syncBeforeRegistering = false;
+ syncBeforeRegistering = true;
useSubstitutes = true;
useChroot = false;
impersonateLinux26 = false;
M
M
Maxime Devos wrote on 17 Oct 2022 20:51
(address . 58035@debbugs.gnu.org)
aa1f542d-9de6-41a0-4eec-2f4390950b7a@telenet.be
On 17-10-2022 20:03, zimoun wrote:
Toggle quote (1 lines)
> 3x time slower with my hardware. Closing?
I had an alternative proposal to 'sync-before-registering = true' --
more work to implement, but potentially faster, so IMO no.
Greetings,
Maxime.
Attachment: OpenPGP_signature
L
L
Ludovic Courtès wrote on 18 Oct 2022 17:34
(name . zimoun)(address . zimon.toutoune@gmail.com)
87sfjlkux0.fsf@gnu.org
Hi,

zimoun <zimon.toutoune@gmail.com> skribis:

Toggle quote (2 lines)
> 3x time slower with my hardware. Closing?

Ouch!

Toggle quote (17 lines)
> On mar., 04 oct. 2022 at 23:49, Ludovic Courtès <ludo@gnu.org> wrote:
>
>> Maybe a good test would be to run a daemon on an “average” HDD with
>> sync-before-registering = true and to run ‘perf timechart record’ while
>> it’s fetching a large number of substitutes. That way we’d have
>> concrete data to talk about.
>
> + Comparison using the manifest below.
> + guix-daemon built using fd4cbcbed7; two flavors.
> + Guix revision f43a783.
> + Before the experiment, complete ’guix gc’.
>
> # test-58035/guix-daemon --build-users-group=guixbuild
> # perf timechart record
> $ time guix build -m some-packages.scm
> # perf timechart --highlight guix

OK.

Toggle quote (19 lines)
> 1/ sync-before-registering = false
>
> real 6m24.215s
> user 0m10.627s
> sys 0m0.512s
>
> [ perf record: Woken up 1984 times to write data ]
> [ perf record: Captured and wrote 497.403 MB perf.data (5042727 samples)]
>
>
> 2/ sync-before-registering = true
>
> real 19m46.470s
> user 0m12.367s
> sys 0m0.557s
>
> [ perf record: Woken up 2625 times to write data ]
> [ perf record: Captured and wrote 658.066 MB perf.data (6712342 samples) ]

That speaks for itself.

Let’s keep the bug open in case Maxime or someone else comes up with a
more practical fix.

Thanks,
Ludo’.
C
C
Christopher Baines wrote on 3 Nov 2022 16:40
tag 58035 moreinfo
(address . control@debbugs.gnu.org)
87pme4xczc.fsf@cbaines.net
tags 58035 + moreinfo
quit
?