From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp0 ([2001:41d0:2:c151::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms11 with LMTPS id EACiLw5cVmBxUAAA0tVLHw (envelope-from ) for ; Sat, 20 Mar 2021 20:33:18 +0000 Received: from aspmx2.migadu.com ([2001:41d0:2:c151::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp0 with LMTPS id cUGHKw5cVmCVFgAA1q6Kng (envelope-from ) for ; Sat, 20 Mar 2021 20:33:18 +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 aspmx2.migadu.com (Postfix) with ESMTPS id 45661C20E for ; Sat, 20 Mar 2021 21:33:18 +0100 (CET) Received: from localhost ([::1]:49130 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1lNiHd-000587-G6 for larch@yhetil.org; Sat, 20 Mar 2021 16:33:17 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:57332) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1lNiHN-00057u-St for bug-guix@gnu.org; Sat, 20 Mar 2021 16:33:01 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:41634) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1lNiHN-0002Qq-Kq for bug-guix@gnu.org; Sat, 20 Mar 2021 16:33:01 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1lNiHN-0001LF-I1 for bug-guix@gnu.org; Sat, 20 Mar 2021 16:33:01 -0400 X-Loop: help-debbugs@gnu.org Subject: bug#47283: Performance regression in narinfo fetching Resent-From: Christopher Baines Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Sat, 20 Mar 2021 20:33:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 47283 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: Ludovic =?UTF-8?Q?Court=C3=A8s?= Received: via spool by 47283-submit@debbugs.gnu.org id=B47283.16162723625130 (code B ref 47283); Sat, 20 Mar 2021 20:33:01 +0000 Received: (at 47283) by debbugs.gnu.org; 20 Mar 2021 20:32:42 +0000 Received: from localhost ([127.0.0.1]:53180 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1lNiH3-0001Kg-KP for submit@debbugs.gnu.org; Sat, 20 Mar 2021 16:32:41 -0400 Received: from mira.cbaines.net ([212.71.252.8]:59174) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1lNiH0-0001KX-Qd for 47283@debbugs.gnu.org; Sat, 20 Mar 2021 16:32:39 -0400 Received: from localhost (unknown [IPv6:2a02:8010:68c1:0:8ac0:b4c7:f5c8:7caa]) by mira.cbaines.net (Postfix) with ESMTPSA id DCF3727BC57; Sat, 20 Mar 2021 20:32:37 +0000 (GMT) Received: from capella (localhost [127.0.0.1]) by localhost (OpenSMTPD) with ESMTP id 411e1e2a; Sat, 20 Mar 2021 20:32:37 +0000 (UTC) References: <87ft0p67z4.fsf@inria.fr> User-agent: mu4e 1.4.15; emacs 27.1 From: Christopher Baines In-reply-to: <87ft0p67z4.fsf@inria.fr> Date: Sat, 20 Mar 2021 20:32:35 +0000 Message-ID: <874kh5d0rg.fsf@cbaines.net> MIME-Version: 1.0 Content-Type: multipart/signed; boundary="=-=-="; micalg=pgp-sha512; protocol="application/pgp-signature" X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: bug-guix@gnu.org List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: 47283@debbugs.gnu.org Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: "bug-Guix" X-Migadu-Flow: FLOW_IN ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1616272398; 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: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=1NkIzxxegMj77sdxOFstssA11puSJhAfK2xHecnA0qU=; b=Ittou43IrQTj6O5TZZzl3TISjsX9m2CoMrNv+shGJeQvY9sWOkXXOvDtnuv8e649l3wZcL +P6yJoccKr29TYogyP8je2rKeCeu3BrvkRL/6V+1E4XsfeAVdF7ekuECOO8LOAK7WaWSqE LPnYMp1twngWrL1mtkBsbTEFhmeM8/LTFE0EY0ofjDO7BCSww+v6Fr665zMjzYtK8kIzAY yoBAQ2YK6B6M+iG5WoP6VLBOcelD0tDpYc/i1oQXAB3n6no60SV3eyUVG90kuMTkT2f6aw WjtkzZE7PDk3NGA7VdAT/Q4Ww/PPMY4lev5Vzu18ZK/GEBgsu7aA3ZcIlbyHcQ== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1616272398; a=rsa-sha256; cv=none; b=g1fdpnhiN3l0m/oVC2X9OmMq2V9hjH6NXsCLwZBGkYSV5mSqXP4ym0Gx1Fcq5av7savvkb YpkBOjoUtGKxqAso9WidcJpAlW/uBypMyPeuXiXOiKT9dZLIyACShhS8PIslro4b5spF8C zk31uaFb0m8tXFKfDAWOYEMecxoZJCRc0cq7Yf3O4PFyM7aA1wRP1dl3yQrF5oztmwVHoI OAlGu7RbOjXv8sxT2M9q2z5WWJLPH7ATpUkZ81CKT7N933HtDqdSm15P3+e4Al2iDl4Jfy HlRbUBnT9y1K4erZh3kbuKLzND1ZDrL83TvICmAmfH67V9aqQNdApHG/T21qYg== ARC-Authentication-Results: i=1; aspmx2.migadu.com; dkim=none; spf=pass (aspmx2.migadu.com: domain of bug-guix-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=bug-guix-bounces@gnu.org X-Migadu-Spam-Score: -4.51 Authentication-Results: aspmx2.migadu.com; dkim=none; dmarc=none; spf=pass (aspmx2.migadu.com: domain of bug-guix-bounces@gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=bug-guix-bounces@gnu.org X-Migadu-Queue-Id: 45661C20E X-Spam-Score: -4.51 X-Migadu-Scanner: scn0.migadu.com X-TUID: mQngSYq2AOZ9 --=-=-= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Ludovic Court=C3=A8s writes: > As reported on guix-devel, =E2=80=98guix weather=E2=80=99 has become extr= emely slow. > Specifically, in the narinfo-fetching phase, it runs at 100% CPU, even > though that part should be network-bound (pipelined HTTP GETs). > > A profile of the =E2=80=98report-server-coverage=E2=80=99 call would show= this: > > --8<---------------cut here---------------start------------->8--- > % cumulative self=20=20=20=20=20=20=20=20=20=20=20=20=20 > time seconds seconds procedure > 62.50 1.06 1.06 fluid-ref* > 6.25 0.11 0.11 regexp-exec > 3.13 0.05 0.05 ice-9/boot-9.scm:1738:4:throw > 2.08 0.04 0.04 string-index > 2.08 0.04 0.04 write > 1.04 568.08 0.02 ice-9/boot-9.scm:1673:4:with-exception-handler > 1.04 0.02 0.02 %read-line > 1.04 0.02 0.02 guix/ci.scm:78:0:json->build > 1.04 0.02 0.02 string-append > --8<---------------cut here---------------end--------------->8--- > > More than half of the time spent in =E2=80=98fluid-ref*=E2=80=99=E2=80=94= sounds fishy. > > Where does that that call come from? There seems to be a single caller, > in boot-9.scm: > > (define* (raise-exception exn #:key (continuable? #f)) > (define (capture-current-exception-handlers) > ;; FIXME: This is quadratic. > (let lp ((depth 0)) > (let ((h (fluid-ref* %exception-handler depth))) > (if h > (cons h (lp (1+ depth))) > (list fallback-exception-handler))))) > ;; =E2=80=A6 > ) > > We must be abusing exceptions somewhere=E2=80=A6 > > Indeed, there=E2=80=99s one place on the hot path where we install except= ion > handlers: in =E2=80=98http-multiple-get=E2=80=99 (from commit > 205833b72c5517915a47a50dbe28e7024dc74e57). I don=E2=80=99t think it=E2= =80=99s needed, > is it? (But if it is, let=E2=80=99s find another approach, this one is > prohibitively expensive.) I think the exception handling has moved around, but I guess the exceptions that could be caught in http-multiple-get could happen, right? I am really just guessing here, as Guile doesn't help tell you about possible exceptions, and I haven't spent enough time to read all the possible code involved to find out if these are definitely possible. > A simple performance test is: > > rm -rf ~/.cache/guix/substitute/ > time ./pre-inst-env guix weather $(guix package -A|head -500| cut -f1) > > After removing this =E2=80=98catch=E2=80=99 in =E2=80=98http-multiple-get= =E2=80=99, the profile is > flatter: > > --8<---------------cut here---------------start------------->8--- > % cumulative self > time seconds seconds procedure > 8.33 0.07 0.07 string-index > 8.33 0.07 0.07 regexp-exec > 5.56 0.05 0.05 anon #x154af88 > 5.56 0.05 0.05 write > 5.56 0.05 0.05 string-tokenize > 5.56 0.05 0.05 read-char > 5.56 0.05 0.05 set-certificate-credentials-x509-trust-data! > 5.56 0.05 0.05 %read-line > --8<---------------cut here---------------end--------------->8--- > > There=E2=80=99s also this =E2=80=98call-with-connection-error-handling=E2= =80=99 call in (guix > substitute), around an =E2=80=98http-multiple-get=E2=80=99 call, that may= not be > justified. > > Attached is a diff of the tweaks I made to test this. > > WDYT, Chris? I haven't looked in to this yet, but maybe it would be possible to adjust the code so that it doesn't perform so badly, but still tries to handle possible exceptions. The two ideas I have is to rewrite the (let ...) bit in terms of a fold, maybe that would perform better, or stop using let for iteration and setup the exception handling, then process each request, using set! to update the state. I haven't tested either of these. It's good to know that Guile exception handling can be excessively expensive though, I wouldn't have expected it to beat out anything over the network in terms of the performance penalty. --=-=-= Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQKlBAEBCgCPFiEEPonu50WOcg2XVOCyXiijOwuE9XcFAmBWW+NfFIAAAAAALgAo aXNzdWVyLWZwckBub3RhdGlvbnMub3BlbnBncC5maWZ0aGhvcnNlbWFuLm5ldDNF ODlFRUU3NDU4RTcyMEQ5NzU0RTBCMjVFMjhBMzNCMEI4NEY1NzcRHG1haWxAY2Jh aW5lcy5uZXQACgkQXiijOwuE9Xenow//RkiKPMtSiWGvnn/tEVC1d+o/4tK/SrKy L5QbyF9k/oOCsCGWyZKlgFhrjctcoYs3He4KY9T8ba2xy3YHN3m5Xm9aZcTS7fgH 8AwjiMZ/Edw+qF55+wXYcxGF8ch8SfMib3rRnBH5K0yhQ1KH2wZzDTCp8MdBfMzl 5PwMbhLpKTlNW82ZuGqDGj50/Ca5QMg4XRr7r1ACQR4W8ee0VilF1K/Kp7QTT0B7 ikwOLvxaqsVwlSo7Kyvu3FIiSeIlWXFRjSTtAUSEtBzREoyp+oh+7YGWJ4buaz5x WAl0/cfs6Blf5Y9MrEaCkHV0kvHzknelWYoR1IBMBAOhwksU1mOKD3I45fhixTYg E4oNkFN9ug9WPzz522skbWyoHuQH6zRLh1aoXpC2xSydcu7hXSyA+NZ5bpBWIzRI rMsHhryV/kA7ZhOQKUSbJIdpu3mFYYmuCAeAdK2oO5FF7oRZ3yb4samHebWFMog+ 7U71Y+iR0ga12NmUzN1sBxfTFHa2ynlRlyuhF/H4KiFa09Z9xzsHRu02dPmh5u0q UXz2twCd/pVg0OmnPpFvedw9NaBoxNViawfHRxLz5C8xqpbpXqM1j0OJcvSqfXC3 OJDhsRNLZrnusLFi31ydxkTr+R+f03PPgmJYAG9ay8iIpFKOt9HLDLQeCPReexdF vBxzyBRUhtM= =gCEB -----END PGP SIGNATURE----- --=-=-=--