GNU bug report logs - #42001
“SQLite database is busy”: contention on the store database

Please note: This is a static page, with minimal formatting, updated once a day.
Click here to see this page with the latest information and nicer formatting.

Package: guix; Severity: important; Reported by: Ludovic Courtès <ludo@HIDDEN>; dated Mon, 22 Jun 2020 11:50:01 UTC; Maintainer for guix is bug-guix@HIDDEN.

Message received at 42001 <at> debbugs.gnu.org:


Received: (at 42001) by debbugs.gnu.org; 23 Jun 2020 09:33:31 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Tue Jun 23 05:33:31 2020
Received: from localhost ([127.0.0.1]:35463 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1jnfJ1-0006Dk-An
	for submit <at> debbugs.gnu.org; Tue, 23 Jun 2020 05:33:31 -0400
Received: from eggs.gnu.org ([209.51.188.92]:45750)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <ludo@HIDDEN>) id 1jnfIy-0006DW-Af
 for 42001 <at> debbugs.gnu.org; Tue, 23 Jun 2020 05:33:26 -0400
Received: from fencepost.gnu.org ([2001:470:142:3::e]:58926)
 by eggs.gnu.org with esmtp (Exim 4.90_1)
 (envelope-from <ludo@HIDDEN>) id 1jnfIt-0001XH-2Q
 for 42001 <at> debbugs.gnu.org; Tue, 23 Jun 2020 05:33:19 -0400
Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=52832 helo=ribbon)
 by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256)
 (Exim 4.82) (envelope-from <ludo@HIDDEN>) id 1jnfIs-0006C6-Fu
 for 42001 <at> debbugs.gnu.org; Tue, 23 Jun 2020 05:33:18 -0400
From: =?utf-8?Q?Ludovic_Court=C3=A8s?= <ludo@HIDDEN>
To: 42001 <at> debbugs.gnu.org
Subject: Re: bug#42001: =?utf-8?Q?=E2=80=9CSQLite?= database is
 =?utf-8?Q?busy=E2=80=9D=3A?= contention on the store database
References: <877dvz7228.fsf@HIDDEN>
Date: Tue, 23 Jun 2020 11:33:17 +0200
In-Reply-To: <877dvz7228.fsf@HIDDEN> ("Ludovic
 \=\?utf-8\?Q\?Court\=C3\=A8s\=22'\?\=
 \=\?utf-8\?Q\?s\?\= message of "Mon, 22 Jun 2020 13:49:35 +0200")
Message-ID: <87sgem2kki.fsf@HIDDEN>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.3 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
X-Spam-Score: -2.3 (--)
X-Debbugs-Envelope-To: 42001
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -3.3 (---)

Ludovic Court=C3=A8s <ludo@HIDDEN> skribis:

> The are several possible causes of contention: (1) database opened too
> many times, (2) database kept opened for too long, and (3) sqlite
> mishandling contention somehow.

Commit fe5de925aa0f2854a679cebdea02b03cac561c8f should make
deduplication more efficient (it was an embarrassing bug=E2=80=A6), partly
addressing #2.

Ludo=E2=80=99.




Information forwarded to bug-guix@HIDDEN:
bug#42001; Package guix. Full text available.
Severity set to 'important' from 'normal' Request was from Ludovic Courtès <ludo@HIDDEN> to control <at> debbugs.gnu.org. Full text available.

Message received at 42001 <at> debbugs.gnu.org:


Received: (at 42001) by debbugs.gnu.org; 23 Jun 2020 07:42:11 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Tue Jun 23 03:42:11 2020
Received: from localhost ([127.0.0.1]:35385 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1jndZL-00015d-FC
	for submit <at> debbugs.gnu.org; Tue, 23 Jun 2020 03:42:11 -0400
Received: from eggs.gnu.org ([209.51.188.92]:54490)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <ludo@HIDDEN>) id 1jndZK-00015R-BI
 for 42001 <at> debbugs.gnu.org; Tue, 23 Jun 2020 03:42:10 -0400
