I think I found something, please look at the session 0x2110edc0 and
"calls", it never ends:
socat /run/haproxy/haproxy2.sock - <<< "show sess all"
0x2110edc0: [05/Apr/2019:12:03:32.141927] id=14505 proto=tcpv4
source=S.S.S.S:52414
flags=0x4504e, conn_retries=3, srv_conn=0xe2e7fb0, pend_pos=(nil)
waiting=0
frontend=dev_metrics_5044_front (id=1015 mode=tcp), listener=? (id=2)
addr=B.B.B.B:5044
backend=B.B.B.B:5044_back (id=1016 mode=tcp) addr=X.X.X.X:16222
server=slot_5_1 (id=34) addr=N.N.N.N:31728
task=0x21105f90 (state=0x00 nice=0 calls=-1222180819 exp=<PAST> tmask=0x1
age=1h6m)
si[0]=0x2110f058 (state=EST flags=0x40000 endp0=CS:0x210fe2a0 exp=<NEVER>
et=0x000 sub=0)
si[1]=0x2110f098 (state=EST flags=0x80010 endp1=CS:0x2109eb10 exp=<NEVER>
et=0x200 sub=0)
co0=0x210f8040 ctrl=tcpv4 xprt=RAW mux=PASS data=STRM
target=LISTENER:0xe25a290
flags=0x00283300 fd=2404 fd.state=22 fd.cache=0 updt=0 fd.tmask=0x1
cs=0x210fe2a0 csf=0x00000640 ctx=0x210fe2c0
co1=0x20d84cb0 ctrl=tcpv4 xprt=RAW mux=PASS data=STRM
target=SERVER:0xe2e7fb0
flags=0x003c3310 fd=1959 fd.state=22 fd.cache=0 updt=0 fd.tmask=0x1
cs=0x2109eb10 csf=0x00001000 ctx=(nil)
req=0x2110edd0 (f=0x848800 an=0x0 pipe=0 tofwd=-1 total=38767)
an_exp=<NEVER> rex=<NEVER> wex=?
buf=0x2110edd8 data=0x20e8a7e0 o=15360 p=15360 req.next=0 i=0
size=16384
res=0x2110ee30 (f=0x8004a028 an=0x0 pipe=0 tofwd=0 total=66)
an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
buf=0x2110ee38 data=(nil) o=0 p=0 rsp.next=0 i=0 size=0
0x20eec3f0: [05/Apr/2019:13:18:24.444808] id=29808 proto=unix_stream
source=unix:2
flags=0x8, conn_retries=0, srv_conn=(nil), pend_pos=(nil) waiting=0
frontend=GLOBAL (id=0 mode=tcp), listener=? (id=2) addr=unix:2
backend=<NONE> (id=-1 mode=-)
server=<NONE> (id=-1)
task=0x21028880 (state=0x00 nice=-64 calls=1 exp=30s tmask=0x1 age=?)
si[0]=0x20eec688 (state=EST flags=0x200008 endp0=CS:0x20cd4600
exp=<NEVER> et=0x000 sub=1)
si[1]=0x20eec6c8 (state=EST flags=0x204018 endp1=APPCTX:0x20cdfe60
exp=<NEVER> et=0x000 sub=0)
co0=0x210af6a0 ctrl=unix_stream xprt=RAW mux=PASS data=STRM
target=LISTENER:0x11b7d20
flags=0x00203306 fd=10 fd.state=25 fd.cache=0 updt=0 fd.tmask=0x1
cs=0x20cd4600 csf=0x00000200 ctx=0x20cd4620
app1=0x20cdfe60 st0=7 st1=0 st2=3 applet=<CLI> tmask=0x1, nice=-64,
calls=2, cpu=0, lat=0
req=0x20eec400 (f=0xc48202 an=0x0 pipe=0 tofwd=-1 total=14)
an_exp=<NEVER> rex=30s wex=<NEVER>
buf=0x20eec408 data=0x20e2a530 o=0 p=0 req.next=0 i=0 size=16384
res=0x20eec460 (f=0x80008002 an=0x0 pipe=0 tofwd=-1 total=1465)
an_exp=<NEVER> rex=<NEVER> wex=<NEVER>
buf=0x20eec468 data=0x20d5bbd0 o=1465 p=1465 rsp.next=0 i=0 size=16384
netstat -untap | grep S.S.S.S
<no output / no connections>
pt., 5 kwi 2019 o 13:05 Maciej Zdeb <[email protected]> napisał(a):
> After process spin up to 100% cpu, I switched traffic to another (backup)
> server then I attached gdb and executed "generate-core-file". However I
> don't know how to proceed with it further (it's quite big 3,2GB).
> When I'm attached with gdb sometimes (not always) "bt full" shows this (no
> idea if it's relevant, I've no experience with gdb):
>
> gdb --pid 75107
> GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.3) 7.7.1
> Copyright (C) 2014 Free Software Foundation, Inc.
> License GPLv3+: GNU GPL version 3 or later <
> http://gnu.org/licenses/gpl.html>
> This is free software: you are free to change and redistribute it.
> There is NO WARRANTY, to the extent permitted by law. Type "show copying"
> and "show warranty" for details.
> This GDB was configured as "x86_64-linux-gnu".
> Type "show configuration" for configuration details.
> For bug reporting instructions, please see:
> <http://www.gnu.org/software/gdb/bugs/>.
> Find the GDB manual and other documentation resources online at:
> <http://www.gnu.org/software/gdb/documentation/>.
> For help, type "help".
> Type "apropos word" to search for commands related to "word".
> Attaching to process 75107
> Reading symbols from /usr/sbin/haproxy...done.
> Reading symbols from /lib/x86_64-linux-gnu/libcrypt.so.1...Reading symbols
> from /usr/lib/debug//lib/x86_64-linux-gnu/libcrypt-2.19.so...done.
> done.
> Loaded symbols for /lib/x86_64-linux-gnu/libcrypt.so.1
> Reading symbols from /lib/x86_64-linux-gnu/libz.so.1...(no debugging
> symbols found)...done.
> Loaded symbols for /lib/x86_64-linux-gnu/libz.so.1
> Reading symbols from /lib/x86_64-linux-gnu/libpthread.so.0...Reading
> symbols from /usr/lib/debug//lib/x86_64-linux-gnu/libpthread-2.19.so...done.
> done.
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
> Loaded symbols for /lib/x86_64-linux-gnu/libpthread.so.0
> Reading symbols from /lib/x86_64-linux-gnu/librt.so.1...Reading symbols
> from /usr/lib/debug//lib/x86_64-linux-gnu/librt-2.19.so...done.
> done.
> Loaded symbols for /lib/x86_64-linux-gnu/librt.so.1
> Reading symbols from
> /usr/lib/haproxy/openssl_1.1.1b/lib/libssl.so.1.1...(no debugging symbols
> found)...done.
> Loaded symbols for /usr/lib/haproxy/openssl_1.1.1b/lib/libssl.so.1.1
> Reading symbols from
> /usr/lib/haproxy/openssl_1.1.1b/lib/libcrypto.so.1.1...(no debugging
> symbols found)...done.
> Loaded symbols for /usr/lib/haproxy/openssl_1.1.1b/lib/libcrypto.so.1.1
> Reading symbols from /lib/x86_64-linux-gnu/libm.so.6...Reading symbols
> from /usr/lib/debug//lib/x86_64-linux-gnu/libm-2.19.so...done.
> done.
> Loaded symbols for /lib/x86_64-linux-gnu/libm.so.6
> Reading symbols from /lib/x86_64-linux-gnu/libdl.so.2...Reading symbols
> from /usr/lib/debug//lib/x86_64-linux-gnu/libdl-2.19.so...done.
> done.
> Loaded symbols for /lib/x86_64-linux-gnu/libdl.so.2
> Reading symbols from /usr/lib/haproxy/pcre_8.42/lib/libpcre.so.1...(no
> debugging symbols found)...done.
> Loaded symbols for /usr/lib/haproxy/pcre_8.42/lib/libpcre.so.1
> Reading symbols from /lib/x86_64-linux-gnu/libc.so.6...Reading symbols
> from /usr/lib/debug//lib/x86_64-linux-gnu/libc-2.19.so...done.
> done.
> Loaded symbols for /lib/x86_64-linux-gnu/libc.so.6
> Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from
> /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.19.so...done.
> done.
> Loaded symbols for /lib64/ld-linux-x86-64.so.2
> Reading symbols from /usr/lib/haproxy/lua/random.so...(no debugging
> symbols found)...done.
> Loaded symbols for /usr/lib/haproxy/lua/random.so
> Reading symbols from /lib/x86_64-linux-gnu/libnss_files.so.2...Reading
> symbols from
> /usr/lib/debug//lib/x86_64-linux-gnu/libnss_files-2.19.so...done.
> done.
> Loaded symbols for /lib/x86_64-linux-gnu/libnss_files.so.2
> 0x00007f762bb226b3 in __epoll_wait_nocancel () at
> ../sysdeps/unix/syscall-template.S:81
> 81 ../sysdeps/unix/syscall-template.S: No such file or directory.
> (gdb) bt full
> #0 0x00007f762bb226b3 in __epoll_wait_nocancel () at
> ../sysdeps/unix/syscall-template.S:81
> No locals.
> #1 0x0000000000421ebe in _do_poll (p=<optimized out>, exp=-316679748) at
> src/ev_epoll.c:156
> timeout = 0
> status = <optimized out>
> fd = <optimized out>
> count = <optimized out>
> updt_idx = <optimized out>
> old_fd = <optimized out>
> #2 0x00000000004bd9e4 in run_poll_loop () at src/haproxy.c:2675
> next = <optimized out>
> exp = <optimized out>
> #3 run_thread_poll_loop (data=data@entry=0x11af740) at src/haproxy.c:2707
> ptif = 0x7f50b0 <per_thread_init_list>
> ptdf = <optimized out>
> start_lock = 0
> #4 0x000000000041fb96 in main (argc=<optimized out>, argv=0x7ffd0e185478)
> at src/haproxy.c:3343
> tids = 0x11af740
> threads = 0x1e2a5460
> i = <optimized out>
> old_sig = {__val = {0, 140145545627744, 140145545626880,
> 140145543473713, 0, 140145545613504, 1, 0, 18446603344811130881,
> 140145545626880, 1, 140145545675208, 0, 140145545676064, 0, 24}}
> blocked_sig = {__val = {18446744067199990583, 18446744073709551615
> <repeats 15 times>}}
> err = <optimized out>
> retry = <optimized out>
> limit = {rlim_cur = 1000000, rlim_max = 1000000}
> errmsg = "\000\000\000\000\000\000\000\000n\000\000\000w", '\000'
> <repeats 11 times>,
> "pq\315,v\177\000\000\000\000\000\000\000\000\000\000`g\336+v\177\000\000\030\000\000\000\000\000\000\000\200f\026\001\000\000\000\000>\001\000\024\000\000\000\000
> *\315,v\177\000\000`\221\027\001\000\000\000\000\340j\252+v\177\000\000\260T\030\016"
> pidfd = <optimized out>
> (gdb) generate-core-file
> warning: target file /proc/75107/cmdline contained unexpected null
> characters
> warning: Memory read failed for corefile section, 12288 bytes at
> 0x7ffd0e1c5000.
> Saved corefile core.75107
> (gdb) quit
>
> pt., 5 kwi 2019 o 09:19 Maciej Zdeb <[email protected]> napisał(a):
>
>> Hi again,
>>
>> I verified that local DoS did not cause that high cpu usage. I'm
>> upgrading from 1.8.19 to 1.9.6.
>>
>> Please look at strace:
>>
>> of process with 100% cpu usage:
>> strace -fp 9790 -c
>> Process 9790 attached
>> % time seconds usecs/call calls errors syscall
>> ------ ----------- ----------- --------- --------- ----------------
>> 27.51 0.009501 0 942536 clock_gettime
>> 13.65 0.004716 0 471268 epoll_wait
>> 12.09 0.004176 0 305211 157644 recvfrom
>> 11.09 0.003831 0 109003 64867 connect
>> 9.04 0.003122 0 141908 6479 sendto
>> 6.55 0.002264 0 193372 epoll_ctl
>> 5.05 0.001746 0 57430 close
>> 4.46 0.001539 0 118067 setsockopt
>> 3.05 0.001053 0 94756 1860 getsockopt
>> 2.55 0.000882 0 50009 socket
>> 1.43 0.000493 0 50009 fcntl
>> 1.32 0.000457 0 14947 7353 accept4
>> 0.89 0.000306 0 11660 1 shutdown
>> 0.58 0.000199 0 12172 3226 read
>> 0.47 0.000164 0 3838 279 write
>> 0.21 0.000074 0 6640 bind
>> 0.06 0.000019 0 1860 getsockname
>> 0.00 0.000000 0 4 brk
>> 0.00 0.000000 0 24 sendmsg
>> ------ ----------- ----------- --------- --------- ----------------
>> 100.00 0.034542 2584714 241709 total
>>
>> fragment of strace:
>> [...]
>> epoll_ctl(3, EPOLL_CTL_ADD, 2020, {EPOLLOUT, {u32=2020, u64=2020}}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87792876}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87804387}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87811541}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87823913}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87830810}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87842796}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87849448}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87859750}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87866006}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87877936}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87885329}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87897045}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87904108}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87915961}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87922580}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87933941}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87940258}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87952045}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87959070}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87971104}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87978136}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87990210}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 87998045}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88009585}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88015976}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88027627}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88034407}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88046698}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88053419}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88065381}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88071551}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88082999}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88089594}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88112393}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88118910}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88130295}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88136707}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88148429}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88155219}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88167019}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88173660}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88185332}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88191732}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88203660}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88210542}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88223145}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88230090}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88242627}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88250786}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88262976}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88270439}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88282001}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88288596}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88299666}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88305992}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88316967}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88324161}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88335865}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88342721}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88354743}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88361932}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88385864}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88392851}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88405104}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88411895}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88423943}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88430569}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88442977}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88450051}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88462006}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88468393}) = 0
>> epoll_wait(3, {}, 200, 0) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88479825}) = 0
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88497719}) = 0
>> epoll_wait(3, {{EPOLLIN, {u32=1142, u64=1142}}}, 200, 0) = 1
>> clock_gettime(CLOCK_THREAD_CPUTIME_ID, {848, 88510556}) = 0
>> [...]
>>
>> After some time I have 2 then 3 haproxy processes with 100% cpu.
>>
>> This is strace of process with normal 10% cpu usage:
>> strace -fp 9809 -c
>> Process 9809 attached
>> % time seconds usecs/call calls errors syscall
>> ------ ----------- ----------- --------- --------- ----------------
>> 38.20 0.020981 0 615163 epoll_wait
>> 15.60 0.008565 0 1230326 clock_gettime
>> 10.32 0.005667 0 110707 66703 connect
>> 8.51 0.004673 0 391704 201233 recvfrom
>> 7.82 0.004292 0 14450 7157 accept4
>> 7.48 0.004106 0 183790 6254 sendto
>> 3.48 0.001909 0 57090 close
>> 3.02 0.001658 0 240248 epoll_ctl
>> 1.66 0.000914 0 50016 socket
>> 1.43 0.000786 0 117936 setsockopt
>> 1.21 0.000666 0 97594 1660 getsockopt
>> 0.51 0.000281 0 50016 fcntl
>> 0.42 0.000229 0 12275 shutdown
>> 0.22 0.000119 0 13236 3752 read
>> 0.08 0.000043 0 4169 280 write
>> 0.03 0.000016 0 6313 bind
>> 0.02 0.000012 0 1660 getsockname
>> 0.00 0.000000 0 4 brk
>> ------ ----------- ----------- --------- --------- ----------------
>> 100.00 0.054917 3196697 287039 total
>>
>> Any guidance how to debug it further would be very helpful.
>>
>> czw., 4 kwi 2019 o 14:56 Maciej Zdeb <[email protected]> napisał(a):
>>
>>> I'm very sorry, it is probably "real" traffic that haproxy needs to
>>> handle. Some local DDoS occurred just in time when I upgraded to 1.9 (what
>>> terribly bad luck).
>>>
>>> Please ignore previous email! Sorry for wasting your time.
>>>
>>> czw., 4 kwi 2019 o 14:36 Maciej Zdeb <[email protected]> napisał(a):
>>>
>>>> Hi,
>>>>
>>>> After haproxy starts everything is fine, but after some time one of
>>>> haproxy processes uses 100% of CPU. I've managed to dump some "show"
>>>> commands (I have also "show fd", "show sess all" and "strace" but if needed
>>>> I would prefer to send it privately). If you could give any advice howto
>>>> debug it further it would be great.
>>>>
>>>> ps aux | grep haprox
>>>> haproxy 99023 97.5 0.6 3139384 623476 ? Rs 14:07 16:38
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>> haproxy 99024 13.0 0.6 3138964 623096 ? Ss 14:07 2:13
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>> haproxy 99025 14.1 0.6 3139044 623160 ? Rs 14:07 2:25
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>> haproxy 99034 11.9 0.6 3139024 623496 ? Ss 14:07 2:02
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>> haproxy 99035 16.3 0.6 3139184 623116 ? Ss 14:07 2:47
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>> haproxy 99037 13.0 0.6 3138724 623076 ? Ss 14:07 2:13
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>> haproxy 99045 16.3 0.6 3139332 623216 ? Ss 14:07 2:47
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>> haproxy 99046 12.0 0.6 3137792 622208 ? Rs 14:07 2:03
>>>> /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D
>>>> -sf 15434 15443 15444 15445 15454 15455 15456 15457
>>>>
>>>> socat /var/run/haproxy/haproxy1.sock - <<< "show info"
>>>> Name: HAProxy
>>>> Version: 1.9.6
>>>> Release_date: 2019/03/29
>>>> Nbthread: 1
>>>> Nbproc: 8
>>>> Process_num: 1
>>>> Pid: 99023
>>>> Uptime: 0d 0h12m26s
>>>> Uptime_sec: 746
>>>> Memmax_MB: 0
>>>> PoolAlloc_MB: 8
>>>> PoolUsed_MB: 8
>>>> PoolFailed: 0
>>>> Ulimit-n: 1000000
>>>> Maxsock: 4012387
>>>> Maxconn: 2000000
>>>> Hard_maxconn: 2000000
>>>> CurrConns: 850
>>>> CumConns: 114038
>>>> CumReq: 179023
>>>> MaxSslConns: 0
>>>> CurrSslConns: 4
>>>> CumSslConns: 6225
>>>> Maxpipes: 0
>>>> PipesUsed: 0
>>>> PipesFree: 0
>>>> ConnRate: 161
>>>> ConnRateLimit: 0
>>>> MaxConnRate: 366
>>>> SessRate: 161
>>>> SessRateLimit: 0
>>>> MaxSessRate: 366
>>>> SslRate: 6
>>>> SslRateLimit: 0
>>>> MaxSslRate: 18
>>>> SslFrontendKeyRate: 3
>>>> SslFrontendMaxKeyRate: 7
>>>> SslFrontendSessionReuse_pct: 50
>>>> SslBackendKeyRate: 0
>>>> SslBackendMaxKeyRate: 10
>>>> SslCacheLookups: 1054
>>>> SslCacheMisses: 103
>>>> CompressBpsIn: 0
>>>> CompressBpsOut: 0
>>>> CompressBpsRateLim: 0
>>>> ZlibMemUsage: 0
>>>> MaxZlibMemUsage: 0
>>>> Tasks: 26283
>>>> Run_queue: 3
>>>> Idle_pct: 39
>>>> node: XXXX
>>>> Stopping: 0
>>>> Jobs: 7181
>>>> Unstoppable Jobs: 0
>>>> Listeners: 6330
>>>> ActivePeers: 0
>>>> ConnectedPeers: 0
>>>> DroppedLogs: 6
>>>> BusyPolling: 0
>>>>
>>>> socat /var/run/haproxy/haproxy1.sock - <<< "show activity"
>>>> thread_id: 0
>>>> date_now: 1554380334.734878
>>>> loops: 355064374
>>>> wake_cache: 2498224
>>>> wake_tasks: 352539647
>>>> wake_signal: 0
>>>> poll_exp: 355037871
>>>> poll_drop: 194560
>>>> poll_dead: 0
>>>> poll_skip: 0
>>>> fd_skip: 0
>>>> fd_lock: 0
>>>> fd_del: 0
>>>> conn_dead: 0
>>>> stream: 710586336
>>>> empty_rq: 15313
>>>> long_rq: 57
>>>> cpust_ms_tot: 747
>>>> cpust_ms_1s: 0
>>>> cpust_ms_15s: 0
>>>> avg_loop_us: 1
>>>>
>>>> haproxy -vv
>>>> HA-Proxy version 1.9.6 2019/03/29 - https://haproxy.org/
>>>> Build options :
>>>> TARGET = linux2628
>>>> CPU = generic
>>>> CC = gcc
>>>> CFLAGS = -O2 -g -fno-strict-aliasing -Wdeclaration-after-statement
>>>> -fwrapv -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter
>>>> -Wno-old-style-declaration -Wno-ignored-qualifiers -Wno-clobbered
>>>> -Wno-missing-field-initializers -Wtype-limits -DIP_BIND_ADDRESS_NO_PORT=24
>>>> OPTIONS = USE_GETADDRINFO=1 USE_ZLIB=1 USE_DL=1 USE_OPENSSL=1
>>>> USE_LUA=1 USE_PCRE=1 USE_PCRE_JIT=1
>>>>
>>>> Default settings :
>>>> maxconn = 2000, bufsize = 16384, maxrewrite = 1024, maxpollevents =
>>>> 200
>>>>
>>>> Built with OpenSSL version : OpenSSL 1.1.1b 26 Feb 2019
>>>> Running on OpenSSL version : OpenSSL 1.1.1b 26 Feb 2019
>>>> 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.5
>>>> Built with transparent proxy support using: IP_TRANSPARENT
>>>> IPV6_TRANSPARENT IP_FREEBIND
>>>> 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 PCRE version : 8.42 2018-03-20
>>>> Running on PCRE version : 8.42 2018-03-20
>>>> PCRE library supports JIT : yes
>>>> Encrypted password support via crypt(3): yes
>>>> Built with multi-threading 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 multiplexer protocols :
>>>> (protocols marked as <default> cannot be specified using 'proto'
>>>> keyword)
>>>> h2 : mode=HTX side=FE|BE
>>>> h2 : mode=HTTP side=FE
>>>> <default> : mode=HTX side=FE|BE
>>>> <default> : mode=TCP|HTTP side=FE|BE
>>>>
>>>> Available filters :
>>>> [SPOE] spoe
>>>> [COMP] compression
>>>> [CACHE] cache
>>>> [TRACE] trace
>>>>
>>>
