DEBUG: epoll: store and compare the FD's generation count with reported event
authorWilly Tarreau <w@1wt.eu>
Thu, 30 Jan 2025 15:28:33 +0000 (16:28 +0100)
committerWilly Tarreau <w@1wt.eu>
Wed, 19 Feb 2025 10:39:38 +0000 (11:39 +0100)
commitc25bd8a78d82a8bd6014b718a84ca69b73fc0e81
tree681b0f5d8fcb68aa0215a157fbc72191f266dfc5
parent3f646022e0d7421a7f105e9aab1546fd7263ce7d
DEBUG: epoll: store and compare the FD's generation count with reported event

There have been some reported cases where races between threads in epoll
were causing wrong reports of close or error events. Since the epoll_event
data is 64 bits, we can store the FD's generation counter in the upper
bits to verify if we're speaking about the same instance of the FD as the
current one or a stale one. If the generation number does not match, then
we classify these into 3 conditions and increment the relevant COUNT_IF()
counters (stale report for closed FD, stale report of harmless event on
reopened FD, stale report of HUP/ERR on reopened FD). Tests have shown that
with heavy concurrency, a very small maxconn (typically 1 per thread),
http-reuse always and a server closing connections first but randomly
(httpterm with /C=2r), such events can happen at a pace of a few per second
for the closed FDs, and a few per minute for the other ones, so there's value
in leaving this accessible for troubleshooting. E.g after a few minutes:

  Count     Type Location function(): "condition" [comment]
  5541       CNT ev_epoll.c:296 _do_poll(): "1" [epoll report of event on a just closed fd (harmless)]
  10         CNT ev_epoll.c:294 _do_poll(): "1" [epoll report of event on a closed recycled fd (rare)]
  42         CNT ev_epoll.c:289 _do_poll(): "1" [epoll report of HUP on a stale fd reopened on the same thread (suspicious)]
  212        CNT ev_epoll.c:279 _do_poll(): "1" [epoll report of HUP/ERR on a stale fd reopened on another thread (harmless)]
  1          CNT mux_h1.c:3911 h1_send(): "b_data(&h1c->obuf)" [connection error (send) with pending output data]

This one with the following setup, whicih abuses threads contention by
starting 64 threads on two cores:
- config:
    global
        nbthread 64
        stats socket /tmp/sock1 level admin
        stats timeout 1h
    defaults
        timeout client 5s
        timeout server 5s
        timeout connect 5s
        mode http
    listen p2
        bind :8002
        http-reuse always
        server s1 127.0.0.1:8000 maxconn 4

- haproxy forcefully started on 2C4T:

    $ taskset -c 0,1,4,5 ./haproxy -db -f epoll-dbg.cfg

- httpterm on port 8000, cpus 2,3,6,7 (2C4T)

- h1load with responses larger than a single buffer, and randomly
  closing/keeping alive:

    $ taskset -c 2,3,6,7 h1load -e -t 4 -c 256 -r 1 0:8002/?s=19k/C=2r

(cherry picked from commit 5012b6c6d9e2278ae247e3e372765be3c11af86c)
Signed-off-by: Willy Tarreau <w@1wt.eu>
src/ev_epoll.c