Bug 219644

Summary: FreeBSD 11 + nginx + apache delay +0.1 second on files greater than 32768 bytes
Product: Base System Reporter: freebsd
Component: kernAssignee: Lawrence Stewart <lstewart>
Status: New ---    
Severity: Affects Many People CC: joneum, lstewart, maxim, v.chernyadev
Priority: ---    
Version: 11.0-RELEASE   
Hardware: amd64   
OS: Any   
Attachments:
Description Flags
test file (size large than 32768 bytes)
none
kdump -E -f nginx > nginx.txt
none
kdump -E -f apache > apache.txt
none
nginx ktrace on FreeBSD10
none
apache ktrace on FreeBSD10
none
tcpdump on FresBSD10
none
tcpdump on FresBSD11 none

Description freebsd 2017-05-29 21:44:36 UTC
Created attachment 183041 [details]
test file (size large than 32768 bytes)

FreeBSD freebsd11.build.ihead.ru 11.0-RELEASE-p8 FreeBSD 11.0-RELEASE-p8 #0: Wed Feb 22 06:12:04 UTC 2017     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64

Proxy requests from nginx to apache.
If apache response more than 32768 bytes (with headers) the request longed on ~0.1 second.

How to reproduce.
1. In httpd.conf add
Listen 127.0.0.1:80
MaxClients 1

2. Add ihead.txt in DocumentRoot (/usr/local/www/apache24/data).
It may be any file larger than 32768 bytes.

3. In nginx.conf in server {...} add 
location /ihead.txt {
proxy_pass http://127.0.0.1:80;
}

4. find nginx and apache PIDs
ps -aux | grep nginx
ps -aux | grep httpd

5. run ktrace on finded PIDs 
ktrace -p 42260 -t cfinpstuwy -f nginx
ktrace -p 42184 -t cfinpstuwy -f apache

6. Request http://IP_nginx/ihead.txt

7. Stop ktrace
ktrace -C

8. Make dumps readable
kdump -E -f nginx > nginx.txt
kdump -E -f apache > apache.txt

9. There is +0.1 second delay
 42260 nginx    0.004903 CSW   stop kernel "kqread"
 42260 nginx    0.110929 CSW   resume kernel "kqread" 
 
 42184 httpd    0.000591 CSW   stop kernel "select"
 42184 httpd    0.199081 CSW   resume kernel "select"


Problem not reproduced on FreeBSD 10.
Comment 1 freebsd 2017-05-29 21:45:42 UTC
Created attachment 183042 [details]
kdump -E -f nginx > nginx.txt
Comment 2 freebsd 2017-05-29 21:46:20 UTC
Created attachment 183043 [details]
kdump -E -f apache > apache.txt
Comment 3 Maxim Konovalov freebsd_committer 2017-05-30 09:21:26 UTC
Hello,

As was suggested in nginx trac ticket gathering tcpdump on FreeBSD 11 and 10 would be useful as well.

Also, comparing problematic traces with FreeBSD 10 is also a good idea.
Comment 4 freebsd 2017-05-30 10:29:56 UTC
Created attachment 183061 [details]
nginx ktrace on FreeBSD10
Comment 5 freebsd 2017-05-30 10:30:35 UTC
Created attachment 183062 [details]
apache ktrace on FreeBSD10
Comment 6 freebsd 2017-05-30 10:31:11 UTC
Created attachment 183063 [details]
tcpdump on FresBSD10
Comment 7 freebsd 2017-05-30 10:31:43 UTC
Created attachment 183064 [details]
tcpdump on FresBSD11
Comment 8 freebsd 2017-05-30 10:33:41 UTC
sysctl net.inet.tcp.delayed_ack
net.inet.tcp.delayed_ack: 1

sysctl net.inet.tcp.delacktime
net.inet.tcp.delacktime: 100

1)
sysctl net.inet.tcp.delayed_ack=0
net.inet.tcp.delayed_ack: 1 -> 0

Problem is not reproduced.

2)
sysctl net.inet.tcp.delayed_ack=1
net.inet.tcp.delayed_ack: 0 -> 1

sysctl net.inet.tcp.delacktime=200
net.inet.tcp.delacktime: 100 -> 200

Problem is reproduced with +0.2 seconds delay.
Comment 9 Maxim Konovalov freebsd_committer 2017-05-30 11:07:09 UTC
What are delayed_ack settings on your FreeBSD 10 system?

