PiBa-NL
HAProxy 1.7.9 FreeBSD 100% CPU usage
November 09, 2017 02:40AM
Hi List,

I've experienced a issue where its using 100% cpu usage with haproxy
1.7.9 on FreeBSD 11.1p3 / pfSense 2.4.2dev.

There is very little traffic actually hitting this haproxy instance. But
it happened for the second time in a few days now.
Actually haproxy has been running for a few weeks with 100% and i didnt
notice.. it does keep working it seems..

Anyhow thought i would try and capture the next event if it would happen
again. It did after a few hours..

After the truss output below the last line keeps repeating fast lots and
lots of times.

kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
kevent(0,0x0,0,{ 1,EVFILT_READ,EV_EOF,0x0,0x0,0x0 },7,{ 0.994000000 }) =
1 (0x1)
recvfrom(1,0x8024ed972,16290,0,NULL,0x0)     = 0 (0x0)
kevent(0,{ 1,EVFILT_READ,EV_DELETE,0x0,0x0,0x0 },1,0x0,0,0x0) = 0 (0x0)
kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)

I tried to gather all possible relevant info in attached file. Not using
much special configuration options.. but i am using lua to server a
small simple static response.. I'm not sure if its a problem that might
be related to LUA, or perhaps there is some other issue.?.
I've got tcpdump and complete truss output from before and while it
happened after a few hours, but actually just a few request (+- 29)..
But i would prefer to send these off list though, Willy if you desire i
send em to your mail address? But maybe i have overlooked it on the
mailinglist and its a known issue already..? Last connection which i
think caused/triggered the issue is in screenshot(if it attaches right
to the mail..)basically just a GET request which gets a ack, followed by
a FYN,ACK packet from the client 30 seconds later again followed by a ack..

The LetsEncrypt backend that is part of the configuration never got a
single request according to stats..

Is it a known issue?
Are tcpdump/truss output desired ..? (where should i send em?)
Is there any other output that can try to gather next time?

Regards,
PiBa-NL

HA-Proxy version 1.7.9 2017/08/18
  TARGET  = freebsd

[2.4.2-DEVELOPMENT][[email protected]]/root:
/usr/local/pkg/haproxy/haproxy_socket.sh show sess all
show sess all 0x80242b800: [08/Nov/2017:19:40:18.868158] id=15
proto=tcpv4 source=45.76.a.b:53752
  flags=0x48a, conn_retries=0, srv_conn=0x0, pend_pos=0x0
  frontend=www (id=3 mode=http), listener=37.97.x.y:80 (id=1)
addr=37.97.x.y:80
  backend=<NONE> (id=-1 mode=-)
  server=<NONE> (id=-1)
  task=0x80248f380 (state=0x04 nice=0 calls=4 exp=<NEVER> age=4h23m)
  txn=0x802421800 flags=0x8200000 meth=1 status=-1 req.st=MSG_BODY
rsp.st=MSG_RPBEFORE waiting=0
  si[0]=0x80242ba38 (state=EST flags=0x08 endp0=CONN:0x8024ca480
exp=<NEVER>, et=0x000)
  si[1]=0x80242ba60 (state=EST flags=0x4010 endp1=APPCTX:0x8024ca600
exp=<NEVER>, et=0x000)
  co0=0x8024ca480 ctrl=tcpv4 xprt=RAW data=STRM target=LISTENER:0x8024ca300
      flags=0x0025b300 fd=1 fd.state=22 fd.cache=0 updt=0
  app1=0x8024ca600 st0=0 st1=0 st2=0 applet=<lua.me_frame_lua>
  req=0x80242b810 (f=0x80c020 an=0x0 pipe=0 tofwd=-1 total=94)
      an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
      buf=0x8024ed900 data=0x8024ed914 o=94 p=94 req.next=94 i=0 size=16384
  res=0x80242b850 (f=0x80400000 an=0xa00000 pipe=0 tofwd=0 total=0)
      an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
      buf=0x783160 data=0x783174 o=0 p=0 rsp.next=0 i=0 size=0
