Skip to content

2.2 dev8 high cpu on health check with DOWN backend #635

Description

@dch

Output of haproxy -vv and uname -a

$ uname -a 
FreeBSD wintermute.skunkwerks.at 13.0-CURRENT FreeBSD 13.0-CURRENT r361107+33e88c81a071-c268610(master) GENERIC-NODEBUG  amd64

$ haproxy -vv
HA-Proxy version 2.2-dev7 2020/05/05 - https://haproxy.org/
Status: development branch - not safe for use in production.
Known bugs: https://github.com/haproxy/haproxy/issues?q=is:issue+is:open
Running on: FreeBSD 13.0-CURRENT FreeBSD 13.0-CURRENT r361107+33e88c81a071-c268610(master) GENERIC-NODEBUG amd64
Build options :
  TARGET  = freebsd
  CPU     = generic
  CC      = cc
  CFLAGS  = -O2 -pipe -fstack-protector-strong -fno-strict-aliasing -Wall -Wextra -Wdeclaration-after-statement -fwrapv -Wno-address-of-packed-member -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter -Wno-ignored-qualifiers -Wno-missing-field-initializers -Wno-implicit-fallthrough -Wno-string-plus-int -Wtype-limits -Wshift-negative-value -Wnull-dereference -DFREEBSD_PORTS
  OPTIONS = USE_PCRE=1 USE_PCRE_JIT=1 USE_STATIC_PCRE=1 USE_GETADDRINFO=1 USE_OPENSSL=1 USE_ACCEPT4=1 USE_ZLIB=1 USE_CPU_AFFINITY=1

Feature list : -EPOLL +KQUEUE -NETFILTER +PCRE +PCRE_JIT -PCRE2 -PCRE2_JIT +POLL -PRIVATE_CACHE +THREAD -PTHREAD_PSHARED -BACKTRACE +STATIC_PCRE -STATIC_PCRE2 +TPROXY -LINUX_TPROXY -LINUX_SPLICE +LIBCRYPT -CRYPT_H +GETADDRINFO +OPENSSL -LUA -FUTEX +ACCEPT4 +ZLIB -SLZ +CPU_AFFINITY -TFO -NS -DL -RT -DEVICEATLAS -51DEGREES -WURFL -SYSTEMD -OBSOLETE_LINKER -PRCTL -THREAD_DUMP -EVPORTS

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

Built with multi-threading support (MAX_THREADS=64, default=8).
Built with OpenSSL version : OpenSSL 1.1.1g-freebsd  21 Apr 2020
Running on OpenSSL version : OpenSSL 1.1.1g-freebsd  21 Apr 2020
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : SSLv3 TLSv1.0 TLSv1.1 TLSv1.2 TLSv1.3
Built with clang compiler version 10.0.0 ([email protected]:llvm/llvm-project.git llvmorg-10.0.0-0-gd32170dbd5b)
Built with transparent proxy support using: IP_BINDANY IPV6_BINDANY
Built with PCRE version : 8.43 2019-02-23
Running on PCRE version : 8.43 2019-02-23
PCRE library supports JIT : yes
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")

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 multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
              h2 : mode=HTTP       side=FE|BE     mux=H2
            fcgi : mode=HTTP       side=BE        mux=FCGI
       <default> : mode=HTTP       side=FE|BE     mux=H1
       <default> : mode=TCP        side=FE|BE     mux=PASS

Available services : none

Available filters :
	[SPOE] spoe
	[CACHE] cache
	[FCGI] fcgi-app
	[TRACE] trace
	[COMP] compression

What's the configuration?