Received: from fencepost.gnu.org ([2001:470:142:3::e]:57860)
 by eggs.gnu.org with esmtp (Exim 4.90_1)
 (envelope-from <ludo@HIDDEN>) id 1jndZF-0004Zj-2p
 for 42001 <at> debbugs.gnu.org; Tue, 23 Jun 2020 03:42:05 -0400
Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=52508 helo=ribbon)
 by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256)
 (Exim 4.82) (envelope-from <ludo@HIDDEN>)
 id 1jndZD-0006sb-K4; Tue, 23 Jun 2020 03:42:04 -0400
From: =?utf-8?Q?Ludovic_Court=C3=A8s?= <ludo@HIDDEN>
To: Mathieu Othacehe <othacehe@HIDDEN>
Subject: Re: bug#42001: =?utf-8?Q?=E2=80=9CSQLite?= database is
 =?utf-8?Q?busy=E2=80=9D=3A?= contention on the store database
References: <877dvz7228.fsf@HIDDEN> <87pn9rdr8r.fsf@HIDDEN>
X-URL: http://www.fdn.fr/~lcourtes/
X-Revolutionary-Date: 6 Messidor an 228 de la =?utf-8?Q?R=C3=A9volution?=
X-PGP-Key-ID: 0x090B11993D9AEBB5
X-PGP-Key: http://www.fdn.fr/~lcourtes/ludovic.asc
X-PGP-Fingerprint: 3CE4 6455 8A84 FDC6 9DB4  0CFB 090B 1199 3D9A EBB5
X-OS: x86_64-pc-linux-gnu
Date: Tue, 23 Jun 2020 09:42:02 +0200
In-Reply-To: <87pn9rdr8r.fsf@HIDDEN> (Mathieu Othacehe's message of "Mon, 22
 Jun 2020 18:01:24 +0200")
Message-ID: <87y2oe44ad.fsf@HIDDEN>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.3 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
X-Spam-Score: -2.3 (--)
X-Debbugs-Envelope-To: 42001
Cc: 42001 <at> debbugs.gnu.org
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -3.3 (---)

Hi,

Mathieu Othacehe <othacehe@HIDDEN> skribis:

>> utimensat(AT_FDCWD, "/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-r=
oot/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-g=
nu/kernel/net/netfilter", [{tv_sec=3D1592814617, tv_nsec=3D396083395} /* 20=
20-06-22T10:30:17.396083395+0200 */, {tv_sec=3D1, tv_nsec=3D0} /* 1970-01-0=
1T01:00:01+0100 */], 0) =3D 0
>> chmod("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/=
n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/=
netfilter", 040555) =3D 0
>> getrusage(RUSAGE_SELF, {ru_utime=3D{tv_sec=3D1306, tv_usec=3D334062}, ru=
_stime=3D{tv_sec=3D143, tv_usec=3D819675}, ...}) =3D 0
>> clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=3D1450, tv_nsec=3D153748=
295}) =3D 0=20
>> lstat("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/=
n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/=
netfilter/xt_connlimit.ko", {st_mode=3DS_IFLNK|0777, st_size=3D125, ...}) =
=3D 0
>
> As discussed on IRC, those "image-root" derivations do exercise store
> deduplication a lot, are could participate to the observed database
> contention.
>
> Turns out I used those derivations as "staging" directories that are
> passed to GNU Xorriso when producing ISO images and "mke2fs" and
> "mkdosfs" when producing raw disk-images. Using the store was also
> convenient to ensure root ownership of the image files.
>
> With 1cb9effc3e875ec7bae31bb06069d16ac89f7e1d and
> 7f75a7ec08975eb6d6e01db61bd6b91f447f655e, I remove those "image-root"
> derivations, and proceed to image creation in a single derivation.

Nice, thanks for the prompt change!

I=E2=80=99ve been monitoring berlin a bit and I=E2=80=99ve become quite con=
vinced that
these big directories are what triggered contention.  The good thing is
that this has allowed us to find weaknesses in (guix store database) and
(guix store deduplicate).

> The later commit is a bit more tricky because "mke2fs" is not able to
> override file permissions. I used "fakeroot" to make sure that the raw
> disk-image files are owned by "root" and not "guixbuilder".

OK, makes sense.

Maybe at some point we=E2=80=99ll have to use libext2fs directly or patch m=
ke2fs
to get the desired flexibility.

Thank you!

Ludo=E2=80=99.




Information forwarded to bug-guix@HIDDEN:
bug#42001; Package guix. Full text available.

Message received at 42001 <at> debbugs.gnu.org:


Received: (at 42001) by debbugs.gnu.org; 22 Jun 2020 16:01:38 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Mon Jun 22 12:01:38 2020
Received: from localhost ([127.0.0.1]:34367 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1jnOt8-00039v-Is
	for submit <at> debbugs.gnu.org; Mon, 22 Jun 2020 12:01:38 -0400
Received: from eggs.gnu.org ([209.51.188.92]:50072)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <othacehe@HIDDEN>) id 1jnOt5-00039f-MX
 for 42001 <at> debbugs.gnu.org; Mon, 22 Jun 2020 12:01:37 -0400
Received: from fencepost.gnu.org ([2001:470:142:3::e]:44247)
 by eggs.gnu.org with esmtp (Exim 4.90_1)
 (envelope-from <othacehe@HIDDEN>)
 id 1jnOsz-0007hA-I3; Mon, 22 Jun 2020 12:01:29 -0400
Received: from lfbn-ann-1-136-86.w86-200.abo.wanadoo.fr ([86.200.104.86]:40856
 helo=meru)
 by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256)
 (Exim 4.82) (envelope-from <othacehe@HIDDEN>)
 id 1jnOsy-0001dh-GQ; Mon, 22 Jun 2020 12:01:29 -0400
