Detailed Description of the Problem

Hi,

it seems that I have a knack for finding CPU-related issues. I recently upgraded to HaProxy 2.7.1 from 2.6.x and noticed that a reload causes full CPU utilization. Here a perf top:

It happens both with TCP and HTTP LBs and it does not seem to matter whether they are under heavy load or not. I have to restart instead of reload to fix this issue and even then the process takes ~half a minute to stop. The issue is not reproducible reliably, but it happened to me on five different machines (2xTCP LB and 3x HTTP LB) by now.

Expected Behavior

Reloading should not affect CPU usage that much.

Steps to Reproduce the Behavior

1. Install HaProxy 2.7.1 on Ubuntu 22.04
2. Reload HaProxy

Do you have any idea what may have caused this?

No response

Do you have an idea how to solve the issue?

No response

What is your configuration?

global
  chroot  /var/lib/haproxy
  daemon  
  group  haproxy
  log  stdout len 4096 format raw local0 notice
  log  localhost:5140 len 4096 format rfc5424 local0 info
  maxconn  3500000
  nbthread  60
  pidfile  /var/run/haproxy.pid
  ssl-default-bind-options  no-sslv3 no-tlsv10 no-tlsv11
  stats  socket /var/lib/haproxy/stats level admin
  tune.ssl.default-dh-param  2048
  user  haproxy

defaults
  balance  leastconn
  log  global
  log-format  "client_ip=%ci client_port=%cp frontend_ip=%fi frontend_port=%fp backend_name=%b server_name=%s termination_state=%ts retries=%rc connect_time=%Tc queue_time=%Tw total_time=%Tt bytes_read=%B"
  mode  tcp
  option  redispatch
  option  contstats
  option  log-health-checks
  option  splice-auto
  option  tcp-smart-accept
  option  tcp-smart-connect
  retries  3
  retry-on  conn-failure empty-response response-timeout
  timeout  connect 5s
  timeout  check 5s
  timeout  client-fin 1s
  timeout  server-fin 1s

# some tcp mode frontends and backends...

Output of haproxy -vv

HAProxy version 2.7.1-1ppa1~focal 2022/12/19 - https://haproxy.org/
Status: stable branch - will stop receiving fixes around Q1 2024.
Known bugs: http://www.haproxy.org/bugs/bugs-2.7.1.html
Running on: Linux 5.4.0-100-generic #113-Ubuntu SMP Thu Feb 3 18:43:29 UTC 2022 x86_64
Build options :
  TARGET  = linux-glibc
  CPU     = generic
  CC      = cc
  CFLAGS  = -O2 -g -O2 -fdebug-prefix-map=/build/haproxy-5g69hi/haproxy-2.7.1=. -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -Wall -Wextra -Wundef -Wdeclaration-after-statement -Wfatal-errors -Wtype-limits -Wshift-negative-value -Wshift-overflow=2 -Wduplicated-cond -Wnull-dereference -fwrapv -Wno-address-of-packed-member -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter -Wno-clobbered -Wno-missing-field-initializers -Wno-cast-function-type -Wno-string-plus-int -Wno-atomic-alignment
  OPTIONS = USE_PCRE2=1 USE_PCRE2_JIT=1 USE_OPENSSL=1 USE_LUA=1 USE_SLZ=1 USE_SYSTEMD=1 USE_PROMEX=1
  DEBUG   = -DDEBUG_STRICT -DDEBUG_MEMORY_POOLS

Feature list : +EPOLL -KQUEUE +NETFILTER -PCRE -PCRE_JIT +PCRE2 +PCRE2_JIT +POLL +THREAD -PTHREAD_EMULATION +BACKTRACE -STATIC_PCRE -STATIC_PCRE2 +TPROXY +LINUX_TPROXY +LINUX_SPLICE +LIBCRYPT +CRYPT_H -ENGINE +GETADDRINFO +OPENSSL -OPENSSL_WOLFSSL +LUA +ACCEPT4 -CLOSEFROM -ZLIB +SLZ +CPU_AFFINITY +TFO +NS +DL +RT -DEVICEATLAS -51DEGREES -WURFL +SYSTEMD -OBSOLETE_LINKER +PRCTL -PROCCTL +THREAD_DUMP -EVPORTS -OT -QUIC +PROMEX -MEMORY_PROFILING +SHM_OPEN

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

