From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp1 ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms0.migadu.com with LMTPS id eJopHmlcLWFaEQEAgWs5BA (envelope-from ) for ; Tue, 31 Aug 2021 00:32:09 +0200 Received: from aspmx1.migadu.com ([2001:41d0:2:4a6f::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp1 with LMTPS id gL23GWlcLWEpBQAAbx9fmQ (envelope-from ) for ; Mon, 30 Aug 2021 22:32:09 +0000 Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by aspmx1.migadu.com (Postfix) with ESMTPS id 07FFA11E70 for ; Tue, 31 Aug 2021 00:32:09 +0200 (CEST) Received: from localhost ([::1]:53642 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mKpp2-00078n-26 for larch@yhetil.org; Mon, 30 Aug 2021 18:32:08 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:37686) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mKpow-00078a-3u for guix-patches@gnu.org; Mon, 30 Aug 2021 18:32:02 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:49024) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1mKpov-0002On-SA for guix-patches@gnu.org; Mon, 30 Aug 2021 18:32:01 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1mKpov-0003tv-Ok for guix-patches@gnu.org; Mon, 30 Aug 2021 18:32:01 -0400 X-Loop: help-debbugs@gnu.org Subject: [bug#50040] [PATCH 0/2] publish: Always render nar/narinfo during backing. Resent-From: Ludovic =?UTF-8?Q?Court=C3=A8s?= Original-Sender: "Debbugs-submit" Resent-CC: guix-patches@gnu.org Resent-Date: Mon, 30 Aug 2021 22:32:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 50040 X-GNU-PR-Package: guix-patches X-GNU-PR-Keywords: patch To: Mathieu Othacehe Cc: 50040@debbugs.gnu.org Received: via spool by 50040-submit@debbugs.gnu.org id=B50040.163036272114988 (code B ref 50040); Mon, 30 Aug 2021 22:32:01 +0000 Received: (at 50040) by debbugs.gnu.org; 30 Aug 2021 22:32:01 +0000 Received: from localhost ([127.0.0.1]:60570 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mKpou-0003tg-M9 for submit@debbugs.gnu.org; Mon, 30 Aug 2021 18:32:00 -0400 Received: from eggs.gnu.org ([209.51.188.92]:49786) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mKpoq-0003tN-VL for 50040@debbugs.gnu.org; Mon, 30 Aug 2021 18:31:59 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:36634) by eggs.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mKpol-0002IM-Om for 50040@debbugs.gnu.org; Mon, 30 Aug 2021 18:31:51 -0400 Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=48790 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mKpol-0005dJ-FU; Mon, 30 Aug 2021 18:31:51 -0400 From: Ludovic =?UTF-8?Q?Court=C3=A8s?= References: <20210813102800.805-1-othacehe@gnu.org> <20210813103030.1017-1-othacehe@gnu.org> Date: Tue, 31 Aug 2021 00:31:49 +0200 In-Reply-To: <20210813103030.1017-1-othacehe@gnu.org> (Mathieu Othacehe's message of "Fri, 13 Aug 2021 12:30:29 +0200") Message-ID: <87sfyqa7je.fsf_-_@gnu.org> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.2 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: guix-patches@gnu.org List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: guix-patches-bounces+larch=yhetil.org@gnu.org Sender: "Guix-patches" X-Migadu-Flow: FLOW_IN ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1630362729; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:cc:mime-version:mime-version: content-type:content-type: content-transfer-encoding:content-transfer-encoding:resent-cc: resent-from:resent-sender:resent-message-id:in-reply-to:in-reply-to: references:references:list-id:list-help:list-unsubscribe: list-subscribe:list-post; bh=hhyDnOPqGxoLtoUcV9ndvvG33mqVLWwlTdcDpCsx+v0=; b=OmqCIYKGZM4/s4J8JxdPzS2tJzKXKjc/bUKrv5QXU1c6J2FgH2G4mOJKEZpV3ulN2RLrzb PuP3MVYM1ENxxGcqzMSf/+dw1YIc1WWbUpURaVAszc+nlZG9/pip5pY7EvySyrvthXBHPa Lh4odqW5xdCHHDtv+Gawl4i/JJpZpQUgocki+3zSPi/mHTYZG1evlIIFDlqweEGVWqUxP8 GapbaM/eLrBI/acVkWHoLWYKIXIOq5z8uVNg/EPO2Mzsv3FqM9lLVUz58yUOPwBYLMXzue rub8agZwKVznnbTznoBV/XBNC56lFu6ve4rnCge08lsFcUNz4D3ZSpvgrx3ezA== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1630362729; a=rsa-sha256; cv=none; b=AD+v71PrFPyVybnYcYi/k0WYSqfzpy8qT1r1LxEVBEa/1YJImxSKCgcjeR42YEKHSf6A8r hBk0j+p85EX3oqtUiAbqPzClMaoOXYuFH1gi7LphQValBV1npJjTNMCMYJ5R/5WtCH+uW2 wtcYkX+OdfMHLFrDz2ijS/FQ+oPtC7c1vpPQrxa4E++05Je66WiaRrN0B0f9J2Pa9rx0WT gh1d19P/tGV4h6XwKPuJejcv5has4ypb98u6cY1XTHZFNdZRCXqoMU8FBrlZ0hHm12JixR 6JwaCpuRIpNv4TgEHAAeQRymNQ+rzpHPzOiU75f85uMpEU4+u/Imob9UF0D1sA== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=none; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of guix-patches-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=guix-patches-bounces@gnu.org X-Migadu-Spam-Score: -2.92 Authentication-Results: aspmx1.migadu.com; dkim=none; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of guix-patches-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=guix-patches-bounces@gnu.org X-Migadu-Queue-Id: 07FFA11E70 X-Spam-Score: -2.92 X-Migadu-Scanner: scn0.migadu.com X-TUID: X3bYWa+pWVRb Mathieu Othacehe 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=E2=80=99t fully understand where the performance problem comes from. =E2=80=98narinfo-string=E2=80=99 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 =3D #f scheme@(guix scripts publish)> (%private-key (read-file-sexp "tests/signing= -key.sec")) $9 =3D #f scheme@(guix scripts publish)> ,t (narinfo-string s "/gnu/store/0ff19dxsjvh= f4hjnw9ixlqpwdmwfpbyp-libreoffice-7.1.4.2") $11 =3D "StorePath: /gnu/store/0ff19dxsjvhf4hjnw9ixlqpwdmwfpbyp-libreoffice= -7.1.4.2\nURL: nar/0ff19dxsjvhf4hjnw9ixlqpwdmwfpbyp-libreoffice-7.1.4.2\nCo= mpression: none\nFileSize: 441389400\n[=E2=80=A6]" ;; 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 =E2=80=98narinfo-string=E2= =80=99 slow: 0. The store=E2=80=99s big GC lock is taken so RPCs don=E2=80=99t complet= e until it=E2=80=99s 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=E2=80=99s a correlation. 1. Contention on the daemon database (=E2=80=9Cdatabase is locked=E2=80= =9D) 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=E2=80=99s typical. = There could still be contention, but that doesn=E2=80=99t sound very likely. 2. It does I/O when it calls =E2=80=98read-derivation-from-file=E2=80=99.= Under high I/O load, that could be relatively expensive, though I=E2=80=99d expec= t it to be measured in tenths of a second at worst? But look, =E2=80=98read-derivation-from-file=E2=80=99 is called just t= o fill in the =E2=80=9CSystem=E2=80=9D field, which is not used anywhere (not a sing= le caller of =E2=80=98narinfo-system=E2=80=99), 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 =E2=80=98http-write=E2=80=99 hack isn=E2=80=99t great, but I think it= =E2=80=99s OK, unless we want to switch to Fibers. Ludo=E2=80=99.