From: Mathieu Othacehe <othacehe@HIDDEN>
To: Ludovic =?utf-8?Q?Court=C3=A8s?= <ludo@HIDDEN>
Subject: Re: bug#42001: =?utf-8?Q?=E2=80=9CSQLite?= database is
 =?utf-8?Q?busy=E2=80=9D=3A?= contention on the store database
References: <877dvz7228.fsf@HIDDEN>
Date: Mon, 22 Jun 2020 18:01:24 +0200
In-Reply-To: <877dvz7228.fsf@HIDDEN> ("Ludovic
 \=\?utf-8\?Q\?Court\=C3\=A8s\=22'\?\=
 \=\?utf-8\?Q\?s\?\= message of "Mon, 22 Jun 2020 13:49:35 +0200")
Message-ID: <87pn9rdr8r.fsf@HIDDEN>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.3 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain
X-Spam-Score: -2.3 (--)
X-Debbugs-Envelope-To: 42001
Cc: 42001 <at> debbugs.gnu.org
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -3.3 (---)


Hey Ludo,

> utimensat(AT_FDCWD, "/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter", [{tv_sec=1592814617, tv_nsec=396083395} /* 2020-06-22T10:30:17.396083395+0200 */, {tv_sec=1, tv_nsec=0} /* 1970-01-01T01:00:01+0100 */], 0) = 0
> chmod("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter", 040555) = 0
> getrusage(RUSAGE_SELF, {ru_utime={tv_sec=1306, tv_usec=334062}, ru_stime={tv_sec=143, tv_usec=819675}, ...}) = 0
> clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=1450, tv_nsec=153748295}) = 0 
> lstat("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/netfilter/xt_connlimit.ko", {st_mode=S_IFLNK|0777, st_size=125, ...}) = 0

As discussed on IRC, those "image-root" derivations do exercise store
deduplication a lot, are could participate to the observed database
contention.

Turns out I used those derivations as "staging" directories that are
passed to GNU Xorriso when producing ISO images and "mke2fs" and
"mkdosfs" when producing raw disk-images. Using the store was also
convenient to ensure root ownership of the image files.

With 1cb9effc3e875ec7bae31bb06069d16ac89f7e1d and
7f75a7ec08975eb6d6e01db61bd6b91f447f655e, I remove those "image-root"
derivations, and proceed to image creation in a single derivation.

The later commit is a bit more tricky because "mke2fs" is not able to
override file permissions. I used "fakeroot" to make sure that the raw
disk-image files are owned by "root" and not "guixbuilder".

Hoping it will help,

Mathieu




Information forwarded to bug-guix@HIDDEN:
bug#42001; Package guix. Full text available.

Message received at submit <at> debbugs.gnu.org:


