154506 – [umass] Copying dir with large files makes FreeBSD load above 4.00 and is rather slow

Bug 154506 - [umass] Copying dir with large files makes FreeBSD load above 4.00 and is rather slow

Summary: [umass] Copying dir with large files makes FreeBSD load above 4.00 and is rat...

Status:	Closed Overcome By Events

Alias:	None

Product:	Base System
Classification:	Unclassified
Component:	usb (show other bugs)
Version:	8.1-RELEASE
Hardware:	Any Any

Importance:	Normal Affects Only Me
Assignee:	freebsd-usb (Nobody)

URL:
Keywords:

Depends on:
Blocks:

Reported:	2011-02-04 10:40 UTC by Slawomir Wojciech Wojtczak
Modified:	2018-05-24 08:53 UTC (History)
CC List:	0 users

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Slawomir Wojciech Wojtczak 2011-02-04 10:40:05 UTC

Copying directory with large files (500-1500MB each) with TAR (from MSDOSFS
USB 2.0 disk info ZFS) makes FreeBSD load about 4.00 - 5.00 and is rather
slow, about 9 MB/s while USB 2.0 is capable of 30MB/s of real transfer
rate, the exact used command is:

$ cd /mnt/DISK
$ tar -cf - * | tar -C /storage/DIR -xvf -

I have added some commands outputs and config files that I use, maybe
that would help.

This is MSI MINI-ITX motherboard with Intel T8100 CPU and Intel GMA965
(with X3100), but there is not even X lauched.

The base system is installed on 8GB CF card (slot under the motherboard)
and the ZFS pool is on mirror of 2 x Seagate LP 2TB, without GELI or any
other form of encryption.

What can be cause of such slowness/problems with such high load (4.00 -
5.00) under such simple task?

Regards,
vermaden



# gstat -I 10000000
dT: 10.045s  w: 10.000s
 L(q)  ops/s    r/s   kBps   ms/r    w/s   kBps   ms/w   %busy Name
    0      0      0      0    0.0      0      0    0.0    0.0| ad0
    0      0      0      0    0.0      0      0    0.0    0.0| ad0s1
    0      0      0      0    0.0      0      0    0.0    0.0| ad0s1a
    0      0      0      0    0.0      0      0    0.0    0.0| ad0s1e
    0      0      0      0    0.0      0      0    0.0    0.0| ad0s1f
    0      0      0      0    0.0      0      0    0.0    0.0| label/root
    0    157      0     32   19.6    157  10182    3.8   13.0| ada0
    0      0      0      0    0.0      0      0    0.0    0.0| label/pkg
    0      0      0      0    0.0      0      0    0.0    0.0| label/usr
    0    157      0     32   19.7    157  10182   12.4   44.2| label/disk0
    0    159      0     19   28.0    159  10463    2.8   11.6| ada1
    1    159      0     19   28.0    159  10463   11.7   42.3| label/disk1
    0    142    142   9081   12.7      0      0    0.0   37.0| da0
    0    142    142   9081   14.4      0      0    0.0   46.5| msdosfs/WORKSTOR
    0      0      0      0    0.0      0      0    0.0    0.0| da1
    0      0      0      0    0.0      0      0    0.0    0.0| da1s1
    0      0      0      0    0.0      0      0    0.0    0.0| msdosfs/TERASTOR



# vmstat 5 5
 procs      memory      page                    disks     faults         cpu
 r b w     avm    fre   flt  re  pi  po    fr  sr ad0 ad0   in   sy   cs us sy id
 1 0 0    591M   121M     7   0   0   0  1378 288   0   0  322 1162 2076 11 12 77
 0 0 0    591M   160M     1   0   0   0  9940 4534   0 139 1292 3027 9864 10 72 18
 6 0 0    591M   114M     0   0   0   0  9254   0   0 133 1350 3197 10770 11 66 23
 0 0 0    591M   164M     0   0   0   0  9860 4545   0 145 1168 2660 9269 10 65 25
 1 0 0    591M   113M     0   0   0   0  9110   0   0 128 1317 3192 10703  9 70 21



# vmstat -i
interrupt                          total       rate
irq14: ata0                        10363          0
irq18: ehci0 uhci4               8233580        133
irq19: uhci3                          20          0
irq23: uhci2 ehci1                113895          1
cpu0: timer                     24657951        399
irq256: em0                      7646483        124
irq258: ahci0                    3886485         63
cpu1: timer                     24657817        399
Total                           69206594       1122



# w
10:01AM  up 17:08, 5 users, load averages: 4.36, 4.69, 4.57
USER             TTY      FROM              LOGIN@  IDLE WHAT
vermaden         pts/1    194.0.181.128:S. Thu05PM 16:53 luit ekg
vermaden         pts/2    194.0.181.128:S. Thu04PM  2:08 zpool iostat 60
vermaden         pts/4    194.0.181.128:S. Thu05PM  2:17 tar -C /storage/f1 -xvf - (bsdtar)
vermaden         pts/5    194.0.181.128:S.  9:58AM     2 top
vermaden         pts/6    194.0.181.128:S.  9:59AM     - w