Built with multi-threading support (MAX_TGROUPS=16, MAX_THREADS=256, default=64).
Built with OpenSSL version : OpenSSL 1.1.1f  31 Mar 2020
Running on OpenSSL version : OpenSSL 1.1.1f  31 Mar 2020
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2 TLSv1.3
Built with Lua version : Lua 5.3.3
Built with the Prometheus exporter as a service
Built with network namespace support.
Support for malloc_trim() is enabled.
Built with libslz for stateless compression.
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with PCRE2 version : 10.34 2019-11-21
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with gcc compiler version 9.4.0

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

Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
         h2 : mode=HTTP  side=FE|BE  mux=H2    flags=HTX|HOL_RISK|NO_UPG
       fcgi : mode=HTTP  side=BE     mux=FCGI  flags=HTX|HOL_RISK|NO_UPG
  <default> : mode=HTTP  side=FE|BE  mux=H1    flags=HTX
         h1 : mode=HTTP  side=FE|BE  mux=H1    flags=HTX|NO_UPG
  <default> : mode=TCP   side=FE|BE  mux=PASS  flags=
       none : mode=TCP   side=FE|BE  mux=PASS  flags=NO_UPG

Available services : prometheus-exporter
Available filters :
    [BWLIM] bwlim-in
    [BWLIM] bwlim-out
    [CACHE] cache
    [COMP] compression
    [FCGI] fcgi-app
    [SPOE] spoe
    [TRACE] trace

Last Outputs and Backtraces

Reloading HAProxy Load Balancer.
[NOTICE]   (45126) : Reloading HAProxy
[NOTICE]   (45126) : haproxy version is 2.7.1-1ppa1~focal
[NOTICE]   (45126) : path to executable is /usr/sbin/haproxy
[ALERT]    (45126) : config : parsing [/etc/haproxy/haproxy.cfg:10] : 'pidfile' already specified. Continuing.
[WARNING]  (45126) : config : missing timeouts for frontend 'http'.
   | While not properly invalid, you will certainly encounter various problems
   | with such a configuration. To fix this, please ensure that all following
   | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
[WARNING]  (45126) : config : missing timeouts for frontend 'https'.
   | While not properly invalid, you will certainly encounter various problems
   | with such a configuration. To fix this, please ensure that all following
   | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
[WARNING]  (45126) : config : missing timeouts for frontend 'https-api'.
   | While not properly invalid, you will certainly encounter various problems
   | with such a configuration. To fix this, please ensure that all following
   | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
[WARNING]  (45126) : config : missing timeouts for frontend 'stats'.
   | While not properly invalid, you will certainly encounter various problems
   | with such a configuration. To fix this, please ensure that all following
   | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
[WARNING]  (45126) : config : missing timeouts for backend 'http'.
   | While not properly invalid, you will certainly encounter various problems
   | with such a configuration. To fix this, please ensure that all following
   | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
[WARNING]  (45126) : config : missing timeouts for backend 'https'.
   | While not properly invalid, you will certainly encounter various problems
   | with such a configuration. To fix this, please ensure that all following
   | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
[WARNING]  (45126) : config : missing timeouts for backend 'https-api'.
   | While not properly invalid, you will certainly encounter various problems
   | with such a configuration. To fix this, please ensure that all following
   | timeouts are set to a non-zero value: 'client', 'connect', 'server'.
