8.1-STABLE: zfs and sendfile: problem still exists

[Jeremy Chadwick]

On Fri, Oct 29, 2010 at 06:31:21PM +0400, Alexander Zagrebin wrote:
> > > I've tried the nginx with
> > > disabled sendfile (the nginx.conf contains "sendfile off;"):
> > > 
> > > $ dd if=/dev/random of=test bs=1m count=100
> > > 100+0 records in
> > > 100+0 records out
> > > 104857600 bytes transferred in 5.892504 secs (17795083 bytes/sec)
> > > $ fetch -o /dev/null http://localhost/test
> > > /dev/null                                     100% of  100 
> > MB   41 MBps
> > > $ fetch -o /dev/null http://localhost/test
> > > /dev/null                                     100% of  100 
> > MB   44 MBps
> > > $ fetch -o /dev/null http://localhost/test
> > > /dev/null                                     100% of  100 
> > MB   44 MBps
> > > 
> > 
> > I am really surprised with such a bad performance of sendfile.
> > Will you be able to profile the issue further?
> 
> Yes.
> 
> > I will also try to think of some measurements.
> 
> A transfer rate is too low for the _first_ attempt only.
> Further attempts demonstrates a reasonable transfer rate.
> For example, nginx with "sendfile on;":
> 
> $ dd if=/dev/random of=test bs=1m count=100
> 100+0 records in
> 100+0 records out
> 104857600 bytes transferred in 5.855305 secs (17908136 bytes/sec)
> $ fetch -o /dev/null http://localhost/test
> /dev/null                                       3% of  100 MB  118 kBps
> 13m50s^C
> fetch: transfer interrupted
> $ fetch -o /dev/null http://localhost/test
> /dev/null                                     100% of  100 MB   39 MBps
> 
> If there was no access to the file during some time, then everything
> repeats:
> The first attempt - transfer rate is too low
> A further attempts - no problems
> 
> Can you reproduce the problem on your system?

I can't reproduce it on mine.  Note the resilvering was induced from
some unrelated disk swaps/tests I was performing, and ftpd is already
enabled via inetd on this system.

icarus# uname -a
FreeBSD icarus.home.lan 8.1-STABLE FreeBSD 8.1-STABLE #0: Sat Oct 16 07:10:54 PDT 2010     root at icarus.home.lan:/usr/obj/usr/src/sys/X7SBA_RELENG_8_amd64  amd64
icarus# df -k
Filesystem   1024-blocks      Used     Avail Capacity  Mounted on
/dev/ada0s1a     1012974    451808    480130    48%    /
devfs                  1         1         0   100%    /dev
/dev/ada0s1d    12186190    103986  11107310     1%    /var
/dev/ada0s1e     4058062      5468   3727950     0%    /tmp
/dev/ada0s1f     8395622   1918300   5805674    25%    /usr
data/cvs       686338517       289 686338228     0%    /cvs
data/home      687130693    792465 686338228     0%    /home
data/storage   957080511 270742283 686338228    28%    /storage
icarus# zpool status
  pool: data
 state: ONLINE
 scrub: resilver completed after 0h43m with 0 errors on Sun Oct 17 10:11:19 2010
config:

        NAME        STATE     READ WRITE CKSUM
        data        ONLINE       0     0     0
          mirror    ONLINE       0     0     0
            ada1    ONLINE       0     0     0
            ada2    ONLINE       0     0     0  258G resilvered

errors: No known data errors

icarus# pw useradd ftp -g users -u 2000 -s /bin/csh
icarus# mkdir /home/ftp
icarus# chown ftp:users /home/ftp
icarus# cd /home/ftp
icarus# dd if=/dev/urandom of=test bs=1m count=100
100+0 records in
100+0 records out
104857600 bytes transferred in 1.384421 secs (75741116 bytes/sec)
icarus# chown ftp:users test
icarus# ls -l test
-rw-r--r--  1 ftp  users  104857600 Oct 29 07:41 test
icarus# date ; fetch -o /dev/null ftp://localhost/test
Fri Oct 29 07:45:47 PDT 2010
/dev/null                                     100% of  100 MB  174 MBps
icarus# date ; fetch -o /dev/null ftp://localhost/test
Fri Oct 29 07:45:48 PDT 2010
/dev/null                                     100% of  100 MB  156 MBps
icarus# date ; fetch -o /dev/null ftp://localhost/test
Fri Oct 29 07:45:49 PDT 2010
/dev/null                                     100% of  100 MB  170 MBps
icarus# date ; fetch -o /dev/null ftp://localhost/test
Fri Oct 29 07:45:50 PDT 2010
/dev/null                                     100% of  100 MB  155 MBps
icarus# date ; fetch -o /dev/null ftp://localhost/test
Fri Oct 29 07:45:52 PDT 2010
/dev/null                                     100% of  100 MB  151 MBps

icarus# dd if=/dev/urandom of=test2 bs=1m count=500
500+0 records in
500+0 records out
524288000 bytes transferred in 6.947780 secs (75461228 bytes/sec)
icarus# chown ftp:users test2
icarus# ls -l test2
-rw-r--r--  1 ftp  users  524288000 Oct 29 07:46 test2
icarus# date ; fetch -o /dev/null ftp://localhost/test2
Fri Oct 29 07:47:19 PDT 2010
/dev/null                                     100% of  500 MB  148 MBps
icarus# date ; fetch -o /dev/null ftp://localhost/test2
Fri Oct 29 07:47:24 PDT 2010
/dev/null                                     100% of  500 MB  175 MBps
icarus# date ; fetch -o /dev/null ftp://localhost/test2
Fri Oct 29 07:47:30 PDT 2010
/dev/null                                     100% of  500 MB  164 MBps

What ZFS tunings have you applied to your system?  Can you provide
output from "sysctl -a kstat.zfs.misc.arcstats" before and after a
transfer which exhibits the initial slowdown?

-- 
| Jeremy Chadwick                                   jdc at parodius.com |
| Parodius Networking                       http://www.parodius.com/ |
| UNIX Systems Administrator                  Mountain View, CA, USA |
| Making life hard for others since 1977.              PGP: 4BD6C0CB |