# vim: filetype=config
# refer to http://cbonte.github.io/haproxy-dconv/2.1/configuration.html
# and      http://cbonte.github.io/haproxy-dconv/2/1/management.html
# https://www.haproxy.com/blog/enhanced-ssl-load-balancing-with-server-name-indication-sni-tls-extension/
global
  daemon
  pidfile /var/run/haproxy.pid
  log 127.0.0.1 format rfc5424 local0

  # drop privileges
  chroot          /var/empty
  group           www
  user            www

  stats           socket /var/run/haproxy.sock mode 660 user root group wheel level admin

  tune.ssl.default-dh-param 2048
  ssl-default-bind-options ssl-min-ver TLSv1.2
  ssl-default-bind-ciphers ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA256:DHE-RSA-AES256-SHA:ECDHE-ECDSA-DES-CBC3-SHA:ECDHE-RSA-DES-CBC3-SHA:EDH-RSA-DES-CBC3-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:DES-CBC3-SHA:!DSS:!EXP:!LOW:!MD5:!aNULL:!eNULL
  # ssl-dh-param-file /usr/local/etc/haproxy/diffie-hellman.cfg

  maxconn         4096
  spread-checks   5

defaults
  log             global
  option          log-health-checks
  mode            http
  option          httplog
  option          dontlognull
  monitor-uri     /_haproxy_health_check

  # load balancing is tricky
  # roundrobin only really matters when we have multiple non-backup backends
  balance         roundrobin
  # forwardfor and http-server-close ensure that backends get the actual IP
  # via the X-Forwarded-For header, but still have the benefits of HTTP
  # KeepAlive for performance
  option          forwardfor
  option          redispatch
  retries         3

  # these need to be long enough to accommodate large view responses from couchdb
  timeout         connect      15s
  # tunnel applies generally to websocket connections only
  # timeout         tunnel       30m
  option          http-keep-alive
  option          tcpka

  # health check settings all have defaults of 2 seconds which generates
  # a lot of unnecessary traffic. Note that TCP connection failures will
  # trigger a check & down state very quickly anyway so this is really
  # just to catch layer 7 (HTTP) issues in addition to network ones.
  # inter:      interval between checks when backend is UP
  # downinter:  interval between checks when backend is DOWN
  # fastinter:  interval between checks when backend is changing state
  default-server  inter 15s downinter 60s fastinter 5s

userlist admins
  user ops        password ...
  user monitor    password ...

frontend admin
  bind            [fc7b:c4d6:6be2:8e50:6c98::1]:1443
  bind            172.16.1.4:1443
  stats           enable
  stats           uri           /
  stats           refresh       30s
  stats           admin         if TRUE
  acl             auth_admins   http_auth(admins)
  no              log
  http-request    auth realm    example                unless auth_admins
  http-request    add-header    X-Forwarded-Port          %[dst_port]
  http-response   add-header    X-proxy                   wintermute
  http-request    add-header    X-Forwarded-Proto         https if { ssl_fc }
#  http-response   add-header    Strict-Transport-Security max-age=31536000;includeSubDomains
  redirect        scheme https unless { ssl_fc }

#################### plex ########################

frontend plex
  bind            172.16.1.4:4444
  bind            [fc7b:c4d6:6be2:8e50:6c98::1]:32400
  default_backend plex_be

backend plex_be
  server          plex          172.16.1.4:32400 check observe layer7

#################### restic ########################

frontend restic
  bind            172.16.1.4:8000
  bind            [fc7b:c4d6:6be2:8e50:6c98::1]:8000
  default_backend restic_be

backend restic_be
  server          restic          127.0.0.1:8000 check observe layer7

#################### bears ########################

frontend gummibaers
  bind            :::5000       v4v6
  # trim off anything until final /
  http-request    set-var(req.lamps) capture.req.uri,regsub(.*/,)
  # ensure its a valid integer
  acl             valid_lamp    capture.req.uri,regsub(.*/,) -m int 0:31
  http-request    deny          unless METH_GET
  http-request    deny          unless valid_lamp
  http-request    set-query     PIO.BYTE=%[var(req.lamps)]
  http-request    set-path      /json/29.330419000000
  http-response   set-header    content-type  application/json
  http-response   set-header    server  wintermute
  http-response   set-header    x-proxy wintermute
  default_backend gummibaers

backend gummibaers
 server          gummibaers    continuity...:5000  check observe layer7

#################### couchdb ########################
#

frontend couch64
  bind           [fca2:927d:4de2:8e50:6c98::1]:5984
  default_backend couch64_be

backend couch64_be
  server          couch        100.64.0.0:5984 check observe layer7

#################### example ########################

