From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp10.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms5.migadu.com with LMTPS id WHmQFisVUWNDzgAAbAwnHQ (envelope-from ) for ; Thu, 20 Oct 2022 11:30:19 +0200 Received: from aspmx1.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp10.migadu.com with LMTPS id v3CrFSsVUWMDawEAG6o9tA (envelope-from ) for ; Thu, 20 Oct 2022 11:30:19 +0200 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 C881325906 for ; Thu, 20 Oct 2022 11:30:18 +0200 (CEST) Received: from localhost ([::1]:34392 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1olRsX-0006xy-I0 for larch@yhetil.org; Thu, 20 Oct 2022 05:30:17 -0400 Received: from [::1] (helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1olRsX-0006X4-61 for larch@yhetil.org; Thu, 20 Oct 2022 05:30:17 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:50736) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1olRsJ-0006RP-En for bug-guix@gnu.org; Thu, 20 Oct 2022 05:30:03 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:33933) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1olRsJ-0001H5-67 for bug-guix@gnu.org; Thu, 20 Oct 2022 05:30:03 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1olRsI-0001Db-IA for bug-guix@gnu.org; Thu, 20 Oct 2022 05:30:02 -0400 X-Loop: help-debbugs@gnu.org Subject: bug#58631: Shepherd crash on berlin Resent-From: Ludovic =?UTF-8?Q?Court=C3=A8s?= Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Thu, 20 Oct 2022 09:30:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 58631 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: 58631@debbugs.gnu.org Received: via spool by 58631-submit@debbugs.gnu.org id=B58631.16662581834631 (code B ref 58631); Thu, 20 Oct 2022 09:30:02 +0000 Received: (at 58631) by debbugs.gnu.org; 20 Oct 2022 09:29:43 +0000 Received: from localhost ([127.0.0.1]:33011 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1olRry-0001Cc-If for submit@debbugs.gnu.org; Thu, 20 Oct 2022 05:29:43 -0400 Received: from eggs.gnu.org ([209.51.188.92]:37112) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1olRrt-0001CG-8S for 58631@debbugs.gnu.org; Thu, 20 Oct 2022 05:29:41 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:36792) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1olRrm-0001CT-Uo for 58631@debbugs.gnu.org; Thu, 20 Oct 2022 05:29:30 -0400 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=gnu.org; s=fencepost-gnu-org; h=MIME-Version:In-Reply-To:Date:References:Subject:To: From; bh=5YUnWOIH8jyxUfqdj0ITG9U2t+uySdGZ5khFx6DmdIg=; b=euc3n17iPP3zap7Yg1ft 2zX4LBkuUvxYu0+nrVI0GjtpxQbqGjjDcaeoW/uh05Au7DCZN5e7Z1b9yz8FKGgUlPFElmEs3geOU jBW8LkP2VJZHY+zmWW8udpuMAWXTUGv/02Foai2r8zswFFF/3aprF2m62zP+BbbnWriM9iR5Hgysb EO5byfUqe55OG0cPpaoSaklRXNH+SCdwfJuDNePQGg+8K+Q0fvrEodI/VGqnlwDj4RE3e4nZNWFt5 7WcbdTX+UIfO2yyciIOd+2CvKiCLhAq01TwGOV74vTIfURk8UxDuZhqjYu5ti/UCFLjSZbapOij6P Q1JSTbJp4bR9qQ==; Received: from 91-160-117-201.subs.proxad.net ([91.160.117.201]:51285 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1olRrm-0004BP-FL for 58631@debbugs.gnu.org; Thu, 20 Oct 2022 05:29:30 -0400 From: Ludovic =?UTF-8?Q?Court=C3=A8s?= References: <87pmeohute.fsf@gnu.org> <87sfjjhjcd.fsf@gnu.org> Date: Thu, 20 Oct 2022 11:29:28 +0200 In-Reply-To: <87sfjjhjcd.fsf@gnu.org> ("Ludovic =?UTF-8?Q?Court=C3=A8s?="'s message of "Wed, 19 Oct 2022 18:24:50 +0200") Message-ID: <87a65qhmh3.fsf@gnu.org> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.1 (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: 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 X-Migadu-Country: US ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1666258219; 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: 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:dkim-signature; bh=5YUnWOIH8jyxUfqdj0ITG9U2t+uySdGZ5khFx6DmdIg=; b=pwercChsE//57idUR+O/lj7Y8SIMBl9uKphWPfh6yxRIsP7NBM6p9TDYy37qEULtqJUaD2 Rad3ipiaamdv6bTNnfbAuqkIZoEb6DBfrc+gE/z7iLzQjp2JWjhqF6rE8qMR3ANgNL6drZ IrmOqrKDe1BXsljzmaTLEylCm3tW+OsUqPLeB9QRDfypy7/DVnYPFV31M+VmLo7oOu9P6J VMIDTtmzW/bki6ZoP/zui6Tf3TmJ01NGAHyBvZCF6a9Uycny/k0civvSdLNvxZxOUdSItS kp/zEVMtg+oyeLuBwW9zvxrEvL96F57nuGilDwM6PMwYzcYClobyMlL7SuwD2A== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1666258219; a=rsa-sha256; cv=none; b=ZnBkKvKhh8MRv8N19V6ZoGEcV5WV6D5qID+xCyvaB2j0oMWWHYOy+cNQGFF/HsSzyDlSCu QRFBJb63VBFfN/vINyWf9ILb7UZ4UEXPq43U08yO6KRED8Xvx+nJts/cMrayNKv8TwvBFG zTga+NGMWZ5/J73Apqwg3D3IF4CT8nFql7rzJoMLNjV2pQbong4kH+VXi/C7CeTq8TkCgd +xUvcLLJFw1G+AmN775Wo75K3sS5YH2mYXxbG9qEdA1aajsdmdsRVGt4h43tNA8Ngeb7l4 vf0Yss46/zitf0HwDbUNwKhzojwT+Zxrr/u8achhH7PQuPCs5BGia7c97ap6bQ== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b=euc3n17i; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Spam-Score: -4.93 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b=euc3n17i; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Queue-Id: C881325906 X-Spam-Score: -4.93 X-Migadu-Scanner: scn0.migadu.com X-TUID: vMHbkIXuTSox Heap usage of shepherd on berlin gathered roughly at T0 (a few hours after booting), T0+8h, an T0+10h: --8<---------------cut here---------------start------------->8--- ludo@berlin ~$ sudo herd eval root '(gc-stats)' Evaluating user expression (gc-stats). ((gc-time-taken . 36730013844) (heap-size . 31494144) (heap-free-size . 833= 9456) (heap-total-allocated . 1198237472) (heap-allocated-since-gc . 758182= 4) (protected-objects . 0) (gc-times . 157)) ludo@berlin ~$ sudo cat /proc/1/maps |grep -A10 heap 016fe000-01810000 rw-p 00000000 00:00 0 [h= eap] 7f78a387d000-7f78a4000000 rw-p 00000000 00:00 0 7f78a4000000-7f78a4021000 rw-p 00000000 00:00 0 7f78a4021000-7f78a8000000 ---p 00000000 00:00 0 7f78a81d0000-7f78a8600000 rw-p 00000000 00:00 0 7f78a8600000-7f78a8640000 rwxp 00000000 00:00 0 7f78a8640000-7f78a8700000 rw-p 00000000 00:00 0 7f78a8700000-7f78a8740000 rwxp 00000000 00:00 0 7f78a8740000-7f78a8c6c000 rw-p 00000000 00:00 0 7f78a8c6c000-7f78a8cac000 rwxp 00000000 00:00 0 7f78a8cac000-7f78a8ccc000 r--p 00000000 00:17 167921 /g= nu/store/9nb1nplyx4gx5pdrmmidngir9jmrzxi3-guile-netlink-1.1.1/lib/guile/3.0= /site-ccache/ip/route.go ludo@berlin ~$ sudo herd eval root '(gc-stats)' Password: Evaluating user expression (gc-stats). ((gc-time-taken . 2698835942232) (heap-size . 322998272) (heap-free-size . = 56537088) (heap-total-allocated . 49605825968) (heap-allocated-since-gc . 6= 7360208) (protected-objects . 0) (gc-times . 1356)) ludo@berlin ~$ sudo cat /proc/1/maps |grep -A12 heap 016fe000-01810000 rw-p 00000000 00:00 0 [h= eap] 7f788ce8d000-7f78a1bdd000 rw-p 00000000 00:00 0 7f78a1bdd000-7f78a1c1d000 rwxp 00000000 00:00 0 7f78a1c1d000-7f78a4000000 rw-p 00000000 00:00 0 7f78a4000000-7f78a4021000 rw-p 00000000 00:00 0 7f78a4021000-7f78a8000000 ---p 00000000 00:00 0 7f78a8000000-7f78a8600000 rw-p 00000000 00:00 0 7f78a8600000-7f78a8640000 rwxp 00000000 00:00 0 7f78a8640000-7f78a8700000 rw-p 00000000 00:00 0 7f78a8700000-7f78a8740000 rwxp 00000000 00:00 0 7f78a8740000-7f78a8c6c000 rw-p 00000000 00:00 0 7f78a8c6c000-7f78a8cac000 rwxp 00000000 00:00 0 7f78a8cac000-7f78a8ccc000 r--p 00000000 00:17 167921 /g= nu/store/9nb1nplyx4gx5pdrmmidngir9jmrzxi3-guile-netlink-1.1.1/lib/guile/3.0= /site-ccache/ip/route.go ludo@berlin ~$ sudo herd eval root '(gc-stats)' Password: Evaluating user expression (gc-stats). ((gc-time-taken . 2909168084878) (heap-size . 348164096) (heap-free-size . = 51949568) (heap-total-allocated . 53131500656) (heap-allocated-since-gc . 9= 4062880) (protected-objects . 0) (gc-times . 1383)) ludo@berlin ~$ sudo cat /proc/1/maps |grep -A12 heap 016fe000-01810000 rw-p 00000000 00:00 0 [h= eap] 7f788b4bd000-7f78a1bdd000 rw-p 00000000 00:00 0=20 7f78a1bdd000-7f78a1c1d000 rwxp 00000000 00:00 0=20 7f78a1c1d000-7f78a4000000 rw-p 00000000 00:00 0=20 7f78a4000000-7f78a4021000 rw-p 00000000 00:00 0=20 7f78a4021000-7f78a8000000 ---p 00000000 00:00 0=20 7f78a8000000-7f78a8600000 rw-p 00000000 00:00 0=20 7f78a8600000-7f78a8640000 rwxp 00000000 00:00 0=20 7f78a8640000-7f78a8700000 rw-p 00000000 00:00 0=20 7f78a8700000-7f78a8740000 rwxp 00000000 00:00 0=20 7f78a8740000-7f78a8c6c000 rw-p 00000000 00:00 0=20 7f78a8c6c000-7f78a8cac000 rwxp 00000000 00:00 0=20 7f78a8cac000-7f78a8ccc000 r--p 00000000 00:17 167921 /g= nu/store/9nb1nplyx4gx5pdrmmidngir9jmrzxi3-guile-netlink-1.1.1/lib/guile/3.0= /site-ccache/ip/route.go --8<---------------cut here---------------end--------------->8--- Heap keeps increasing, and quite quickly. That includes code arenas allocated for JIT (the =E2=80=9Crwx=E2=80=9D mappings), but the biggest par= t seems to be the rest of the heap (in particular the second mapping on the second and third samples). During that time shepherd is mostly receiving and logging messages from =E2=80=98guix publish=E2=80=99, and occasionally accepting a connection on = port 22 and spawning =E2=80=98sshd=E2=80=99: --8<---------------cut here---------------start------------->8--- ludo@berlin ~$ sudo strace -p1 -Tt strace: Process 1 attached 10:33:59 rt_sigprocmask(SIG_BLOCK, NULL, [HUP INT TERM CHLD], 8) =3D 0 <0.0= 00009> 10:33:59 epoll_wait(13, [{events=3DEPOLLIN, data=3D{u32=3D50, u64=3D50}}], = 8, -1) =3D 1 <0.925330> 10:34:00 read(50, "GET /nar/lzip/z0l3fp12ck539qkzc2"..., 4096) =3D 76 <0.00= 0012> 10:34:00 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=3DS_IFREG|0444, st= _size=3D2298, ...}, 0) =3D 0 <0.000012> 10:34:00 write(51, "2022-10-20 10:34:00 GET /nar/lzi"..., 96) =3D 96 <0.000= 036> 10:34:00 read(50, 0x7f78a88d8020, 4096) =3D -1 EAGAIN (Resource temporarily= unavailable) <0.000008> 10:34:00 epoll_ctl(13, EPOLL_CTL_MOD, 50, {events=3DEPOLLIN|EPOLLRDHUP|EPOL= LONESHOT, data=3D{u32=3D50, u64=3D50}}) =3D 0 <0.000009> 10:34:00 rt_sigprocmask(SIG_BLOCK, NULL, [HUP INT TERM CHLD], 8) =3D 0 <0.0= 00007> 10:34:00 epoll_wait(13, [{events=3DEPOLLIN, data=3D{u32=3D50, u64=3D50}}], = 8, -1) =3D 1 <0.001968> 10:34:00 read(50, "GET /x2ii2b9zwxnaf020zinccckl2bh"..., 4096) =3D 46 <0.00= 0010> 10:34:00 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=3DS_IFREG|0444, st= _size=3D2298, ...}, 0) =3D 0 <0.000012> 10:34:00 write(51, "2022-10-20 10:34:00 GET /x2ii2b9"..., 66) =3D 66 <0.000= 019> 10:34:00 read(50, 0x7f78a88d8020, 4096) =3D -1 EAGAIN (Resource temporarily= unavailable) <0.000007> 10:34:00 epoll_ctl(13, EPOLL_CTL_MOD, 50, {events=3DEPOLLIN|EPOLLRDHUP|EPOL= LONESHOT, data=3D{u32=3D50, u64=3D50}}) =3D 0 <0.000008> 10:34:00 rt_sigprocmask(SIG_BLOCK, NULL, [HUP INT TERM CHLD], 8) =3D 0 <0.0= 00007> 10:34:00 epoll_wait(13, [{events=3DEPOLLIN, data=3D{u32=3D50, u64=3D50}}], = 8, -1) =3D 1 <0.097714> 10:34:00 read(50, "GET /lclbcq0jds63zal1p55g6v0mwz9"..., 4096) =3D 46 <0.00= 0009> 10:34:00 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=3DS_IFREG|0444, st= _size=3D2298, ...}, 0) =3D 0 <0.000011> 10:34:00 write(51, "2022-10-20 10:34:00 GET /lclbcq0"..., 66) =3D 66 <0.000= 018> 10:34:00 read(50, 0x7f78a88d8020, 4096) =3D -1 EAGAIN (Resource temporarily= unavailable) <0.000009> 10:34:00 epoll_ctl(13, EPOLL_CTL_MOD, 50, {events=3DEPOLLIN|EPOLLRDHUP|EPOL= LONESHOT, data=3D{u32=3D50, u64=3D50}}) =3D 0 <0.000011> --8<---------------cut here---------------end--------------->8--- Logging as performed by =E2=80=98%service-file-logger=E2=80=99 is quite GC-= intensive (but shouldn=E2=80=99t be leaky!); this bit: (let ((prefix (strftime default-logfile-date-format (localtime (current-time))))) (format output "~a~a~%" prefix line) (loop)) ends up allocating a couple of vectors (for =E2=80=98localtime=E2=80=99), a= bunch of strings, a string port (via (ice-9 format) it seems), etc. That puts GC under stress. Still, what=E2=80=99s leaking? Why are JIT code arenas being allocated? Ludo=E2=80=99.