[Bug 219049] ftruncate() slow on UFS+journaled softupdates

[bugzilla-noreply]

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=219049

Conrad Meyer  changed:

   What|Removed |Added

   Assignee|freebsd-bugs@FreeBSD.org|freebsd...@freebsd.org
 CC||c...@freebsd.org,
   ||k...@freebsd.org,
   ||mckus...@freebsd.org

-- 
You are receiving this mail because:
You are the assignee for the bug.
___
freebsd-bugs@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-bugs
To unsubscribe, send any mail to "freebsd-bugs-unsubscr...@freebsd.org"

[Bug 219049] ftruncate() slow on UFS+journaled softupdates

[bugzilla-noreply]

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=219049

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: wal...@lifeforms.nl

After upgrading to pkg 1.10, I noticed on my package build machine (bare metal
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 disk
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 170MB/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/2085a3e975fc3b1102cbf809f325cb2d394117bc)
hence why the problem appeared only recently.

I created a minimal example which exhibits the problem:

 example.c 

#include 
#include 

int main()
{
char* outfile = "woot2";

int fd = open(outfile, O_WRONLY|O_CREAT|O_EXCL, 0100644);
ftruncate(fd, 10);
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
r...@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) = 0 (0x0)
0.431741841 ftruncate(3,0x186a0) = 0 (0x0)
0.000638086 ftruncate(3,0x186a0) = 0 (0x0)
0.000648680 ftruncate(3,0x186a0) = 0 (0x0)
0.477675635 ftruncate(3,0x186a0) = 0 (0x0)
0.000652645 ftruncate(3,0x186a0) = 0 (0x0)
0.467652474 ftruncate(3,0x186a0) = 0 (0x0)
0.000646409 ftruncate(3,0x186a0) = 0 (0x0)
0.466081847 ftruncate(3,0x186a0) = 0 (0x0)
0.432613030 ftruncate(3,0x186a0) = 0 (0x0)
[...]

As can be seen, a significant part of the ftruncate() calls take almost half 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 suddenly
so slow.

I have tried disabling SU-journaling, and also disabling softupdates entirely.
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: 

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=0x1<4K>
ada0: Previously was known as ad8

Partition table should be good I think:

=>   34  500118125  ada0  GPT  (238G)
 34  6- free -  (3.0K)
 40128 1  freebsd-boot  (64K)
168  490733432 2  freebsd-ufs  (234G)
  4907336008388608 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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
___
freebsd-bugs@freebsd.org mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-bugs
To unsubscribe, send any mail to "freebsd-bugs-unsubscr...@freebsd.org"