# see https://www.rabbitmq.com/reliability.html and also
# https://deviantony.wordpress.com/2014/10/30/rabbitmq-and-haproxy-a-timeout-issue/
frontend rabbitmq_example
  mode            tcp
  bind            10.241.0.0:5672
  option          tcplog
  default_backend rabbitmq_backend

backend rabbitmq_backend
  mode            tcp
  option          tcplog
  option          tcp-check
  tcp-check       send-binary   414d515000000901   # <<"AMQP", 0, 0, 9, 1>>
  tcp-check       expect string AMQP
  # ensure that non-heartbeat sending clients like hase or daemonise aren't
  # arbitrarily disconnected, but if one side closes client-fin ensures the
  # connection is still freed up reasonably promptly.
  timeout         client-fin    30s
  timeout         tunnel        24h
  timeout         client        24h
  timeout         server        24h
  server          cloudamqp_rabbit cloudamqp.com:5671 ssl ca-file /usr/local/share/certs/ca-root-nss.crt check observe layer4

#################### example ########################

frontend rabbitmq_tcp
  mode            tcp
  bind            :::5678       v4v6
  option          tcplog
  default_backend rabbitmq_be

backend rabbitmq_be
  mode            tcp
  option          tcp-check
  tcp-check       send-binary   414d515000000901   # <<"AMQP", 0, 0, 9, 1>>
  tcp-check       expect string AMQP
  # ensure that non-heartbeat sending clients like hase or daemonise aren't
  # arbitrarily disconnected, but if one side closes client-fin ensures the
  # connection is still freed up reasonably promptly.
  timeout         client-fin    30s
  timeout         tunnel        24h
  timeout         client        24h
  timeout         server        24h
  server          cloudamqp     cloudamqp.com:5671 ssl verify none

frontend example
  bind            [::1]:4003

  # detect requests via SNI and Host header
  acl www   hdr_dom(host)       www.example.com
  acl api   hdr_dom(host)       api.example.com
  acl beta  hdr_dom(host)       beta.example.com
  acl test  hdr_dom(host)       test.example.com

  # response headers
  http-response   set-header    X-example                   wintermute
  http-response   set-header    X-SNI                     %[ssl_fc_sni]
  # redirect anything that doesn't match our ACLs or isn't TLS
  http-request redirect code 301 location https://www.example.com%[capture.req.uri] unless www or api or beta or test
  # http-request redirect scheme https code 301 if !api !{ ssl_fc }

  # useful stuff follows
  acl webhooks    path_beg      /webhooks/
  use_backend     example_webhooks_be   if webhooks api METH_POST
  use_backend     example_www_be        if !api !beta !test
  # default_backend www

backend example_www_be
  server          www           example.com:443           check observe layer7

backend example_webhooks_be
  option          httpchk GET /healthz
  server          webhooks      127.0.0.1:4003            check observe layer7

Steps to reproduce the behavior

leave computer alone over weekend? sadly not at all sure what causes this yet

Actual behavior