[WARNING]  (1618370) : Proxy http stopped (cumulated conns: FE: 21876, BE: 0).
Proxy http stopped (cumulated conns: FE: 21876, BE: 0).
[WARNING]  (1618370) : Proxy https stopped (cumulated conns: FE: 80642805, BE: 0).
Proxy https stopped (cumulated conns: FE: 80642805, BE: 0).
[WARNING]  (1618370) : Proxy https-api stopped (cumulated conns: FE: 3971853, BE: 0).
Proxy https-api stopped (cumulated conns: FE: 3971853, BE: 0).
[WARNING]  (1618370) : Proxy stats stopped (cumulated conns: FE: 1, BE: 0).
Proxy stats stopped (cumulated conns: FE: 1, BE: 0).
[NOTICE]   (45126) : New worker (1674708) forked
Reloaded HAProxy Load Balancer.
[NOTICE]   (45126) : Loading success.

Additional Information

No response

I suspect it's trying to crash when existing due to an abnormal condition (which I don't know). If you happen to witness it again, I would very much appreciate if you can attach a gdb to it and issue t a a bt full so that we can understand how it went there.

Thanks, will do!

Hi, I got the problem again and was able to gdb into it:

Thanks! However your executable is missing the debug symbols, there's likely a package called something like "-debuginfo" or "-debugsym" or something similar on your distro that needs to be installed for gdb to resolve the function names in the backtrace.

Regardless there are still a lot of send() syscalls running so it looks like haproxy is still evacuating data to clients. Seeing FD numbers like 2.8 million makes me think you might possibly still have very large client counts. Maybe something is failing with these clients and haproxy is insisting for whatever reason. That's also where the stack trace with resolved symbols will help.

Thanks, I now installed the debug symbols and I will be back with a better trace when this happens again.

Ah sorry, I forgot it was a live process. If you want, next time, you can issue generate-core-file from gdb, and it will produce a core of the running process without killing it. This way even if another minor issue happens you still have the exploitable core.

Actually I did that before restarting the service. It is 18 GB big. Is it safe to share the coredump somewhere without disclosing private information?

Edit: Come to think of it: The dump is probably so big because I use stick-tables to stick up to ~2.5 million connections (TCP mode) to a server. Could handing over the contents of the stick table to the new process be the problem here?

Is it safe to share the coredump somewhere without disclosing private information?

@phihos It is not. The coredump will contain the full process memory, including TLS private keys and headers (e.g. session cookies) of in-flight requests.

You should be able to open the core using gdb haproxy /path/to/core though and with the haproxy-dbgsym package installed it should be more useful now.

Thank you very much. I did that and it seems to contain more information, but there are still symbols missing:

It's very strange that symbols are still not resolved. I seem to remember that installing the debug symbols on the system is normally enough. I don't want to harass Vincent about this yet. Tim, do you remember if there is something else to do for gdb to consider them ? I seldom had to manually enter a command such as "symbols" with a full path to the file but that was when retrieving packages from other distros.

