From nobody Fri Jan 20 10:18:25 2023 X-Original-To: stable@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 4NywSR0D4mz2t7w2 for ; Fri, 20 Jan 2023 10:18:31 +0000 (UTC) (envelope-from peter@peter-dambier.de) Received: from mout.gmx.net (mout.gmx.net [212.227.15.18]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange ECDHE (P-256) server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (2048 bits) client-digest SHA256) (Client CN "mout.gmx.net", Issuer "TeleSec ServerPass Class 2 CA" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4NywSP6Rglz3DTp for ; Fri, 20 Jan 2023 10:18:29 +0000 (UTC) (envelope-from peter@peter-dambier.de) Authentication-Results: mx1.freebsd.org; dkim=none; spf=none (mx1.freebsd.org: domain of peter@peter-dambier.de has no SPF policy when checking 212.227.15.18) smtp.mailfrom=peter@peter-dambier.de; dmarc=none Received: from cesium.dl2fba ([217.113.183.83]) by mail.gmx.net (mrgmx004 [212.227.17.190]) with ESMTPSA (Nemesis) id 1M7sDg-1pMg5Z2VAw-00550f for ; Fri, 20 Jan 2023 11:18:27 +0100 Date: Fri, 20 Jan 2023 11:18:25 +0100 From: Peter Dambier To: stable@freebsd.org Subject: Re: close() taking minutes Message-ID: <20230120111825.46d0e337.peter@peter-dambier.de> In-Reply-To: References: Reply-To: peter@peter-dambier.de X-Mailer: Claws Mail 3.17.3 (GTK+ 2.24.31; i586-slackware-linux-gnu) List-Id: Production branch of FreeBSD source code List-Archive: https://lists.freebsd.org/archives/freebsd-stable List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-stable@freebsd.org X-BeenThere: freebsd-stable@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit X-Provags-ID: V03:K1:6OBTQCqZa6h1hDOux5ml88NZWYiqLgPCjd6PaGas4M2lXH+F81W RCDEp2Kk+A/cLWR/spmLbBFTenDJwz23WmzF/JbQI8r2zkHTj0S98pGO2zgMH7AybwtwKAg BcxR5fNrSEo7wIzMPNwPRQuLjhtjHezPBF0lL9keThT5SCc+I48cWxWyHuH87XM+9aM3mcP bGJLMBQpzlvc7SUOvkNXA== X-Spam-Flag: NO UI-OutboundReport: notjunk:1;M01:P0:ukbfMVnG7ZI=;jSG6YnzOpMcf4drjgpdIepZpSNf Apj6on/BFw/jM1fz1Jo6zQ40zI+16tzBdxTc30UiongTAStcOl/vTEYPCnT83gjuPtWxHAqyf gR8mrAovp6wwVcRtvtO4ogpGdK3AwVKODF1bhNTJerWhdbb3OggcDHKNJE1ZpdQqtrpW/vfEV S3zdvPlD716snrtw+c9YsEFXUF0rADwAH5g+tm2dLLSHNoGGLItuVYCjj7tkULKise8Qw1Z0L j/Inckb1TwM14dDdE/wBpz8H7p8NmmoN53dHMg+Pnfz0/au7CnFyejVjQ2Pgjv1XfGImDKnn2 N0Aq0lbx6/1UT36BxUAWXEWg+IhZGWLABDbn5liIOfVg2Gqpe4ndUxpgrvJtxJVD8tKbIVbUK IuVAvtafiA8HQsuCrAw4tSCKJP6OyTYrZK4hfMeIla6saAHgqp0gpMgmdhGfPaKXGE5wkntSM 1K72NhpBMEK2Zf2LVjo4WdK9oouEV/07PgfuHNWgJLsNnK5BNT8M83YYPxISnQyu376PHPAkt 8xsak9ysbWA9uXlhakNEqLbrUhpfPwaHHwJkgmwbawBPQjPyh9BdsxN/tDKW9q9Xs/3QbQfvA gVRzmm4kV9JQhU8Zq6N3/SVu2DYSYqVSgc5cKYlp3+Sm0cAIAjM3vFKzh47ONjsGI3zoTUdp6 4Kensm2jFDt+7JAnC8ed/E4w+UnibsfFn6tJSP061qCAr0Nju+3xe+VQ8EUjUEQxGrxo6mIW0 EG+ZmedQMQqxkTENavdb5MDOlvVVzCny1vmH80pSg+bjiAksqGkLqiW9fpeT59xMNZB0I35BY S3FSDdipdLIhSS4DLQ7QNFp/tlaNRUf66WpinRW/aCCJMDDYTnSektkTZ13UbKktOiNbaCTN3 bN9eeQ+KbmqXP4pU83f7YwUwIdy4QiChpfttuDse63AWtBqaH90b01mw9coNG6TvNa7bKtfx9 JATYOQ== X-Spamd-Result: default: False [-1.20 / 15.00]; AUTH_NA(1.00)[]; MID_CONTAINS_FROM(1.00)[]; NEURAL_HAM_LONG(-1.00)[-1.000]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; NEURAL_HAM_SHORT(-1.00)[-1.000]; MIME_GOOD(-0.10)[text/plain]; RCVD_IN_DNSWL_LOW(-0.10)[212.227.15.18:from]; PREVIOUSLY_DELIVERED(0.00)[stable@freebsd.org]; HAS_REPLYTO(0.00)[peter@peter-dambier.de]; RCPT_COUNT_ONE(0.00)[1]; MLMMJ_DEST(0.00)[stable@freebsd.org]; DMARC_NA(0.00)[peter-dambier.de]; RWL_MAILSPIKE_POSSIBLE(0.00)[212.227.15.18:from]; R_SPF_NA(0.00)[no SPF record]; TO_MATCH_ENVRCPT_ALL(0.00)[]; FROM_HAS_DN(0.00)[]; FREEFALL_USER(0.00)[peter]; TO_DN_NONE(0.00)[]; REPLYTO_ADDR_EQ_FROM(0.00)[]; RCVD_VIA_SMTP_AUTH(0.00)[]; RCVD_COUNT_TWO(0.00)[2]; FROM_EQ_ENVFROM(0.00)[]; MIME_TRACE(0.00)[0:+]; R_DKIM_NA(0.00)[]; ARC_NA(0.00)[]; ASN(0.00)[asn:8560, ipnet:212.227.0.0/16, country:DE]; RCVD_TLS_ALL(0.00)[] X-Rspamd-Queue-Id: 4NywSP6Rglz3DTp X-Spamd-Bar: - X-ThisMailContainsUnwantedMimeParts: N On Fri, 20 Jan 2023 05:11:38 +0100 Peter wrote: > Does this look familiar with anybody? ("truss -dD ls -l something") > > 0.047760369 0.000017548 > open("/etc/nsswitch.conf",O_RDONLY|O_CLOEXEC,0666) = 4 (0x4) > 0.047845099 0.000011290 > fstat(4,{ mode=-rw-r--r-- ,inode=13886,size=272,blksize=4096 }) = 0 > (0x0) 0.047932166 0.000034182 read(4,"#\n# nsswitch.conf(5) - name > ser"...,4096) = 272 (0x110) 0.048007308 0.000010661 > read(4,0x801848000,4096) = 0 (0x0) 45.827173802 45.779056767 > close(4) = 0 (0x0) ^^^^^^^^^^^^ ... 45.866272643 > 0.000020608 open("/etc/localtime",O_RDONLY,077) = 6 (0x6) > 45.866398048 0.000017731 > fstat(6,{ mode=-r--r--r-- ,inode=41572,size=2309,blksize=4096 }) = 0 > (0x0) 45.866505596 0.000054084 > read(6,"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0"...,41448) = 2309 (0x905) > 49.511709215 3.645026276 close(6) = 0 (0x0) ^^^^^^^^^^^ > > (The longest I've seen was more than 5 minutes) > > There is otherwise nothing wrong with the machine, only I am running > a postgres table merge for some 10 mio. rows. And only during that the > effect happens, reproducibly. > > The concerned disk is a mirror of two consumer SATA-SSD. > > "gstat -pod" doesn't look bad, 1-2 items in the queue. > > zfs says it knows nothing of these delays, it just shows two > consumer SSD usually busy with their own garbage collection: > > # zpool iostat -vlq im 3 > capacity operations bandwidth > total_wait disk_wait syncq_wait asyncq_wait scrub trim > syncq_read syncq_write asyncq_read asyncq_write scrubq_read > trimq_write pool alloc free read write read > write read write read write read write read write > wait wait pend activ pend activ pend activ pend activ > pend activ pend activ ---------------- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- ----- im 30.6G 14.9G > 0 4.84K 0 111M - 2ms - 670us - - > - 2ms - - 0 0 0 0 0 0 > 47 2 0 0 0 0 mirror-0 30.6G > 14.9G 0 4.84K 0 111M - 2ms - 670us > - - - 2ms - - 0 0 0 0 > 0 0 47 2 0 0 0 0 ada5p9.elip1 > - - 0 1.65K 0 55.7M - 3ms - 927us > - - - 3ms - - 0 0 0 0 > 0 0 0 0 0 0 0 0 ada1p9.elip1 > - - 0 3.19K 0 55.8M - 2ms - 536us > - - - 1ms - - 0 0 0 0 > 0 0 47 2 0 0 0 0 ---------------- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- capacity > operations bandwidth total_wait disk_wait syncq_wait > asyncq_wait scrub trim syncq_read syncq_write asyncq_read > asyncq_write scrubq_read trimq_write pool alloc > free read write read write read write read write read > write read write wait wait pend activ pend activ pend > activ pend activ pend activ pend activ ---------------- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- > im 30.6G 14.9G 0 5.69K 0 103M - > 3ms - 544us - - - 2ms - - > 0 0 0 0 0 0 84 2 0 0 > 0 0 mirror-0 30.6G 14.9G 0 5.69K 0 > 103M - 3ms - 544us - - - 2ms > - - 0 0 0 0 0 0 98 4 > 0 0 0 0 ada5p9.elip1 - - 0 2.05K > 0 51.4M - 5ms - 837us - - - 4ms > - - 0 0 0 0 0 0 93 2 > 0 0 0 0 ada1p9.elip1 - - 0 3.64K > 0 51.6M - 1ms - 379us - - - 1ms > - - 0 0 0 0 0 0 0 0 > 0 0 0 0 ---------------- ----- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- > ----- ----- ----- ----- > > So where does it happen? (13.1-RELEASE-p5) > > The root, /usr and /var are on ufs, on the same(!) disk (unmirrored), > and have no problem. > > The next 100-some filesystems are on the "im" pool, and there is the > problem, so it is somehow related to ZFS. (The above truss output > was in a jail, which is on the ZFS.) > > I had other things saturating these disks, with no such effect. It > seems postgres does something different here. > > It does also not really look like a congestion problem, because I > can have two or three tasks get stuck in this (and all of them will), > and they continue at very much different times. Looks rather like > some lock wait thing. > > Any clues, anybody? > Maybe unrelated or ot. Both BSD and linux, firefox in partcular or mplayer, kplayer xine ... the program has many windows or tabs open and slowly behaves like molasses. Closing or killing it takes a lot of time and cpu and sometimes never ends. "ps" will show ghosts that go away by killing "X" I have a feeling that I have seen it only on 32 bit os not on 64 bit. I am running "twm" as my window manager that is why logging out is not a good idea on my FreeBSD 13.1-RELEASE releng/13.1-n250148-fc952ac2212 GENERIC amd64 cheers Peter