Are they non default?
Comment 10 freebsd 2017-05-30 11:40:05 UTC
(In reply to Maxim Konovalov from comment #9)

Defaults are:

sysctl net.inet.tcp.delayed_ack
net.inet.tcp.delayed_ack: 1

sysctl net.inet.tcp.delacktime
net.inet.tcp.delacktime: 100
Comment 11 freebsd 2017-05-30 11:42:11 UTC
(In reply to Maxim Konovalov from comment #9)

[root@freebsd10 ~]# uname -a
FreeBSD freebsd10.build.ihead.ru 10.3-RELEASE-p18 FreeBSD 10.3-RELEASE-p18 #0: Tue Apr 11 10:31:00 UTC 2017     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64
[root@freebsd10 ~]# sysctl net.inet.tcp.delayed_ack
net.inet.tcp.delayed_ack: 1
[root@freebsd10 ~]# sysctl sysctl net.inet.tcp.delacktime
net.inet.tcp.delacktime: 100
Comment 12 Maxim Konovalov freebsd_committer 2017-05-30 12:08:58 UTC
Can you share please "sysctl net.inet.tcp" on your FreeBSD 10 and FreeBSD 11?
Comment 13 freebsd 2017-05-30 12:20:49 UTC
(In reply to Maxim Konovalov from comment #12)

[root@freebsd10 ~]# sysctl net.inet.tcp
net.inet.tcp.rfc1323: 1
net.inet.tcp.mssdflt: 536
net.inet.tcp.keepidle: 7200000
net.inet.tcp.keepintvl: 75000
net.inet.tcp.sendspace: 32768
net.inet.tcp.recvspace: 65536
net.inet.tcp.keepinit: 75000
net.inet.tcp.delacktime: 100
net.inet.tcp.v6mssdflt: 1220
net.inet.tcp.nolocaltimewait: 0
net.inet.tcp.maxtcptw: 12950
net.inet.tcp.per_cpu_timers: 0
net.inet.tcp.v6pmtud_blackhole_mss: 1220
net.inet.tcp.pmtud_blackhole_mss: 1200
net.inet.tcp.pmtud_blackhole_failed: 0
net.inet.tcp.pmtud_blackhole_activated_min_mss: 0
net.inet.tcp.pmtud_blackhole_activated: 0
net.inet.tcp.pmtud_blackhole_detection: 0
net.inet.tcp.rexmit_drop_options: 0
net.inet.tcp.keepcnt: 8
net.inet.tcp.finwait2_timeout: 60000
net.inet.tcp.fast_finwait2_recycle: 0
net.inet.tcp.always_keepalive: 1
net.inet.tcp.rexmit_slop: 200
net.inet.tcp.rexmit_min: 30
net.inet.tcp.msl: 30000
net.inet.tcp.persmax: 60000
net.inet.tcp.persmin: 5000
net.inet.tcp.syncache.rst_on_sock_fail: 1
net.inet.tcp.syncache.rexmtlimit: 3
net.inet.tcp.syncache.hashsize: 512
net.inet.tcp.syncache.count: 0
net.inet.tcp.syncache.cachelimit: 15375
net.inet.tcp.syncache.bucketlimit: 30
net.inet.tcp.syncookies_only: 0
net.inet.tcp.syncookies: 1
net.inet.tcp.soreceive_stream: 0
net.inet.tcp.isn_reseed_interval: 0
net.inet.tcp.icmp_may_rst: 1
net.inet.tcp.pcbcount: 4
net.inet.tcp.do_tcpdrain: 1
net.inet.tcp.tcbhashsize: 16384
net.inet.tcp.log_debug: 0
net.inet.tcp.minmss: 216
net.inet.tcp.sack.globalholes: 0
net.inet.tcp.sack.globalmaxholes: 65536
net.inet.tcp.sack.maxholes: 128
net.inet.tcp.sack.enable: 1
net.inet.tcp.reass.overflows: 9
net.inet.tcp.reass.cursegments: 0
net.inet.tcp.reass.maxsegments: 7900
net.inet.tcp.sendbuf_max: 2097152
net.inet.tcp.sendbuf_inc: 8192
net.inet.tcp.sendbuf_auto: 1
net.inet.tcp.tso: 1
net.inet.tcp.path_mtu_discovery: 1
net.inet.tcp.recvbuf_max: 2097152
net.inet.tcp.recvbuf_inc: 16384
net.inet.tcp.recvbuf_auto: 1
net.inet.tcp.insecure_rst: 0
net.inet.tcp.ecn.maxretries: 1
net.inet.tcp.ecn.enable: 0
net.inet.tcp.abc_l_var: 2
net.inet.tcp.rfc3465: 1
net.inet.tcp.experimental.initcwnd10: 1
net.inet.tcp.rfc3390: 1
net.inet.tcp.rfc3042: 1
net.inet.tcp.do_pipe: 0
net.inet.tcp.drop_synfin: 0
net.inet.tcp.delayed_ack: 1
net.inet.tcp.blackhole: 0
net.inet.tcp.log_in_vain: 0
net.inet.tcp.hostcache.purge: 0
net.inet.tcp.hostcache.prune: 300
net.inet.tcp.hostcache.expire: 3600
net.inet.tcp.hostcache.count: 0
net.inet.tcp.hostcache.bucketlimit: 30
net.inet.tcp.hostcache.hashsize: 512
net.inet.tcp.hostcache.cachelimit: 15360
net.inet.tcp.cc.available: newreno
net.inet.tcp.cc.algorithm: newreno

[root@freebsd11 ~]# sysctl net.inet.tcp
net.inet.tcp.rfc1323: 1
net.inet.tcp.mssdflt: 536
net.inet.tcp.keepidle: 7200000
net.inet.tcp.keepintvl: 75000
net.inet.tcp.sendspace: 32768
net.inet.tcp.recvspace: 65536
net.inet.tcp.keepinit: 75000
net.inet.tcp.delacktime: 100
net.inet.tcp.v6mssdflt: 1220
net.inet.tcp.nolocaltimewait: 0
net.inet.tcp.maxtcptw: 12900
net.inet.tcp.per_cpu_timers: 0
net.inet.tcp.v6pmtud_blackhole_mss: 1220
net.inet.tcp.pmtud_blackhole_mss: 1200
net.inet.tcp.pmtud_blackhole_failed: 0
net.inet.tcp.pmtud_blackhole_activated_min_mss: 0
net.inet.tcp.pmtud_blackhole_activated: 0
net.inet.tcp.pmtud_blackhole_detection: 0
net.inet.tcp.rexmit_drop_options: 0
net.inet.tcp.keepcnt: 8
net.inet.tcp.finwait2_timeout: 60000
net.inet.tcp.fast_finwait2_recycle: 0
net.inet.tcp.always_keepalive: 1
net.inet.tcp.rexmit_slop: 200
net.inet.tcp.rexmit_min: 30
net.inet.tcp.msl: 30000
net.inet.tcp.persmax: 60000
net.inet.tcp.persmin: 5000
net.inet.tcp.syncache.rst_on_sock_fail: 1
net.inet.tcp.syncache.rexmtlimit: 3
net.inet.tcp.syncache.hashsize: 512
net.inet.tcp.syncache.count: 0
net.inet.tcp.syncache.cachelimit: 15364
net.inet.tcp.syncache.bucketlimit: 30
net.inet.tcp.syncookies_only: 0
net.inet.tcp.syncookies: 1
net.inet.tcp.functions_available:
Stack                           D PCB count
default                         * 4

net.inet.tcp.functions_default: default
net.inet.tcp.soreceive_stream: 0
net.inet.tcp.isn_reseed_interval: 0
net.inet.tcp.icmp_may_rst: 1
net.inet.tcp.pcbcount: 4
net.inet.tcp.do_tcpdrain: 1
net.inet.tcp.tcbhashsize: 16384
net.inet.tcp.log_debug: 0
net.inet.tcp.minmss: 216
net.inet.tcp.sack.globalholes: 0
net.inet.tcp.sack.globalmaxholes: 65536
net.inet.tcp.sack.maxholes: 128
net.inet.tcp.sack.enable: 1
net.inet.tcp.reass.cursegments: 0
net.inet.tcp.reass.maxsegments: 7900
net.inet.tcp.sendbuf_max: 2097152
net.inet.tcp.sendbuf_inc: 8192
net.inet.tcp.sendbuf_auto: 1
net.inet.tcp.tso: 1
net.inet.tcp.path_mtu_discovery: 1
net.inet.tcp.recvbuf_max: 2097152
net.inet.tcp.recvbuf_inc: 16384
net.inet.tcp.recvbuf_auto: 1
net.inet.tcp.insecure_rst: 0
net.inet.tcp.insecure_syn: 0
net.inet.tcp.ecn.maxretries: 1
net.inet.tcp.ecn.enable: 2
net.inet.tcp.abc_l_var: 2
net.inet.tcp.rfc3465: 1
net.inet.tcp.initcwnd_segments: 10
net.inet.tcp.rfc3390: 1
net.inet.tcp.rfc3042: 1
net.inet.tcp.rfc6675_pipe: 0
net.inet.tcp.drop_synfin: 0
net.inet.tcp.delayed_ack: 1
net.inet.tcp.blackhole: 0
net.inet.tcp.log_in_vain: 0
net.inet.tcp.hostcache.purgenow: 0
net.inet.tcp.hostcache.purge: 0
net.inet.tcp.hostcache.prune: 300
net.inet.tcp.hostcache.expire: 3600
net.inet.tcp.hostcache.count: 0
net.inet.tcp.hostcache.bucketlimit: 30
net.inet.tcp.hostcache.hashsize: 512
net.inet.tcp.hostcache.cachelimit: 15360
net.inet.tcp.cc.available: newreno
net.inet.tcp.cc.algorithm: newreno
Comment 14 Maxim Konovalov freebsd_committer 2017-05-30 13:58:02 UTC
Can you also share your nginx.conf from both systems please?
Comment 15 freebsd 2017-05-30 14:02:30 UTC
(In reply to Maxim Konovalov from comment #14)

nginx.conf is identical on both systems.


#user  nobody;
worker_processes  1;

#error_log  logs/error.log;
#error_log  logs/error.log  notice;
#error_log  logs/error.log  info;

#pid        logs/nginx.pid;


events {
    worker_connections  1024;
}


http {
    include       mime.types;
    default_type  application/octet-stream;

    #log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
    #                  '$status $body_bytes_sent "$http_referer" '
    #                  '"$http_user_agent" "$http_x_forwarded_for"';

    #access_log  logs/access.log  main;

    sendfile        on;
    #tcp_nopush     on;

    #keepalive_timeout  0;
    keepalive_timeout  65;

    #gzip  on;

    server {
        listen       80;
        server_name  localhost;

        #charset koi8-r;

        #access_log  logs/host.access.log  main;

        location / {
            root   html;
            index  index.html index.htm;
        }

        #error_page  404              /404.html;

        # redirect server error pages to the static page /50x.html
        #
        error_page   500 502 503 504  /50x.html;
        location = /50x.html {
            root   html;
        }

        # proxy the PHP scripts to Apache listening on 127.0.0.1:80
        #
        #location ~ \.php$ {
        #    proxy_pass   http://127.0.0.1;
        #}

        # pass the PHP scripts to FastCGI server listening on 127.0.0.1:9000
        #
        #location ~ \.php$ {
        #    root           html;
        #    fastcgi_pass   127.0.0.1:9000;
        #    fastcgi_index  index.php;
        #    fastcgi_param  SCRIPT_FILENAME  /scripts$fastcgi_script_name;
        #    include        fastcgi_params;
        #}

        # deny access to .htaccess files, if Apache's document root
        # concurs with nginx's one
        #
        #location ~ /\.ht {
        #    deny  all;
        #}

location /ihead.txt {
proxy_pass http://127.0.0.1:80;
}
    }

}
Comment 16 Maxim Konovalov freebsd_committer 2017-06-01 08:50:23 UTC
Hello,

I haven't had a change to dig further so far but just noticed this bug report:

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

It could be related to the issue you observe.

Can you try to update FreeBSD 11.0 to @319397 and check if it still manifest itself?

Thanks,

Maxim
Comment 17 freebsd 2017-06-01 18:51:51 UTC
(In reply to Maxim Konovalov from comment #16)
Hi.
I got diff from https://svnweb.freebsd.org/base?view=revision&revision=319397 rebuild and install kernel.

It did not help.
Comment 18 freebsd 2017-06-11 20:12:56 UTC
Can anybody help with this?
Is is easy reproduceble FreeBSD11's strange behavior.
Comment 19 Maxim Konovalov freebsd_committer 2017-06-13 16:36:06 UTC
Can you run one more experiments for me please?  Specifically re-run your test with the following sysctl before:

sysctl net.inet.tcp.initcwnd_segments=40

Thanks,

Maxim
Comment 20 freebsd 2017-06-13 17:58:04 UTC
(In reply to Maxim Konovalov from comment #19)

sysctl net.inet.tcp.initcwnd_segments=40
net.inet.tcp.initcwnd_segments: 10 -> 40

result: no problem
Comment 21 freebsd 2017-08-10 14:55:57 UTC
Problem is reproduced on FreeBSD 11.1.

FreeBSD 11.1-RELEASE-p1 #0: Wed Aug  9 11:55:48 UTC 2017     root@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64

Why nobody cares about it?
Comment 22 Maxim Konovalov freebsd_committer 2017-08-10 15:05:00 UTC
(In reply to freebsd from comment #21)

You've got the workaround, right?  Does it work for you?
Comment 23 freebsd 2017-08-10 15:13:21 UTC
Yes, I have workaround (sysctl net.inet.tcp.delayed_ack=0) and it works.
But I not sure is it ok, and what problems it may bring in other parts of network stack.

By the way, the problem exists on default setup, and this is not good.
People may think, that FreeBSD is slow.
Comment 24 v.chernyadev 2018-09-17 11:42:55 UTC
This is still relevant for us. When to wait for correction?
Comment 25 Lawrence Stewart freebsd_committer 2018-10-09 02:58:11 UTC
Apologies, I had completely forgotten about this issue. Thanks for the reminder.
Comment 26 Jochen Neumeister freebsd_committer 2019-02-11 11:16:02 UTC
(In reply to Lawrence Stewart from comment #25)

ping :-)