0x80242ac00: [09/Nov/2017:00:04:24.403636] id=31 proto=unix_stream
source=unix:1
  flags=0x88, conn_retries=0, srv_conn=0x0, pend_pos=0x0
  frontend=GLOBAL (id=0 mode=tcp), listener=? (id=1) addr=unix:1
  backend=<NONE> (id=-1 mode=-)
  server=<NONE> (id=-1)
  task=0x80248f4d0 (state=0x0a nice=-64 calls=1 exp=10s age=?)
  si[0]=0x80242ae38 (state=EST flags=0x08 endp0=CONN:0x8024ca900
exp=<NEVER>, et=0x000)
  si[1]=0x80242ae60 (state=EST flags=0x4018 endp1=APPCTX:0x8024ca780
exp=<NEVER>, et=0x000)
  co0=0x8024ca900 ctrl=unix_stream xprt=RAW data=STRM
target=LISTENER:0x8024ca000
      flags=0x0020b306 fd=2 fd.state=25 fd.cache=0 updt=0
  app1=0x8024ca780 st0=7 st1=0 st2=3 applet=<CLI>
  req=0x80242ac10 (f=0xc08200 an=0x0 pipe=0 tofwd=-1 total=15)
      an_exp=<NEVER> rex=10s wex=<NEVER>
      buf=0x8024e7dc0 data=0x8024e7dd4 o=0 p=0 req.next=0 i=0 size=16384
  res=0x80242ac50 (f=0x80008002 an=0x0 pipe=0 tofwd=-1 total=1198)
      an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
      buf=0x8025603c0 data=0x8025603d4 o=1198 p=1198 rsp.next=0 i=0
size=16384

FreeBSD pfsense.local 11.1-RELEASE-p3 FreeBSD 11.1-RELEASE-p3 #362 r313908+9cf44ec5484(RELENG_2_4): Fri Nov 3 08:23:14 CDT 2017

[2.4.2-DEVELOPMENT][[email protected]]/root: haproxy -vv
HA-Proxy version 1.7.9 2017/08/18
Copyright 2000-2017 Willy Tarreau <[email protected]>

Build options :
TARGET = freebsd
CPU = generic
CC = cc
CFLAGS = -O2 -pipe -fstack-protector -fno-strict-aliasing -fno-strict-aliasing -Wdeclaration-after-statement -fwrapv -DFREEBSD_PORTS
OPTIONS = USE_GETADDRINFO=1 USE_ZLIB=1 USE_CPU_AFFINITY=1 USE_ACCEPT4=1 USE_REGPARM=1 USE_OPENSSL=1 USE_LUA=1 USE_STATIC_PCRE=1 USE_PCRE_JIT=1

Default settings :
maxconn = 2000, bufsize = 16384, maxrewrite = 1024, maxpollevents = 200

Encrypted password support via crypt(3): yes
Built with zlib version : 1.2.11
Running on zlib version : 1.2.11
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with OpenSSL version : OpenSSL 1.0.2k-freebsd 26 Jan 2017
Running on OpenSSL version : OpenSSL 1.0.2k-freebsd 26 Jan 2017
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports prefer-server-ciphers : yes
Built with PCRE version : 8.40 2017-01-11
Running on PCRE version : 8.40 2017-01-11
PCRE library supports JIT : yes
Built with Lua version : Lua 5.3.4
Built with transparent proxy support using: IP_BINDANY IPV6_BINDANY

Available polling systems :
kqueue : pref=300, test result OK
poll : pref=200, test result OK
select : pref=150, test result OK
Total: 3 (3 usable), will use kqueue.

Available filters :
[SPOE] spoe
[TRACE] trace
[COMP] compression


# Automaticaly generated, dont edit manually.
# Generated on: 2017-11-08 16:21
global
maxconn 100
stats socket /tmp/haproxy.socket level admin
uid 80
gid 80
nbproc 1
chroot /tmp/haproxy_chroot
daemon
server-state-file /tmp/haproxy_server_state
lua-load /var/etc/haproxy/luascript_frame_me_nl

