From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp1 ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms11 with LMTPS id ykVWBHEzVmCoCQAA0tVLHw (envelope-from ) for ; Sat, 20 Mar 2021 17:40:01 +0000 Received: from aspmx1.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp1 with LMTPS id oGExO3AzVmCyNQAAbx9fmQ (envelope-from ) for ; Sat, 20 Mar 2021 17:40:00 +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 E5DA81CD74 for ; Sat, 20 Mar 2021 18:39:59 +0100 (CET) Received: from localhost ([::1]:56614 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1lNfZu-0006zg-Ne for larch@yhetil.org; Sat, 20 Mar 2021 13:39:58 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:37284) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1lNfZ1-0006zV-7V for bug-guix@gnu.org; Sat, 20 Mar 2021 13:39:03 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:41554) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1lNfYz-0003li-SD for bug-guix@gnu.org; Sat, 20 Mar 2021 13:39:03 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1lNfYz-0005gn-Nv; Sat, 20 Mar 2021 13:39:01 -0400 X-Loop: help-debbugs@gnu.org Subject: bug#47283: Performance regression in narinfo fetching Resent-From: Ludovic =?UTF-8?Q?Court=C3=A8s?= Original-Sender: "Debbugs-submit" Resent-CC: mail@cbaines.net, bug-guix@gnu.org Resent-Date: Sat, 20 Mar 2021 17:39:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: report 47283 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: 47283@debbugs.gnu.org X-Debbugs-Original-To: X-Debbugs-Original-Xcc: Christopher Baines Received: via spool by submit@debbugs.gnu.org id=B.161626193621856 (code B ref -1); Sat, 20 Mar 2021 17:39:01 +0000 Received: (at submit) by debbugs.gnu.org; 20 Mar 2021 17:38:56 +0000 Received: from localhost ([127.0.0.1]:53099 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1lNfYt-0005gQ-EJ for submit@debbugs.gnu.org; Sat, 20 Mar 2021 13:38:56 -0400 Received: from lists.gnu.org ([209.51.188.17]:58226) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1lNfYp-0005gG-Lv for submit@debbugs.gnu.org; Sat, 20 Mar 2021 13:38:54 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:37248) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1lNfYk-0006xn-ER for bug-guix@gnu.org; Sat, 20 Mar 2021 13:38:51 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:56957) by eggs.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1lNfYi-0003jH-6v for bug-guix@gnu.org; Sat, 20 Mar 2021 13:38:45 -0400 Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=33620 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256) (Exim 4.82) (envelope-from ) id 1lNfYf-0007Mn-Ru for bug-guix@gnu.org; Sat, 20 Mar 2021 13:38:42 -0400 From: Ludovic =?UTF-8?Q?Court=C3=A8s?= X-URL: http://www.fdn.fr/~lcourtes/ X-Revolutionary-Date: 30 =?UTF-8?Q?Vent=C3=B4se?= an 229 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: Sat, 20 Mar 2021 18:38:39 +0100 Message-ID: <87ft0p67z4.fsf@inria.fr> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.1 (gnu/linux) MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" 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: , 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=1616262000; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:mime-version:mime-version: content-type:content-type:resent-cc:resent-from:resent-sender: resent-message-id:list-id:list-help:list-unsubscribe:list-subscribe: list-post; bh=hrmJlaN/QsFghCJKBVQ2bIpbFAq4FEndmLmGGmE0cxc=; b=i0R3OifWazhX3MLDcP6ek085WF8a2XnsMLE0Qc6dAujgRd7O8VC09gn8vNZpvRobiNJtWd KyqMAHxl/0kngwr5QIumanYRlf3HrzF5oHw5xrhqEYlBMeDfLb7fs6NW8QZGAgH7C4LF1t RvJnSOyIidmm9uqkVezk0FB3URXVXhwihwRYPkzIENpFrUBZaV0iOR8pruZBiso2xF1M1Y RD78tPBTpYg7T+eSjxIXidykX0NX5q4xb01Uo9Oq43Fn7GLHlgIutCcOPzPhTNl/l9Gpx6 gSiZUclk+qbSMqNkDGYZo9igfU+qNGnnVHutGR0MAgh5/0Sh6DOcrgRbFjJFHQ== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1616262000; a=rsa-sha256; cv=none; b=S1c48+NG3Tuh1R+qcnI1lVzznmjc9d02mZ/qB77fpIXiVxedueJ48RYaih36JBkMZVRU4N 8HQLrdTdF2R/pdMkecPwvz5VKtu7FzZP1TDrkqltsG0S+lXmzivXKu5pVTdaeRRvPFClRw m+zD8xf894ssSbYayIhUesue5YOJBm9VCe0APbJiFdywAezt1heqLl8FEBwBo2iEbEr+D0 dpaN8upCzFtCGelCKNgWqZrT+MsfBaBFGFOs8nm6Cvzkv8OutEfqGCyD+Fug6Hsvt3RIsR sF48Kp2oXZzOP49dIs1bITimKhpGbOOCGXbKdClqr45uLyoGExGF2RWrjhWIRA== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=none; spf=pass (aspmx1.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: -2.91 Authentication-Results: aspmx1.migadu.com; dkim=none; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.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: E5DA81CD74 X-Spam-Score: -2.91 X-Migadu-Scanner: scn0.migadu.com X-TUID: 6OCarJ9ZurPB --=-=-= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Hello! As reported on guix-devel, =E2=80=98guix weather=E2=80=99 has become extrem= ely 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 t= his: --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=94so= unds 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 exception 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.) 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=20=20=20=20=20=20=20=20=20=20=20=20=20 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 n= ot be justified. Attached is a diff of the tweaks I made to test this. WDYT, Chris? Ludo=E2=80=99. --=-=-= Content-Type: text/x-patch Content-Disposition: inline diff --git a/guix/http-client.scm b/guix/http-client.scm index 4b4c14ed0b..a28523201e 100644 --- a/guix/http-client.scm +++ b/guix/http-client.scm @@ -219,42 +219,21 @@ returning." (remainder (connect p remainder result)))) ((head tail ...) - (catch #t - (lambda () - (let* ((resp (read-response p)) - (body (response-body-port resp)) - (result (proc head resp body result))) - ;; The server can choose to stop responding at any time, - ;; in which case we have to try again. Check whether - ;; that is the case. Note that even upon "Connection: - ;; close", we can read from BODY. - (match (assq 'connection (response-headers resp)) - (('connection 'close) - (close-port p) - (connect #f ;try again - (drop requests (+ 1 processed)) - result)) - (_ - (loop tail (+ 1 processed) result))))) ;keep going - (lambda (key . args) - ;; If PORT was cached and the server closed the connection - ;; in the meantime, we get EPIPE. In that case, open a - ;; fresh connection and retry. We might also get - ;; 'bad-response or a similar exception from (web response) - ;; later on, once we've sent the request, or a - ;; ERROR/INVALID-SESSION from GnuTLS. - (if (or (and (eq? key 'system-error) - (= EPIPE (system-error-errno `(,key ,@args)))) - (and (eq? key 'gnutls-error) - (eq? (first args) error/invalid-session)) - (memq key - '(bad-response bad-header bad-header-component))) - (begin - (close-port p) - (connect #f ; try again - (drop requests (+ 1 processed)) - result)) - (apply throw key args)))))))))) + (let* ((resp (read-response p)) + (body (response-body-port resp)) + (result (proc head resp body result))) + ;; The server can choose to stop responding at any time, + ;; in which case we have to try again. Check whether + ;; that is the case. Note that even upon "Connection: + ;; close", we can read from BODY. + (match (assq 'connection (response-headers resp)) + (('connection 'close) + (close-port p) + (connect #f ;try again + (drop requests (+ 1 processed)) + result)) + (_ + (loop tail (+ 1 processed) result)))))))))) ;;; diff --git a/guix/scripts/weather.scm b/guix/scripts/weather.scm index 5164fe0494..3d8d50d5e3 100644 --- a/guix/scripts/weather.scm +++ b/guix/scripts/weather.scm @@ -184,9 +184,10 @@ Return the coverage ratio, an exact number between 0 and 1." (let/time ((time narinfos requests-made (lookup-narinfos server items - #:make-progress-reporter - (lambda* (total #:key url #:allow-other-keys) - (progress-reporter/bar total))))) + ;; #:make-progress-reporter + ;; (lambda* (total #:key url #:allow-other-keys) + ;; (progress-reporter/bar total)) + ))) (format #t "~a~%" server) (let ((obtained (length narinfos)) (requested (length items)) @@ -504,6 +505,7 @@ SERVER. Display information for packages with at least THRESHOLD dependents." ;;; Entry point. ;;; +(use-modules (statprof)) (define-command (guix-weather . args) (synopsis "report on the availability of pre-built package binaries") @@ -551,9 +553,11 @@ SERVER. Display information for packages with at least THRESHOLD dependents." (exit (every* (lambda (server) (define coverage - (report-server-coverage server items - #:display-missing? - (assoc-ref opts 'display-missing?))) + (statprof + (lambda () + (report-server-coverage server items + #:display-missing? + (assoc-ref opts 'display-missing?))))) (match (assoc-ref opts 'coverage) (#f #f) (threshold diff --git a/guix/substitutes.scm b/guix/substitutes.scm index 08f8c24efd..04bf70caaa 100644 --- a/guix/substitutes.scm +++ b/guix/substitutes.scm @@ -59,8 +59,6 @@ #:use-module (guix http-client) #:export (%narinfo-cache-directory - call-with-connection-error-handling - lookup-narinfos lookup-narinfos/diverse)) @@ -235,14 +233,11 @@ if file doesn't exist, and the narinfo otherwise." (let* ((requests (map (cut narinfo-request url <>) paths)) (result (begin (start-progress-reporter! progress-reporter) - (call-with-connection-error-handling - uri - (lambda () - (http-multiple-get uri - handle-narinfo-response '() - requests - #:open-connection open-connection - #:verify-certificate? #f)))))) + (http-multiple-get uri + handle-narinfo-response '() + requests + #:open-connection open-connection + #:verify-certificate? #f)))) (stop-progress-reporter! progress-reporter) result)) ((file #f) --=-=-=--