FreeBSD 12.0RC1 desperately slow

Sun Nov 18 20:43:00 UTC 2018

[I should have mentioned: non-debug kernel, buildworld
and buildkernel using devel/powerpc64-xtoolchain-gcc
materials instead of gcc 4.2.1 . I add another comparison.]

On 2018-Nov-18, at 10:41, Mark Millard <marklmi at yahoo.com> wrote:

> On 2018-Nov-18, at 05:16, Dennis Clarke <dclarke at blastwave.org> wrote:
> 
>> I am seeing nearly 1980's type speeds :
>> 
>> 
>> eris# uname -a
>> FreeBSD eris 12.0-RC1 FreeBSD 12.0-RC1 r340470 GENERIC  powerpc
>> eris#
>> 
>> eris# /usr/bin/time -p /usr/sbin/portsnap fetch extract
>> .
>> .
>> .
>> Building new INDEX files... done.
>> real 4181.61
>> user 306.68
>> sys 2917.95
>> eris#
>> 
>> 
>> dmesg says :
>> 
>> ada0 at ata2 bus 0 scbus0 target 0 lun 0
>> ada0: <Hitachi HDS725050KLA360 K2ABC20A> ATA-7 SATA 1.x device
>> ada0: Serial Number KRVN23ZAHA5DBD
>> ada0: 150.000MB/s transfers (SATA 1.x, UDMA5, PIO 8192bytes)
>> ada0: 476940MB (976773168 512 byte sectors)
>> 
>> However performance in just about any trivial test is very very very
>> bad. Three "very" on purpose.  Better than serial interface speeds and
>> even better than old SCO ODT3 UNIX running with tape based swap. However
>> this is just like being back in mid 1980's on MFM/RLL disks :
>> 
>> eris# uname -a
>> FreeBSD eris 12.0-RC1 FreeBSD 12.0-RC1 r340470 GENERIC  powerpc
>> eris#
>> eris# /usr/bin/time -p dd if=/dev/urandom of=/var/tmp/root/random_8GB.dat bs=8192 count=1048576
>> 1048576+0 records in
>> 1048576+0 records out
>> 8589934592 bytes transferred in 498.075845 secs (17246238 bytes/sec)
>> real 498.11
>> user 0.99
>> sys 260.24
>> eris#
> 
> 
> For comparison: for head based on -r339076 on a G5 Quad Core (system
> total core count), 16 GiBytes RAM, SSD file system, SMP enabled (so
> Justin's change has been reverted):
> 
> # /usr/bin/time -p dd if=/dev/urandom of=/var/tmp/random_8GB.dat bs=8192 count=1048576
> 1048576+0 records in
> 1048576+0 records out
> 8589934592 bytes transferred in 206.345413 secs (41628910 bytes/sec)
> real 206.35
> user 1.03
> sys 201.34
> 
> # uname -apKU
> FreeBSD FBSDG5L 12.0-ALPHA8 FreeBSD 12.0-ALPHA8 #4 r339076M: Mon Oct 15 13:19:35 PDT 2018     markmi at FBSDG5L:/usr/obj/powerpc64vtsc_xtoolchain-gcc/powerpc.powerpc64/usr/src/powerpc.powerpc64/sys/GENERIC64vtsc-NODBG  powerpc powerpc64 1200084 1200084
> 
> The old SSD vs. old hardrive transfer rate differences might not
> be all that surprising.

I should have mentioned: non-debug kernel, buildworld
and buildkernel using devel/powerpc64-xtoolchain-gcc
materials instead of gcc 4.2.1 and its toolchain.

[I'll note that such experiments with alternate toolchains
end up with some aspects that do not work right, even if
things build. (I sometimes experiment in this area for more
modern compilers/toolchains.)]

I'll also provide one more item for comparison/contrast
to help isolate processor bottlenecks from I/O ones:

# /usr/bin/time -p dd if=/dev/zero of=/var/tmp/zero_8GB.dat bs=8192 count=1048576
1048576+0 records in
1048576+0 records out
8589934592 bytes transferred in 85.941324 secs (99951155 bytes/sec)
real 85.95
user 0.92
sys 30.48

So, in my context it looks like /dev/urandom use is the
bottleneck when it is in use for the dd. But it still
does around 40 MByte/s for storage I/O with /dev/urandom
--instead of around 17 MByte/s.

For reference, using the dd with /dev/urandom I see things
like the following for the top cpu usage:

  PID USERNAME    THR PRI NICE   SIZE    RES SWAP STATE    C   TIME     CPU COMMAND
   11 root          4 155 ki31      0   128K    0 RUN      0 1503.4 283.49% [idle]
49063 root          1 101    0    12M  2804K    0 CPU3     3   0:33  94.77% dd if=/dev/urandom of=/var/tmp/random_8GB.dat bs=8192 count=1048576
   12 root         22 -56    -      0   704K    0 WAIT    -1 159:20   6.87% [intr]
    2 root          2 -16    -      0    64K    0 -        0   5:17   5.81% [cam]
    0 root         23 -16    -      0   736K    0 swapin   1   1:53   5.72% [kernel]
   18 root          5  20    -      0   160K    0 qsleep   0   3:05   1.72% [bufdaemon]
   21 root          1 -16    -      0    32K    0 smu      3 179:44   1.33% [pmac_thermal]
    5 root          1 -16    -      0    32K    0 -        0   1:59   0.16% [rand_harvestq]
. . .

>> A small x86 boxen machine nearby says :
>> 
>> titan#
>> titan# uname -a
>> FreeBSD titan 12.0-RC1 FreeBSD 12.0-RC1 r340470 GENERIC  amd64
>> titan# /usr/bin/time -p dd if=/dev/urandom of=/var/tmp/root/random_8GB.dat bs=8192 count=1048576
>> 1048576+0 records in
>> 1048576+0 records out
>> 8589934592 bytes transferred in 116.799755 secs (73544115 bytes/sec)
>> real 116.80
>> user 0.40
>> sys 115.80
>> titan#
>> 
>> 
>> and ye old Solaris SPARC crate :
>> 
>> node000 $ uname -a
>> SunOS node000 5.10 Generic_150400-61 sun4u sparc SUNW,SPARC-Enterprise
>> node000 $ /usr/bin/time -p dd if=/dev/urandom of=random_8GB.dat bs=8192 count=1048576
>> 0+1048576 records in
>> 0+1048576 records out
>> 
>> real 161.95
>> user 1.01
>> sys 159.46
>> 
>> 
>> Sure /dev/urandom should be fed as fast as the system can make up
>> numbers from whatever noise sources it has but even a trivial copy
>> of that 8GB file is terribly slow.
>> 
>> eris# /usr/bin/time -p cp -p random_8GB.dat /home/dclarke/
>> real 727.43
>> user 0.05
>> sys 46.81
>> eris#
>> 
>> eris# echo "8k 8589934592 727.43 / pq" | dc
>> 11808606.45285457
>> 
>> So maybe 10 or 11MB/sec on the filesystem.
>> Would love ZFS but this is UFS here.
>> 
>> However I am running with kern.smp.disable=1 but that can't account for
>> this mess .. could it ?

===
Mark Millard
marklmi at yahoo.com
( dsl-only.net went
away in early 2018-Mar)