listen HAProxyLocalStats
bind 127.0.0.1:2200 name localstats
mode http
stats enable
stats refresh 10
stats admin if TRUE
stats uri /haproxy/haproxy_stats.php?haproxystats=1
timeout client 5000
timeout connect 5000
timeout server 5000

frontend www
bind 37.97.x.y:80 name 37.97.x.y:80
mode http
log global
option http-keep-alive
timeout client 30000
acl acme path_beg -i /.well-known/acme-challenge/
http-request use-service lua.me_frame_lua if !acme
use_backend LetsEncrypt_http_ipvANY if acme

backend LetsEncrypt_http_ipvANY
mode http
log global
timeout connect 30000
timeout server 30000
retries 3
server acme 127.0.0.1:1080



core.register_service("me_frame_lua", "http", function(applet)
local response = [[

<html><head><title>Me</title>
</head>
<frameset framespacing="0" border="0" rows="0,*" frameborder="0">
<frame name="ICredir__1" noresize>
<frame name="ICredir__2" src="http://www.me.nl"; noresize>
<noframes><body><p>Op deze pagina worden frames gebruikt, maar uw browser ondersteunt geen frames.</p></body></noframes>
</frameset></html>
]]
applet:set_status(200)
applet:add_header("content-length", string.len(response))
applet:add_header("content-type", "text/html")
applet:start_response()
applet:send(response)
end)

[2.4.2-DEVELOPMENT][[email protected]]/root: /usr/local/pkg/haproxy/haproxy_socket.sh show stat
show stat # pxname,svname,qcur,qmax,scur,smax,slim,stot,bin,bout,dreq,dresp,ereq,econ,eresp,wretr,wredis,status,weight,act,bck,chkfail,chkdown,lastchg,downtime,qlimit,pid,iid,sid,throttle,lbtot,tracked,type,rate,rate_lim,rate_max,check_status,check_code,check_duration,hrsp_1xx,hrsp_2xx,hrsp_3xx,hrsp_4xx,hrsp_5xx,hrsp_other,hanafail,req_rate,req_rate_max,req_tot,cli_abrt,srv_abrt,comp_in,comp_out,comp_byp,comp_rsp,lastsess,last_chk,last_agt,qtime,ctime,rtime,ttime,agent_status,agent_code,agent_duration,check_desc,agent_desc,check_rise,check_fall,check_health,agent_rise,agent_fall,agent_health,addr,cookie,mode,algo,conn_rate,conn_rate_max,conn_tot,intercepted,dcon,dses,
HAProxyLocalStats,FRONTEND,,,0,0,2000,0,0,0,0,0,0,,,,,OPEN,,,,,,,,,1,2,0,,,,0,0,0,0,,,,0,0,0,0,0,0,,0,0,0,,,0,0,0,0,,,,,,,,,,,,,,,,,,,,,http,,0,0,0,0,0,0,
HAProxyLocalStats,BACKEND,0,0,0,0,200,0,0,0,0,0,,0,0,0,0,UP,0,0,0,,0,27671,,,1,2,0,,0,,1,0,,0,,,,0,0,0,0,0,0,,,,0,0,0,0,0,0,0,-1,,,0,0,0,0,,,,,,,,,,,,,,http,roundrobin,,,,,,,
www,FRONTEND,,,1,4,2000,29,7799,12164,0,0,1,,,,,OPEN,,,,,,,,,1,3,0,,,,0,0,0,3,,,,0,27,0,1,0,0,,0,2,29,,,0,0,0,0,,,,,,,,,,,,,,,,,,,,,http,,0,3,29,28,0,0,
LetsEncrypt_http_ipvANY,acme,0,0,0,0,,0,0,0,,0,,0,0,0,0,no check,1,1,0,,,27671,,,1,4,1,,0,,2,0,,0,,,,0,0,0,0,0,0,,,,,0,0,,,,,-1,,,0,0,0,0,,,,,,,,,,,,127.0.0.1:1080,,http,,,,,,,,
LetsEncrypt_http_ipvANY,BACKEND,0,0,0,0,200,0,0,0,0,0,,0,0,0,0,UP,1,1,0,,0,27671,0,,1,4,0,,0,,1,0,,0,,,,0,0,0,0,0,0,,,,0,0,0,0,0,0,0,-1,,,0,0,0,0,,,,,,,,,,,,,,http,roundrobin,,,,,,,