Received: (at submit) by debbugs.gnu.org; 22 Jun 2020 11:49:45 +0000
From debbugs-submit-bounces <at> debbugs.gnu.org Mon Jun 22 07:49:45 2020
Received: from localhost ([127.0.0.1]:33397 helo=debbugs.gnu.org)
	by debbugs.gnu.org with esmtp (Exim 4.84_2)
	(envelope-from <debbugs-submit-bounces <at> debbugs.gnu.org>)
	id 1jnKxM-0004va-Qa
	for submit <at> debbugs.gnu.org; Mon, 22 Jun 2020 07:49:45 -0400
Received: from lists.gnu.org ([209.51.188.17]:48372)
 by debbugs.gnu.org with esmtp (Exim 4.84_2)
 (envelope-from <ludo@HIDDEN>) id 1jnKxI-0004vM-UZ
 for submit <at> debbugs.gnu.org; Mon, 22 Jun 2020 07:49:43 -0400
Received: from eggs.gnu.org ([2001:470:142:3::10]:51724)
 by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
 (Exim 4.90_1) (envelope-from <ludo@HIDDEN>) id 1jnKxI-0005C2-0n
 for bug-guix@HIDDEN; Mon, 22 Jun 2020 07:49:40 -0400
Received: from fencepost.gnu.org ([2001:470:142:3::e]:40147)
 by eggs.gnu.org with esmtp (Exim 4.90_1)
 (envelope-from <ludo@HIDDEN>) id 1jnKxH-0003P1-OQ
 for bug-guix@HIDDEN; Mon, 22 Jun 2020 07:49:39 -0400
Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=48038 helo=ribbon)
 by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256)
 (Exim 4.82) (envelope-from <ludo@HIDDEN>) id 1jnKxF-0006OQ-SN
 for bug-guix@HIDDEN; Mon, 22 Jun 2020 07:49:39 -0400
From: =?utf-8?Q?Ludovic_Court=C3=A8s?= <ludo@HIDDEN>
To: <bug-guix@HIDDEN>
Subject: =?utf-8?Q?=E2=80=9CSQLite?= database is =?utf-8?Q?busy=E2=80=9D?=
 =?utf-8?Q?=3A?= contention on the store database
X-URL: http://www.fdn.fr/~lcourtes/
X-Revolutionary-Date: 5 Messidor an 228 de la =?utf-8?Q?R=C3=A9volution?=
X-PGP-Key-ID: 0x090B11993D9AEBB5
X-PGP-Key: http://www.fdn.fr/~lcourtes/ludovic.asc
X-PGP-Fingerprint: 3CE4 6455 8A84 FDC6 9DB4  0CFB 090B 1199 3D9A EBB5
X-OS: x86_64-pc-linux-gnu
Date: Mon, 22 Jun 2020 13:49:35 +0200
Message-ID: <877dvz7228.fsf@HIDDEN>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.3 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
X-Spam-Score: -2.3 (--)
X-Debbugs-Envelope-To: submit
X-BeenThere: debbugs-submit <at> debbugs.gnu.org
X-Mailman-Version: 2.1.18
Precedence: list
List-Id: <debbugs-submit.debbugs.gnu.org>
List-Unsubscribe: <https://debbugs.gnu.org/cgi-bin/mailman/options/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=unsubscribe>
List-Archive: <https://debbugs.gnu.org/cgi-bin/mailman/private/debbugs-submit/>
List-Post: <mailto:debbugs-submit <at> debbugs.gnu.org>
List-Help: <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=help>
List-Subscribe: <https://debbugs.gnu.org/cgi-bin/mailman/listinfo/debbugs-submit>, 
 <mailto:debbugs-submit-request <at> debbugs.gnu.org?subject=subscribe>
Errors-To: debbugs-submit-bounces <at> debbugs.gnu.org
Sender: "Debbugs-submit" <debbugs-submit-bounces <at> debbugs.gnu.org>
X-Spam-Score: -3.3 (---)

Hi,

On berlin.guix.gnu.org, we=E2=80=99ve seen a lot of contention on the store
database for a month or so, with messages like:

  warning: SQLite database is busy

More often than not, everything slows down to a halt, and builds don=E2=80=
=99t
proceed.

We initially discussed it here:

  https://issues.guix.gnu.org/41119#4

