From nobody Tue Oct 31 13:57:34 2023 X-Original-To: freebsd-fs@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 4SKWtn0MLZz4yPD4 for ; Tue, 31 Oct 2023 13:58:09 +0000 (UTC) (envelope-from jfc@mit.edu) Received: from outgoing-exchange-1.mit.edu (outgoing-exchange-1.mit.edu [18.9.28.15]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "*.outgoing-exchange.mit.edu", Issuer "InCommon RSA Server CA" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4SKWtl6kMtz3GBP for ; Tue, 31 Oct 2023 13:58:07 +0000 (UTC) (envelope-from jfc@mit.edu) Authentication-Results: mx1.freebsd.org; dkim=pass header.d=mit.edu header.s=outgoing header.b=UmpK9uKx; spf=pass (mx1.freebsd.org: domain of jfc@mit.edu designates 18.9.28.15 as permitted sender) smtp.mailfrom=jfc@mit.edu; dmarc=pass (policy=none) header.from=mit.edu Received: from w92exedge3.exchange.mit.edu (W92EXEDGE3.EXCHANGE.MIT.EDU [18.7.73.15]) by outgoing-exchange-1.mit.edu (8.14.7/8.12.4) with ESMTP id 39VDvXcA001542 for ; Tue, 31 Oct 2023 09:58:05 -0400 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mit.edu; s=outgoing; t=1698760685; bh=mesJnXWKcdLpuZ4254Q9DN4Jh3bo+ssnb90wyO27oWo=; h=From:Subject:Date:Message-ID:Content-Type:MIME-Version; b=UmpK9uKxmJ1MZT0ZAahgvqjurn5EAbUgDDso71vkaBiG3NrLvdZ67/HT8ayUbqUpJ WwzqFh7Y9OhETcJr+Xf4+q46linRD41gOAPV/03psNWSOOg/4ZKwfu3mAWOP3EsFSW okiS5cJnejjWqONHdrlf1xa6aGl8S4VXewwuVR0z+QB9qBQWgaHRoCMcIFNxWfVDUs SlMGKorRgRHXRAkdy5y1sqvl6gDnjYkGHzaJSr62xVl1uBXXQkosVAGUKv4TLQSHx4 zPZGxBo7ogOvWPMCSEXXycGA6moNHT1cJXKX8tLhDsLyFhzd5cFEtnC2R4Ug/RXD6f c34/F1zV+nSzA== Received: from OC11EXPO27.exchange.mit.edu (18.9.4.98) by w92exedge3.exchange.mit.edu (18.7.73.15) with Microsoft SMTP Server (TLS) id 15.0.1497.48; Tue, 31 Oct 2023 09:57:34 -0400 Received: from oc11exhyb6.exchange.mit.edu (18.9.1.111) by OC11EXPO27.exchange.mit.edu (18.9.4.98) with Microsoft SMTP Server (TLS) id 15.0.1497.42; Tue, 31 Oct 2023 09:57:37 -0400 Received: from NAM11-CO1-obe.outbound.protection.outlook.com (104.47.56.168) by oc11exhyb6.exchange.mit.edu (18.9.1.111) with Microsoft SMTP Server (TLS) id 15.0.1497.48 via Frontend Transport; Tue, 31 Oct 2023 09:57:37 -0400 Received: from SA3PR01MB8450.prod.exchangelabs.com (2603:10b6:806:382::17) by CYYPR01MB8291.prod.exchangelabs.com (2603:10b6:930:c4::14) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.6933.19; Tue, 31 Oct 2023 13:57:35 +0000 Received: from SA3PR01MB8450.prod.exchangelabs.com ([fe80::2e94:6383:c13:23b1]) by SA3PR01MB8450.prod.exchangelabs.com ([fe80::2e94:6383:c13:23b1%4]) with mapi id 15.20.6907.032; Tue, 31 Oct 2023 13:57:34 +0000 From: "John F Carr" To: Freebsd fs Subject: vnode_init took over 6 minutes Thread-Topic: vnode_init took over 6 minutes Thread-Index: AQHaDAIyORVK7QVkx0+UPxykgQSM3g== Date: Tue, 31 Oct 2023 13:57:34 +0000 Message-ID: <67FBC292-E83D-4171-BE79-D28D5578F031@mit.edu> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: x-ms-publictraffictype: Email x-ms-traffictypediagnostic: SA3PR01MB8450:EE_|CYYPR01MB8291:EE_ x-ms-office365-filtering-correlation-id: 12fb0a59-5da3-41f8-963b-08dbda19556c x-ms-exchange-senderadcheck: 1 x-ms-exchange-antispam-relay: 0 x-microsoft-antispam: BCL:0; x-microsoft-antispam-message-info: Q5+1gM9C1FActITEnJHvjZ++UBMXr7Rb5Jcp7PpH7hfUj8rfTqYLlUC9IWOPGFmGxb1M+Wm3IIjkTdkMOv5//odDxQ2aGR65+ixYw4USYaU3e7ccotEnrONmyl8Hda3RbDzbvcC+WoSoDVia5Gp162F3vJN3912Ib0L8lWdbG9HFBP+zfj2iDtE8NVd9Nw4xyZWAqK1EXTO4W1d8ovy8FvDtoy8fBoTOZ4ILPME3l8ImR5vAHUE+BFLrhhYk9PfPEAtFV1KNLSWXi01xL7X0N0jWvG4i+JOFdnXX4GPrbjd1ipOG9gJ4iQbZ5t2RCNJr7oIsZgJV2z7VAVn81u03X37XhbxZykFfHbLcYXjmnZq/SQRJURLg+c0dTgsH5Ix2Betu4rKLci7Vh8nMB2ZjSIfSfsYVAyiVlgYbpBwYLH1w2yicYsZNj616BNhzXW1jKcEO8CtKnqEO4vEYsmM6HO5syexgmuwLi7IjKioh0t9Ai6NKq4+AIhaGWjA2FensjI80xy2E7ZiHrfrBIiVPi7wTYwQfMb5D1GxTU7wv79I/Reg+1/MzaLIkqZ0jRsye1RbW5wTWu3nPjrNQ1mE8x5iRfaxO7gjrn6CTJrWXbd6jQgJcWCrAtlX7AUrzPcgg x-forefront-antispam-report: CIP:255.255.255.255;CTRY:;LANG:en;SCL:1;SRV:;IPV:NLI;SFV:NSPM;H:SA3PR01MB8450.prod.exchangelabs.com;PTR:;CAT:NONE;SFS:(13230031)(136003)(376002)(346002)(39860400002)(396003)(366004)(230922051799003)(451199024)(186009)(1800799009)(64100799003)(75432002)(71200400001)(2906002)(478600001)(6486002)(2616005)(38070700009)(122000001)(38100700002)(33656002)(36756003)(83380400001)(86362001)(6512007)(6506007)(8936002)(8676002)(5660300002)(41300700001)(91956017)(6916009)(786003)(316002)(66946007)(76116006)(66556008)(66476007)(66446008)(64756008);DIR:OUT;SFP:1102; x-ms-exchange-antispam-messagedata-chunkcount: 1 x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?u2EaNNvYLq9RyiDFIWVMX40IjHMrTGQTXOowl/1KVLVMIskHb7ylErO/cvyX?= =?us-ascii?Q?lj3XG18fNpkbf/NPSwJ0KAXEd9oXG8uyVl8cSQNaazkIwYtNwxk23U7OIXMX?= =?us-ascii?Q?NO0Xi6xcLgGBPI2wJwhYn/1ZVCe+dpqXI/IHOwyEENRx7dRKH44CUMzae2aH?= =?us-ascii?Q?p6q9H3i+6stbClvpELXXg7F0fyXykF7vEiSUlLJqyupUjGhjRNEAgxhsfHTx?= =?us-ascii?Q?4uP7qnjWW4cbpPrN8+3od12yQaAk0+XvPAcnOjx8DeUT+gOCjzX2hBJCUj09?= =?us-ascii?Q?+4G68w27sshSNv2ep1//PesJ2UcxDZmDC/IuLlTMHTz0OV4YyHNqO8mS/2lC?= =?us-ascii?Q?jYmy2MmrVYADa+jQ2usEP81l5Fy1wJSybIAPudz11vFqs+WJi6g5dGW/mZDm?= =?us-ascii?Q?9hQbOYDJtKPt7q3NcLfwYSSH8au8UUUOU1JZHj50DeLk1ojYuR6/lxqjh0bk?= =?us-ascii?Q?2YYeBslFEVjsevg0OnuR0w4gxFbKeaDuzRxQ21ZUft1GXPVQy3CWHwjzyhDd?= =?us-ascii?Q?YCoF6hgkVOOFNIRSsEIs7gz8okampWPXLORXRqNe644x3sl0X4fLd7ngu6b0?= =?us-ascii?Q?hRIrQTq84hLdedOm60u5noeqcpGA5Kp6eGkLjBWc0WDWzlhuDccNYV313bDI?= =?us-ascii?Q?lWJtQTEWS+d1IUSpcdAUaR08gxV+r9mYnDMcxxyht+/yHFfh96rkVWjdPPoj?= =?us-ascii?Q?Wvdi+90DJGPkJYLiy3X/Ecju02IDndEDKgmjsbWJXv/NI4CHbdZFtzZsnJFX?= =?us-ascii?Q?bCS8WrlWtRx66KEDf2+hSACgr9/q4X1D8cRj40CAZmrbi/qdMOdxUiNVTjzv?= =?us-ascii?Q?w/fipwsmRJQbjdRUx/kLo/CAne6Fg/CL3j1Adf+OdHEaa/Ty0H7H1lgyrCVD?= =?us-ascii?Q?BbrVXF4TfGzODXi3jJiDm4YPdmrSOjPt8R26nWoQZYNxBzkiGh0PdHfZxRQW?= =?us-ascii?Q?lJiC67CaUvuRFlqD4zs2M9u3aOvU7qbl3EV7mJmW9tXaM3r0TwVi/NeHLjN+?= =?us-ascii?Q?VToYsF8Q9u5PB4x1J1V5swRHby8eYGYN0IHoCRGzp6y+Q9QJJAmquftnKmqY?= =?us-ascii?Q?hvP3OvGzhW/OoD2kd3WBcheOt4u9ZUZdOhVVTMMX5Cs/VQWnYNUUjltKe1M1?= =?us-ascii?Q?blCxwkAaQoX5017gtS3iSh9Npko5oq65e8JY0SpAlTZOF7dIchPVB337V2xS?= =?us-ascii?Q?uoCBP811s6/CNbh7GE7SxIsezwwPnBWkkiLdsCJiSU7roeJKpjsABmNhkeZ5?= =?us-ascii?Q?5miIZsjS/nDYM6B4GZ+yMlmkRzF8oEqLkDf7yS5d+gHQ6MA1K8VfpnBZiAzz?= =?us-ascii?Q?ZTNV5J+ivJjYbgoXEDfctc/8OYxHcOp3e5Jjs6avcSGk0c3kAGcbM7/wr3Wx?= =?us-ascii?Q?tk5FuhYiafVn+5YFiu+8IU4HChRROqf5kMKfvlee6Lb82tUPaF4jWmS05nD9?= =?us-ascii?Q?pXfIoNR+P/YQmYW5za0SIC3iPRAp2qzVlAhlxEL3S8b1ie3DskKv4EjG0U90?= =?us-ascii?Q?MH/n4xNDTI0Gfsd8zjsOmhAYNfDuixyvDntPkgrHfRdDgMI4cdtD4SkQ2hmy?= =?us-ascii?Q?59qdsTLfja0ZPZfyv+Ffk+kQ6RqkAh6azn4oFgNvEKjGY0cp7HcKfyVsHzVZ?= =?us-ascii?Q?0vvq4zENwN8C4q5AraEF+chYnj3pofDlJNZSjj5yQteN?= Content-Type: text/plain; charset="us-ascii" Content-ID: <82B9792814CFB041B0C6A69E3E0110C4@prod.exchangelabs.com> Content-Transfer-Encoding: quoted-printable List-Id: Filesystems List-Archive: https://lists.freebsd.org/archives/freebsd-fs List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-fs@freebsd.org MIME-Version: 1.0 X-MS-Exchange-CrossTenant-AuthAs: Internal X-MS-Exchange-CrossTenant-AuthSource: SA3PR01MB8450.prod.exchangelabs.com X-MS-Exchange-CrossTenant-Network-Message-Id: 12fb0a59-5da3-41f8-963b-08dbda19556c X-MS-Exchange-CrossTenant-originalarrivaltime: 31 Oct 2023 13:57:34.5020 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: 64afd9ba-0ecf-4acf-bc36-935f6235ba8b X-MS-Exchange-CrossTenant-mailboxtype: HOSTED X-MS-Exchange-CrossTenant-userprincipalname: zgPgwk7/3S8JqUcpQ+pmdIm/+2+MXUIb0cTFLwWRrNez1e4xtM8KZgKbVYpLjpxu X-MS-Exchange-Transport-CrossTenantHeadersStamped: CYYPR01MB8291 X-OriginatorOrg: mit.edu X-Spamd-Result: default: False [-5.80 / 15.00]; DWL_DNSWL_LOW(-1.00)[mit.edu:dkim]; NEURAL_HAM_LONG(-1.00)[-1.000]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; NEURAL_HAM_SHORT(-1.00)[-0.998]; RCVD_DKIM_ARC_DNSWL_MED(-0.50)[]; DMARC_POLICY_ALLOW(-0.50)[mit.edu,none]; R_SPF_ALLOW(-0.20)[+ip4:18.9.28.0/24]; RCVD_IN_DNSWL_MED(-0.20)[18.9.28.15:from]; R_DKIM_ALLOW(-0.20)[mit.edu:s=outgoing]; MIME_GOOD(-0.10)[text/plain]; RCVD_IN_DNSWL_LOW(-0.10)[18.7.73.15:received]; MID_RHS_MATCH_FROM(0.00)[]; DKIM_TRACE(0.00)[mit.edu:+]; FROM_EQ_ENVFROM(0.00)[]; PREVIOUSLY_DELIVERED(0.00)[freebsd-fs@freebsd.org]; TO_DN_ALL(0.00)[]; RCPT_COUNT_ONE(0.00)[1]; ASN(0.00)[asn:3, ipnet:18.9.0.0/16, country:US]; TO_MATCH_ENVRCPT_ALL(0.00)[]; MIME_TRACE(0.00)[0:+]; RCVD_IN_DNSWL_NONE(0.00)[18.9.1.111:received,104.47.56.168:received]; FROM_HAS_DN(0.00)[]; ARC_NA(0.00)[]; RCVD_COUNT_FIVE(0.00)[6]; RCVD_TLS_LAST(0.00)[]; MLMMJ_DEST(0.00)[freebsd-fs@freebsd.org] X-Rspamd-Queue-Id: 4SKWtl6kMtz3GBP X-Spamd-Bar: ----- During a poudriere build control-T showed an awk process was stuck for over 6 minutes trying to acquire a lock in vnode_init. load: 8.58 cmd: awk 51238 [running] 392.88r 0.00u 392.88s 100% 2604k __mtx_lock_sleep+0xf8 __mtx_lock_flags+0xa4 vnode_init+0xc3 keg_alloc_slab+= 0x277 zone_import+0x143 cache_alloc+0x3ed cache_alloc_retry+0x23 getnewvnod= e_reserve+0x20 zfs_zget+0x1f zfs_dirent_lookup+0x16d zfs_dirlook+0x7f zfs_l= ookup+0x3e0 zfs_freebsd_cachedlookup+0x74 vfs_cache_lookup+0xa7 cache_fploo= kup_noentry+0x241 cache_fplookup+0x575 namei+0x1ea vn_open_cred+0x48d=20 The stack trace was the same for several minutes. System CPU time was incr= easing. Address vnode_init+0xc3 corresponds to the mtx_lock call here. vp->v_holdcnt =3D VHOLD_NO_SMR; vp->v_type =3D VNON; mtx_lock(&vnode_list_mtx); TAILQ_INSERT_BEFORE(vnode_list_free_marker, vp, v_vnodelist); mtx_unlock(&vnode_list_mtx); return (0); Address __mtx_lock_sleep+0xf8 is the instruction after a call to lock_delay= . ps says the command line was /usr/bin/awk -f /usr/bin/awk old-default/2023-10-31_08h21m03s/.poudriere.bu= ilders old-default/2023-10-31_08h21m03s/.poudriere.buildname ... with the full list of input files exceeding the ~2KB command line length li= mit of ps. "/usr/bin/awk" is probably not the real second argument. It would cause an immediate syntax error. The hang resolved within a few more minutes and poudriere is continuing hap= pily.=20 I have never seen such behavior before. Code in vfs_subr.c tries not to ho= ld the vnode_list_mtx lock for too long. Any thoughts? FreeBSD 13.2-STABLE up through commit b180f0040f95, 24 core 48 thread Zen 2= , zfs pool on SSD connected via 12 Gbps SAS with cache on NVME, 160 GB RAM.