From nobody Tue Oct 31 15:57:59 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 4SKZYm5NBqz4yXrB for ; Tue, 31 Oct 2023 15:58:36 +0000 (UTC) (envelope-from jfc@mit.edu) Received: from outgoing-exchange-7.mit.edu (outgoing-exchange-7.mit.edu [18.9.28.58]) (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 4SKZYm3KxRz3YSM for ; Tue, 31 Oct 2023 15:58:36 +0000 (UTC) (envelope-from jfc@mit.edu) Authentication-Results: mx1.freebsd.org; none Received: from oc11exedge2.exchange.mit.edu (OC11EXEDGE2.EXCHANGE.MIT.EDU [18.9.3.18]) by outgoing-exchange-7.mit.edu (8.14.7/8.12.4) with ESMTP id 39VFvdha019072; Tue, 31 Oct 2023 11:58:35 -0400 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mit.edu; s=outgoing; t=1698767915; bh=9Eqk2NsFNax1ILb2xwmeHE9yJ4QjLyie1zeDpx28XN4=; h=From:Subject:Date:Message-ID:Content-Type:MIME-Version; b=ER4qd76x/n3V1Cqy0wBMM6MeKAsAb4SBD+f6K5gpKGlPW/x0vtN+HcXcHEfeNTkcU 3vWcyZZuyEbCmFxT1h3y/N0uch/SNDA67bXXLHOk8K3z44ZwtBoARKMrWvAzIxKNtA yGTpBzaWdDRMwEyPb5GCMiibEvyvmp+61c1Rd0SG/snal+QXM0JV+NRWGXJEoJWjrx YPyKgvRwatnGRl2wPoijExYmgZZ3cqebzrhCVRjY0dny5iN2zMIBLF9cLdAhwS8Ksn STpuUIWfwsffWH0LFsmTxeNEr+8JNYEF4dWQk8en7wenbtf5OHNCapniGKfFE9F5nU qXpQXxXSssMJQ== Received: from oc11exhyb4.exchange.mit.edu (18.9.1.100) by oc11exedge2.exchange.mit.edu (18.9.3.18) with Microsoft SMTP Server (TLS) id 15.0.1497.48; Tue, 31 Oct 2023 11:57:29 -0400 Received: from oc11exhyb3.exchange.mit.edu (18.9.1.99) by oc11exhyb4.exchange.mit.edu (18.9.1.100) with Microsoft SMTP Server (TLS) id 15.0.1497.48; Tue, 31 Oct 2023 11:58:01 -0400 Received: from NAM12-MW2-obe.outbound.protection.outlook.com (104.47.66.41) by oc11exhyb3.exchange.mit.edu (18.9.1.99) with Microsoft SMTP Server (TLS) id 15.0.1497.48 via Frontend Transport; Tue, 31 Oct 2023 11:58:01 -0400 Received: from SA3PR01MB8450.prod.exchangelabs.com (2603:10b6:806:382::17) by IA0PR01MB8615.prod.exchangelabs.com (2603:10b6:208:48a::17) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.6907.33; Tue, 31 Oct 2023 15:57:59 +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 15:57:59 +0000 From: "John F Carr" To: Mateusz Guzik CC: Freebsd fs Subject: Re: vnode_init took over 6 minutes Thread-Topic: vnode_init took over 6 minutes Thread-Index: AQHaDAIzJL6ZDeRtpkqkNz6JuK6CTLBj8YcAgAATW4CAAAS4AIAABF4A Date: Tue, 31 Oct 2023 15:57:59 +0000 Message-ID: <29268BEF-8620-4CAE-B69D-2D2C2EF59868@mit.edu> References: <67FBC292-E83D-4171-BE79-D28D5578F031@mit.edu> <8F17FEC3-C3CB-410D-ACEC-ADD12B3A747A@mit.edu> In-Reply-To: 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_|IA0PR01MB8615:EE_ x-ms-office365-filtering-correlation-id: 839474c4-f6de-4512-e978-08dbda2a2796 x-ms-exchange-senderadcheck: 1 x-ms-exchange-antispam-relay: 0 x-microsoft-antispam: BCL:0; x-microsoft-antispam-message-info: l4aKj9eD+HT/iIBtP8yg+Va32NGMjfvQtm63hwEU/9kZcCBpfjl4hQmS8wGvIvY5XAXr/g00wDmMrEzNfkYbeTZw0rh0fnVHYmAk54+QIOgLLO8759ZYveS98eDI61DZdf18xf5653mpm0i+JIOMGnhUV+Ox0fZjmVeIaCHqW5wCb/vp5a5Zwk8ZF2BMAHycONyv4/e43FwEWY7CSjUhdicBBahS3cQWjOw6ciXgkcuat/Q4b2hDl7AGPirKr5IO/FgoL/h0ljjZrUiQKlMeBuFATU1/oH0qAL9pYWO4iixp80iE/g8oaDIGMWOTqdfCmTE0U9DlGLqn/6ZEL5//DPaKHvGxcbDbtedK90EMArd+oh7/Sy0e1sdNW6xuX9jSKi1BgMxKTWhGZYXEuuauNT1eJZjqMA3QIheP576w7yFgza4GJ7TLkseZNyWMLYbCeIR6N6Kqjn0hJ19zOI1aXJmiJLaJF4mXPV1rMYumR4aOd2M2niH1yc9yPVMFCsL/vRl5B2KW1B3sBfTrmTocqj2J8AWSjyNjG7kEC2cJt63uKvO7N5XGXgeYENXYDKY1tsnCmFqdnQekvo24ij8P6LJqMIC1W70quXQerRwnnBIMFFbKazvvVXcWTEXy1Mi9 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)(346002)(396003)(39860400002)(376002)(366004)(136003)(230922051799003)(1800799009)(451199024)(186009)(64100799003)(6916009)(66446008)(2906002)(38100700002)(41300700001)(71200400001)(316002)(66946007)(786003)(66476007)(53546011)(64756008)(76116006)(66556008)(478600001)(91956017)(122000001)(6506007)(6512007)(6486002)(83380400001)(86362001)(5660300002)(8676002)(36756003)(33656002)(4326008)(2616005)(8936002)(75432002)(38070700009);DIR:OUT;SFP:1102; x-ms-exchange-antispam-messagedata-chunkcount: 1 x-ms-exchange-antispam-messagedata-0: =?us-ascii?Q?FDog2AUQAIopDD3VjtOmwlKD6OSAPifwSdNwcED6vt4pes6jcR8pIwzf2ga8?= =?us-ascii?Q?fZoeAwFWsTdi8gTnYpqvJ2WhGaPX8hDblXoeZluNRePt/O9QP9vf5BzkbPty?= =?us-ascii?Q?jhk6QvSOX2rTmOC5jQryYbVYgf9v6Mw/gmvWDrQQV3vW1hWj9DYNJSJF9K16?= =?us-ascii?Q?p5dXBfkm2UWZlxmQFKHZsr+bQkdh8ilfAB3hICYxkunsuP3uXhoH1COLCv96?= =?us-ascii?Q?snAhsKiOyO7CPWBqZCGluuZxy8zbwS4fvl+pRFPcWWb6fFgmEiyqBy11NsVO?= =?us-ascii?Q?OCM03JzKUCFl4Cz5zFNRNElEYxsIh4ivAnZutmASk7UQKilqldNtoATSGTYd?= =?us-ascii?Q?THYVsfKpC1W0ea4eU8F5jZeGfxFgrUk19wbliwT6tM7iHgqFP3H8sfYLhgI9?= =?us-ascii?Q?un3KWAM+2j5/a6M20Sw9FkMvxql4w2vbbEompshbOEAgTTtgwF/y726J3/Sw?= =?us-ascii?Q?9wfueWuenbTDtygAqPUzxWvysleF7ICBIs1N0QpwUzrslbEmvtDnz0KskiZp?= =?us-ascii?Q?7PJ0UNdLBzT69K4lXvRWSam9psdX3mBYPW7Cdes+Fk243QWTH/SQnv8mItUv?= =?us-ascii?Q?cyjoXxfDHWfPFtbrUKuMvOdQ5zphhUla8TsMISOcNWVR4NegnMhZ7EeA9L06?= =?us-ascii?Q?4Tkgd/twJafr8K2bUlZJn8bKU7o3DaTVjMQvE4UmtYYaeNNICyCYomUhKAY+?= =?us-ascii?Q?Q0LfXqUhtUmAeZC77jhjv8kt2/iH2Q1WS6h6Y3A2Iwe/BjwW5APhXnp0DEpn?= =?us-ascii?Q?SGJIyemm6oSPIFMTTZdhmRhSk2ltMpAfuA2tcNhgF7Kp9f+WnHRGTT9Pgrk4?= =?us-ascii?Q?YVLj7RkMiSX+gyEZT5KKjMzOuHKjn72Zk1WmZYzuDGuCxkw5/Hkj4tS6587q?= =?us-ascii?Q?srV9RPKgA/k1B3DGQNLwChMKGyAiATWUTXr73LYZ9ZQww2ow7YOl2wFquSfJ?= =?us-ascii?Q?higx3dLZfybzIzUZAp4cBfWd8dRT6u525ESIdwP71vWusXb6Vx87CLlS3R3X?= =?us-ascii?Q?9krKSWQb9BupfhKRPYlVVfLlY0CEZmD4FFoqMu29t6zgq4YGwzq83XPqNgB3?= =?us-ascii?Q?SOfjVxqwxivCU5VkNyHdqQ1SMfN0f+gV5LHWmkLZ0kVPGqpW4K0PYrepJvY/?= =?us-ascii?Q?Dqb11DlCphrd6ZclIHvY9gK2LfzFQk9mg81x3RtD1g6iH5CrCypTssl9APM4?= =?us-ascii?Q?yc7WBluFqNbugZWT4V0Rn0um0MxWq9rwD01fEjgzURSHo7VF2d+/LKSpgv33?= =?us-ascii?Q?j8wWqifJ6mEmNyL9wDz1+oDVjpZZgRqV0bEq591CY8u14jqnuPq6q7a1KV02?= =?us-ascii?Q?RkEerAROy5yUO/geCzAhjKpPjxPKh5cBdVhnvF3jgHafXeU//GmeHYxa6Qvl?= =?us-ascii?Q?LIE3yfFhgpxzBUOhBQoqk8LXD2xKZQSRgqA8NJ1paHIzvR9lfQXuk/tGszpA?= =?us-ascii?Q?eeyp5Ffz9NHRVKqHH7XPvs+ZZh4p1TFWLssIaVk9gJ6mteOV+LYo7dBTRGmf?= =?us-ascii?Q?dkKivWPSBHKDqmwyEY1GNexOcviA2xAVSaXLKkzaaooQ+yUoYBOOnQ+KpSlh?= =?us-ascii?Q?Dmd2p+zuzUw/szp0QnmU/mGWGkPcrgniWQqn/gHfgThgpM0fksDbG5S2krwx?= =?us-ascii?Q?r1emHGBUeqZXm0yLi6cp/A0caXRN/t7e1GIgijl0f4SK?= Content-Type: text/plain; charset="us-ascii" Content-ID: <3467FD3A0A53BD449E6E51D5D874DE0A@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: 839474c4-f6de-4512-e978-08dbda2a2796 X-MS-Exchange-CrossTenant-originalarrivaltime: 31 Oct 2023 15:57:59.0567 (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: IMbUdageHO8m75HBcN2r7F2Uo4p6OGW3bL5+WyCYPm6xi1sw0jGUMda9Uv4816xJ X-MS-Exchange-Transport-CrossTenantHeadersStamped: IA0PR01MB8615 X-OriginatorOrg: mit.edu X-Spamd-Bar: ---- X-Rspamd-Pre-Result: action=no action; module=replies; Message is reply to one we originated X-Spamd-Result: default: False [-4.00 / 15.00]; REPLY(-4.00)[]; ASN(0.00)[asn:3, ipnet:18.9.0.0/16, country:US] X-Rspamd-Queue-Id: 4SKZYm3KxRz3YSM > On Oct 31, 2023, at 11:42, Mateusz Guzik wrote: >=20 > On 10/31/23, John F Carr wrote: >>=20 >>=20 >>> On Oct 31, 2023, at 10:16, Mateusz Guzik wrote: >>>=20 >>> On 10/31/23, John F Carr wrote: >>>> During a poudriere build control-T showed an awk process was stuck >>>> for over 6 minutes trying to acquire a lock in vnode_init. >>>>=20 >>>> 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 getnewvnode_reserve+0x20 zfs_zget+0x1f >>>> zfs_dirent_lookup+0x16d zfs_dirlook+0x7f zfs_lookup+0x3e0 >>>> zfs_freebsd_cachedlookup+0x74 vfs_cache_lookup+0xa7 >>>> cache_fplookup_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 >>>> increasing. >>>>=20 >>>> Address vnode_init+0xc3 corresponds to the mtx_lock call here. >>>>=20 >>>> 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); >>>>=20 >>>> Address __mtx_lock_sleep+0xf8 is the instruction after a call to >>>> lock_delay. >>>>=20 >>>> ps says the command line was >>>>=20 >>>> /usr/bin/awk -f /usr/bin/awk >>>> old-default/2023-10-31_08h21m03s/.poudriere.builders >>>> old-default/2023-10-31_08h21m03s/.poudriere.buildname ... >>>>=20 >>>> with the full list of input files exceeding the ~2KB command line leng= th >>>> limit of ps. >>>> "/usr/bin/awk" is probably not the real second argument. It would cau= se >>>> an >>>> immediate syntax error. >>>>=20 >>>> The hang resolved within a few more minutes and poudriere is continuin= g >>>> happily. >>>>=20 >>>> I have never seen such behavior before. Code in vfs_subr.c tries not = to >>>> hold the >>>> vnode_list_mtx lock for too long. >>>>=20 >>>> Any thoughts? >>>>=20 >>>>=20 >>>> 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. >>>>=20 >>>=20 >>> what does "sysctl vfs.vnode" say >>>=20 >>>=20 >>> -- >>> Mateusz Guzik >>=20 >> With the builds now complete, >>=20 >> vfs.vnode.vnlru.uma_reclaim_calls: 0 >> vfs.vnode.vnlru.kicks: 0 >> vfs.vnode.vnlru.max_free_per_call: 10000 >> vfs.vnode.vnlru.failed_runs: 0 >> vfs.vnode.vnlru.direct_recycles_free: 152871194 >> vfs.vnode.vnlru.recycles_free: 77190881 >> vfs.vnode.vnlru.recycles: 0 >> vfs.vnode.stats.alloc_sleeps: 0 >> vfs.vnode.stats.free: 1269702 >> vfs.vnode.stats.skipped_requeues: 9375158 >> vfs.vnode.stats.created: 235594976 >> vfs.vnode.stats.count: 1407640 >> vfs.vnode.param.wantfree: 681059 >> vfs.vnode.param.limit: 2724237 >>=20 >> Uptime is 11 days, mostly with low I/O rates. >>=20 >>=20 >=20 > please add the uma stats: "sysctl vm.uma.VNODE" >=20 > --=20 > Mateusz Guzik vm.uma.VNODE.stats.xdomain: 0 vm.uma.VNODE.stats.fails: 0 vm.uma.VNODE.stats.frees: 245129082 vm.uma.VNODE.stats.allocs: 246536724 vm.uma.VNODE.stats.current: 1407642 vm.uma.VNODE.domain.0.timin: 215 vm.uma.VNODE.domain.0.limin: 4613 vm.uma.VNODE.domain.0.wss: 10080 vm.uma.VNODE.domain.0.bimin: 391986 vm.uma.VNODE.domain.0.imin: 391986 vm.uma.VNODE.domain.0.imax: 391986 vm.uma.VNODE.domain.0.nitems: 391986 vm.uma.VNODE.limit.bucket_max: 18446744073709551615 vm.uma.VNODE.limit.sleeps: 0 vm.uma.VNODE.limit.sleepers: 0 vm.uma.VNODE.limit.max_items: 0 vm.uma.VNODE.limit.items: 0 vm.uma.VNODE.keg.domain.0.free_slabs: 0 vm.uma.VNODE.keg.domain.0.free_items: 324187 vm.uma.VNODE.keg.domain.0.pages: 266134 vm.uma.VNODE.keg.efficiency: 95 vm.uma.VNODE.keg.reserve: 0 vm.uma.VNODE.keg.align: 7 vm.uma.VNODE.keg.ipers: 8 vm.uma.VNODE.keg.ppera: 1 vm.uma.VNODE.keg.rsize: 488 vm.uma.VNODE.keg.name: VNODE vm.uma.VNODE.bucket_size_max: 254 vm.uma.VNODE.bucket_size: 88 vm.uma.VNODE.flags: 0xd0000 vm.uma.VNODE.size: 488