[2.4.2-DEVELOPMENT][[email protected]]/root: /usr/local/pkg/haproxy/haproxy_socket.sh show sess
show sess 0x80242b800: proto=tcpv4 src=45.76.70.8:53752 fe=www be=<NONE> srv=<none> ts=04 age=4h23m calls=4 rq[f=80c020h,i=0,an=00h,rx=,wx=,ax=] rp[f=80400000h,i=0,an=a00000h,rx=,wx=,ax=] s0=[7,8h,fd=1,ex=] s1=[7,4010h,fd=-1,ex=] exp=
0x80242ac00: proto=unix_stream src=unix:1 fe=GLOBAL be=<NONE> srv=<none> ts=0a age=0s calls=1 rq[f=c08200h,i=0,an=00h,rx=10s,wx=,ax=] rp[f=80008002h,i=0,an=00h,rx=,wx=,ax=] s0=[7,8h,fd=2,ex=] s1=[7,4018h,fd=-1,ex=] exp=10s

[2.4.2-DEVELOPMENT][[email protected]]/root: /usr/local/pkg/haproxy/haproxy_socket.sh show sess all
show sess all 0x80242b800: [08/Nov/2017:19:40:18.868158] id=15 proto=tcpv4 source=45.76.70.8:53752
flags=0x48a, conn_retries=0, srv_conn=0x0, pend_pos=0x0
frontend=www (id=3 mode=http), listener=37.97.x.y:80 (id=1) addr=37.97.x.y:80
backend=<NONE> (id=-1 mode=-)
server=<NONE> (id=-1)
task=0x80248f380 (state=0x04 nice=0 calls=4 exp=<NEVER> age=4h23m)
txn=0x802421800 flags=0x8200000 meth=1 status=-1 req.st=MSG_BODY rsp.st=MSG_RPBEFORE waiting=0
si[0]=0x80242ba38 (state=EST flags=0x08 endp0=CONN:0x8024ca480 exp=<NEVER>, et=0x000)
si[1]=0x80242ba60 (state=EST flags=0x4010 endp1=APPCTX:0x8024ca600 exp=<NEVER>, et=0x000)
co0=0x8024ca480 ctrl=tcpv4 xprt=RAW data=STRM target=LISTENER:0x8024ca300
flags=0x0025b300 fd=1 fd.state=22 fd.cache=0 updt=0
app1=0x8024ca600 st0=0 st1=0 st2=0 applet=<lua.me_frame_lua>
req=0x80242b810 (f=0x80c020 an=0x0 pipe=0 tofwd=-1 total=94)
an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
buf=0x8024ed900 data=0x8024ed914 o=94 p=94 req.next=94 i=0 size=16384
res=0x80242b850 (f=0x80400000 an=0xa00000 pipe=0 tofwd=0 total=0)
an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
buf=0x783160 data=0x783174 o=0 p=0 rsp.next=0 i=0 size=0
0x80242ac00: [09/Nov/2017:00:04:24.403636] id=31 proto=unix_stream source=unix:1
flags=0x88, conn_retries=0, srv_conn=0x0, pend_pos=0x0
frontend=GLOBAL (id=0 mode=tcp), listener=? (id=1) addr=unix:1
backend=<NONE> (id=-1 mode=-)
server=<NONE> (id=-1)
task=0x80248f4d0 (state=0x0a nice=-64 calls=1 exp=10s age=?)
si[0]=0x80242ae38 (state=EST flags=0x08 endp0=CONN:0x8024ca900 exp=<NEVER>, et=0x000)
si[1]=0x80242ae60 (state=EST flags=0x4018 endp1=APPCTX:0x8024ca780 exp=<NEVER>, et=0x000)
co0=0x8024ca900 ctrl=unix_stream xprt=RAW data=STRM target=LISTENER:0x8024ca000
flags=0x0020b306 fd=2 fd.state=25 fd.cache=0 updt=0
app1=0x8024ca780 st0=7 st1=0 st2=3 applet=<CLI>
req=0x80242ac10 (f=0xc08200 an=0x0 pipe=0 tofwd=-1 total=15)
an_exp=<NEVER> rex=10s wex=<NEVER>
buf=0x8024e7dc0 data=0x8024e7dd4 o=0 p=0 req.next=0 i=0 size=16384
res=0x80242ac50 (f=0x80008002 an=0x0 pipe=0 tofwd=-1 total=1198)
an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
buf=0x8025603c0 data=0x8025603d4 o=1198 p=1198 rsp.next=0 i=0 size=16384