# top -m io -d 2 -s 10 -b
last pid:  3629;  load averages:  4.31,  4.16,  4.37  up 0+17:10:03    10:03:02
46 processes:  2 running, 44 sleeping
CPU: 10.7% user,  0.0% nice, 66.4% system,  1.9% interrupt, 21.0% idle
Mem: 47M Active, 2692M Inact, 978M Wired, 153M Cache, 415M Buf, 49M Free
Swap: 

  PID USERNAME       VCSW  IVCSW   READ  WRITE  FAULT  TOTAL PERCENT COMMAND
 3338 vermaden        899  16022      0      0      0      0   0.00% bsdtar
 1238 vermaden         10   3736      0      0      0      0   0.00% ekg
 3337 vermaden       9252   3233   1438      0      0   1438 100.00% bsdtar
  899 vermaden         78     51      0      0      0      0   0.00% transmission-daemon
  853 root              8      0      0      0      0      0   0.00% nfsd
  989 root             10      2      0      0      0      0   0.00% powerd
 1239 vermaden          0      0      0      0      0      0   0.00% zsh
 3572 vermaden          0      0      0      0      0      0   0.00% zsh
  847 root              0      0      0      0      0      0   0.00% nfsd
 1185 vermaden          3     34      0      0      0      0   0.00% screen
 3580 vermaden          0      0      0      0      0      0   0.00% zsh
 1188 vermaden          0      0      0      0      0      0   0.00% zsh
  876 www              18      1      0      0      0      0   0.00% hiawatha
 3248 vermaden          0      0      0      0      0      0   0.00% zsh
 1097 root              1      1      0      0      0      0   0.00% cron
  731 root              1      0      0      0      0      0   0.00% rpcbind
  917 root              1      0      0      0      0      0   0.00% nmbd
 3254 vermaden          1      1      0      0      0      0   0.00% screen



last pid:  3633;  load averages:  4.25,  4.11,  4.32  up 0+17:11:51    10:04:50
46 processes:  2 running, 44 sleeping
CPU: 10.4% user,  0.0% nice, 64.5% system,  2.4% interrupt, 22.8% idle
Mem: 47M Active, 2720M Inact, 993M Wired, 123M Cache, 415M Buf, 37M Free
Swap: 


  
# top -d 2 -s 10 -b
  PID USERNAME      THR PRI NICE   SIZE    RES STATE   C   TIME   WCPU COMMAND
 3338 vermaden        1  72    0 12972K  2436K tx->tx  1  42:25 23.97% bsdtar
 1238 vermaden        1  57    0 23160K  5208K RUN     1 219:08 18.99% ekg
 3337 vermaden        1  48    0 12972K  2540K pipdwt  1  14:10  8.98% bsdtar
  899 vermaden        3  44    0 29220K  9708K select  1  18:44  0.00% transmission-daemon
  853 root            4  44    0  5804K  1240K rpcsvc  1   0:46  0.00% nfsd
  989 root            1  44    0  6896K  1148K select  1   0:18  0.00% powerd
 1239 vermaden        1  44    0 19468K  4184K pause   1   0:12  0.00% zsh
 3572 vermaden        1  76    0 14572K  3560K pause   1   0:07  0.00% zsh
  847 root            1  44    0  5804K  1508K select  1   0:06  0.00% nfsd
 1185 vermaden        1  44    0  9512K  3156K select  1   0:05  0.00% screen
 3580 vermaden        1  76    0 14572K  3576K pause   1   0:05  0.00% zsh
 1188 vermaden        1  44    0 14572K  3576K pause   0   0:03  0.00% zsh
  876 www             2  44    0 22540K  3264K nanslp  1   0:02  0.00% hiawatha
 3248 vermaden        1  76    0 18308K  4032K pause   1   0:02  0.00% zsh
 1097 root            1  44    0  7952K  1408K nanslp  1   0:02  0.00% cron
  731 root            1  44    0  7956K  1516K select  0   0:01  0.00% rpcbind
  917 root            1  44    0 23088K  3316K select  1   0:01  0.00% nmbd
 3254 vermaden        1  44    0  9384K  2132K pause   1   0:01  0.00% screen



# cat /boot/loader.conf 
# MODULES
ahci_load=YES
zfs_load=YES
aio_load=YES
coretemp_load=YES
msdosfs_iconv_load=YES

# NETWORK
kern.ipc.maxsockbuf=16777216
kern.ipc.nmbclusters=32768
kern.ipc.shmall=32768
kern.ipc.shmmax=67108864
kern.ipc.somaxconn=8192
net.inet.tcp.delayed_ack=0
net.inet.tcp.inflight.enable=0
net.inet.tcp.path_mtu_discovery=0
net.inet.tcp.recvbuf_max=16777216
net.inet.tcp.sendbuf_max=16777216
net.inet.tcp.recvspace=65536
net.inet.tcp.sendspace=65536
net.inet.udp.maxdgram=65536
net.local.stream.recvspace=65536
net.local.stream.sendspace=65536

