TCP SYN backlog change likely has concurrent global var access issues

[pfalcon]

ab -n1000 http://192.0.2.1:8080/ run against http_server.py (see #728) of MicroPython built against tag v1.8.0:

Time taken for tests:   21.512 seconds
Complete requests:      1000
Failed requests:        910
   (Connect: 0, Receive: 0, Length: 910, Exceptions: 0)
Total transferred:      45920 bytes
HTML transferred:       28920 bytes
Requests per second:    46.49 [#/sec] (mean)
Time per request:       21.512 [ms] (mean)
Time per request:       21.512 [ms] (mean, across all concurrent requests)
Transfer rate:          2.08 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        5    9   9.8      7     116
Processing:     8   12   9.2     11     118
Waiting:        8   11   8.8     10     118
Total:         14   21  14.9     18     158

ab -n10 http://192.0.2.1:8080/ (note - 10 requests!) run against uPy build against Z master:

Time taken for tests:   17.383 seconds
Complete requests:      10
Failed requests:        1
   (Connect: 0, Receive: 0, Length: 1, Exceptions: 0)
Total transferred:      441 bytes
HTML transferred:       271 bytes
Requests per second:    0.58 [#/sec] (mean)
Time per request:       1738.346 [ms] (mean)
Time per request:       1738.346 [ms] (mean, across all concurrent requests)
Transfer rate:          0.02 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        6 1723 1170.2   1030    3051
Processing:    10   16  10.0     12      41
Waiting:        8   15  10.5     10      41
Total:         19 1738 1173.0   1042    3092

[pfalcon]

Bisecting...

[pfalcon]

No unsurprisingly it's #672. Specifically, the first broken commit is 117771e

[pfalcon]

@pfl: FYI ^^

[pfalcon]

D'oh. So, by default there's 1 entry in backlog table. When we send SYN/ACK, we take that entry and set up worker timer there. When we receive ACK, we've done with that entry, but can't remove it, as there sits counting down worker timer. At which point a new connection arrives, and being dropped, many times, until long ACK delay expires and worker handler clear the entry.

That's how the patch developed to allow multiple concurrent connections regressed multiple sequential connections. Using any other arbitrary sizes for backlog queue aren't going to help of course, the culprit is in the usage of worker API and its deficiency (#682) in Zephyr.

[pfalcon]

Actually, I guess there's confusion with how k_delayed_work_cancel() works. Let's consider this specific example, which uses ACK timeout of 1000ms. That's big timeout, and all this 1000ms delayed work just counts down this timeout and can be perfectly cancelled. Only at the end of these 1000ms it gets added to scheduler queue, where it can't be cancelled. It spends there maybe 100us (well, depends on well-behavedness of other delay work handlers and perhaps other components of system, e.g. #672 calls send_reset(), dunno how fast that may finish). So, following patch works as expected:

+       if (k_delayed_work_cancel(&tcp_backlog[r].ack_timer) < 0) {
+               /* Too late to cancel - we may be preempted on the next
+                * instruction. But with few instructions we have left so
+                * far, we stay positive and send final hello to impending
+                * worker asking not to destroy our connection. I don't know
+                * why we're doing that though - too late is too late. Also,
+                * there can be race condition with us patching entry after
+                * it was cleared by the worker.
+                */
+               tcp_backlog[r].cancelled = true;
+       } else {
+               memset(&tcp_backlog[r], 0, sizeof(struct tcp_backlog_entry));
+       }
+#if 0
        if (k_delayed_work_remaining_get(&tcp_backlog[r].ack_timer) > 0) {
                tcp_backlog[r].cancelled = true;
        } else {
                k_delayed_work_cancel(&tcp_backlog[r].ack_timer);
                memset(&tcp_backlog[r], 0, sizeof(struct tcp_backlog_entry));
        }
+#endif

As can be seen I was skeptical for the need of "cancelled" flag at all, given then window of 1000ms when it can be cancelled vs 0.1ms when it can't. But here's another issue - I'm not sure how this (tcp_backlog_ack()) function is called, so conservative assumption is that it may be preempted by work handler. But then tcp_backlog_ack() both reads and writes tcp_backlog[r] and work handler frees it. Then, there must be synchronization when accessing tcp_backlog[r], and as work handler is handled by thread scheduler, I guess the (only) reasonable way is to use irq_lock. But then there's also contention who will free tcp_backlog[r] - if tcp_backlog_ack() can't cancel the worker, it must not free it, but it will know it only after call to k_delayed_work_cancel(). That means that the critical section would be quite big - literally from the start of tcp_backlog_ack() until it calls k_delayed_work_cancel(), 95% of the function body.

Given these concerns on how to synchronize access to tcp_backlog, I don't propose a patch, but instead would appreciate comments from @jukkar , @pfl, @Vudentz , and other folks.