Welcome! Log In Create A New Profile

Advanced

Idle HAProxy 1.8 spins at 100% in user space

Posted by Krishna Kumar (Engineering) 
Krishna Kumar (Engineering)
Idle HAProxy 1.8 spins at 100% in user space
March 12, 2018 08:00AM
As an aside, could someone also post a simple configuration file to
enable 40 listeners (thread)?

I get 100% cpu util when running high number (>30, on a 48 core system)
of threads, I have tried both these versions:

HA-Proxy version 1.8.4-1ppa1~xenial 2018/02/10: Installed via .deb file
HA-Proxy version 1.8.4-1deb90d 2018/02/08: Built from source
http://www.haproxy.org/download/1.8/src/haproxy-1.8.4.tar.gz


1. Distro/kernel: Ubuntu 16.04.1 LTS, 4.4.0-36-generic

2. Top:
# top -d 1 -b | head -12
top - 11:59:06 up 4 days, 41 min, 1 user, load average: 1.00, 1.00, 2.14
Tasks: 492 total, 2 running, 464 sleeping, 0 stopped, 26 zombie
%Cpu(s): 0.5 us, 0.2 sy, 0.0 ni, 99.2 id, 0.0 wa, 0.0 hi, 0.1 si,
0.0 st
KiB Mem : 13191999+total, 77779520 free, 1222684 used, 52917792 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 12986652+avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
87994 haproxy 20 0 896624 14996 1468 R 100.0 0.0 3:09.60 haproxy
1 root 20 0 38856 7088 4132 S 0.0 0.0 0:08.69 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.08
kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 4:05.79
ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00
kworker/0:0H

3. As to what it is doing:
%Cpu0 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu1 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st
%Cpu2 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si,
0.0 st