[2.4.2-DEVELOPMENT][[email protected]]/root: lsof | grep haproxy
lsof: WARNING: compiled for FreeBSD release 11.1-RELEASE-p1; this is 11.1-RELEASE-p3.
lsof: WARNING: access /root/.lsof_pfScloud: No such file or directory
lsof: WARNING: created device cache file: /root/.lsof_pfScloud
haproxy 2739 www cwd VDIR 0,79 512 2808969 /tmp/haproxy_chroot
haproxy 2739 www rtd VDIR 0,79 512 2808969 /tmp/haproxy_chroot
haproxy 2739 www jld VDIR 0,79 512 2808969 /tmp/haproxy_chroot
haproxy 2739 www txt VREG 0,79 1633536 1446049 /usr/local/sbin/haproxy
haproxy 2739 www txt VREG 0,79 139832 4494338 /libexec/ld-elf.so.1
haproxy 2739 www txt VREG 0,79 56664 2166914 /lib/libcrypt.so.5
haproxy 2739 www txt VREG 0,79 101808 2166922 /lib/libz.so.6
haproxy 2739 www txt VREG 0,79 469920 1450348 /usr/lib/libssl.so.8
haproxy 2739 www txt VREG 0,79 2528824 2166925 /lib/libcrypto.so.8
haproxy 2739 www txt VREG 0,79 246024 1446220 /usr/local/lib/liblua-5.3.so
haproxy 2739 www txt VREG 0,79 176184 2166945 /lib/libm.so.5
haproxy 2739 www txt VREG 0,79 1604240 2166946 /lib/libc.so.7
haproxy 2739 www txt VREG 0,79 115784 2166936 /lib/libthr.so.3
haproxy 2739 www 0u KQUEUE 0xfffff80003e29000 count=0, state=0
haproxy 2739 www 1u IPv4 0xfffff80025113000 0t0 TCP rtr.me.nl:http->45.76.70.8.vultr.com:53752 (CLOSED)
haproxy 2739 www 4u unix 0xfffff800162fa000 0t0 /tmp/haproxy.socket.2663.tmp
haproxy 2739 www 5u IPv4 0xfffff80025115820 0t0 TCP localhost:2200 (LISTEN)
haproxy 2739 www 6u IPv4 0xfffff800169b0410 0t0 TCP rtr.me.nl:http (LISTEN)
haproxy 2739 www 9u unix 0xfffff80003ec5000 0t0 /var/run/php-fpm.socket
haproxy 2739 www 10w VREG 0,79 0 2808996 /tmp/haproxy.lock
syslogd 77429 root txt VREG 0,79 10240 722482 /var/log/haproxy.log
syslogd 77429 root 7u unix 0xfffff800162fa360 0t0 /tmp/haproxy_chroot/var/run/log
syslogd 77429 root 14u VREG 0,79 10240 722482 /var/log/haproxy.log
[2.4.2-DEVELOPMENT][[email protected]]/root:

