From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp0 ([2001:41d0:2:bcc0::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms0.migadu.com with LMTPS id UOb2GAe0RGHCbAEAgWs5BA (envelope-from ) for ; Fri, 17 Sep 2021 17:28:07 +0200 Received: from aspmx1.migadu.com ([2001:41d0:2:bcc0::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp0 with LMTPS id IN/SFAe0RGFkRAAA1q6Kng (envelope-from ) for ; Fri, 17 Sep 2021 15:28:07 +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 112E912D83 for ; Fri, 17 Sep 2021 17:28:07 +0200 (CEST) Received: from localhost ([::1]:49560 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mRFmY-0003YK-3S for larch@yhetil.org; Fri, 17 Sep 2021 11:28:06 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:51456) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mRFmU-0003Y8-Ke for guix-patches@gnu.org; Fri, 17 Sep 2021 11:28:02 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:49385) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1mRFmU-0003OS-Dj for guix-patches@gnu.org; Fri, 17 Sep 2021 11:28:02 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1mRFmU-0002iF-7x for guix-patches@gnu.org; Fri, 17 Sep 2021 11:28:02 -0400 X-Loop: help-debbugs@gnu.org Subject: [bug#50040] [PATCH 0/2] publish: Always render nar/narinfo during backing. Resent-From: Mathieu Othacehe Original-Sender: "Debbugs-submit" Resent-CC: guix-patches@gnu.org Resent-Date: Fri, 17 Sep 2021 15:28:02 +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: Ludovic =?UTF-8?Q?Court=C3=A8s?= Cc: 50040@debbugs.gnu.org Received: via spool by 50040-submit@debbugs.gnu.org id=B50040.163189243510372 (code B ref 50040); Fri, 17 Sep 2021 15:28:02 +0000 Received: (at 50040) by debbugs.gnu.org; 17 Sep 2021 15:27:15 +0000 Received: from localhost ([127.0.0.1]:60931 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mRFlj-0002hD-1y for submit@debbugs.gnu.org; Fri, 17 Sep 2021 11:27:15 -0400 Received: from eggs.gnu.org ([209.51.188.92]:34210) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mRFlh-0002h0-AE for 50040@debbugs.gnu.org; Fri, 17 Sep 2021 11:27:14 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:34450) by eggs.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mRFlb-0002bQ-Um; Fri, 17 Sep 2021 11:27:07 -0400 Received: from [178.250.34.74] (port=40814 helo=meije) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mRFlb-0005r7-DV; Fri, 17 Sep 2021 11:27:07 -0400 From: Mathieu Othacehe References: <20210813102800.805-1-othacehe@gnu.org> <87sfz2j5ls.fsf@gnu.org> <87r1eaa7gu.fsf_-_@gnu.org> <87tuix7qsw.fsf_-_@gnu.org> Date: Fri, 17 Sep 2021 17:27:04 +0200 In-Reply-To: <87tuix7qsw.fsf_-_@gnu.org> ("Ludovic =?UTF-8?Q?Court=C3=A8s?="'s message of "Mon, 06 Sep 2021 15:54:23 +0200") Message-ID: <87zgsbuss7.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=1631892487; 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=bcTj7VxwYswRQ4KAERRKi9HQTapQycCs9m0PzrO5Hm4=; b=gYEPrpSm2W3XwrjWLjFoFTOgIpcByw0K5QxLrKMjrBSy2umSm6pjLB/bIZmLlZ3ch/FjyB 1XpqLtjuzQiMXMK0JHEykELLQ04Ha1fJc/wFpgOJSAagkAIbL4uIvazcqPC9kcdREXNkch VDic89P33OL3EETX610XzixQN7bPOHjfF70rhQliVXBBvClewFVrbBwOO66KTsZpDXDrbn 0SMJ1yM6CwYp5Rnu4aZEcJWxKCqH8OHp+SwoUpRFe60sd2IqZwG2fhfj0LB/i+LGOGbMvx brSv3zinotR12LYkN7k9KA0NLLlaKybvHmqweq47uawWhj8yVUPhR74NQbzx9g== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1631892487; a=rsa-sha256; cv=none; b=pLFjaaekJXlPoyoWfJBYMxpzv2MfNLNawkn4II82gn19BohjOh5z8yih+IslITXt0UYS+f CzmrgFy7IcZzj7VcNtzSvhS16SK8YSc7cogH5A5wnjX1oTjjr9QfgPpewcGRuxBxPcYrx3 zM/5BP+MyMxG2IoEbxzXI82VWAvuQx7uuUoNJbcZ3Tk43mFVHTKpJKNwvl0Q/WWbws9qxY PX8hD+QW951Z1VTMx2exLxxImBagG5yg0YeuC2ZXpwf9cEz4Nxkj85iDiD8d00w3Uq47Zh KDhrczShJeeU/Q/aDbc9TWsArYmq2RJxuC6Xu0WN9vb3B4V3Yxy/4CfCARST/g== 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.90 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: 112E912D83 X-Spam-Score: -2.90 X-Migadu-Scanner: scn0.migadu.com X-TUID: /MfqxbRCuCUW Hey Ludo, > The =E2=80=98mumi worker=E2=80=99 process also seems to be doing a lot of= I/O and using > quite a bit of CPU (presumably allocating a lot). Its =E2=80=98perf=E2= =80=99 profile is > like this: > > 2.62% .mumi-real libguile-3.0.so.1.1.1 [.] scm_ilength > 1.20% .mumi-real libguile-3.0.so.1.1.1 [.] scm_getc > 1.12% .mumi-real libgc.so.1.4.3 [.] GC_add_to_black_list_nor= mal.part.4 > 1.06% .mumi-real libgc.so.1.4.3 [.] GC_build_fl > 0.98% .mumi-real libgc.so.1.4.3 [.] GC_reclaim_clear > 0.97% .mumi-real libguile-3.0.so.1.1.1 [.] get_callee_vcode > 0.91% .mumi-real libgc.so.1.4.3 [.] GC_generic_malloc_many > 0.90% .mumi-real libguile-3.0.so.1.1.1 [.] peek_byte_or_eof > 0.78% .mumi-real [JIT] tid 62601 [.] 0x00007f886964804d > > Food for thought=E2=80=A6 Yep, interesting findings, thanks for sharing. I just discovered that the Nginx server is logging in /var/log/nginx/error.log the errors we are interested in: --8<---------------cut here---------------start------------->8--- 2021/09/17 14:13:37 [error] 129925#0: *3727055 upstream timed out (110: Con= nection timed out) while reading response header from upstream, client: XXX= , server: ci.guix.gnu.org, request: "GET /3m1j4ddx11 prp6azw3rjdhljg5vchf1s.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/= 3m1j4ddx11prp6azw3rjdhljg5vchf1s.narinfo", host: "ci.guix.gnu.org" 2021/09/17 14:13:37 [error] 129925#0: *3727020 upstream timed out (110: Con= nection timed out) while reading response header from upstream, client: XXX= , server: ci.guix.gnu.org, request: "GET /pdhr7fgql3 qm1x24yxkj4c2f6s7vffi5.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/= pdhr7fgql3qm1x24yxkj4c2f6s7vffi5.narinfo", host: "ci.guix.gnu.org" 2021/09/17 14:13:37 [error] 129925#0: *3726717 upstream timed out (110: Con= nection timed out) while reading response header from upstream, client: XXX= , server: ci.guix.gnu.org, request: "GET /19gv6sq qcmn8q020bpm9jyl6n9bjpg05.narinfo HTTP/1.1", upstream: "http://127.0.0.1:30= 00/19gv6sqqcmn8q020bpm9jyl6n9bjpg05.narinfo", host: "ci.guix.gnu.org" 2021/09/17 14:13:37 [error] 129925#0: *3725361 upstream timed out (110: Con= nection timed out) while reading response header from upstream, client: 141= .80.167.169, server: ci.guix.gnu.org, request: "GET /y8dp69gk y4dn5vnn7wnx04j20q0yrdja.narinfo HTTP/1.1", upstream: "http://127.0.0.1:300= 0/y8dp69gky4dn5vnn7wnx04j20q0yrdja.narinfo", host: "141.80.167.131" --8<---------------cut here---------------end--------------->8--- Despite the following diff, extending the timeout delays to 10 seconds, we still have a lot of those errors. Some happening on the build farm (141.80.167.X), some directly on user machines. --8<---------------cut here---------------start------------->8--- diff --git a/hydra/nginx/berlin.scm b/hydra/nginx/berlin.scm index 44ff28e..7a085e5 100644 --- a/hydra/nginx/berlin.scm +++ b/hydra/nginx/berlin.scm @@ -97,9 +97,9 @@ =20 ;; Do not tolerate slowness of hydra.gnu.org when fetching ;; narinfos: better return 504 quickly than wait forever. - "proxy_connect_timeout 2s;" - "proxy_read_timeout 2s;" - "proxy_send_timeout 2s;" + "proxy_connect_timeout 10s;" + "proxy_read_timeout 10s;" + "proxy_send_timeout 10s;" --8<---------------cut here---------------end--------------->8--- I'll see if I can reproduce the I/O pressure on demand, to be able to have more accurate strace/perf investigations. Thanks, Mathieu