Date: Fri, 4 Feb 2011 10:39:46 GMT From: vermaden <vermaden@interia.pl> To: freebsd-gnats-submit@FreeBSD.org Subject: amd64/154506: Copying dir with large files makes FreeBSD load above 4.00 and is rather slow Message-ID: <201102041039.p14AdkOj052961@red.freebsd.org> Resent-Message-ID: <201102041040.p14Ae5lT049174@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 154506
>Category: amd64
>Synopsis: Copying dir with large files makes FreeBSD load above 4.00 and is rather slow
>Confidential: no
>Severity: serious
>Priority: low
>Responsible: freebsd-amd64
>State: open
>Quarter:
>Keywords:
>Date-Required:
>Class: sw-bug
>Submitter-Id: current-users
>Arrival-Date: Fri Feb 04 10:40:05 UTC 2011
>Closed-Date:
>Last-Modified:
>Originator: vermaden
>Release: GENERIC 8.1-RELEASE
>Organization:
>Environment:
FreeBSD blackbox 8.1-RELEASE FreeBSD 8.1-RELEASE #0: Mon Jul 19 02:36:49 UTC 2010 root@mason.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC amd64
>Description:
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 slowlyness/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.
>Fix:
>Release-Note:
>Audit-Trail:
>Unformatted:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201102041039.p14AdkOj052961>