4. Minimal configuration file to reproduce this (using this blog:
https://www.haproxy.com/blog/multithreading-in-haproxy/):

global
daemon
nbproc 1
nbthread 40
cpu-map auto:1/1-40 0-39

frontend test-fe
mode http
bind 10.33.110.118:80 process all/all
use_backend test-be

backend test-be
mode http
server 10.33.5.62 10.33.5.62:80 weight 255

5. Problem disappears when "cpu-map auto:1/1-40 0-39" is commented out.
Same strace output, so it is in user space as shown by 'top' above.

6. Version/build (gcc version 5.4.0 20160609 (Ubuntu
5.4.0-6ubuntu1~16.04.2))

# haproxy -vv
HA-Proxy version 1.8.4-1deb90d 2018/02/08
Copyright 2000-2018 Willy Tarreau <[email protected]>

Build options :
TARGET = linux2628
CPU = generic
CC = gcc
CFLAGS = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement
-fwrapv -Wno-unused-label
OPTIONS = USE_ZLIB=yes USE_OPENSSL=1 USE_PCRE=1

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

Built with OpenSSL version : OpenSSL 1.0.2g 1 Mar 2016
Running on OpenSSL version : OpenSSL 1.0.2g 1 Mar 2016
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT
IP_FREEBIND
Encrypted password support via crypt(3): yes
Built with multi-threading support.
Built with PCRE version : 8.38 2015-11-23
Running on PCRE version : 8.38 2015-11-23
PCRE library supports JIT : no (USE_PCRE_JIT not set)
Built with zlib version : 1.2.8
Running on zlib version : 1.2.8
Compression algorithms supported : identity("identity"),
deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with network namespace support.

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 filters :
[SPOE] spoe
[COMP] compression
[TRACE] trace

7. Strace of the process:
88033 11:57:18.946030 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001144>
88032 11:57:18.946046 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001149>
88033 11:57:18.946078 epoll_wait(47, <unfinished ...>
88034 11:57:18.946092 epoll_wait(48, <unfinished ...>
88032 11:57:18.946104 epoll_wait(46, <unfinished ...>
88031 11:57:18.946115 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001153>
88030 11:57:18.946128 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001154>
88029 11:57:18.946140 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001155>
88028 11:57:18.946152 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001216>
88031 11:57:18.946169 epoll_wait(44, <unfinished ...>
88027 11:57:18.946181 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001183>
88030 11:57:18.946196 epoll_wait(43, <unfinished ...>
88029 11:57:18.946208 epoll_wait(40, <unfinished ...>
88028 11:57:18.946219 epoll_wait(39, <unfinished ...>
88027 11:57:18.946231 epoll_wait(38, <unfinished ...>
88026 11:57:18.946244 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001296>
88025 11:57:18.946257 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001248>
88024 11:57:18.946269 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001226>
88023 11:57:18.946282 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001210>
88026 11:57:18.946293 epoll_wait(37, <unfinished ...>
88022 11:57:18.946307 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001224>
88025 11:57:18.946320 epoll_wait(36, <unfinished ...>
88024 11:57:18.946332 epoll_wait(35, <unfinished ...>
88023 11:57:18.946344 epoll_wait(34, <unfinished ...>
88022 11:57:18.946356 epoll_wait(33, <unfinished ...>
88021 11:57:18.946368 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001267>
88020 11:57:18.946380 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001269>
88021 11:57:18.946393 epoll_wait(32, <unfinished ...>
88020 11:57:18.946444 epoll_wait(31, <unfinished ...>
88019 11:57:18.946472 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001331>
88018 11:57:18.946486 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001319>
88019 11:57:18.946514 epoll_wait(30, <unfinished ...>
88017 11:57:18.946526 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001345>
88016 11:57:18.946538 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001346>
88018 11:57:18.946571 epoll_wait(29, <unfinished ...>
88016 11:57:18.946602 epoll_wait(27, <unfinished ...>
88017 11:57:18.946617 epoll_wait(28, <unfinished ...>
88015 11:57:18.946628 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001422>
88014 11:57:18.946640 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001423>
88013 11:57:18.946657 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001427>
88012 11:57:18.946669 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001428>
88015 11:57:18.946708 epoll_wait(25, <unfinished ...>
88014 11:57:18.946724 epoll_wait(42, <unfinished ...>
88013 11:57:18.946738 epoll_wait(41, <unfinished ...>
88012 11:57:18.946749 epoll_wait(45, <unfinished ...>
88011 11:57:18.946761 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001460>
88010 11:57:18.946773 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001460>
88009 11:57:18.946788 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001463>
88008 11:57:18.946806 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001469>
88011 11:57:18.946847 epoll_wait(22, <unfinished ...>
88010 11:57:18.946860 epoll_wait(26, <unfinished ...>
88009 11:57:18.946874 epoll_wait(21, <unfinished ...>
88008 11:57:18.946885 epoll_wait(14, <unfinished ...>
88007 11:57:18.946897 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001548>
88006 11:57:18.946909 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001549>
88005 11:57:18.946925 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001552>
88003 11:57:18.946943 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001548>
88007 11:57:18.946978 epoll_wait(11, <unfinished ...>
88006 11:57:18.946990 epoll_wait(24, <unfinished ...>
88005 11:57:18.947005 epoll_wait(18, <unfinished ...>
88003 11:57:18.947020 epoll_wait(19, <unfinished ...>
88001 11:57:18.947032 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001626>
88000 11:57:18.947046 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001628>
87999 11:57:18.947065 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001615>
87998 11:57:18.947079 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001507>
88001 11:57:18.947097 epoll_wait(17, <unfinished ...>
87997 11:57:18.947111 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001519>
88000 11:57:18.947130 epoll_wait(13, <unfinished ...>
87999 11:57:18.947143 epoll_wait(23, <unfinished ...>
87998 11:57:18.947156 epoll_wait(20, <unfinished ...>
87997 11:57:18.947173 epoll_wait(15, <unfinished ...>
87996 11:57:18.947185 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001582>
87995 11:57:18.947198 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001581>
88004 11:57:18.947265 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001879>
87996 11:57:18.947307 epoll_wait(12, <unfinished ...>
87995 11:57:18.947323 epoll_wait(10, <unfinished ...>
88004 11:57:18.947355 epoll_wait(16, <unfinished ...>
88034 11:57:19.947175 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001073>
88033 11:57:19.947220 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001133>
88032 11:57:19.947236 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001124>
88031 11:57:19.947248 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001072>
88030 11:57:19.947264 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001060>
88034 11:57:19.947284 epoll_wait(48, <unfinished ...>
88033 11:57:19.947297 epoll_wait(47, <unfinished ...>
88032 11:57:19.947310 epoll_wait(46, <unfinished ...>
88031 11:57:19.947322 epoll_wait(44, <unfinished ...>
88030 11:57:19.947333 epoll_wait(43, <unfinished ...>
88029 11:57:19.947349 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001135>
88028 11:57:19.947361 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001135>
88027 11:57:19.947373 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001136>
88026 11:57:19.947386 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001085>
88029 11:57:19.947409 epoll_wait(40, <unfinished ...>
88028 11:57:19.947422 epoll_wait(39, <unfinished ...>
88027 11:57:19.947434 epoll_wait(38, <unfinished ...>
88026 11:57:19.947446 epoll_wait(37, <unfinished ...>
88025 11:57:19.947459 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001131>
88024 11:57:19.947471 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001132>
88023 11:57:19.947483 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001132>
88022 11:57:19.947495 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001132>
88025 11:57:19.947511 epoll_wait(36, <unfinished ...>
88024 11:57:19.947528 epoll_wait(35, <unfinished ...>
88023 11:57:19.947540 epoll_wait(34, <unfinished ...>
88022 11:57:19.947553 epoll_wait(33, <unfinished ...>
88021 11:57:19.947565 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001164>
88020 11:57:19.947576 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001112>
88019 11:57:19.947590 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001069>
88016 11:57:19.947602 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000993>
88021 11:57:19.947619 epoll_wait(32, <unfinished ...>
88020 11:57:19.947638 epoll_wait(31, <unfinished ...>
88019 11:57:19.947650 epoll_wait(30, <unfinished ...>
88018 11:57:19.947661 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001083>
88016 11:57:19.947674 epoll_wait(27, <unfinished ...>
88017 11:57:19.947690 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001067>
88018 11:57:19.947703 epoll_wait(29, <unfinished ...>
88017 11:57:19.947716 epoll_wait(28, <unfinished ...>
88015 11:57:19.947728 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001012>
88014 11:57:19.947740 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001008>
88015 11:57:19.947753 epoll_wait(25, <unfinished ...>
88013 11:57:19.947764 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001020>
88012 11:57:19.947776 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001021>
88014 11:57:19.947789 epoll_wait(42, <unfinished ...>
88010 11:57:19.947801 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000933>
88008 11:57:19.947813 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000921>
88012 11:57:19.947826 epoll_wait(45, <unfinished ...>
88013 11:57:19.947845 epoll_wait(41, <unfinished ...>
88011 11:57:19.947860 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001005>
88010 11:57:19.947872 epoll_wait(26, <unfinished ...>
88011 11:57:19.947885 epoll_wait(22, <unfinished ...>
88009 11:57:19.947896 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001016>
88008 11:57:19.947908 epoll_wait(14, <unfinished ...>
88001 11:57:19.947920 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000815>
88009 11:57:19.947933 epoll_wait(21, <unfinished ...>
88007 11:57:19.947979 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000987>
88006 11:57:19.948022 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001024>
88005 11:57:19.948038 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001027>
88006 11:57:19.948053 epoll_wait(24, <unfinished ...>
88001 11:57:19.948067 epoll_wait(17, <unfinished ...>
88007 11:57:19.948078 epoll_wait(11, <unfinished ...>
88003 11:57:19.948117 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001089>
88005 11:57:19.948134 epoll_wait(18, <unfinished ...>
88003 11:57:19.948146 epoll_wait(19, <unfinished ...>
88000 11:57:19.948158 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001021>
87998 11:57:19.948171 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001008>
88000 11:57:19.948239 epoll_wait(13, <unfinished ...>
87999 11:57:19.948275 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001125>
87998 11:57:19.948293 epoll_wait(20, <unfinished ...>
87997 11:57:19.948305 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001125>
87999 11:57:19.948336 epoll_wait(23, <unfinished ...>
87997 11:57:19.948355 epoll_wait(15, <unfinished ...>
88004 11:57:19.948460 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001093>
87996 11:57:19.948500 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001182>
87995 11:57:19.948518 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001187>
88004 11:57:19.948536 epoll_wait(16, <unfinished ...>
87996 11:57:19.948560 epoll_wait(12, <unfinished ...>
87995 11:57:19.948576 epoll_wait(10, <unfinished ...>
88034 11:57:20.948304 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001009>
88001 11:57:20.948348 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000275>
88033 11:57:20.948365 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001060>
88032 11:57:20.948382 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001064>
88034 11:57:20.948397 epoll_wait(48, <unfinished ...>
88033 11:57:20.948412 epoll_wait(47, <unfinished ...>
88032 11:57:20.948424 epoll_wait(46, <unfinished ...>
88031 11:57:20.948436 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001107>
88030 11:57:20.948449 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001110>
88031 11:57:20.948467 epoll_wait(44, <unfinished ...>
88029 11:57:20.948479 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001061>
88028 11:57:20.948492 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001062>
88027 11:57:20.948505 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001063>
88030 11:57:20.948518 epoll_wait(43, <unfinished ...>
88028 11:57:20.948530 epoll_wait(39, <unfinished ...>
88029 11:57:20.948541 epoll_wait(40, <unfinished ...>
88027 11:57:20.948553 epoll_wait(38, <unfinished ...>
88026 11:57:20.948564 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001111>
88025 11:57:20.948578 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001060>
88024 11:57:20.948590 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001056>
88023 11:57:20.948603 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001055>
88026 11:57:20.948615 epoll_wait(37, <unfinished ...>
88022 11:57:20.948627 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001068>
88025 11:57:20.948640 epoll_wait(36, <unfinished ...>
88024 11:57:20.948653 epoll_wait(35, <unfinished ...>
88023 11:57:20.948665 epoll_wait(34, <unfinished ...>
88022 11:57:20.948682 epoll_wait(33, <unfinished ...>
88021 11:57:20.948694 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001060>
88020 11:57:20.948707 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001061>
88021 11:57:20.948724 epoll_wait(32, <unfinished ...>
88020 11:57:20.948735 epoll_wait(31, <unfinished ...>
88019 11:57:20.948747 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001090>
88018 11:57:20.948764 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001055>
88019 11:57:20.948778 epoll_wait(30, <unfinished ...>
88017 11:57:20.948791 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001068>
88018 11:57:20.948809 epoll_wait(29, <unfinished ...>
88016 11:57:20.948822 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001140>
88015 11:57:20.948834 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001074>
88014 11:57:20.948846 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001050>
88017 11:57:20.948860 epoll_wait(28, <unfinished ...>
88016 11:57:20.948871 epoll_wait(27, <unfinished ...>
88013 11:57:20.948884 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001031>
88015 11:57:20.948902 epoll_wait(25, <unfinished ...>
88014 11:57:20.948914 epoll_wait(42, <unfinished ...>
88012 11:57:20.948926 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001093>
88013 11:57:20.948939 epoll_wait(41, <unfinished ...>
88011 11:57:20.948951 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001059>
88010 11:57:20.948963 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001084>
88012 11:57:20.948978 epoll_wait(45, <unfinished ...>
88009 11:57:20.948990 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001050>
88008 11:57:20.949002 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001087>
88011 11:57:20.949020 epoll_wait(22, <unfinished ...>
88010 11:57:20.949032 epoll_wait(26, <unfinished ...>
88001 11:57:20.949044 epoll_wait(17, <unfinished ...>
88009 11:57:20.949057 epoll_wait(21, <unfinished ...>
88008 11:57:20.949069 epoll_wait(14, <unfinished ...>
88007 11:57:20.949081 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000996>
88006 11:57:20.949094 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001033>
88007 11:57:20.949123 epoll_wait(11, <unfinished ...>
88006 11:57:20.949136 epoll_wait(24, <unfinished ...>
88005 11:57:20.949149 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001009>
88005 11:57:20.949199 epoll_wait(18, <unfinished ...>
88003 11:57:20.949214 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001061>
88003 11:57:20.949255 epoll_wait(19, <unfinished ...>
88000 11:57:20.949295 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001026>
88000 11:57:20.949437 epoll_wait(13, <unfinished ...>
87999 11:57:20.949477 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001130>
87998 11:57:20.949494 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001193>
87997 11:57:20.949508 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001145>
87999 11:57:20.949574 epoll_wait(23, <unfinished ...>
88004 11:57:20.949613 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001058>
87998 11:57:20.949629 epoll_wait(20, <unfinished ...>
87997 11:57:20.949642 epoll_wait(15, <unfinished ...>
87996 11:57:20.949653 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001085>
87995 11:57:20.949666 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001082>
88004 11:57:20.949678 epoll_wait(16, <unfinished ...>
87996 11:57:20.949710 epoll_wait(12, <unfinished ...>
87995 11:57:20.949723 epoll_wait(10, <unfinished ...>
88033 11:57:21.949419 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000997>
88032 11:57:21.949461 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001030>
88034 11:57:21.949477 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001071>
88031 11:57:21.949493 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001018>
88033 11:57:21.949525 epoll_wait(47, <unfinished ...>
88034 11:57:21.949545 epoll_wait(48, <unfinished ...>
88032 11:57:21.949557 epoll_wait(46, <unfinished ...>
88031 11:57:21.949568 epoll_wait(44, <unfinished ...>
88030 11:57:21.949580 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001054>
88029 11:57:21.949592 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001044>
88028 11:57:21.949610 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001074>
88027 11:57:21.949631 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001071>
88030 11:57:21.949645 epoll_wait(43, <unfinished ...>
88029 11:57:21.949657 epoll_wait(40, <unfinished ...>
88028 11:57:21.949669 epoll_wait(39, <unfinished ...>
88026 11:57:21.949681 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001060>
88027 11:57:21.949695 epoll_wait(38, <unfinished ...>
88026 11:57:21.949714 epoll_wait(37, <unfinished ...>
88025 11:57:21.949728 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001080>
88024 11:57:21.949746 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001086>
88023 11:57:21.949759 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001086>
88022 11:57:21.949772 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001083>
88025 11:57:21.949791 epoll_wait(36, <unfinished ...>
88024 11:57:21.949802 epoll_wait(35, <unfinished ...>
88023 11:57:21.949815 epoll_wait(34, <unfinished ...>
88021 11:57:21.949827 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001096>
88022 11:57:21.949839 epoll_wait(33, <unfinished ...>
88020 11:57:21.949855 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001108>
88019 11:57:21.949875 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001091>
88018 11:57:21.949887 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001072>
88021 11:57:21.949901 epoll_wait(32, <unfinished ...>
88020 11:57:21.949916 epoll_wait(31, <unfinished ...>
88019 11:57:21.949929 epoll_wait(30, <unfinished ...>
88018 11:57:21.949941 epoll_wait(29, <unfinished ...>
88017 11:57:21.949957 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001090>
88016 11:57:21.949969 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001091>
88015 11:57:21.949982 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001072>
88014 11:57:21.949993 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001073>
88017 11:57:21.950031 epoll_wait(28, <unfinished ...>
88016 11:57:21.950044 epoll_wait(27, <unfinished ...>
88015 11:57:21.950057 epoll_wait(25, <unfinished ...>
88014 11:57:21.950068 epoll_wait(42, <unfinished ...>
88013 11:57:21.950080 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001134>
88012 11:57:21.950093 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001107>
88011 11:57:21.950117 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001089>
88010 11:57:21.950130 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001092>
88013 11:57:21.950144 epoll_wait(41, <unfinished ...>
88012 11:57:21.950156 epoll_wait(45, <unfinished ...>
88009 11:57:21.950168 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001103>
88010 11:57:21.950180 epoll_wait(26, <unfinished ...>
88011 11:57:21.950193 epoll_wait(22, <unfinished ...>
88008 11:57:21.950204 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001129>
88007 11:57:21.950225 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001092>
88009 11:57:21.950237 epoll_wait(21, <unfinished ...>
88006 11:57:21.950249 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001105>
88008 11:57:21.950261 epoll_wait(14, <unfinished ...>
88005 11:57:21.950274 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001065>
88007 11:57:21.950287 epoll_wait(11, <unfinished ...>
88006 11:57:21.950299 epoll_wait(24, <unfinished ...>
88001 11:57:21.950311 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001259>
88005 11:57:21.950357 epoll_wait(18, <unfinished ...>
88001 11:57:21.950371 epoll_wait(17, <unfinished ...>
88003 11:57:21.950392 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001104>
88003 11:57:21.950463 epoll_wait(19, <unfinished ...>
88000 11:57:21.950505 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001034>
88000 11:57:21.950636 epoll_wait(13, <unfinished ...>
87999 11:57:21.950675 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001071>
88004 11:57:21.950762 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001075>
87999 11:57:21.950807 epoll_wait(23, <unfinished ...>
87998 11:57:21.950822 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001186>
88004 11:57:21.950843 epoll_wait(16, <unfinished ...>
87997 11:57:21.950856 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001208>
87996 11:57:21.950869 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001151>
87995 11:57:21.950883 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001152>
87998 11:57:21.950899 epoll_wait(20, <unfinished ...>
87997 11:57:21.950913 epoll_wait(15, <unfinished ...>
87996 11:57:21.950925 epoll_wait(12, <unfinished ...>
87995 11:57:21.950938 epoll_wait(10, <unfinished ...>
88033 11:57:22.950577 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001042>
88034 11:57:22.950620 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001067>
88032 11:57:22.950637 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001073>
88031 11:57:22.950651 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001076>
88033 11:57:22.950678 epoll_wait(47, <unfinished ...>
88034 11:57:22.950700 epoll_wait(48, <unfinished ...>
88032 11:57:22.950713 epoll_wait(46, <unfinished ...>
88031 11:57:22.950735 epoll_wait(44, <unfinished ...>
88030 11:57:22.950748 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001095>
88029 11:57:22.950762 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001098>
88030 11:57:22.950776 epoll_wait(43, <unfinished ...>
88029 11:57:22.950789 epoll_wait(40, <unfinished ...>
88028 11:57:22.950801 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001125>
88027 11:57:22.950814 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001107>
88028 11:57:22.950828 epoll_wait(39, <unfinished ...>
88027 11:57:22.950841 epoll_wait(38, <unfinished ...>
88026 11:57:22.950854 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001131>
88025 11:57:22.950867 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001068>
88024 11:57:22.950879 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001070>
88023 11:57:22.950892 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001069>
88026 11:57:22.950906 epoll_wait(37, <unfinished ...>
88024 11:57:22.950918 epoll_wait(35, <unfinished ...>
88025 11:57:22.950930 epoll_wait(36, <unfinished ...>
88023 11:57:22.950942 epoll_wait(34, <unfinished ...>
88022 11:57:22.950954 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001107>
88021 11:57:22.950966 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001058>
88020 11:57:22.950979 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001055>
88019 11:57:22.950990 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001054>
88022 11:57:22.951014 epoll_wait(33, <unfinished ...>
88021 11:57:22.951027 epoll_wait(32, <unfinished ...>
88020 11:57:22.951040 epoll_wait(31, <unfinished ...>
88019 11:57:22.951051 epoll_wait(30, <unfinished ...>
88018 11:57:22.951063 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001115>
88017 11:57:22.951075 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001035>
88016 11:57:22.951087 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001037>
88015 11:57:22.951099 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001035>
88018 11:57:22.951114 epoll_wait(29, <unfinished ...>
88017 11:57:22.951126 epoll_wait(28, <unfinished ...>
88016 11:57:22.951138 epoll_wait(27, <unfinished ...>
88015 11:57:22.951150 epoll_wait(25, <unfinished ...>
88014 11:57:22.951162 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001086>
88013 11:57:22.951173 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001022>
88012 11:57:22.951186 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001023>
88011 11:57:22.951198 <... epoll_wait resumed> [], 200, 1000) = 0 <1.000998>
88014 11:57:22.951213 epoll_wait(42, <unfinished ...>
88013 11:57:22.951225 epoll_wait(41, <unfinished ...>
88012 11:57:22.951238 epoll_wait(45, <unfinished ...>
88011 11:57:22.951249 epoll_wait(22, <unfinished ...>
88010 11:57:22.951261 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001073>
88009 11:57:22.951273 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001028>
88008 11:57:22.951285 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001017>
88009 11:57:22.951297 epoll_wait(21, <unfinished ...>
88007 11:57:22.951310 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001016>
88010 11:57:22.951323 epoll_wait(26, <unfinished ...>
88008 11:57:22.951336 epoll_wait(14, <unfinished ...>
88006 11:57:22.951348 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001042>
88007 11:57:22.951364 epoll_wait(11, <unfinished ...>
88005 11:57:22.951376 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001011>
88005 11:57:22.951403 epoll_wait(18, <unfinished ...>
88006 11:57:22.951420 epoll_wait(24, <unfinished ...>
88001 11:57:22.951432 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001055>
88003 11:57:22.951500 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001024>
88001 11:57:22.951541 epoll_wait(17, <unfinished ...>
88003 11:57:22.951611 epoll_wait(19, <unfinished ...>
88000 11:57:22.951721 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001053>
88000 11:57:22.951755 epoll_wait(13, <unfinished ...>
87999 11:57:22.951895 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001075>
88004 11:57:22.951937 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001085>
87998 11:57:22.951956 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001049>
87997 11:57:22.951974 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001055>
87999 11:57:22.951989 epoll_wait(23, <unfinished ...>
88004 11:57:22.952003 epoll_wait(16, <unfinished ...>
87998 11:57:22.952015 epoll_wait(20, <unfinished ...>
87997 11:57:22.952027 epoll_wait(15, <unfinished ...>
87996 11:57:22.952040 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001108>
87995 11:57:22.952053 <... epoll_wait resumed> [], 200, 1000) = 0 <1.001107>
Cyril Bonté
Re: Idle HAProxy 1.8 spins at 100% in user space
March 12, 2018 12:40PM
Hi Krishna and Willy,

----- Mail original -----
> De: "Krishna Kumar (Engineering)" <[email protected]>
> À: "HAProxy" <[email protected]>
> Envoyé: Lundi 12 Mars 2018 07:48:50
> Objet: Idle HAProxy 1.8 spins at 100% in user space
>
> As an aside, could someone also post a simple configuration file to
> enable 40 listeners (thread)?
>
> I get 100% cpu util when running high number (>30, on a 48 core
> system)
> of threads, I have tried both these versions:
>
> HA-Proxy version 1.8.4-1ppa1~xenial 2018/02/10: Installed via .deb
> file
> HA-Proxy version 1.8.4-1deb90d 2018/02/08: Built from source
> http://www.haproxy.org/download/1.8/src/haproxy-1.8.4.tar.gz
>
> 1. Distro/kernel: Ubuntu 16.04.1 LTS, 4.4.0-36-generic
>
>
> 2. Top:
> # top -d 1 -b | head -12
> top - 11:59:06 up 4 days, 41 min, 1 user, load average: 1.00, 1.00,
> 2.14
> Tasks: 492 total, 2 running, 464 sleeping, 0 stopped, 26 zombie
> %Cpu(s): 0.5 us, 0.2 sy, 0.0 ni, 99.2 id, 0.0 wa, 0.0 hi, 0.1 si, 0.0
> st
> KiB Mem : 13191999+total, 77779520 free, 1222684 used, 52917792
> buff/cache
> KiB Swap: 0 total, 0 free, 0 used. 12986652+avail Mem
>
>
> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> 87994 haproxy 20 0 896624 14996 1468 R 100.0 0.0 3:09.60 haproxy
> 1 root 20 0 38856 7088 4132 S 0.0 0.0 0:08.69 systemd
> 2 root 20 0 0 0 0 S 0.0 0.0 0:00.08 kthreadd
> 3 root 20 0 0 0 0 S 0.0 0.0 4:05.79 ksoftirqd/0
> 5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
>
>
> 3. As to what it is doing:
> %Cpu0 :100.0 us, 0.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0
> st
>
>
> %Cpu1 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0
> st
> %Cpu2 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0
> st
>
>
> 4. Minimal configuration file to reproduce this (using this blog:
> https://www.haproxy.com/blog/multithreading-in-haproxy/ ):
>
>
>
> global
> daemon
> nbproc 1
> nbthread 40
> cpu-map auto:1/1-40 0-39

I confirm I can reproduce the issue once 32 (and more) threads are used : the main process enters an endless loop.
I think the same issue may occur with nbproc on FreeBSD (the same code in an #ifdef ____FreeBSD__).

Can you try the patch attached ? I'll send a clean one later.

>
>
> frontend test-fe
> mode http
> bind 10.33.110.118:80 process all/all
> use_backend test-be
>
>
> backend test-be
> mode http
> server 10.33.5.62 10.33.5.62:80 weight 255
>
>
> 5. Problem disappears when " cpu-map auto:1/1-40 0-39" is commented
> out.
> Same strace output, so it is in user space as shown by 'top' above.
>
>
> 6. Version/build (gcc version 5.4.0 20160609 (Ubuntu
> 5.4.0-6ubuntu1~16.04.2))
>
>
>
> # haproxy -vv
> HA-Proxy version 1.8.4-1deb90d 2018/02/08
> Copyright 2000-2018 Willy Tarreau < willy@haproxy.org >
>
>
> Build options :
> TARGET = linux2628
> CPU = generic
> CC = gcc
> CFLAGS = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement
> -fwrapv -Wno-unused-label
> OPTIONS = USE_ZLIB=yes USE_OPENSSL=1 USE_PCRE=1
>
>
> Default settings :
> maxconn = 2000, bufsize = 16384, maxrewrite = 1024, maxpollevents =
> 200
>
>
> Built with OpenSSL version : OpenSSL 1.0.2g 1 Mar 2016
> Running on OpenSSL version : OpenSSL 1.0.2g 1 Mar 2016
> OpenSSL library supports TLS extensions : yes
> OpenSSL library supports SNI : yes
> OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2
> Built with transparent proxy support using: IP_TRANSPARENT
> IPV6_TRANSPARENT IP_FREEBIND
> Encrypted password support via crypt(3): yes
> Built with multi-threading support.
> Built with PCRE version : 8.38 2015-11-23
> Running on PCRE version : 8.38 2015-11-23
> PCRE library supports JIT : no (USE_PCRE_JIT not set)
> Built with zlib version : 1.2.8
> Running on zlib version : 1.2.8
> Compression algorithms supported : identity("identity"),
> deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
> Built with network namespace support.
>
>
> 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 filters :
> [SPOE] spoe
> [COMP] compression
> [TRACE] trace
>
>
> 7. Strace of the process:
> 88033 11:57:18.946030 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001144>
> 88032 11:57:18.946046 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001149>
> 88033 11:57:18.946078 epoll_wait(47, <unfinished ...>
> 88034 11:57:18.946092 epoll_wait(48, <unfinished ...>
> 88032 11:57:18.946104 epoll_wait(46, <unfinished ...>
> 88031 11:57:18.946115 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001153>
> 88030 11:57:18.946128 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001154>
> 88029 11:57:18.946140 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001155>
> 88028 11:57:18.946152 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001216>
> 88031 11:57:18.946169 epoll_wait(44, <unfinished ...>
> 88027 11:57:18.946181 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001183>
> 88030 11:57:18.946196 epoll_wait(43, <unfinished ...>
> 88029 11:57:18.946208 epoll_wait(40, <unfinished ...>
> 88028 11:57:18.946219 epoll_wait(39, <unfinished ...>
> 88027 11:57:18.946231 epoll_wait(38, <unfinished ...>
> 88026 11:57:18.946244 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001296>
> 88025 11:57:18.946257 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001248>
> 88024 11:57:18.946269 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001226>
> 88023 11:57:18.946282 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001210>
> 88026 11:57:18.946293 epoll_wait(37, <unfinished ...>
> 88022 11:57:18.946307 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001224>
> 88025 11:57:18.946320 epoll_wait(36, <unfinished ...>
> 88024 11:57:18.946332 epoll_wait(35, <unfinished ...>
> 88023 11:57:18.946344 epoll_wait(34, <unfinished ...>
> 88022 11:57:18.946356 epoll_wait(33, <unfinished ...>
> 88021 11:57:18.946368 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001267>
> 88020 11:57:18.946380 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001269>
> 88021 11:57:18.946393 epoll_wait(32, <unfinished ...>
> 88020 11:57:18.946444 epoll_wait(31, <unfinished ...>
> 88019 11:57:18.946472 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001331>
> 88018 11:57:18.946486 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001319>
> 88019 11:57:18.946514 epoll_wait(30, <unfinished ...>
> 88017 11:57:18.946526 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001345>
> 88016 11:57:18.946538 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001346>
> 88018 11:57:18.946571 epoll_wait(29, <unfinished ...>
> 88016 11:57:18.946602 epoll_wait(27, <unfinished ...>
> 88017 11:57:18.946617 epoll_wait(28, <unfinished ...>
> 88015 11:57:18.946628 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001422>
> 88014 11:57:18.946640 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001423>
> 88013 11:57:18.946657 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001427>
> 88012 11:57:18.946669 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001428>
> 88015 11:57:18.946708 epoll_wait(25, <unfinished ...>
> 88014 11:57:18.946724 epoll_wait(42, <unfinished ...>
> 88013 11:57:18.946738 epoll_wait(41, <unfinished ...>
> 88012 11:57:18.946749 epoll_wait(45, <unfinished ...>
> 88011 11:57:18.946761 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001460>
> 88010 11:57:18.946773 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001460>
> 88009 11:57:18.946788 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001463>
> 88008 11:57:18.946806 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001469>
> 88011 11:57:18.946847 epoll_wait(22, <unfinished ...>
> 88010 11:57:18.946860 epoll_wait(26, <unfinished ...>
> 88009 11:57:18.946874 epoll_wait(21, <unfinished ...>
> 88008 11:57:18.946885 epoll_wait(14, <unfinished ...>
> 88007 11:57:18.946897 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001548>
> 88006 11:57:18.946909 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001549>
> 88005 11:57:18.946925 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001552>
> 88003 11:57:18.946943 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001548>
> 88007 11:57:18.946978 epoll_wait(11, <unfinished ...>
> 88006 11:57:18.946990 epoll_wait(24, <unfinished ...>
> 88005 11:57:18.947005 epoll_wait(18, <unfinished ...>
> 88003 11:57:18.947020 epoll_wait(19, <unfinished ...>
> 88001 11:57:18.947032 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001626>
> 88000 11:57:18.947046 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001628>
> 87999 11:57:18.947065 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001615>
> 87998 11:57:18.947079 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001507>
> 88001 11:57:18.947097 epoll_wait(17, <unfinished ...>
> 87997 11:57:18.947111 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001519>
> 88000 11:57:18.947130 epoll_wait(13, <unfinished ...>
> 87999 11:57:18.947143 epoll_wait(23, <unfinished ...>
> 87998 11:57:18.947156 epoll_wait(20, <unfinished ...>
> 87997 11:57:18.947173 epoll_wait(15, <unfinished ...>
> 87996 11:57:18.947185 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001582>
> 87995 11:57:18.947198 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001581>
> 88004 11:57:18.947265 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001879>
> 87996 11:57:18.947307 epoll_wait(12, <unfinished ...>
> 87995 11:57:18.947323 epoll_wait(10, <unfinished ...>
> 88004 11:57:18.947355 epoll_wait(16, <unfinished ...>
> 88034 11:57:19.947175 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001073>
> 88033 11:57:19.947220 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001133>
> 88032 11:57:19.947236 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001124>
> 88031 11:57:19.947248 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001072>
> 88030 11:57:19.947264 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001060>
> 88034 11:57:19.947284 epoll_wait(48, <unfinished ...>
> 88033 11:57:19.947297 epoll_wait(47, <unfinished ...>
> 88032 11:57:19.947310 epoll_wait(46, <unfinished ...>
> 88031 11:57:19.947322 epoll_wait(44, <unfinished ...>
> 88030 11:57:19.947333 epoll_wait(43, <unfinished ...>
> 88029 11:57:19.947349 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001135>
> 88028 11:57:19.947361 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001135>
> 88027 11:57:19.947373 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001136>
> 88026 11:57:19.947386 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001085>
> 88029 11:57:19.947409 epoll_wait(40, <unfinished ...>
> 88028 11:57:19.947422 epoll_wait(39, <unfinished ...>
> 88027 11:57:19.947434 epoll_wait(38, <unfinished ...>
> 88026 11:57:19.947446 epoll_wait(37, <unfinished ...>
> 88025 11:57:19.947459 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001131>
> 88024 11:57:19.947471 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001132>
> 88023 11:57:19.947483 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001132>
> 88022 11:57:19.947495 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001132>
> 88025 11:57:19.947511 epoll_wait(36, <unfinished ...>
> 88024 11:57:19.947528 epoll_wait(35, <unfinished ...>
> 88023 11:57:19.947540 epoll_wait(34, <unfinished ...>
> 88022 11:57:19.947553 epoll_wait(33, <unfinished ...>
> 88021 11:57:19.947565 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001164>
> 88020 11:57:19.947576 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001112>
> 88019 11:57:19.947590 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001069>
> 88016 11:57:19.947602 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000993>
> 88021 11:57:19.947619 epoll_wait(32, <unfinished ...>
> 88020 11:57:19.947638 epoll_wait(31, <unfinished ...>
> 88019 11:57:19.947650 epoll_wait(30, <unfinished ...>
> 88018 11:57:19.947661 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001083>
> 88016 11:57:19.947674 epoll_wait(27, <unfinished ...>
> 88017 11:57:19.947690 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001067>
> 88018 11:57:19.947703 epoll_wait(29, <unfinished ...>
> 88017 11:57:19.947716 epoll_wait(28, <unfinished ...>
> 88015 11:57:19.947728 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001012>
> 88014 11:57:19.947740 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001008>
> 88015 11:57:19.947753 epoll_wait(25, <unfinished ...>
> 88013 11:57:19.947764 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001020>
> 88012 11:57:19.947776 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001021>
> 88014 11:57:19.947789 epoll_wait(42, <unfinished ...>
> 88010 11:57:19.947801 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000933>
> 88008 11:57:19.947813 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000921>
> 88012 11:57:19.947826 epoll_wait(45, <unfinished ...>
> 88013 11:57:19.947845 epoll_wait(41, <unfinished ...>
> 88011 11:57:19.947860 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001005>
> 88010 11:57:19.947872 epoll_wait(26, <unfinished ...>
> 88011 11:57:19.947885 epoll_wait(22, <unfinished ...>
> 88009 11:57:19.947896 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001016>
> 88008 11:57:19.947908 epoll_wait(14, <unfinished ...>
> 88001 11:57:19.947920 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000815>
> 88009 11:57:19.947933 epoll_wait(21, <unfinished ...>
> 88007 11:57:19.947979 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000987>
> 88006 11:57:19.948022 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001024>
> 88005 11:57:19.948038 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001027>
> 88006 11:57:19.948053 epoll_wait(24, <unfinished ...>
> 88001 11:57:19.948067 epoll_wait(17, <unfinished ...>
> 88007 11:57:19.948078 epoll_wait(11, <unfinished ...>
> 88003 11:57:19.948117 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001089>
> 88005 11:57:19.948134 epoll_wait(18, <unfinished ...>
> 88003 11:57:19.948146 epoll_wait(19, <unfinished ...>
> 88000 11:57:19.948158 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001021>
> 87998 11:57:19.948171 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001008>
> 88000 11:57:19.948239 epoll_wait(13, <unfinished ...>
> 87999 11:57:19.948275 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001125>
> 87998 11:57:19.948293 epoll_wait(20, <unfinished ...>
> 87997 11:57:19.948305 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001125>
> 87999 11:57:19.948336 epoll_wait(23, <unfinished ...>
> 87997 11:57:19.948355 epoll_wait(15, <unfinished ...>
> 88004 11:57:19.948460 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001093>
> 87996 11:57:19.948500 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001182>
> 87995 11:57:19.948518 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001187>
> 88004 11:57:19.948536 epoll_wait(16, <unfinished ...>
> 87996 11:57:19.948560 epoll_wait(12, <unfinished ...>
> 87995 11:57:19.948576 epoll_wait(10, <unfinished ...>
> 88034 11:57:20.948304 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001009>
> 88001 11:57:20.948348 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000275>
> 88033 11:57:20.948365 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001060>
> 88032 11:57:20.948382 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001064>
> 88034 11:57:20.948397 epoll_wait(48, <unfinished ...>
> 88033 11:57:20.948412 epoll_wait(47, <unfinished ...>
> 88032 11:57:20.948424 epoll_wait(46, <unfinished ...>
> 88031 11:57:20.948436 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001107>
> 88030 11:57:20.948449 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001110>
> 88031 11:57:20.948467 epoll_wait(44, <unfinished ...>
> 88029 11:57:20.948479 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001061>
> 88028 11:57:20.948492 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001062>
> 88027 11:57:20.948505 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001063>
> 88030 11:57:20.948518 epoll_wait(43, <unfinished ...>
> 88028 11:57:20.948530 epoll_wait(39, <unfinished ...>
> 88029 11:57:20.948541 epoll_wait(40, <unfinished ...>
> 88027 11:57:20.948553 epoll_wait(38, <unfinished ...>
> 88026 11:57:20.948564 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001111>
> 88025 11:57:20.948578 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001060>
> 88024 11:57:20.948590 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001056>
> 88023 11:57:20.948603 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001055>
> 88026 11:57:20.948615 epoll_wait(37, <unfinished ...>
> 88022 11:57:20.948627 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001068>
> 88025 11:57:20.948640 epoll_wait(36, <unfinished ...>
> 88024 11:57:20.948653 epoll_wait(35, <unfinished ...>
> 88023 11:57:20.948665 epoll_wait(34, <unfinished ...>
> 88022 11:57:20.948682 epoll_wait(33, <unfinished ...>
> 88021 11:57:20.948694 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001060>
> 88020 11:57:20.948707 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001061>
> 88021 11:57:20.948724 epoll_wait(32, <unfinished ...>
> 88020 11:57:20.948735 epoll_wait(31, <unfinished ...>
> 88019 11:57:20.948747 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001090>
> 88018 11:57:20.948764 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001055>
> 88019 11:57:20.948778 epoll_wait(30, <unfinished ...>
> 88017 11:57:20.948791 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001068>
> 88018 11:57:20.948809 epoll_wait(29, <unfinished ...>
> 88016 11:57:20.948822 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001140>
> 88015 11:57:20.948834 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001074>
> 88014 11:57:20.948846 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001050>
> 88017 11:57:20.948860 epoll_wait(28, <unfinished ...>
> 88016 11:57:20.948871 epoll_wait(27, <unfinished ...>
> 88013 11:57:20.948884 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001031>
> 88015 11:57:20.948902 epoll_wait(25, <unfinished ...>
> 88014 11:57:20.948914 epoll_wait(42, <unfinished ...>
> 88012 11:57:20.948926 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001093>
> 88013 11:57:20.948939 epoll_wait(41, <unfinished ...>
> 88011 11:57:20.948951 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001059>
> 88010 11:57:20.948963 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001084>
> 88012 11:57:20.948978 epoll_wait(45, <unfinished ...>
> 88009 11:57:20.948990 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001050>
> 88008 11:57:20.949002 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001087>
> 88011 11:57:20.949020 epoll_wait(22, <unfinished ...>
> 88010 11:57:20.949032 epoll_wait(26, <unfinished ...>
> 88001 11:57:20.949044 epoll_wait(17, <unfinished ...>
> 88009 11:57:20.949057 epoll_wait(21, <unfinished ...>
> 88008 11:57:20.949069 epoll_wait(14, <unfinished ...>
> 88007 11:57:20.949081 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000996>
> 88006 11:57:20.949094 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001033>
> 88007 11:57:20.949123 epoll_wait(11, <unfinished ...>
> 88006 11:57:20.949136 epoll_wait(24, <unfinished ...>
> 88005 11:57:20.949149 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001009>
> 88005 11:57:20.949199 epoll_wait(18, <unfinished ...>
> 88003 11:57:20.949214 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001061>
> 88003 11:57:20.949255 epoll_wait(19, <unfinished ...>
> 88000 11:57:20.949295 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001026>
> 88000 11:57:20.949437 epoll_wait(13, <unfinished ...>
> 87999 11:57:20.949477 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001130>
> 87998 11:57:20.949494 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001193>
> 87997 11:57:20.949508 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001145>
> 87999 11:57:20.949574 epoll_wait(23, <unfinished ...>
> 88004 11:57:20.949613 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001058>
> 87998 11:57:20.949629 epoll_wait(20, <unfinished ...>
> 87997 11:57:20.949642 epoll_wait(15, <unfinished ...>
> 87996 11:57:20.949653 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001085>
> 87995 11:57:20.949666 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001082>
> 88004 11:57:20.949678 epoll_wait(16, <unfinished ...>
> 87996 11:57:20.949710 epoll_wait(12, <unfinished ...>
> 87995 11:57:20.949723 epoll_wait(10, <unfinished ...>
> 88033 11:57:21.949419 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000997>
> 88032 11:57:21.949461 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001030>
> 88034 11:57:21.949477 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001071>
> 88031 11:57:21.949493 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001018>
> 88033 11:57:21.949525 epoll_wait(47, <unfinished ...>
> 88034 11:57:21.949545 epoll_wait(48, <unfinished ...>
> 88032 11:57:21.949557 epoll_wait(46, <unfinished ...>
> 88031 11:57:21.949568 epoll_wait(44, <unfinished ...>
> 88030 11:57:21.949580 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001054>
> 88029 11:57:21.949592 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001044>
> 88028 11:57:21.949610 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001074>
> 88027 11:57:21.949631 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001071>
> 88030 11:57:21.949645 epoll_wait(43, <unfinished ...>
> 88029 11:57:21.949657 epoll_wait(40, <unfinished ...>
> 88028 11:57:21.949669 epoll_wait(39, <unfinished ...>
> 88026 11:57:21.949681 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001060>
> 88027 11:57:21.949695 epoll_wait(38, <unfinished ...>
> 88026 11:57:21.949714 epoll_wait(37, <unfinished ...>
> 88025 11:57:21.949728 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001080>
> 88024 11:57:21.949746 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001086>
> 88023 11:57:21.949759 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001086>
> 88022 11:57:21.949772 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001083>
> 88025 11:57:21.949791 epoll_wait(36, <unfinished ...>
> 88024 11:57:21.949802 epoll_wait(35, <unfinished ...>
> 88023 11:57:21.949815 epoll_wait(34, <unfinished ...>
> 88021 11:57:21.949827 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001096>
> 88022 11:57:21.949839 epoll_wait(33, <unfinished ...>
> 88020 11:57:21.949855 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001108>
> 88019 11:57:21.949875 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001091>
> 88018 11:57:21.949887 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001072>
> 88021 11:57:21.949901 epoll_wait(32, <unfinished ...>
> 88020 11:57:21.949916 epoll_wait(31, <unfinished ...>
> 88019 11:57:21.949929 epoll_wait(30, <unfinished ...>
> 88018 11:57:21.949941 epoll_wait(29, <unfinished ...>
> 88017 11:57:21.949957 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001090>
> 88016 11:57:21.949969 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001091>
> 88015 11:57:21.949982 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001072>
> 88014 11:57:21.949993 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001073>
> 88017 11:57:21.950031 epoll_wait(28, <unfinished ...>
> 88016 11:57:21.950044 epoll_wait(27, <unfinished ...>
> 88015 11:57:21.950057 epoll_wait(25, <unfinished ...>
> 88014 11:57:21.950068 epoll_wait(42, <unfinished ...>
> 88013 11:57:21.950080 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001134>
> 88012 11:57:21.950093 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001107>
> 88011 11:57:21.950117 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001089>
> 88010 11:57:21.950130 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001092>
> 88013 11:57:21.950144 epoll_wait(41, <unfinished ...>
> 88012 11:57:21.950156 epoll_wait(45, <unfinished ...>
> 88009 11:57:21.950168 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001103>
> 88010 11:57:21.950180 epoll_wait(26, <unfinished ...>
> 88011 11:57:21.950193 epoll_wait(22, <unfinished ...>
> 88008 11:57:21.950204 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001129>
> 88007 11:57:21.950225 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001092>
> 88009 11:57:21.950237 epoll_wait(21, <unfinished ...>
> 88006 11:57:21.950249 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001105>
> 88008 11:57:21.950261 epoll_wait(14, <unfinished ...>
> 88005 11:57:21.950274 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001065>
> 88007 11:57:21.950287 epoll_wait(11, <unfinished ...>
> 88006 11:57:21.950299 epoll_wait(24, <unfinished ...>
> 88001 11:57:21.950311 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001259>
> 88005 11:57:21.950357 epoll_wait(18, <unfinished ...>
> 88001 11:57:21.950371 epoll_wait(17, <unfinished ...>
> 88003 11:57:21.950392 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001104>
> 88003 11:57:21.950463 epoll_wait(19, <unfinished ...>
> 88000 11:57:21.950505 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001034>
> 88000 11:57:21.950636 epoll_wait(13, <unfinished ...>
> 87999 11:57:21.950675 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001071>
> 88004 11:57:21.950762 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001075>
> 87999 11:57:21.950807 epoll_wait(23, <unfinished ...>
> 87998 11:57:21.950822 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001186>
> 88004 11:57:21.950843 epoll_wait(16, <unfinished ...>
> 87997 11:57:21.950856 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001208>
> 87996 11:57:21.950869 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001151>
> 87995 11:57:21.950883 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001152>
> 87998 11:57:21.950899 epoll_wait(20, <unfinished ...>
> 87997 11:57:21.950913 epoll_wait(15, <unfinished ...>
> 87996 11:57:21.950925 epoll_wait(12, <unfinished ...>
> 87995 11:57:21.950938 epoll_wait(10, <unfinished ...>
> 88033 11:57:22.950577 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001042>
> 88034 11:57:22.950620 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001067>
> 88032 11:57:22.950637 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001073>
> 88031 11:57:22.950651 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001076>
> 88033 11:57:22.950678 epoll_wait(47, <unfinished ...>
> 88034 11:57:22.950700 epoll_wait(48, <unfinished ...>
> 88032 11:57:22.950713 epoll_wait(46, <unfinished ...>
> 88031 11:57:22.950735 epoll_wait(44, <unfinished ...>
> 88030 11:57:22.950748 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001095>
> 88029 11:57:22.950762 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001098>
> 88030 11:57:22.950776 epoll_wait(43, <unfinished ...>
> 88029 11:57:22.950789 epoll_wait(40, <unfinished ...>
> 88028 11:57:22.950801 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001125>
> 88027 11:57:22.950814 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001107>
> 88028 11:57:22.950828 epoll_wait(39, <unfinished ...>
> 88027 11:57:22.950841 epoll_wait(38, <unfinished ...>
> 88026 11:57:22.950854 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001131>
> 88025 11:57:22.950867 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001068>
> 88024 11:57:22.950879 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001070>
> 88023 11:57:22.950892 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001069>
> 88026 11:57:22.950906 epoll_wait(37, <unfinished ...>
> 88024 11:57:22.950918 epoll_wait(35, <unfinished ...>
> 88025 11:57:22.950930 epoll_wait(36, <unfinished ...>
> 88023 11:57:22.950942 epoll_wait(34, <unfinished ...>
> 88022 11:57:22.950954 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001107>
> 88021 11:57:22.950966 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001058>
> 88020 11:57:22.950979 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001055>
> 88019 11:57:22.950990 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001054>
> 88022 11:57:22.951014 epoll_wait(33, <unfinished ...>
> 88021 11:57:22.951027 epoll_wait(32, <unfinished ...>
> 88020 11:57:22.951040 epoll_wait(31, <unfinished ...>
> 88019 11:57:22.951051 epoll_wait(30, <unfinished ...>
> 88018 11:57:22.951063 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001115>
> 88017 11:57:22.951075 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001035>
> 88016 11:57:22.951087 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001037>
> 88015 11:57:22.951099 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001035>
> 88018 11:57:22.951114 epoll_wait(29, <unfinished ...>
> 88017 11:57:22.951126 epoll_wait(28, <unfinished ...>
> 88016 11:57:22.951138 epoll_wait(27, <unfinished ...>
> 88015 11:57:22.951150 epoll_wait(25, <unfinished ...>
> 88014 11:57:22.951162 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001086>
> 88013 11:57:22.951173 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001022>
> 88012 11:57:22.951186 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001023>
> 88011 11:57:22.951198 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.000998>
> 88014 11:57:22.951213 epoll_wait(42, <unfinished ...>
> 88013 11:57:22.951225 epoll_wait(41, <unfinished ...>
> 88012 11:57:22.951238 epoll_wait(45, <unfinished ...>
> 88011 11:57:22.951249 epoll_wait(22, <unfinished ...>
> 88010 11:57:22.951261 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001073>
> 88009 11:57:22.951273 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001028>
> 88008 11:57:22.951285 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001017>
> 88009 11:57:22.951297 epoll_wait(21, <unfinished ...>
> 88007 11:57:22.951310 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001016>
> 88010 11:57:22.951323 epoll_wait(26, <unfinished ...>
> 88008 11:57:22.951336 epoll_wait(14, <unfinished ...>
> 88006 11:57:22.951348 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001042>
> 88007 11:57:22.951364 epoll_wait(11, <unfinished ...>
> 88005 11:57:22.951376 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001011>
> 88005 11:57:22.951403 epoll_wait(18, <unfinished ...>
> 88006 11:57:22.951420 epoll_wait(24, <unfinished ...>
> 88001 11:57:22.951432 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001055>
> 88003 11:57:22.951500 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001024>
> 88001 11:57:22.951541 epoll_wait(17, <unfinished ...>
> 88003 11:57:22.951611 epoll_wait(19, <unfinished ...>
> 88000 11:57:22.951721 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001053>
> 88000 11:57:22.951755 epoll_wait(13, <unfinished ...>
> 87999 11:57:22.951895 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001075>
> 88004 11:57:22.951937 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001085>
> 87998 11:57:22.951956 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001049>
> 87997 11:57:22.951974 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001055>
> 87999 11:57:22.951989 epoll_wait(23, <unfinished ...>
> 88004 11:57:22.952003 epoll_wait(16, <unfinished ...>
> 87998 11:57:22.952015 epoll_wait(20, <unfinished ...>
> 87997 11:57:22.952027 epoll_wait(15, <unfinished ...>
> 87996 11:57:22.952040 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001108>
> 87995 11:57:22.952053 <... epoll_wait resumed> [], 200, 1000) = 0
> <1.001107>
>
>
Willy Tarreau
Re: Idle HAProxy 1.8 spins at 100% in user space
March 12, 2018 01:00PM
On Mon, Mar 12, 2018 at 12:36:05PM +0100, Cyril Bonté wrote:
> I confirm I can reproduce the issue once 32 (and more) threads are used : the main process enters an endless loop.
> I think the same issue may occur with nbproc on FreeBSD (the same code in an #ifdef ____FreeBSD__).
>
> Can you try the patch attached ? I'll send a clean one later.

Ah good catch, I'm pretty sure you nailed it down indeed! The fun thing
is that the initial purpose of that patch was precisely to avoid this
kind of annoying stuff in the first place!

Cheers,
Willy
Krishna Kumar (Engineering)
Re: Idle HAProxy 1.8 spins at 100% in user space
March 12, 2018 02:20PM
Hi Cyril,

Thanks, this patch fixes it, it is now back to 0%. Confirmed it a few
times, and undid the patch, back to 100%, and re-added the patch,
back to 0%. Fixes perfectly.

Thanks,
- Krishna


On Mon, Mar 12, 2018 at 5:23 PM, Willy Tarreau <[email protected]> wrote:

> On Mon, Mar 12, 2018 at 12:36:05PM +0100, Cyril Bonté wrote:
> > I confirm I can reproduce the issue once 32 (and more) threads are used
> : the main process enters an endless loop.
> > I think the same issue may occur with nbproc on FreeBSD (the same code
> in an #ifdef ____FreeBSD__).
> >
> > Can you try the patch attached ? I'll send a clean one later.
>
> Ah good catch, I'm pretty sure you nailed it down indeed! The fun thing
> is that the initial purpose of that patch was precisely to avoid this
> kind of annoying stuff in the first place!
>
> Cheers,
> Willy
>
Cyril Bonté
Re: Idle HAProxy 1.8 spins at 100% in user space
March 12, 2018 09:50PM
Le 12/03/2018 à 14:11, Krishna Kumar (Engineering) a écrit :
> Hi Cyril,
>
> Thanks, this patch fixes it, it is now back to 0%. Confirmed it a few
> times, and undid the patch, back to 100%, and re-added the patch,
> back to 0%. Fixes perfectly.

Thanks for confirming, I'm preparing the patch with a reasonable commit
message. It should be ready in a few minutes ;-)


--
Cyril Bonté
Sorry, only registered users may post in this forum.

Click here to login