From owner-freebsd-bugs@freebsd.org Wed May 3 16:21:58 2017 Return-Path: Delivered-To: freebsd-bugs@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 772ADD5CABA for ; Wed, 3 May 2017 16:21:58 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from kenobi.freebsd.org (kenobi.freebsd.org [IPv6:2001:1900:2254:206a::16:76]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 5D8951B1 for ; Wed, 3 May 2017 16:21:58 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from bugs.freebsd.org ([127.0.1.118]) by kenobi.freebsd.org (8.15.2/8.15.2) with ESMTP id v43GLwPB075402 for ; Wed, 3 May 2017 16:21:58 GMT (envelope-from bugzilla-noreply@freebsd.org) From: bugzilla-noreply@freebsd.org To: freebsd-bugs@FreeBSD.org Subject: [Bug 219049] ftruncate() slow on UFS+journaled softupdates Date: Wed, 03 May 2017 16:21:58 +0000 X-Bugzilla-Reason: AssignedTo X-Bugzilla-Type: new X-Bugzilla-Watch-Reason: None X-Bugzilla-Product: Base System X-Bugzilla-Component: kern X-Bugzilla-Version: 10.3-RELEASE X-Bugzilla-Keywords: X-Bugzilla-Severity: Affects Only Me X-Bugzilla-Who: walter@lifeforms.nl X-Bugzilla-Status: New X-Bugzilla-Resolution: X-Bugzilla-Priority: --- X-Bugzilla-Assigned-To: freebsd-bugs@FreeBSD.org X-Bugzilla-Flags: X-Bugzilla-Changed-Fields: bug_id short_desc product version rep_platform op_sys bug_status bug_severity priority component assigned_to reporter Message-ID: Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: https://bugs.freebsd.org/bugzilla/ Auto-Submitted: auto-generated MIME-Version: 1.0 X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 03 May 2017 16:21:58 -0000 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D219049 Bug ID: 219049 Summary: ftruncate() slow on UFS+journaled softupdates Product: Base System Version: 10.3-RELEASE Hardware: amd64 OS: Any Status: New Severity: Affects Only Me Priority: --- Component: kern Assignee: freebsd-bugs@FreeBSD.org Reporter: walter@lifeforms.nl After upgrading to pkg 1.10, I noticed on my package build machine (bare me= tal i7+SSD) that extracting packages was about 100x slower than with pkg 1.9, a 'pkg upgrade' took hours instead of minutes, making it unusable. I noticed that pkg was in 'biowr' state, and 'systat -vmstat' showed the di= sk at '100% busy' even though there were maybe 10-50 transactions/sec and less than 1MB/s throughput. Doing 'dd' in a separate terminal can write with 170= MB/s so the physical disk is not saturated. The truss tool showed that a lot of time was spent in the ftruncate() call, which was introduced in pkg 1.10 (https://github.com/freebsd/pkg/commit/2085a3e975fc3b1102cbf809f325cb2d3941= 17bc) hence why the problem appeared only recently. I created a minimal example which exhibits the problem: ________ example.c ________ #include #include int main() { char* outfile =3D "woot2"; int fd =3D open(outfile, O_WRONLY|O_CREAT|O_EXCL, 0100644); ftruncate(fd, 100000); close(fd); } ________ loop.sh ________ #!/bin/sh /usr/bin/cc -o example example.c || exit 1 /usr/bin/uname -a /sbin/mount | grep ada while true; do rm -f ./woot2 sleep 1 /usr/bin/truss -D -o truss.out ./example grep ftruncate truss.out done _________________________ This produces the following output on my machine: FreeBSD builder.dt.lfms.nl 10.3-RELEASE-p18 FreeBSD 10.3-RELEASE-p18 #0: Tue Apr 11 10:31:00 UTC 2017=20=20=20=20 root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64 /dev/ada0p2 on / (ufs, local, noatime, journaled soft-updates) 0.439747415 ftruncate(3,0x186a0) =3D 0 (0x0) 0.431741841 ftruncate(3,0x186a0) =3D 0 (0x0) 0.000638086 ftruncate(3,0x186a0) =3D 0 (0x0) 0.000648680 ftruncate(3,0x186a0) =3D 0 (0x0) 0.477675635 ftruncate(3,0x186a0) =3D 0 (0x0) 0.000652645 ftruncate(3,0x186a0) =3D 0 (0x0) 0.467652474 ftruncate(3,0x186a0) =3D 0 (0x0) 0.000646409 ftruncate(3,0x186a0) =3D 0 (0x0) 0.466081847 ftruncate(3,0x186a0) =3D 0 (0x0) 0.432613030 ftruncate(3,0x186a0) =3D 0 (0x0) [...] As can be seen, a significant part of the ftruncate() calls take almost hal= f a second to complete. You would expect this operation to be 0.0 seconds almost always. It explains why pkg, which ftruncates thousands of files, is sudden= ly so slow. I have tried disabling SU-journaling, and also disabling softupdates entire= ly. The problem only appears when using UFS with journaled softupdates: mount | delay -------------------------------|-------- journaled softupdates | PRESENT softupdates without journaling | absent no softupdates | absent I have tried booting in single user mode from various live CDs, letting the loop script run for a longer time. The problem is most severe on FreeBSD 10= .3, is absent on FreeBSD 11.0, and seems back in very diminished form on a 12.0-CURRENT (Thu Apr 20 05:39:11) image. I took the following measurements: Kernel | slow | fast | slow% ---------------------------|------|------|------ 10.3-RELEASE-p18 amd64 | 54 | 138 | 28% 11.0-RELEASE-p1 amd64 | 0 | 299 | 0% 12.0-CURRENT r317181 amd64 | 5 | 224 | 2% I have tried to reproduce this problem on various VMs, but could not get it= to appear. I just have a single bare metal Core i7 SSD machine which has it. The disk is a:=20 ada0 at ahcich2 bus 0 scbus2 target 0 lun 0 ada0: ACS-2 ATA SATA 3.x device ada0: Serial Number OCZ-**************** ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes) ada0: Command Queueing enabled ada0: 244198MB (500118192 512 byte sectors) ada0: quirks=3D0x1<4K> ada0: Previously was known as ad8 Partition table should be good I think: =3D> 34 500118125 ada0 GPT (238G) 34 6 - free - (3.0K) 40 128 1 freebsd-boot (64K) 168 490733432 2 freebsd-ufs (234G) 490733600 8388608 3 freebsd-swap (4.0G) 499122208 995951 - free - (486M) I would like to debug further into the kernel but have little dtrace experience. Any hints would be welcome. --=20 You are receiving this mail because: You are the assignee for the bug.=