last pid: 80289; load averages: 1.02, 1.03, 1.00 up 5+09:04:52 01:03:53
55 processes: 2 running, 53 sleeping
CPU: 94.5% user, 0.0% nice, 5.1% system, 0.4% interrupt, 0.0% idle
Mem: 39M Active, 591M Inact, 67M Laundry, 200M Wired, 102M Buf, 56M Free
Swap: 2048M Total, 21M Used, 2027M Free, 1% Inuse

PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND
2739 www 1 103 0 28008K 6884K RUN 150:11 99.53% haproxy
Willy Tarreau
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 09, 2017 05:50AM
Hi Pieter,

On Thu, Nov 09, 2017 at 02:28:46AM +0100, PiBa-NL wrote:
> Actually haproxy has been running for a few weeks with 100% and i didnt
> notice.. it does keep working it seems..
>
> Anyhow thought i would try and capture the next event if it would happen
> again. It did after a few hours..
>
> After the truss output below the last line keeps repeating fast lots and
> lots of times.
>
> kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
> kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
> kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
> kevent(0,0x0,0,{ 1,EVFILT_READ,EV_EOF,0x0,0x0,0x0 },7,{ 0.994000000 }) = 1
> (0x1)
> recvfrom(1,0x8024ed972,16290,0,NULL,0x0)     = 0 (0x0)
> kevent(0,{ 1,EVFILT_READ,EV_DELETE,0x0,0x0,0x0 },1,0x0,0,0x0) = 0 (0x0)
> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)

We had something similar on Linux in relation with TCP splicing and the
fd cache, for which a fix was emitted. But yesterday Christopher explained
me that the fix has an impact on the way applets are scheduled in 1.8, so
actually it could mean that the initial bug might possibly cover a larger
scope than splicing only, and that recv+send might also be affected. If
you're interested in testing, the commit in 1.7 is
c040c1f ("BUG/MAJOR: stream-int: don't re-arm recv if send fails") and
is present in the latest snapshot (we really need to emit 1.7.10 BTW).

I'd be curious to know if it fixes it or not. At least it will tell us
if that's related to this fd cache thing or to something completely
different such as Lua.

I also need to check with Thierry if we could find a way to add some
stats about the time spent in Lua to "show info" to help debugging such
cases where Lua is involved.

By the way, thanks for your dump, we'll check the sessions' statuses.
There are not that many, and maybe it will give us a useful indication!

Cheers,
Willy
PiBa-NL
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 09, 2017 11:20PM
Hi Willy,

Op 9-11-2017 om 5:45 schreef Willy Tarreau:
> Hi Pieter,
>
> On Thu, Nov 09, 2017 at 02:28:46AM +0100, PiBa-NL wrote:
>> Actually haproxy has been running for a few weeks with 100% and i didnt
>> notice.. it does keep working it seems..
>>
>> Anyhow thought i would try and capture the next event if it would happen
>> again. It did after a few hours..
>>
>> After the truss output below the last line keeps repeating fast lots and
>> lots of times.
>>
>> kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
>> kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
>> kevent(0,0x0,0,{ },7,{ 1.000000000 })         = 0 (0x0)
>> kevent(0,0x0,0,{ 1,EVFILT_READ,EV_EOF,0x0,0x0,0x0 },7,{ 0.994000000 }) = 1
>> (0x1)
>> recvfrom(1,0x8024ed972,16290,0,NULL,0x0)     = 0 (0x0)
>> kevent(0,{ 1,EVFILT_READ,EV_DELETE,0x0,0x0,0x0 },1,0x0,0,0x0) = 0 (0x0)
>> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
>> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
>> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
>> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
>> kevent(0,0x0,0,{ },7,{ 0.000000000 })         = 0 (0x0)
> We had something similar on Linux in relation with TCP splicing and the
> fd cache, for which a fix was emitted. But yesterday Christopher explained
> me that the fix has an impact on the way applets are scheduled in 1.8, so
> actually it could mean that the initial bug might possibly cover a larger
> scope than splicing only, and that recv+send might also be affected. If
> you're interested in testing, the commit in 1.7 is
> c040c1f ("BUG/MAJOR: stream-int: don't re-arm recv if send fails") and
> is present in the latest snapshot (we really need to emit 1.7.10 BTW).
>
> I'd be curious to know if it fixes it or not. At least it will tell us
> if that's related to this fd cache thing or to something completely
> different such as Lua.
>
> I also need to check with Thierry if we could find a way to add some
> stats about the time spent in Lua to "show info" to help debugging such
> cases where Lua is involved.
>
> By the way, thanks for your dump, we'll check the sessions' statuses.
> There are not that many, and maybe it will give us a useful indication!
>
> Cheers,
> Willy