When that happens we typically see 30+ processes that have opened the
database:

--8<---------------cut here---------------start------------->8---
ludo@berlin ~$ sudo fuser -v /var/guix/db/db.sqlite-shm=20
                     USER        PID ACCESS COMMAND
/var/guix/db/db.sqlite-shm:
                     root       1211 F...m guix offload
                     root       1845 F...m guix-daemon
                     root       6070 F...m guix-daemon
                     root      31378 F...m guix-daemon
                     root      31380 F...m guix-daemon
                     root      47381 F...m guix-daemon
                     root      47382 F...m guix-daemon
                     root      47383 F...m guix-daemon
                     root      47385 F...m guix-daemon
                     root      47681 F...m guix-daemon
                     root      48506 F...m guix offload
                     root      48542 F...m guix offload
                     root      49417 F...m guix-daemon
                     root      49472 F...m guix-daemon
                     root      49971 F...m guix-daemon
                     root      50027 F...m guix-daemon
                     root      50847 F...m guix offload
                     root      54625 F...m guix-daemon
                     root      54723 F...m guix-daemon
                     root      55470 F...m guix-daemon
                     root      55614 F...m guix-daemon
                     root      55617 F...m guix-daemon
                     root      56225 F...m guix-daemon
                     root      57732 F...m guix-daemon
                     root      57733 F...m guix-daemon
                     root      57738 F...m guix-daemon
                     root      57739 F...m guix-daemon
                     root      57740 F...m guix-daemon
                     root      58772 F...m guix-daemon
                     root      59056 F...m guix-daemon
                     root      99055 F...m guix-daemon
                     root      127690 F...m guix offload
--8<---------------cut here---------------end--------------->8---

In this case, the first process seems to be in the deduplication phase
in =E2=80=98finalize-store-file=E2=80=99:

