Hello,
Thanks for your answer Willy !
On Mon, Jan 22, 2018 at 05:47:55PM +0100, Willy Tarreau wrote:
> Hi Marc,
>
> On Mon, Jan 22, 2018 at 03:18:20PM +0100, Marc Fournier wrote:
> > Cyril Bonté <cyril.bo...@free.fr> writes:
> >
> > Hello,
> >
> > > Im' not sure you saw Samuel Reed's mail.
> > > He reported a similar issue some hours ago (High load average under
> > > 1.8 with multiple draining processes). It would be interesting to find
> > > a common configuration to reproduce the issue, so I add him to the thread.
> >
> > I've been observing the same error messages Emmanuel reports, using
> > 1.8.3 and nbthread. I tried to simplify & anonymize my configuration so
> > I could share a version which reproduces the problem, but didn't
> > succeed: the problem disappears at some point in the process, and I'm
> > unable figure out exactly which change makes the difference :-(
>
> We've done some work over the week-end to address an issue related to
> FDs and threads : in short, it's impossible to let a thread sleep when
> there's some activity on another one because they share the same epoll_fd.
>
> We've sent Samuel a copy of patches to test (I'm attaching them here in
> case you're interested to try as well, to add on top of latest 1.8, though
> 1.8.3 will be OK). Since you seem to be able to reproduce the bug on a
> full config, you may be tempted to try htem.
Ok, thanks ! I built 1.8.3 with only this patchset added to it, but the
issue still occurred. strace shows similar sequence of actions, slightly
differently. Example:
6629 12:34:38.312873 set_robust_list(0x7f4a21c449e0, 24 <unfinished ...>
6434 12:34:38.312900 munmap(0x7f4a22446000, 8003584 <unfinished ...>
6629 12:34:38.312920 <... set_robust_list resumed> ) = 0
6629 12:34:38.312941 gettimeofday( <unfinished ...>
6630 12:34:38.312965 <... epoll_create resumed> ) = 19
6434 12:34:38.312999 <... munmap resumed> ) = 0
6629 12:34:38.313020 <... gettimeofday resumed> {1516707278, 313013}, NULL) = 0
6629 12:34:38.313055 mmap(NULL, 134217728, PROT_NONE,
MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0 <unfinished ...>
6630 12:34:38.313095 close(16 <unfinished ...>
6629 12:34:38.313118 <... mmap resumed> ) = 0x7f4a1385e000
6630 12:34:38.313172 <... close resumed> ) = 0
6434 12:34:38.313196 munmap(0x7f4a22be8000, 32006144 <unfinished ...>
6629 12:34:38.313220 munmap(0x7f4a1385e000, 8003584) = 0
6434 12:34:38.313265 <... munmap resumed> ) = 0
6629 12:34:38.313287 munmap(0x7f4a18000000, 59105280 <unfinished ...>
6434 12:34:38.313308 munmap(0x7f4a24a6e000, 112009216 <unfinished ...>
6629 12:34:38.313330 <... munmap resumed> ) = 0
6434 12:34:38.313839 <... munmap resumed> ) = 0
6629 12:34:38.313870 mprotect(0x7f4a14000000, 135168, PROT_READ|PROT_WRITE) = 0
6630 12:34:38.313911 fcntl(15, F_SETFL, O_RDONLY|O_NONBLOCK <unfinished ...>
6629 12:34:38.313959 mmap(NULL, 8003584, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
6630 12:34:38.313985 <... fcntl resumed> ) = 0
6630 12:34:38.314010 gettimeofday({1516707278, 314022}, NULL) = 0
6630 12:34:38.314070 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP <unfinished ...>
6629 12:34:38.314096 <... mmap resumed> ) = 0x7f4a1b0bc000
6629 12:34:38.314126 epoll_create(2000128 <unfinished ...>
6630 12:34:38.314158 <... socket resumed> ) = 16
6629 12:34:38.314182 <... epoll_create resumed> ) = 20
6629 12:34:38.314203 close(16 <unfinished ...>
6630 12:34:38.314226 fcntl(16, F_SETFL, O_RDONLY|O_NONBLOCK <unfinished ...>
6629 12:34:38.314256 <... close resumed> ) = 0
6630 12:34:38.314278 <... fcntl resumed> ) = -1 EBADF (Bad file descriptor)
6630 12:34:38.314303 close(16 <unfinished ...>
6629 12:34:38.314324 fcntl(15, F_SETFL, O_RDONLY|O_NONBLOCK <unfinished ...>
6630 12:34:38.314344 <... close resumed> ) = -1 EBADF (Bad file descriptor)
6629 12:34:38.314365 <... fcntl resumed> ) = 0
But HAProxy still isn't able to recover from the mayhem it created, in this
case.
> > - when exposed to client requests, I only observed high CPU load on one
> > instance out of the three I have, which receeded after a restart of
> > haproxy. When working in isolation (no client requests), I never
> > noticed high CPU load.
>
> So this could indicate an uncaught error on a specific fd. A "show fd"
> on the CLI may give some useful information about this. And the patches
> above also add "show activity", to run twice one second apart, and which
> will indicate the various causes of wakeups.
Attached to this email, you have the output of five sequential
"show fd;show activity" with a one second sleep between each. The first one
was taken just before sending SIGUSR2 to HAProxy.
> > # thread 12166 gets created, and closes an fd it didn't create, which
> > # happens to be the socket opened to the DNS server:
> >
> > strace: Process 12166 attached
> > [pid 12167] sendto(16,
> > "\316\352\1\0\0\1\0\0\0\0\0\1\nprivate-25\10backends"..., 79, 0, NULL, 0
> > <unfinished ...>
> > [pid 12166] set_robust_list(0x7ff9bc9aa9e0, 24 <unfinished ...>
> > [pid 12167] <... sendto resumed> ) = 79
> > [pid 12166] <... set_robust_list resumed> ) = 0
> > [pid 12166] gettimeofday({1516289044, 684014}, NULL) = 0
> > [pid 12167] sendto(16,
> > "\37\367\1\0\0\1\0\0\0\0\0\1\nprivate-26\10backends"..., 79, 0, NULL, 0
> > <unfinished ...>
> > [pid 12166] mmap(NULL, 134217728, PROT_NONE,
> > MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0 <unfinished ...>
> > [pid 12167] <... sendto resumed> ) = 79
> > [pid 12167] sendto(16,
> > "\224\10\1\0\0\1\0\0\0\0\0\1\nprivate-27\10backends"..., 79, 0, NULL, 0) =
> > 79
> > [pid 12166] <... mmap resumed> ) = 0x7ff9ac000000
> > [pid 12167] sendto(16, "\25
> > \1\0\0\1\0\0\0\0\0\1\nprivate-28\10backends"..., 79, 0, NULL, 0) = 79
> > [pid 12166] munmap(0x7ff9b0000000, 67108864) = 0
> > [pid 12167] sendto(16,
> > "\275\n\1\0\0\1\0\0\0\0\0\1\nprivate-29\10backends"..., 79, 0, NULL, 0
> > <unfinished ...>
> > [pid 12166] mprotect(0x7ff9ac000000, 135168, PROT_READ|PROT_WRITE
> > <unfinished ...>
> > [pid 12167] <... sendto resumed> ) = 79
> > [pid 12166] <... mprotect resumed> ) = 0
> > [pid 12167] sendto(16,
> > "\312\360\1\0\0\1\0\0\0\0\0\1\nprivate-30\10backends"..., 79, 0, NULL, 0
> > <unfinished ...>
> > [pid 12166] mmap(NULL, 8003584, PROT_READ|PROT_WRITE,
> > MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
> > [pid 12167] <... sendto resumed> ) = 79
> > [pid 12167] sendto(16,
> > "\247e\1\0\0\1\0\0\0\0\0\1\nprivate-31\10backends"..., 79, 0, NULL, 0) = 79
> > [pid 12166] <... mmap resumed> ) = 0x7ff9baa65000
> > [pid 12167] sendto(16, "_k\1\0\0\1\0\0\0\0\0\1\tprivate-0\nbackoffic"...,
> > 80, 0, NULL, 0 <unfinished ...>
> > [pid 12166] close(16 <unfinished ...>
>
> Wow, that's scary! Are you certain it's not the parent process and that
> it's really a thread ? you may see a clone() syscall in 12166 giving birth
> to 12167. If they are different processes, that can be fine, but ...
Yes, the options to strace I used there doesn't print out the pid of the
master process, only those of sub-processes (and threads). This is how
things look like when reload occurs after receiving SIGUSR2:
kill(48, SIGUSR1) = 0
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024*1024, rlim_max=1024*1024}) = 0
getpid() = 1
write(2, "[WARNING] 017/152404 (1) : [hapr"..., 172) = 172
getpid() = 1
write(-1, "1\n", 2) = -1 EBADF (Bad file descriptor)
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7ff9ca196c50) = 57
strace: Process 12164 attached
[pid 12164] set_robust_list(0x7ff9ca196c60, 24 <unfinished ...>
[pid 11084] close(4) = 0
[pid 12164] <... set_robust_list resumed> ) = 0
[pid 11084] close(5) = 0
[pid 11084] close(7) = 0
[pid 12164] open("/dev/null", O_RDWR <unfinished ...>
[pid 11084] close(8) = 0
[pid 12164] <... open resumed> ) = 17
[pid 11084] close(9) = 0
[pid 12164] getgroups(0, <unfinished ...>
> > [pid 12164] getpid() = 57
> > [pid 12164] getpid() = 57
>
> Pids are collected for logging. Strange that the libc didn't cache
> the getpid()'s result by the way, usually it does. Thinking about it,
> getpid()==57 is a bit surprising, maybe it's not really a getpid in
> fact.
Sorry I didn't mention this in my last email: HAProxy is running in a
docker container, but I'm running strace from the host. The pid namespace
isolation would be causing this pid number mismatch.
I don't have any explanation for the repeated calls to getpid() though.
I'll reply to your other email in a moment.
Thanks !
Marc
4 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x55e0a118fa80 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=GLOBAL
5 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x55e0a1192780 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=https_redirection
7 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x55e0a1194840 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=entrypoint
8 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x55e0a1198d80 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=app_internal
9 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x55e0a119bb50 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=sorry_internal
10 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x55e0a119c340 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_bypass_varnish
11 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x55e0a11f1db0 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_blue
12 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x55e0a121ab50 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_green
13 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x55e0a1565e80 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=stats
14 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x55e0a1567f50 iocb=0x55e0a0910890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=healthcheck
15 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlc] cache=0
owner=0x55e0a0baca38 iocb=0x55e0a08dfed0(unknown) tmask=0xffffffffffffffff
umask=0x0
16 : st=0x22(R:pRa W:pRa) ev=0x00(heopi) [Nlc] cache=0
owner=0x7f0310013130 iocb=0x55e0a0923d40(conn_fd_handler) tmask=0x4 umask=0x8
cflg=0x00241300 fe=GLOBAL
21 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nlc] cache=0
owner=0x7f03180124c0 iocb=0x55e0a0923d40(conn_fd_handler) tmask=0x8 umask=0x0
cflg=0x80201306 fe=healthcheck
thread_id: 2
date_now: 1516707278.042397
loops: 1879 39538 40174 24107064
wake_cache: 84 164 203 996
wake_tasks: 9 9 10 1767
wake_applets: 2 37569 38160 6
wake_signal: 0 0 0 0
poll_exp: 95 37742 38373 2769
poll_drop: 7 8 8 20
poll_dead: 0 0 0 0
poll_skip: 0 0 0 0
fd_skip: 28 59 85 1705
fd_lock: 0 2 2 13
fd_del: 14 24 23 11
conn_dead: 0 0 0 0
stream: 35 37654 38244 24
empty_rq: 80 130 177 24105239
long_rq: 0 0 0 0
4 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x5587cd0a7ad0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=GLOBAL
5 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0aa7d0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=https_redirection
7 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0ac890 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=entrypoint
8 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b0dd0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=app_internal
9 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b3ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=sorry_internal
10 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b4390 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_bypass_varnish
11 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd109e30 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_blue
12 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd132ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_green
13 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd47ded0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=stats
14 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd47ffa0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=healthcheck
15 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlc] cache=0
owner=0x5587cb83aa38 iocb=0x5587cb56ded0(unknown) tmask=0xffffffffffffffff
umask=0x0
16 : st=0x25(R:PrA W:pRa) ev=0x04(heOpi) [nlc] cache=0
owner=0x5587cd4977d0 iocb=0x5587cb5ce2b0(dgram_fd_handler)
tmask=0xffffffffffffffff umask=0x0
21 : st=0x22(R:pRa W:pRa) ev=0x00(heopi) [Nlc] cache=0
owner=0x7f4a1c0122f0 iocb=0x5587cb5b1d40(conn_fd_handler) tmask=0x4 umask=0x0
cflg=0x00241300 fe=GLOBAL
thread_id: 2
date_now: 1516707279.023984
loops: 33 5526 28 29
wake_cache: 2 1 2 2
wake_tasks: 2 28 0 0
wake_applets: 0 0 0 0
wake_signal: 0 0 0 0
poll_exp: 4 29 2 2
poll_drop: 6 6 6 6
poll_dead: 0 0 0 0
poll_skip: 0 0 0 0
fd_skip: 1 1 0 1
fd_lock: 0 0 0 0
fd_del: 0 0 1 0
conn_dead: 0 0 0 0
stream: 0 0 1 0
empty_rq: 3 5497 0 2
long_rq: 0 0 0 0
4 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x5587cd0a7ad0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=GLOBAL
5 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0aa7d0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=https_redirection
7 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0ac890 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=entrypoint
8 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b0dd0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=app_internal
9 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b3ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=sorry_internal
10 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b4390 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_bypass_varnish
11 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd109e30 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_blue
12 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd132ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_green
13 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd47ded0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=stats
14 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x5587cd47ffa0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=healthcheck
15 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlc] cache=0
owner=0x5587cb83aa38 iocb=0x5587cb56ded0(unknown) tmask=0xffffffffffffffff
umask=0x0
16 : st=0x25(R:PrA W:pRa) ev=0x04(heOpi) [nlc] cache=0
owner=0x5587cd4977d0 iocb=0x5587cb5ce2b0(dgram_fd_handler)
tmask=0xffffffffffffffff umask=0x0
21 : st=0x25(R:PrA W:pRa) ev=0x00(heopi) [nlc] cache=0
owner=0x7f4a1c0122f0 iocb=0x5587cb5b1d40(conn_fd_handler) tmask=0x8 umask=0x0
cflg=0x00201306 fe=GLOBAL
thread_id: 3
date_now: 1516707280.047117
loops: 83 13949 83 83
wake_cache: 7 4 10 9
wake_tasks: 2 69 0 1
wake_applets: 0 0 1 1
wake_signal: 0 0 0 0
poll_exp: 9 73 11 11
poll_drop: 6 6 6 6
poll_dead: 0 0 0 0
poll_skip: 0 0 0 0
fd_skip: 1 3 6 7
fd_lock: 0 0 0 0
fd_del: 2 0 1 1
conn_dead: 0 0 0 0
stream: 4 0 2 1
empty_rq: 7 13878 12 13
long_rq: 0 0 0 0
4 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x5587cd0a7ad0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=GLOBAL
5 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0aa7d0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=https_redirection
7 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0ac890 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=entrypoint
8 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b0dd0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=app_internal
9 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b3ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=sorry_internal
10 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b4390 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_bypass_varnish
11 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd109e30 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_blue
12 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd132ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_green
13 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd47ded0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=stats
14 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x5587cd47ffa0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=healthcheck
15 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlc] cache=0
owner=0x5587cb83aa38 iocb=0x5587cb56ded0(unknown) tmask=0xffffffffffffffff
umask=0x0
16 : st=0x25(R:PrA W:pRa) ev=0x04(heOpi) [nlc] cache=0
owner=0x5587cd4977d0 iocb=0x5587cb5ce2b0(dgram_fd_handler)
tmask=0xffffffffffffffff umask=0x0
21 : st=0x26(R:PRa W:pRa) ev=0x10(Heopi) [nlc] cache=0
owner=0x7f4a1c0122f0 iocb=0x5587cb5b1d40(conn_fd_handler) tmask=0x8 umask=0x8
cflg=0x00241300 fe=GLOBAL
thread_id: 3
date_now: 1516707281.058964
loops: 103 24168 133 137
wake_cache: 11 7 13 14
wake_tasks: 3 113 0 1
wake_applets: 0 0 1 2
wake_signal: 0 0 0 0
poll_exp: 14 120 14 17
poll_drop: 6 6 6 7
poll_dead: 0 0 0 0
poll_skip: 0 0 0 0
fd_skip: 4 3 6 10
fd_lock: 0 0 0 0
fd_del: 2 0 2 2
conn_dead: 0 0 0 0
stream: 4 0 4 3
empty_rq: 12 24051 15 20
long_rq: 0 0 0 0
4 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x5587cd0a7ad0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=GLOBAL
5 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0aa7d0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=https_redirection
7 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0ac890 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=entrypoint
8 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b0dd0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=app_internal
9 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b3ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=sorry_internal
10 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd0b4390 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_bypass_varnish
11 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd109e30 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_blue
12 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd132ba0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=backdoor_green
13 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlC] cache=0
owner=0x5587cd47ded0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=stats
14 : st=0x05(R:PrA W:pra) ev=0x01(heopI) [nlC] cache=0
owner=0x5587cd47ffa0 iocb=0x5587cb59e890(listener_accept)
tmask=0xffffffffffffffff umask=0x0 l.st=RDY fe=healthcheck
15 : st=0x05(R:PrA W:pra) ev=0x00(heopi) [nlc] cache=0
owner=0x5587cb83aa38 iocb=0x5587cb56ded0(unknown) tmask=0xffffffffffffffff
umask=0x0
16 : st=0x25(R:PrA W:pRa) ev=0x04(heOpi) [nlc] cache=0
owner=0x5587cd4977d0 iocb=0x5587cb5ce2b0(dgram_fd_handler)
tmask=0xffffffffffffffff umask=0x0
21 : st=0x26(R:PRa W:pRa) ev=0x10(Heopi) [nlc] cache=0
owner=0x7f4a1c0122f0 iocb=0x5587cb5b1d40(conn_fd_handler) tmask=0x8 umask=0x8
cflg=0x00241300 fe=GLOBAL
thread_id: 3
date_now: 1516707282.078082
loops: 117 34766 177 186
wake_cache: 12 7 16 20
wake_tasks: 3 153 0 1
wake_applets: 0 0 1 3
wake_signal: 0 0 0 0
poll_exp: 15 160 17 24
poll_drop: 6 6 6 8
poll_dead: 0 0 0 0
poll_skip: 0 0 0 0
fd_skip: 5 6 8 10
fd_lock: 0 0 0 0
fd_del: 2 0 2 5
conn_dead: 0 0 0 0
stream: 4 0 4 9
empty_rq: 14 34609 20 25
long_rq: 0 0 0 0