# FILES
kern.maxfiles=65536
kern.maxfilesperproc=32768

# ZFS | tuning
vfs.zfs.prefetch_disable=1
vfs.zfs.vdev.min_pending=2
vfs.zfs.vdev.max_pending=12
vfs.zfs.cache_flush_disable=1
vfs.zfs.txg.timeout=5

# ZFS | ARC
vfs.zfs.arc_max=1024M
vfs.zfs.arc_min=256M

# 100 is more then enought
kern.hz=100

# avoid additional 128 interrupts per second per core
hint.atrtc.0.clock=0

# do not power devices without driver
hw.pci.do_power_nodriver=3

# disable throttling
hint.p4tcc.0.disabled=1
hint.acpi_throttle.0.disabled=1

# ahci power management
hint.ahcich.0.pm_level=5
hint.ahcich.1.pm_level=5
hint.ahcich.2.pm_level=5

# reduce sound generated interrupts
hint.pcm.0.buffersize=65536
hint.pcm.1.buffersize=65536
hint.pcm.2.buffersize=65536
hw.snd.feeder_buffersize=65536
hw.snd.latency=7



# zpool status
  pool: storage
 state: ONLINE
 scrub: none requested
config:

        NAME             STATE     READ WRITE CKSUM
        storage          ONLINE       0     0     0
          mirror         ONLINE       0     0     0
            label/disk0  ONLINE       0     0     0
            label/disk1  ONLINE       0     0     0

errors: No known data errors



# zpool iostat 30 3
               capacity     operations    bandwidth
pool         used  avail   read  write   read  write
----------  -----  -----  -----  -----  -----  -----
storage     1.07T   761G      6    202  41.4K  1.43M
storage     1.07T   761G      0  1.26K    664  9.66M
storage     1.07T   761G      0  1.25K     68  9.32M



# mount
/dev/label/root on / (ufs, local, noatime)
devfs on /dev (devfs, local, multilabel)
/dev/label/usr on /usr (ufs, local, noatime, soft-updates)
storage/home on /home (zfs, local, noatime)
storage/tmp on /tmp (zfs, local, noatime)
storage/var on /var (zfs, local, noatime)
/dev/label/pkg on /var/db/pkg (ufs, local, noatime, soft-updates)
storage on /storage (zfs, NFS exported, local, noatime)
storage/usr/obj on /usr/obj (zfs, local, noatime)
storage/usr/src on /usr/src (zfs, local, noatime)
storage/usr/ports on /usr/ports (zfs, local, noatime)
storage/usr/ports/obj on /usr/ports/obj (zfs, local, noatime)
storage/usr/ports/distfiles on /usr/ports/distfiles (zfs, local, noatime)
storage/var/db/portsnap on /var/db/portsnap (zfs, local, noatime)
storage/var/db/freebsd-update on /var/db/freebsd-update (zfs, local, noatime)
/dev/msdosfs/TERASTOR on /mnt/TERASTOR (msdosfs, local)
/dev/msdosfs/WORKSTOR on /mnt/WORKSTOR (msdosfs, local)



# df -m
Filesystem                    1M-blocks    Used  Avail Capacity  Mounted on
/dev/label/root                     495      72    418    15%    /
devfs                                 0       0      0   100%    /dev
/dev/label/usr                     6830     771   5990    11%    /usr
storage/home                     747881    2318 745563     0%    /home
storage/tmp                      745563       0 745563     0%    /tmp
storage/var                      745592      29 745563     0%    /var
/dev/label/pkg                      123       9    113     7%    /var/db/pkg
storage                         1867841 1122278 745563    60%    /storage
storage/usr/obj                  745563       0 745563     0%    /usr/obj
storage/usr/src                  745563       0 745563     0%    /usr/src
storage/usr/ports                745981     418 745563     0%    /usr/ports
storage/usr/ports/obj            745566       3 745563     0%    /usr/ports/obj
storage/usr/ports/distfiles      745602      39 745563     0%    /usr/ports/distfiles
storage/var/db/portsnap          745649      86 745563     0%    /var/db/portsnap
storage/var/db/freebsd-update    745569       5 745563     0%    /var/db/freebsd-update
/dev/msdosfs/TERASTOR            952959  263406 689553    28%    /mnt/TERASTOR
/dev/msdosfs/WORKSTOR            953609  776804 176804    81%    /mnt/WORKSTOR

How-To-Repeat: Copy files from USB 2.0 MSDOSFS drive into ZFS pool.

Comment 1 Mark Linimon freebsd_committer

2011-02-07 03:32:44 UTC

Responsible Changed
From-To: freebsd-amd64->freebsd-usb

reclassify.

Comment 2 Eitan Adler freebsd_committer

2017-12-31 07:58:54 UTC

For bugs matching the following criteria:

Status: In Progress Changed: (is less than) 2014-06-01

Reset to default assignee and clear in-progress tags.

Mail being skipped

Comment 3 Slawomir Wojciech Wojtczak 2018-05-24 08:53:14 UTC

That was on FreeBSD 8.x ...