Thanks for your time, i didn't think the 'splice' problem mentioned on
mailing-list would be relevant for my case so i didn't see a need to try
latest snapshot. Couldn't find much other recent cpu issues there. But
ill try and compile haproxy 1.7 latest snapshot or perhaps just 1.7.9
with this extra patch and see if it keeps running with low cpu usage for
a few days.. I have not compiled haproxy for a while, ill see what works
the easiest for me, assuming can make it work build on a separate
FreeBSD machine and packaged/copied to the actual 'problem machine' that
doesn't have compilation tools on it.. hopefully my build binary will be
'compatible'..

Will report back in a few day's..

Thanks,
PiBa-NL / Pieter
PiBa-NL
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 10, 2017 12:30AM
Hi Willy, List,

Is it correct that when i build a haproxy-ss-20171017 snapshot that the
version still shows up as:
"HAProxy version 1.7.9, released 2017/08/18"
on both haproxy -vv and stats page.?

Or did i do it wrong?

p.s. I changed the Makefile like this:
PORTNAME=    haproxy-ss
PORTVERSION=    20171017
CATEGORIES=    net www
MASTER_SITES=    http://www.haproxy.org/download/1.7/src/snapshot/

And then ran:
    make clean build install NO_CHECKSUM=yes

Which did 'seem' to download the 'intended?' file..

Thanks,
PiBa-NL / Pieter
Willy Tarreau
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 10, 2017 05:30AM
Hi Pieter,

On Fri, Nov 10, 2017 at 12:18:30AM +0100, PiBa-NL wrote:
> Hi Willy, List,
>
> Is it correct that when i build a haproxy-ss-20171017 snapshot that the
> version still shows up as:
> "HAProxy version 1.7.9, released 2017/08/18"
> on both haproxy -vv and stats page.?
>
> Or did i do it wrong?

I just checked the contents and its OK. I think we have something wrong
on the script which generates the snapshots. The git version and the date
are normally updated on the fly by git when building the archive, thanks
to attributes. I'm not seeing the attribute file anymore in the repository
so it's possible we've lost it during the last server migration, I'll take
care of it.

Thanks for the report.

> p.s. I changed the Makefile like this:
> PORTNAME=    haproxy-ss
> PORTVERSION=    20171017
> CATEGORIES=    net www
> MASTER_SITES=    http://www.haproxy.org/download/1.7/src/snapshot/
>
> And then ran:
>     make clean build install NO_CHECKSUM=yes
>
> Which did 'seem' to download the 'intended?' file..

I don't know these files above, they're probably related to your system,
but in the snapshot file I'm clearly seeing that this is wrong :

bash-4.2$ cd haproxy-ss-20171017/
bash-4.2$ cat SUBVERS
-$Format:%h$

bash-4.2$ cat VERDATE
$Format:%ci$
2017/08/18

Normally these ones are changed on the fly by git-archive. Don't worry,
the problem is on our side :-)

Thanks for reporting this,
Willy
Willy Tarreau
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 10, 2017 05:40AM
On Fri, Nov 10, 2017 at 05:25:11AM +0100, Willy Tarreau wrote:
> I just checked the contents and its OK. I think we have something wrong
> on the script which generates the snapshots. The git version and the date
> are normally updated on the fly by git when building the archive, thanks
> to attributes. I'm not seeing the attribute file anymore in the repository
> so it's possible we've lost it during the last server migration, I'll take
> care of it.