Hmm looking closer it seems that the stack is not correctly decoded by gdb (I don't know why):

#0  0x00007f5e29a4e46e in ?? ()
No symbol table info available.
#1  0x0000000000000001 in ?? ()  => it's definitely not a code pointer
No symbol table info available.
#2  0x0000009a81f52340 in ?? ()

Apparently the code from the haproxy binary itself looks like 0x0000561a81a69d1d, so it should roughly start with 0x0000561a8. The rest comes from other libs but they are not properly decoded and I don't understand why :-(

Just in case, would you happen to run gdb on a different machine or maybe to run haproxy inside a container and run gdb outside ? This could result in slightly different binaries being used for the same libs and could explain this anomaly (the symbols one, not the CPU usage).

If we can't exploit the core it will become a bit difficult. If you're using the master-worker mode, it should be possible from the master socket to enter the old process and issue some debugging commands such as "show info", "show activity", "show threads", "show tasks", "show fd", and "show sess all". Note that the latter will reveal private info, so you'd rather keep it for you and only share it privately if we estimate based on the other ones that it will help. Let us know if you need some guidance. The location of the master socket could depend on your distro or your deployment (and it could also be disabled). If you find it, issuing "show proc" on it via socat will show the old process, then using "@-1" for example to enter old process -1, you enter the worker process' CLI and can then issue the regular commands.

Tim, do you remember if there is something else to do for gdb to consider them ?

Nope, on Debian and Ubuntu it should just work when installing the appropriate -dbgsym package and the package system makes sure that the versions of the dbgsym package and the regular package match up. In this case it's an Ubuntu with Vincent's repository (Vincent's Ubuntu repository is indicated by the ppa in the version number).

The location of the master socket could depend on your distro or your deployment (and it could also be disabled).

On Ubuntu it's /run/haproxy-master.sock by default, as it just uses the upstream service file: https://github.com/haproxy/haproxy/blob/40725a4eb0beadcdaa3c60b6f8c8fe20ab53abc3/admin/systemd/haproxy.service.in#L9

It seems to me that when under gdb, you should be able to issue:

p/x ha_tgroup_ctx[0].threads_harmless
p/x thread_dump_state
p thread_dump_tid
set print elements 0
x/s thread_dump_buffer->area

and it should show the dump state and the whole threads that have already been dumped.

Shame that the coredump turned out to be of no use. I will keep it regardless in case you find a way to get it to work.

Just in case, would you happen to run gdb on a different machine or maybe to run haproxy inside a container and run gdb outside ?

I ran it on the same machine - no containers involved. I created the dump when the debug symbols were not yet available, but that should not be an issue right? I also double checked if the running process had been an older version but that is not the case either.

The location of the master socket could depend on your distro or your deployment (and it could also be disabled).

As @TimWolla pointed out it is /run/haproxy-master.sock and the CLI args my instance is running with confirm that. I will get back to you once I have the information collected via socket after such an incident happens again.

It seems to me that when under gdb, you should be able to issue: p/x ha_tgroup_ctx[0].threads_harmless p/x thread_dump_state p thread_dump_tid set print elements 0 x/s thread_dump_buffer->area

and it should show the dump state and the whole threads that have already been dumped.

I did that on the coredump but only got this:

Core was generated by `/usr/sbin/haproxy'.
#0  0x00007f5e29a4e46e in ?? ()
[Current thread is 1 (LWP 2569361)]
(gdb) p/x ha_tgroup_ctx[0].threads_harmless
$1 = 0xfffffffffffffff
(gdb) p/x thread_dump_state
$2 = 0x0
(gdb) p thread_dump_tid
$3 = 0
(gdb) set print elements 0
(gdb) x/s thread_dump_buffer->area
Cannot access memory at address 0x8

What am I doing wrong?

OK indeed don't throw the core, usually they are correct. The fact that debug syms were not installed is indeed not relevant, they're only used by the debugger. In your attempt at decoding some elements above, it's clear that there's an issue. But your not doing anything wrong in my opinion. Keep in mind that you're witnessing an abnormal behavior that we haven't yet figured, and here it might very well just be a consequence of this abnormal behavior and nothing else.

By the way @phihos I'm thinking about something. Could you please check if it is normal to have 60 threads, or if more were expected ? I'm indeed wondering if it would be possible that during the soft-stop, a few threads already left and that the other ones would all be waiting for each other. It's unlikely but still a possibility we should not completely rule out given that the process is soft-stopping.

Could you please check if it is normal to have 60 threads, or if more were expected ?

Sadly this is not it. The config I posted at the top is the one from the instance I took the backtraces from. It has nbthread set to 60.

Sorry, I looked for it and couldn't find it :-( I guess I should read less configs and less issues ... For now I really have no other idea. Between issues, I'm still working on the backports for 2.7.2. While I don't see why it would magically fix this issue, it will still be interesting to know if it surprisingly vanishes, just in case it's a side effect of another one.

@phihos I think I managed to reproduce it now. Performing 10 reloads per second while running "show threads" in loops gave me a looping process where all threads are waiting in the debug handler. Now investigating. This is still postponing 2.7.2, hoping I'll find it quickly.

This is great news! Fingers crossed 🤞

So I've pushed two fixes for this in 2.7-maint. I hope to release 2.7.2 tomorrow.

Since 2.7.2 was released today, I'm marking this as fixed and am waiting for your confirmation before closing.

Hi, I just upgraded the first machine and after install I got the same issue again. That was expected because the old process was still running as v2.7.1. I could not get any gdb thread information out of this because I upgraded the debug symbols as well and the old version does not seem to be available via PPA anymore.

But I managed to execute the socket commands:

echo "show proc" | socat stdio /run/haproxy-master.sock
#<PID>          <type>          <reloads>       <uptime>        <version>      
434460          master          7 [failed: 0]   8d14h10m45s     2.7.2-1ppa1~focal
# workers
1734768         worker          0               0d00h13m33s     2.7.2-1ppa1~focal
# old workers
866153          worker          1               5d17h48m16s     2.7.1-1ppa1~focal
# programs

echo '@-1 show info' | socat stdio /run/haproxy-master.sock
Can't find the target PID matching the prefix '@-1'
echo '@!866153 show info' | socat stdio /run/haproxy-master.sock
echo '@!866153 show activity' | socat stdio /run/haproxy-master.sock
echo '@!866153 show threads' | socat stdio /run/haproxy-master.sock
echo '@!866153 show tasks' | socat stdio /run/haproxy-master.sock
echo '@!866153 show fd' | socat stdio /run/haproxy-master.sock
echo '@!866153 show sess all' | socat stdio /run/haproxy-master.sock

Not sure if that process was so broken that it did indeed not display anything at all or the version difference was reponsible for this.

I will get back to you on Monday about how it went.

Looking very good so far. I had to reload multiple times for config changes and encountered no CPU issues.

Maybe a short off-topic issue if that is ok: The config changes I made were related to the EPYC CPU issues we discussed recently. You mentioned that HaProxy 2.7 is capable of handling disjoint L3 caches. As far a I understood the docs I will have to change the following

global
  nbthread  48
  # [...]

frontend https
  bind *:443 ssl
  # [...]

# [...]

to the following

global
  nbthread  48
  thread-groups 4 # because of the 4 L3 caches
  # cpu mapped according to output of lscpu -e
  cpu-map auto:1/1-12    0-5 24-29
  cpu-map auto:2/1-12   6-11 30-35
  cpu-map auto:3/1-12   12-17 36-41
  cpu-map auto:4/1-12   18-23 42-47
  # [...]

frontend https
  bind *:443 ssl thread 1/all
  bind *:443 ssl thread 2/all
  bind *:443 ssl thread 3/all
  bind *:443 ssl thread 4/all
  # [...]

# [...]

Is that the intended way of doing it? A blog post dedicated to that topic might really clear things up since it is not easy to extract that kind of information from the docs.

Thanks for the positive and encouraging feedback!

Regarding thread groups, yes that's the way of dealing with it for now. You may even use cpu-map 1/all 0-5 ... (i.e. drop "auto" and the explicit thread count), it will still do the right thing.

For 2.8 I absolutely want to be able to support a single bind line that takes all groups. It has started (was started before 2.7 even) but I'm still making slow progess on it. That's why you still have to explicitly set it for now but the intent is that you won't have to deal with all that anymore. And once that's OK we can imagine automatically counting the number of groups and the respective CPU ids so that you don't even need cpu-map anymore.

For 2.8 I absolutely want to be able to support a single bind line that takes all groups.

That is great news. This currently requires a lot of extra config work.

Currently at least on low to medium loads the CPU utilization seems a little bit higher with more than one thread group (a few %). Is there something wrong or is this expected and will perform better on high load?

In theory it should not, but in practice it might be caused by the multiple bind lines. While having several is better for scalability and handle larger loads, it also causes more threads to be woken up for the same amount of work, each doing less. For example if you receive 50 new connections in the same millisecond, chances are that without "thread" the same thread will take them all at once, while without, you could have 10 threads wake up to take 5 connections each and go back to sleep.

Another element to watch normally (but that's not your case since you're exclusively TCP) is the HTTP reuse rate. Threads from one group will never steal idle connections from another group. Depending on the tuning in place, it could cause a lower reuse rate by more often exceeding the max number of idle conns, resulting in more open/close on the server side. Other than that, there's less sharing of everything with more groups so it shouldn't increase CPU usage.

One point though, you have network IRQs on the same cores/threads. Maybe the "auto" in cpu-map is the one causing some contention between haproxy and the network driver by insisting that each thread sticks to a specific CPU. When not setting "auto", all the threads from one group are free to move to any CPU from the same group, which offers more flexibility to coexist with the network stack. It could be possible that it counts in your case.

Thank you very much for the detailed explanation!

I actually have both L4 in front and L7 "in the middle". On both it seemed to have caused minimally more CPU utilization, but nothing serious. I just tried removing auto and it might have helped. Not really sure:

The green line is idle time. But traffic was declining anyways :man_shrugging:

Anyway thank you very much. Maybe what you have just told me could be made into an official blog post? I always quite enjoy them :-)

Maybe what you have just told me could be made into an official blog post

It's planned and started but it's taking ages to complete it :-/

@wtarreau Something similar happened again. I moved traffic from one L4 LB to another previously idle L4 LB which had been restarted recently. This is the gdb backtrace:

Also a perf top taken after letting gdb contin ue the process:

Just tell me when I need to create a new ticket.

Edit: Since I updated haproxy in the meantime:

Edit 2: Shortly before the was a sharp increase in new TCP connections due to a poorly performing backend app with high traffic. This congestion might have something to do with it. At that time I was investigating whether to increase tcp_wmem because it was almost fully utilized according to sockstat. Could that be the root cause?

This one is totally different actually, all the time it spent in the kernel's TCP sending functions, there's no sched_yield() involved anymore. I'm particularly concerned by __skmem_raise_allocated() and sk_stream_alloc_skb() which may possibly indicate some form of socket buffer shortage in the kernel. Thus it could be possible that tcp_sendmsg() and friends are actually waiting for some locks to be released in order to make progress, or might be looping a few times trying to find memory. Did you notice a sudden drop of available memory at the same time on the server ?

Oh I'm seeing your Edit2 now. Yeah, given that you're dealing with millions of connections, any tiny variation in memory allocation can be greatly amplified. The default tcp_wmem is 16kB so even the default value will consume 16 GB of kernel memory per million connections. Given that your connections are on the two sides of the proxy you can count on 32 GB of RAM for the kernel alone per million forwarded connections. With such large numbers you need to be extremely careful about these parameters. Large values will allow large bandwidth per client at the expense of memory consumption. Low values will not necessarily fill a client's available bandwidth but may be necessary to preserve your resources. Note that in order not to fiddle with these parameters at the system level, you can adjust them in the haproxy config per side: tune.sndbuf.client, tune.sndbuf.server etc. If you're dealing with two different traffic classes (e.g. few videos and millions of websocket conns for example) it could make sense to split that into two haproxy processes to have two distinct settings. If it turns out to be a good solution we could study a way to move them per-frontend or per-backend.

Thank you for the advice. Maybe something that I also should mention is that I recorded the stack trace AFTER I moved the traffic away from that machine. CPU consumption still kept at 100% until I restarted the service. This behavior looked very similar to the initial problem and this is why I posted it here. Is staying at 100% CPU load expected minutes after the traffic is gone?

Hi, I just wanted to let you know that I have not experienced this kind of issue with newer HaProxy versions (I think 2.7.4+, but I am not quite sure).

Thanks for the feedback. We can close the issue.