--8<---------------cut here---------------start------------->8---
ludo@berlin ~$ sudo strace -p 1211
strace: Process 1211 attached
utimensat(AT_FDCWD, "/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root=
/gnu/store/n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/=
kernel/net/netfilter", [{tv_sec=3D1592814617, tv_nsec=3D396083395} /* 2020-=
06-22T10:30:17.396083395+0200 */, {tv_sec=3D1, tv_nsec=3D0} /* 1970-01-01T0=
1:00:01+0100 */], 0) =3D 0
chmod("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l=
40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/net=
filter", 040555) =3D 0
getrusage(RUSAGE_SELF, {ru_utime=3D{tv_sec=3D1306, tv_usec=3D334062}, ru_st=
ime=3D{tv_sec=3D143, tv_usec=3D819675}, ...}) =3D 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=3D1450, tv_nsec=3D153748295=
}) =3D 0=20
lstat("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l=
40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/net=
filter/xt_connlimit.ko", {st_mode=3DS_IFLNK|0777, st_size=3D125, ...}) =3D 0
readlink("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/=
n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/=
netfilter/xt_connlimit.ko", "/gnu/store/x8d1hmv17jawp4a7nwwb4"..., 100) =3D=
 100
readlink("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/=
n6l40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/=
netfilter/xt_connlimit.ko", "/gnu/store/x8d1hmv17jawp4a7nwwb4"..., 200) =3D=
 125
mkdir("/gnu", 0777)                     =3D -1 EEXIST (File exists)
mkdir("/gnu/store", 0777)               =3D -1 EEXIST (File exists)
mkdir("/gnu/store/.links", 0777)        =3D -1 EEXIST (File exists)
lstat("/gnu/store/whhc80cx1zpi9cj3bil3sp8wwzcf8p9p-image-root/gnu/store/n6l=
40ygclxfysnc2nxwrslnn5ab6wv3v-profile/lib/modules/5.4.47-gnu/kernel/net/net=
filter/xt_connlimit.ko", {st_mode=3DS_IFLNK|0777, st_size=3D125, ...}) =3D 0
stat("/gnu/store/.links/05p6zpj56f00g07c3621747kz3bjc6zbr8bgg8xysdajq18qgvl=
v", {st_mode=3DS_IFREG|0444, st_size=3D6880, ...}) =3D 0
--8<---------------cut here---------------end--------------->8---

At that point it has the database opened 3 times: once from
=E2=80=98with-temporary-store-file=E2=80=99, once =E2=80=98with-database=E2=
=80=99 in
=E2=80=98finalize-store-file=E2=80=99, and once from =E2=80=98register-item=
s=E2=80=99 in
=E2=80=98finalize-store-file=E2=80=99.  Commit d7fb5538013710288e91657499f0=
e04207115776
removed the last one.

--8<---------------cut here---------------start------------->8---
ludo@berlin ~$ sudo ls -l /proc/1211/fd
total 0
lr-x------ 1 root root 64 Jun 22 11:49 0 -> 'pipe:[10239344]'
l-wx------ 1 root root 64 Jun 22 11:49 1 -> 'pipe:[10239343]'
lr-x------ 1 root root 64 Jun 22 11:49 10 -> 'pipe:[10129708]'
l-wx------ 1 root root 64 Jun 22 11:49 11 -> 'pipe:[10129708]'
lr-x------ 1 root root 64 Jun 22 11:49 12 -> 'pipe:[10214031]'
l-wx------ 1 root root 64 Jun 22 11:49 13 -> 'pipe:[10214031]'
l-wx------ 1 root root 64 Jun 22 11:49 14 -> /var/guix/offload/141.80.167.1=
68:22/1
lrwx------ 1 root root 64 Jun 22 11:49 15 -> 'socket:[8056368]'
lrwx------ 1 root root 64 Jun 22 11:49 16 -> 'socket:[10433466]'
lrwx------ 1 root root 64 Jun 22 11:49 17 -> /var/guix/db/db.sqlite
lrwx------ 1 root root 64 Jun 22 11:49 18 -> /var/guix/db/db.sqlite-wal
lrwx------ 1 root root 64 Jun 22 11:49 19 -> /var/guix/db/db.sqlite-shm
l-wx------ 1 root root 64 Jun 22 11:49 2 -> 'pipe:[10239343]'
lrwx------ 1 root root 64 Jun 22 11:49 20 -> /var/guix/db/db.sqlite
lrwx------ 1 root root 64 Jun 22 11:49 21 -> /var/guix/db/db.sqlite-wal
lr-x------ 1 root root 64 Jun 22 11:49 3 -> 'pipe:[10021329]'
l-wx------ 1 root root 64 Jun 22 11:49 4 -> 'pipe:[10239345]'
lr-x------ 1 root root 64 Jun 22 11:49 40 -> /dev/urandom
l-wx------ 1 root root 64 Jun 22 11:49 5 -> 'pipe:[10021329]'
lr-x------ 1 root root 64 Jun 22 11:49 6 -> 'pipe:[10222125]'
l-wx------ 1 root root 64 Jun 22 11:49 7 -> 'pipe:[10222125]'
lr-x------ 1 root root 64 Jun 22 11:49 8 -> 'pipe:[10021332]'
l-wx------ 1 root root 64 Jun 22 11:49 9 -> 'pipe:[10021332]'
--8<---------------cut here---------------end--------------->8---

The are several possible causes of contention: (1) database opened too
many times, (2) database kept opened for too long, and (3) sqlite
mishandling contention somehow.

I think we can work on #1 and #2.  As for #3, I wonder if there=E2=80=99s a
change in sqlite that could have made contention more contentious (ah
ha!), given that all this happened around the time of the last
=E2=80=98core-updates=E2=80=99 merge, roughly corresponding to an upgrade f=
rom 3.24.0 to
3.31.0:

  http://data.guix.gnu.org/repository/1/branch/master/package/sqlite

Maybe the most likely change that caused contention is that we increased
the number of machines (or rather the sum of build jobs that can be
handled by the build machines), and thus the number of parallel build
processes.

Ludo=E2=80=99.




Acknowledgement sent to Ludovic Courtès <ludo@HIDDEN>:
New bug report received and forwarded. Copy sent to bug-guix@HIDDEN. Full text available.
Report forwarded to bug-guix@HIDDEN:
bug#42001; Package guix. Full text available.
Please note: This is a static page, with minimal formatting, updated once a day.
Click here to see this page with the latest information and nicer formatting.
Last modified: Tue, 23 Jun 2020 09:45:01 UTC

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