Now fixed, 1.4 to 1.7 were affected. Future snapshots should be OK starting
from tomorrow.

Willy
PiBa-NL
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 10, 2017 11:50PM
Hi Willy,

Op 9-11-2017 om 5:45 schreef Willy Tarreau:
> Hi Pieter,
>
> We had something similar on Linux in relation with TCP splicing and the
> fd cache, for which a fix was emitted. But yesterday Christopher explained
> me that the fix has an impact on the way applets are scheduled in 1.8, so
> actually it could mean that the initial bug might possibly cover a larger
> scope than splicing only, and that recv+send might also be affected. If
> you're interested in testing, the commit in 1.7 is
> c040c1f ("BUG/MAJOR: stream-int: don't re-arm recv if send fails") and
> is present in the latest snapshot (we really need to emit 1.7.10 BTW).
>
> I'd be curious to know if it fixes it or not. At least it will tell us
> if that's related to this fd cache thing or to something completely
> different such as Lua.
>
> I also need to check with Thierry if we could find a way to add some
> stats about the time spent in Lua to "show info" to help debugging such
> cases where Lua is involved.
>
> By the way, thanks for your dump, we'll check the sessions' statuses.
> There are not that many, and maybe it will give us a useful indication!
>
> Cheers,
> Willy

Okay have been running with haproxy-ss-20171017 for a day now. Sofar it
sticks to <1% cpu usage.

Will report if anything changes, cant tell for sure as don't have a
clear reproduction of the issue, but my issue 'seems' fixed.

Regards,

PiBa-NL / Pieter
Willy Tarreau
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 11, 2017 07:20AM
Hi Pieter,

On Fri, Nov 10, 2017 at 11:43:41PM +0100, PiBa-NL wrote:
> Okay have been running with haproxy-ss-20171017 for a day now. Sofar it
> sticks to <1% cpu usage.
>
> Will report if anything changes, cant tell for sure as don't have a clear
> reproduction of the issue, but my issue 'seems' fixed.

Great! If anything changes and you want to report what is wrong, please
don't forget to issue the following :
- "show sess all" on the cli
- attach gdb to the running process and issue a few series of "bt full",
"cont", ctrl-c, "bt full", ... to try to catch the code path commonly
called.

Cheers,
Willy
Lukas Tribus
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 12, 2017 08:20PM
Hello,


2017-11-10 23:43 GMT+01:00 PiBa-NL <[email protected]>:
> Okay have been running with haproxy-ss-20171017 for a day now. Sofar it
> sticks to <1% cpu usage.

FYI a similar report is on discourse, on linux without splicing
involved. Upgrading from 1.7.9 to haproxy-ss-20171017 appears to have
solved the problem:

https://discourse.haproxy.org/t/haproxy-consuming-100-cpu/1758


Lukas
Willy Tarreau
Re: HAProxy 1.7.9 FreeBSD 100% CPU usage
November 12, 2017 09:40PM
Hi Lukas,

On Sun, Nov 12, 2017 at 08:09:29PM +0100, Lukas Tribus wrote:
> Hello,
>
>
> 2017-11-10 23:43 GMT+01:00 PiBa-NL <[email protected]>:
> > Okay have been running with haproxy-ss-20171017 for a day now. Sofar it
> > sticks to <1% cpu usage.
>
> FYI a similar report is on discourse, on linux without splicing
> involved. Upgrading from 1.7.9 to haproxy-ss-20171017 appears to have
> solved the problem:
>
> https://discourse.haproxy.org/t/haproxy-consuming-100-cpu/1758

Thanks for the feedback. We'll release 1.7.10 ASAP with the pending
fixes. It's been waiting too long now.

Cheers,
Willy
Sorry, only registered users may post in this forum.

Click here to login