overnight reasonably heavy load runs through restic front/back end, otherwise
this is very boring. a couple of backends are down over the weekend. on monday
morning, 1 core is pegged at 100% cpu. ktrace shows:

   41 101194 haproxy  0.000052 CALL  clock_gettime[232](0xe,0x7fffdf5f8f00)
    41 101194 haproxy  0.000053 RET   clock_gettime[232] 0
    41 101194 haproxy  0.000054 CALL  clock_gettime[232](0xe,0x7fffdf5f8f00)
    41 101194 haproxy  0.000054 RET   clock_gettime[232] 0
    41 101194 haproxy  0.000055 CALL  kevent[560](0x25,0,0,0x80362c940,0xc8,0x7fffdf5f8ef0)
    41 101194 haproxy  0.000056 STRU  struct kevent[] = {  }
    41 101194 haproxy  0.000057 STRU  struct kevent[] = { { ident=40, filter=EVFILT_READ, flags=0x8040<EV_RECEIPT|EV_EOF>, fflags=0x3c, data=0, udata=0x0 } }
    41 101194 haproxy  0.000057 RET   kevent[560] 1
    41 101194 haproxy  0.000059 CALL  clock_gettime[232](0xe,0x7fffdf5f8f00)
    41 101194 haproxy  0.000059 RET   clock_gettime[232] 0
    41 101194 haproxy  0.000060 CALL  clock_gettime[232](0xe,0x7fffdf5f8f00)
    41 101194 haproxy  0.000061 RET   clock_gettime[232] 0
    41 101194 haproxy  0.000062 CALL  kevent[560](0x25,0,0,0x80362c940,0xc8,0x7fffdf5f8ef0)
    41 101194 haproxy  0.000063 STRU  struct kevent[] = {  }
    41 101194 haproxy  0.000064 STRU  struct kevent[] = { { ident=40, filter=EVFILT_READ, flags=0x8040<EV_RECEIPT|EV_EOF>, fflags=0x3c, data=0, udata=0x0 } }
    41 101194 haproxy  0.000064 RET   kevent[560] 1
    41 101194 haproxy  0.000065 CALL  clock_gettime[232](0xe,0x7fffdf5f8f00)
    41 101194 haproxy  0.000066 RET   clock_gettime[232] 0
    41 101194 haproxy  0.000067 CALL  clock_gettime[232](0xe,0x7fffdf5f8f00)
    41 101194 haproxy  0.000068 RET   clock_gettime[232] 0

and dtrace is similarly unhelpful.

    41/101194:  18373689       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0
    41/101194:  18373690       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0
    41/101194:  18373691       1      0 kevent(0x25, 0x0, 0x0)		 = 1 0
    41/101194:  18373692       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0
    41/101194:  18373693       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0
    41/101194:  18373694       1      0 kevent(0x25, 0x0, 0x0)		 = 1 0
    41/101194:  18373695       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0
    41/101194:  18373696       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0
    41/101194:  18373697       1      0 kevent(0x25, 0x0, 0x0)		 = 1 0
    41/101194:  18373697       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0
    41/101194:  18373698       1      0 clock_gettime(0xE, 0x7FFFDF5F8F00, 0x0)		 = 0 0

show activity

Name: HAProxy
Version: 2.2-dev7
Release_date: 2020/05/05
Nbthread: 8
Nbproc: 1
Process_num: 1
Pid: 41
Uptime: 2d 0h20m52s
Uptime_sec: 174052
Memmax_MB: 0
PoolAlloc_MB: 0
PoolUsed_MB: 0
PoolFailed: 0
Ulimit-n: 8255
Maxsock: 8255
Maxconn: 4096
Hard_maxconn: 4096
CurrConns: 1
CumConns: 61990
CumReq: 10945
MaxSslConns: 0
CurrSslConns: 0
CumSslConns: 11357
Maxpipes: 0
PipesUsed: 0
PipesFree: 0
ConnRate: 0
ConnRateLimit: 0
MaxConnRate: 4
SessRate: 0
SessRateLimit: 0
MaxSessRate: 4
SslRate: 0
SslRateLimit: 0
MaxSslRate: 0
SslFrontendKeyRate: 0
SslFrontendMaxKeyRate: 0
SslFrontendSessionReuse_pct: 0
SslBackendKeyRate: 0
SslBackendMaxKeyRate: 1
SslCacheLookups: 0
SslCacheMisses: 0
CompressBpsIn: 0
CompressBpsOut: 0
CompressBpsRateLim: 0
ZlibMemUsage: 0
MaxZlibMemUsage: 0
Tasks: 45
Run_queue: 1
Idle_pct: 63
node: wintermute.skunkwerks.at
Stopping: 0
Jobs: 14
Unstoppable Jobs: 0
Listeners: 12
ActivePeers: 0
ConnectedPeers: 0
DroppedLogs: 0
BusyPolling: 0
FailedResolutions: 0
TotalBytesOut: 3487610356
BytesOutRate: 0
DebugCommandsIssued: 0

show activity

thread_id: 8 (1..8)
date_now: 1589828043.956348
loops: 2900171228 [ 28429606 15410247 13312262 9640770 16199402 16184052 2790348459 10646430 ]
wake_tasks: 301637 [ 72382 37584 31420 15181 31173 36224 56740 20933 ]
wake_signal: 0 [ 0 0 0 0 0 0 0 0 ]
poll_exp: 0 [ 0 0 0 0 0 0 0 0 ]
poll_drop: 17 [ 4 2 2 1 3 1 0 4 ]
poll_dead: 0 [ 0 0 0 0 0 0 0 0 ]
poll_skip: 84788832 [ 21276399 9101288 8918480 7266485 10922224 10483661 10336356 6483939 ]
fd_lock: 0 [ 0 0 0 0 0 0 0 0 ]
conn_dead: 0 [ 0 0 0 0 0 0 0 0 ]
stream: 24488 [ 7428 1685 1478 3210 4136 2450 1365 2736 ]
pool_fail: 0 [ 0 0 0 0 0 0 0 0 ]
buf_wait: 0 [ 0 0 0 0 0 0 0 0 ]
empty_rq: 2899205117 [ 28272149 15299590 13209657 9555761 16093131 16074519 2790146629 10553681 ]
long_rq: 288623 [ 71742 37180 31034 14854 30779 35825 46587 20622 ]
ctxsw: 1135345 [ 250298 128673 108509 57430 112528 123795 276675 77437 ]
tasksw: 148527 [ 9677 3788 3597 5383 6180 4596 110536 4770 ]
cpust_ms_tot: 339569 [ 142 164 107 84 147 134 338702 89 ]
cpust_ms_1s: 0 [ 0 0 0 0 0 0 0 0 ]
cpust_ms_15s: 33 [ 0 0 0 0 0 0 33 0 ]
avg_loop_us: 7 [ 4 7 9 24 4 4 1 4 ]
accepted: 97 [ 8 11 17 11 28 3 13 6 ]
accq_pushed: 97 [ 16 12 12 12 12 13 5 15 ]
accq_full: 0 [ 0 0 0 0 0 0 0 0 ]
accq_ring: 0 [ 0 0 0 0 0 0 0 0 ]

output of json stats from admin ui is also available

stats.json

Expected behavior

the usual perfection in proxying :-)

Do you have any idea what may have caused this?

not yet

Do you have an idea how to solve the issue?

no

Activity

  1. wtarreau commented on May 26, 2020

    @wtarreau
    Member

    I'm not fluent in kevent nor ktrace, but it seems to be saying that kevent reported an EOF (a shut read) which was ignored and not even disabled. This could be a subscribe issue, and I'm seeing that health checks received a few fixes exactly on this so that could be one explanation. Also I think it could make sense to imagine that health checks are rare enough to avoid triggering the problem for 30 hours, which would be harder to achieve on real traffic.

    I'd suggest to try again with latest snapshot which has all this fixed so that we get more confident on this.

  2. dch commented on May 26, 2020

    @dch
    Author

    updated, I'll close in 1 week if I see no recurrence

  3. dch commented on May 27, 2020

    @dch
    Author

    With this backend marked as health DISABLE CHECKS in the web ui, usage is around 0.5% normally.

    When enabled again, I can see CPU usage rocket up to 60-80%, and cycles repeatedly up & down.

    frontend couch64
      bind           [fca2:927d:4de2:8e50:6c98::1]:5984
      default_backend couch64_be
    
    backend couch64_be
      server          couch        100.64.0.0:5984 check observe layer7
    

    at present there's no server listening on the backend, so it will always be down. BTW this is effectively a 6-4 proxy for CouchDB.

  4. changed the title [-]2.2 dev7 pegged at 100% cpu after ~ 30h uptime on FreeBSD[/-] [+]2.2 dev8 high cpu on health check with DOWN backend[/+] on May 27, 2020
  5. capflam commented on May 28, 2020

    @capflam
    Member

    @dch, I pushed a patch that should fix this bug. Could you confirm it works ?

  6. dch commented on May 28, 2020

    @dch
    Author

    @capflam merci bcp, it's applied, and I'll update ticket tomorrow with news good or bad. So far cpu is very stable.

  7. dch commented on May 29, 2020

    @dch
    Author

    🚢 no issues - looking forward to seeing this in the next release 🚀

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    status: needs-triageThis issue needs to be triaged.type: bugThis issue describes a bug.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions